Yes. Thank you!

Does this commit fix things for you?

Changes have been made in Git for this ticket:

Bug #10017: Only list sidebar apps in listApps() if parent app is active

  3 files changed, 18 insertions(+), 7 deletions(-)
http://git.horde.org/horde-git/-/commit/a2ca17646d2be80b726282b9b3732194babc36bf

The following is logged with debugging enabled (similar entries for 
chora, whups, jonah, hermes and gollem):

2011-06-07T21:20:43+02:00 ERR: HORDE [horde] trean is not activated. 
[pid 14724 on line 1247 of "/usr/share/php5/PEAR/Horde/Registry.php"]
2011-06-07T21:20:43+02:00 DEBUG:  1. 
Horde_Core_Ajax_Application->doAction() 
/srv/www/htdocs/horde4/services/ajax.php:60
  2. call_user_func() /usr/share/php5/PEAR/Horde/Core/Ajax/Application.php:95
  3. Horde_Ajax_Application->sidebarUpdate()
  4. Horde_Core_Sidebar->getTree() 
/srv/www/htdocs/horde4/lib/Ajax/Application.php:36
  5. Horde_Registry->hasPermission() 
/usr/share/php5/PEAR/Horde/Core/Sidebar.php:79
  6. Horde_Registry->isAuthenticated() 
/usr/share/php5/PEAR/Horde/Registry.php:1407
  7. Horde_Core_Auth_Application->transparent() 
/usr/share/php5/PEAR/Horde/Registry.php:1840
  8. Horde_Core_Auth_Application->_setAuth() 
/usr/share/php5/PEAR/Horde/Core/Auth/Application.php:311
  9. Horde_Registry->callAppMethod() 
/usr/share/php5/PEAR/Horde/Core/Auth/Application.php:593
10. Horde_Registry->pushApp() /usr/share/php5/PEAR/Horde/Registry.php:1060

2011-06-07T21:20:43+02:00 DEBUG: HORDE [horde] SQL  (0,0006s)
         SELECT cache_data FROM horde_cache WHERE cache_id =
           '8c8e788cebc63413d300e711b2ddae43' AND cache_timestamp >= 
1307388043 [pid 14724 on line 783 of 
"/usr/share/php5/PEAR/Horde/Db/Adapter/Base.php"]
2011-06-07T21:20:43+02:00 DEBUG: HORDE [horde] SQL  (0,0002s)
         SELECT COUNT(*) FROM horde_perms WHERE perm_name = 'trean' 
[pid 14724 on line 783 of 
"/usr/share/php5/PEAR/Horde/Db/Adapter/Base.php"]
2011-06-07T21:20:43+02:00 DEBUG: HORDE [horde] SQL  (0,0005s)
         DELETE FROM horde_cache WHERE
           cache_id='8c8e788cebc63413d300e711b2ddae43' [pid 14724 on 
line 783 of "/usr/share/php5/PEAR/Horde/Db/Adapter/Base.php"]
2011-06-07T21:20:43+02:00 DEBUG: HORDE [horde] SQL  (0,0005s)
         INSERT INTO horde_cache (cache_id, cache_timestamp, cache_expiration,
           cache_data) VALUES ('8c8e788cebc63413d300e711b2ddae43', 1307474443,
           1307560843, '\00') [pid 14724 on line 783 of 
"/usr/share/php5/PEAR/Horde/Db/Adapter/Base.php"]

Is this of any help in finding what goes wrong?

I'm seeing the same behavior for all users without administration 
rights after upgrading from H3.3.11 -> H4.0.3. Strangely enough, this 
doesn't happen when administrators log-in.

More info: there is at least one more user on the list with the same errors:
http://lists.horde.org/archives/horde/Week-of-Mon-20110516/040864.html

(message is not exactlty about my problem, but you can see the same
errors in the log)

Unfortunately, there's nothing more we can do because no developer can 
reproduce.

It's not failling here. I've determined that entry point for the error 
is hasPermission check some lines sooner. Also I've modified 
callAppMethod to log the method which is called and got 
"authAuthenticateCallback" in all five logged cases. Further debugging 
is really over my head here.
Again this doesn't happen on that particular Exception.

Yes - that is correct.

But again, this should not matter.  Because in the sidebar generation 
code, this happens:

             case 'sidebar':
                 try {
                     $registry->callAppMethod($params['app'], 
'sidebarCreate', array('args' => array($this->_tree, 
empty($params['menu_parent']) ? null : $params['menu_parent'], 
isset($params['sidebar_params']) ? $params['sidebar_params'] : 
array())));
                 } catch (Horde_Exception $e) {
                     if ($e->getCode() != Horde_Registry::NOT_ACTIVE) {
                         Horde::logMessage($e, 'ERR');
                     }
                 }

callAppMethod() should immediately fail because the application 
($params['app']) is not active.

It is debatable whether we could optimize this check more.  Right now, 
the code is very clean, since all application existence checking takes 
place inside of the Registry object.  Conversely, Jan has shown in the 
past that throwing/catching Exceptions is not the most efficient of 
operations.  So there is a trade-off between nice OO-coding style with 
performance here.  However, for purposes of analyzing this current 
issue, this is irrelevant.

Back to the analysis... when callAppMethod() throws an Exception, we 
check to see if the exception is that the application does not exist.   
If that is the error, then we ignore the exception and continuing 
processing the next sidebar block.  And this is what happens on my 
installation.

So once again, the question remains: why is this Exception returning 
something other than Horde_Registry::NOT_ACTIVE for you?  Because this 
is what is broken, not anything dealing with marking 'sidebar' 
registry blocks active or inactive.

Correct me if I'm wrong but this code always marks 'heading' and 
'sidebar' applications as active, no?

} elseif ($app['status'] == 'heading' ||
              $app['status'] == 'sidebar') {
            continue;
}

Maybe I was not clear. Horde log correctly marks 'chora' as inactive, 
but as you can see from my list below it is 'chora-menu' 'sidebar' 
application that's still active. 'sidebar' applications doesn't have 
fileroot directory and the code doesn't even go to check that. The 
loop just continue.

I'm also attaching now modified registry.local.php files.

No - this patch is not correct.

As previously mentioned, you need to figure out why these applications 
are NOT automatically being marked inactive.  There is no need to fix 
anything else - if the applications are marked inactive, everything 
works properly.

Until/unless you can provide a reproducible explanation why these apps 
are not being marked inactive, there is nothing to fix in this ticket.

I'm not sure if this is the best way, but this patch fixes things for me.

I've added Horde::logMessage($app, 'ERR'); just after foreach 
statement in Sidebar.php getTree() and this is what I've got:

2011-05-03T00:56:10+03:00 ERR: HORDE [horde] horde [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] imp [pid 15665 on line 75 
of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] ingo [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] organizing [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] turba [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] turba-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] kronolith [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] kronolith-alarms [pid 
15665 on line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] kronolith-menu [pid 15665 
on line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] nag [pid 15665 on line 75 
of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] nag-alarms [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] nag-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] mnemo [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] mnemo-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] trean-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] devel [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] chora-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] whups [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] whups-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] info [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] office [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] hermes-stopwatch [pid 
15665 on line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] hermes-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] myaccount [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] gollem-menu [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] passwd [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] website [pid 15665 on 
line 75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] agora [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]
2011-05-03T00:56:10+03:00 ERR: HORDE [horde] wicked [pid 15665 on line 
75 of "/usr/share/pear/Horde/Core/Sidebar.php"]

Seems like chora, hermes and others correctly market as inactive, but 
their blocks are still active. I have looked at _loadApplications() 
but still cannot understand why they are active.

This is incorrect.  Generation of the applications list is done in the 
Horde_Registry constructor (Horde_Registry::_loadApplications()).   
Thus, by the time you call any registry method, the list of activated 
applications has been generated.
Not sure what the relevance of this is?  This code is only run if an 
application is marked active.  As mentioned previously, any 
application that doesn't exist on disk will be marked inactive by 
_loadApplications().

You need to debug Horde_Registry (line 599) as to why this isn't 
running correctly for you:

             if (!file_exists($app['fileroot']) ||
                 (empty($this->_args['test']) &&
                  file_exists($app['fileroot'] . '/config/conf.xml') &&
                  !file_exists($app['fileroot'] . '/config/conf.php'))) {
                 $app['status'] = 'inactive';
                 Horde::logMessage('Setting ' . $appName . ' inactive 
because the fileroot does not exist or the application is not 
configured yet.', 'DEBUG');
             }

As can be seen by this code, an application is marked inactive if its 
directory does not exist.  You will need to determine why the 
file_exists() call is returning true for you (since the second part of 
that conditional should not be pertinent for your setup).

I'm using default registry.php file. No local or registry.d files.

I've disabled 5 applications in questions however I still get the same 
errors. Some fiddling revealed that no matter what I do with 
applications their sidebar blocks are always active unless I comment 
blocks out. That's because this commit 
http://git.horde.org/diff.php/framework/Core/lib/Horde/Core/Sidebar.php?rt=horde-git&ws=1&r1=b75941743afb913804b317f8f01134b3a8ef16e4 makes always check block permissions without first checking if related applications are active. Which if course results in 
errors.

Also I've found this 
http://git.horde.org/diff.php/framework/Core/lib/Horde/Core/Sidebar.php?rt=horde-git&ws=1&r1=4afec82f03a8a773fc6ab0748d3142ba2e870559

If code is explicitly trying to access an application that doesn't 
exist, it is most likely a configuration file issue.  You can't be 
hiding configuration file issues in INFO messages - this is exactly 
what the logs are useful for.  The whole point is you should NOT be 
seeing these errors at all (see below).
They don't fill the logs with ERRORs.  That's the whole point.  These 
non-existent applications will be ignored if the application doesn't 
exist in your installation.

See Horde_Registry when we parse the registry.php file - when looping 
through the list of applications defined as "not inactive" in 
registry.php, we do a file_exists() check to see if that application's 
directory exists.  If it doesn't, we issue a DEBUG message and mark 
the application (or block) as inactive.  So there is most likely an 
issue with your configuration that is causing this check to fail, even 
though the applications don't exist.

Can you elaborate why this is a big deal?

Also I still don't see a logic why applications without blocks are 
"silently" ignored at DEBUG level but with blocks fills the log with 
ERRORs?

If an application is marked as being active, and doesn't exist, that 
is a big deal and most definitely needs to be marked as an ERROR.

Then those applications appear in a menu (e.g. sidebar) or something 
like that.  And since all users don't have the sidebar displayed, they 
may not authenticate to the same list of applications.

We do.  And sure enough, I see a bunch of entries like this in my log:

2011-05-02T11:43:28-06:00 DEBUG: HORDE Setting luxor inactive because 
the fileroot does not exist or the application is not configured yet. 
[pid 21876 on line 604 of 
"/disk2/src/horde/framework/Core/lib/Horde/Registry.php"]

After more debugging, this happens because applications in question 
have blocks associated with them: chora-menu, hermes-stopwatch, etc. 
Horde should ignore blocks in the registry if applications for them 
are not installed.

Yeah I could, but this is not consistent between applications. For 
example I don't have Ansel installed, and it does not appear in the 
logs. At least it should not be logged with ERROR level. INFO should 
be more appropriate.

This also does not explain why it didn't happen in 4.0.0 RC or Final. 
Only in 4.0.1.

This is not what I see here. Log messages appear in the logs all at 
once. Also I have made a test: deleted all sessions, authenticated to 
Horde and went straight to Administration -> Sessions. Again it showed 
all installed, and even some not installed applications authenticated 
to.

Then you need to disable these applications (setting to 'inactive') in 
registry.php.
Not sure what you think is wrong here.  Different people will see 
different applications depending on their browsing behavior in their 
session - applications are authenticated to on demand, not all at once.

After upgrade from Horde 4.0.0 to 4.0.1 I constantly get these 
messages in the logs when normal user logs in into Horde:

2011-04-30T22:47:09+03:00 ERR: HORDE [horde] trean is not activated. 
[pid 6165 on line 1246 of "/usr/share/pear/Horde/Registry.php"]
2011-04-30T22:47:09+03:00 ERR: HORDE [horde] chora is not activated. 
[pid 6165 on line 1246 of "/usr/share/pear/Horde/Registry.php"]
2011-04-30T22:47:09+03:00 ERR: HORDE [horde] jonah is not activated. 
[pid 6165 on line 1246 of "/usr/share/pear/Horde/Registry.php"]
2011-04-30T22:47:09+03:00 ERR: HORDE [horde] hermes is not activated. 
[pid 6165 on line 1246 of "/usr/share/pear/Horde/Registry.php"]
2011-04-30T22:47:09+03:00 ERR: HORDE [horde] gollem is not activated. 
[pid 6165 on line 1246 of "/usr/share/pear/Horde/Registry.php"]

The strange thing is that only these 5 applications gets called. Even 
though they were never installed.

Also attaching Administration -> Sessions page screenshot. As you can 
see different users have different applications authenticated for some 
reason.

As far as I can tell only administrators get correct application list.