We have exactly the same issue with rc0.4.2.
Random session invalid or expired messages for users while they are logged in. In pretty much all cases, this is happening at the time of any IMAP activity.
the roundcube/logs/error logfile shows an IMAP authentication failure at the precise moment that the user is disconnected.
example:
[24-Nov-2010 12:34:36 +0100]: IMAP Error: Authentication for username failed (LOGIN): in
/usr/share/roundcube/program/include/rcube_imap.php on line 143 (GET
/roundcube/?_task=mail&_action=preview&_uid=5&_mbox=INBOX&_framed=1)
The problem is that it is happening at random, sometimes a user can go for 20 minutes with no problem, other times they get this after only a couple of clicks after successfully logging in, but in every case the above error is generated in the log. There are no corresponding authentication failures in the IMAP server logs at all, every connection is successfully authenticated.
I tried to debug a little further and exposed the IMAP connection error code contained in the generic imap connection object via line 144 of program/include/rcube_imap.php to be able to see the exact error number code returned. The modification made is:
'messge' => $this->conn->error . " " . $this->conn->errornum), true, false);
Using this additional information, every time the user is randomly disconnected, the errornum of the generic imap connection object is always -1, which from rcube_imap_generic.php reveals to be either empty username or empty password. (I suspect more likely empty username as there are no specific failures for the username in the IMAP server logs)
It seems to me that there is something somewhere that is causing RC to use a null username when making a new IMAP server, which returns -1, causing rcube to invalidate/expire the session.
We are unable to track down exactly WHY this is occurring.
If anyone has any bright ideas, I'm all ears
Thanks in advance!
Leland
---- Updated ----
More strange but useful information. Doing database debugging at the time of these session expiries reveals the following additional information:
Just before the invalid/expired session, there are a series of SQL queries for the session ID which oddly appear in this order.
Firstly, it deletes the session:
-Nov-2010 17:16:03 +0100]: query(1): DELETE FROM session WHERE sess_id = 'a87a9e46155c5aed473161819de4d0cf';
Then it updates for the same session ID:
24-Nov-2010 17:16:03 +0100]: query(1): UPDATE session SET vars = 'language|s:5:\"fr_FR\";auth_time|i:1290615363;imap_root|s:0:\"\";imap_delimiter|s:1:\".\";user_id|s:4:\"4816\";
(----REST OF VARS CLIPPED FOR BREVITY----)
, changed = FROM_UNIXTIME(1290615363) WHERE sess_id = 'a87a9e46155c5aed473161819de4d0cf';
It then tries to retrieve the vars from the session id (which it had already deleted previously):
24-Nov-2010 17:16:05 +0100]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed FROM session WHERE sess_id = 'a87a9e46155c5aed473161819de4d0cf';
[24-Nov-2010 17:16:05 +0100]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed FROM session WHERE sess_id = 'a87a9e46155c5aed473161819de4d0cf';
And then finally it attempts to INSERT with the same session ID:
[24-Nov-2010 17:16:05 +0100]: query(1): INSERT INTO session (sess_id, vars, ip, created, changed) VALUES ('a87a9e46155c5aed473161819de4d0cf', 'auth_time|i: ---(SNIPPED FOR BREVITY)--- FROM_UNIXTIME(1290615365), FROM_UNIXTIME(1290615365));
Something seems a little bit out of sequence here, no?
This further supports my original theory in that the authentication failure in the roundcube error log is related to an empty userid or password, as it apparently is looking to obtain this information with the SELECT, which of course returns NULL as the record was previously deleted. The question is.. why/what triggered the DELETE before the UPDATE.
L.