[horde] IMAP authentication, hordeauth, double login

[amy.rich@tufts.edu]

We've just switched back to using IMAP auth instead of LDAP auth to get around
the issue of orphaned horde sessions (horde but no imap).  We've specified
hordeauth in the imp/servers.php file.  I'm able to log in, read mail, all of
the normal activities.  However, if I look at the log, I notice that it's
trying to do a double login.  Obviously this is going to be a performance
overhead, and I'd like to stop this from happening.  Here's the log of actions
that take place during a single login.  Note the "Invalid server key" error
from redirect.php about half way down.

I did a search for this sort of error, and it looks like there was some logic
added to imp/horde prevent an infinite login loop.  Where should I start
looking to find out why we're hitting this issue in the first place (I'm happy
to include any pertinent config files)?


Nov  8 15:19:03 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [horde] SQL Query by SessionHandler_mysql::read(): query = "SELECT session_data FROM horde_sessionhandler WHERE session_id = '8476a549a7af49330a0cd51c16f57835' AND session_lastmodified > 1131477543" [on line 97 of "/usr/local/apache/htdocs/horde/lib/Horde/SessionHandler/mysql.php"]
Nov  8 15:19:03 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [horde] SQL Query by Prefs_sql::retrieve(): SELECT pref_scope, pref_name, pref_value FROM horde_prefs WHERE pref_uid = ? AND (pref_scope = ? OR pref_scope = 'horde') ORDER BY pref_scope [on line 123 of "/usr/local/apache/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov  8 15:19:03 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.notice] [horde] Login success for test01 [my-client-ip] to Horde [on line 76 of "/usr/local/apache/htdocs/horde/login.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [horde] SQL Query by SessionHandler_mysql::read(): query = "SELECT session_data FROM horde_sessionhandler WHERE session_id = 'e6a32fe9d61650e6861445a11085ef1e' AND session_lastmodified > 1131477544" [on line 97 of "/usr/local/apache/htdocs/horde/lib/Horde/SessionHandler/mysql.php"]
Nov  8 15:19:04 webmailserver.our.domain last message repeated 1 time
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [] SQL Query by Prefs_sql::retrieve(): SELECT pref_scope, pref_name, pref_value FROM horde_prefs WHERE pref_uid = ? AND (pref_scope = ? OR pref_scope = 'horde') ORDER BY pref_scope [on line 123 of "/usr/local/apache/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [horde] SQL Query by SessionHandler_mysql::read(): query = "SELECT session_data FROM horde_sessionhandler WHERE session_id = 'e6a32fe9d61650e6861445a11085ef1e' AND session_lastmodified > 1131477544" [on line 97 of "/usr/local/apache/htdocs/horde/lib/Horde/SessionHandler/mysql.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.info] [imp] Invalid server key "" from client [my-client-ip] [on line 143 of "/usr/local/apache/htdocs/horde/imp/redirect.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [imp] SQL Query by Prefs_sql::retrieve(): SELECT pref_scope, pref_name, pref_value FROM horde_prefs WHERE pref_uid = ? AND (pref_scope = ? OR pref_scope = 'horde') ORDER BY pref_scope [on line 123 of "/usr/local/apache/htdocs/horde/lib/Horde/Prefs/sql.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.notice] [imp] Login success for test01 [my-client-ip] to {imap.tufts.edu:993} [on line 150 of "/usr/local/apache/htdocs/horde/imp/redirect.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [horde] SQL Query by SessionHandler_mysql::read(): query = "SELECT session_data FROM horde_sessionhandler WHERE session_id = 'e6a32fe9d61650e6861445a11085ef1e' AND session_lastmodified > 1131477544" [on line 97 of "/usr/local/apache/htdocs/horde/lib/Horde/SessionHandler/mysql.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23229]: [ID 800047 local4.debug] [horde] SQL Query by SessionHandler_mysql::read(): query = "SELECT session_data FROM horde_sessionhandler WHERE session_id = 'e6a32fe9d61650e6861445a11085ef1e' AND session_lastmodified > 1131477544" [on line 97 of "/usr/local/apache/htdocs/horde/lib/Horde/SessionHandler/mysql.php"]
Nov  8 15:19:04 webmailserver.our.domain HORDE[23227]: [ID 800047 local4.debug] [horde] SQL Query by SessionHandler_mysql::read(): query = "SELECT session_data FROM horde_sessionhandler WHERE session_id = 'e6a32fe9d61650e6861445a11085ef1e' AND session_lastmodified > 1131477544" [on line 97 of "/usr/local/apache/htdocs/horde/lib/Horde/SessionHandler/mysql.php"]