0.3-beta duplicate insertion of session_id break navigation

[dan]

To begin with I cleared the browser cookies, authenticated sessions and truncated the session table.

I set sql_debug to true in the main.inc.php file.

Below is a view of tail -f /var/log/apache/access.log /var/log/mail.log

[23/May/2009:07:33:30 +0000] "GET /roundcubemail-0.3-beta HTTP/1.1" 301
[23/May/2009:07:33:30 +0000] "GET /roundcubemail-0.3-beta/
[23-May-2009 07:33:30 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='18ftfG429atYquHJ09onAGtvD-5'  
May 23 07:33:30 webmail roundcube: [23-May-2009 07:33:30 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='18ftfG429atYquHJ09onAGtvD-5'  
May 23 07:33:30 webmail roundcube: [23-May-2009 07:33:30 +0000]: query(1): INSERT INTO session        (sess_id, vars, ip, created, changed)        VALUES ('18ftfG429atYquHJ09onAGtvD-5', 'Omg...c7kl', '59.167.48.107', FROM_UNIXTIME(1243064010), FROM_UNIXTIME(1243064010))
[23/May/2009:07:33:30 +0000] "GET /roundcubemail-0.3-beta/ (few gifs/css/javascript)

After this I confirmed that the browser cookie for roundcube_sessid was set to the session id.

I then logged in:

23/May/2009:07:35:02 +0000] "POST /roundcubemail-0.3-beta/ HTTP/1.1" 302
[23-May-2009 07:35:02 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='18ftfG429atYquHJ09onAGtvD-5'  
[23-May-2009 07:35:02 +0000]: query(1): DELETE FROM session WHERE sess_id='18ftfG429atYquHJ09onAGtvD-5'                                                          
[23-May-2009 07:35:02 +0000]: query(1): SELECT * FROM users WHERE mail_host='imapserver' AND username='daniel'                                                   
[23-May-2009 07:35:02 +0000]: query(1): UPDATE users          SET    last_login=now()          WHERE  user_id='1'                                                
[23-May-2009 07:35:02 +0000]: query(1): DELETE FROM cache        WHERE  user_id='1'        AND    cache_key='IMAP.mailboxes'                                     
[23-May-2009 07:35:02 +0000]: query(1): DELETE FROM session WHERE sess_id='18ftfG429atYquHJ09onAGtvD-5'                                                          
[23-May-2009 07:35:02 +0000]: Successful login for daniel@imapserver (id 1) from 59.167.48.107                                                                   
[23-May-2009 07:35:02 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='d9518d70b4524aabab3154cbaba3637c'  
[23-May-2009 07:35:02 +0000]: query(1): INSERT INTO session        (sess_id, vars, ip, created, changed)        VALUES ('d9518d70b4524aabab3154cbaba3637c', 'kHHM.....J0M0uc', '59.167.48.107', FROM_UNIXTIME(1243064102), FROM_UNIXTIME(1243064102))                                                           
[23-May-2009 07:35:04 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='d9518d70b4524aabab3154cbaba3637c'                                     
[23-May-2009 07:35:04 +0000]: query(1): SELECT * FROM users WHERE  user_id='1'                                                                                                                           
[23-May-2009 07:35:04 +0000]: query(1): SELECT cache_id, data          FROM cache          WHERE  user_id='1'          AND    cache_key='IMAP.messagecount'                                              
[23-May-2009 07:35:04 +0000]: query(1): SELECT cache_id, data          FROM cache          WHERE  user_id='1'          AND    cache_key='IMAP.mailboxes'                                                 
[23-May-2009 07:35:04 +0000]: query(1): SELECT idx, uid        FROM messages        WHERE  user_id='1'        AND    cache_key='INBOX.msg'        ORDER BY `idx` ASC
[23/May/2009:07:35:04 +0000] "GET /roundcubemail-0.3-beta/?_task=mail HTTP/1.1" 200
[23-May-2009 07:35:04 +0000]: query(1): DELETE FROM messages        WHERE  user_id='1'        AND    cache_key='INBOX.msg'        AND    idx>=639  
[23-May-2009 07:35:04 +0000]: query(1): UPDATE cache          SET    created=now(), data='a:1:{s:5:\"INBOX\";a:1:{s:3:\"ALL\";i:638;}}'          WHERE  user_id='1'          AND    cache_key='IMAP.messagecount'                                                                                                                                                                                                                                    
[23-May-2009 07:35:04 +0000]: query(1): SELECT cache_id          FROM cache          WHERE  user_id='1'          AND    cache_key='IMAP.mailboxes'                                                       
[23-May-2009 07:35:04 +0000]: query(1): INSERT INTO cache          (created, user_id, cache_key, data)          VALUES (now(), '1', 'IMAP.mailboxes', 'a:23:{i.......\";}')                                                                                 
[23-May-2009 07:35:04 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='d9518d70b4524aabab3154cbaba3637c'                                     
[23-May-2009 07:35:04 +0000]: query(1): UPDATE session        SET    vars='', changed= FROM_UNIXTIME(1243064104)        WHERE  sess_id='d9518d70b4524aabab3154cbaba3637c'
[23/May/2009:07:35:08 +0000] "GET /roundcubemail-0.3-beta/skins/default/mail.css HTTP/1.1" 200
...(more page requests)....

Then came the error from apache-error.log

[Sat May 23 07:35:14 2009] [error] [client 59.167.48.107] MDB2 Error: constraint violation (-3): _doQuery: [Error message: Could not execute statement]\n[Last executed query: INSERT INTO session\n       (sess_id, vars, ip, created, changed)\n       VALUES ('d9518d70b4524aabab3154cbaba3637c', 'RD3Mk......tQ0T7_EFv69', '59.167.48.107', FROM_UNIXTIME(1243064114), FROM_UNIXTIME(1243064114))]\n[Native code: 1062]\n[Native message: Duplicate entry 'd9518d70b4524aabab3154cbaba3637c' for key 1]\n, referer: https://webmail/roundcubemail-0.3-beta/?_task=mail                                   
[Sat May 23 07:35:14 2009] [error] [client 59.167.48.107] PHP Warning:  Cannot modify header information - headers already sent in Unknown on line 0, referer: https://webmail/roundcubemail-0.3-beta/?_task=mail              
[Sat May 23 07:35:14 2009] [error] [client 59.167.48.107] PHP Warning:  Cannot modify header information - headers already sent in Unknown on line 0, referer: https://webmail/roundcubemail-0.3-beta/?_task=mail 

at the same time as the mail.log

[23-May-2009 07:35:14 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='d9518d70b4524aabab3154cbaba3637c'  
[23-May-2009 07:35:14 +0000]: query(1): SELECT vars, ip, UNIX_TIMESTAMP(changed) AS changed      FROM session      WHERE  sess_id='d9518d70b4524aabab3154cbaba3637c'  
[23-May-2009 07:35:14 +0000]: query(1): INSERT INTO session        (sess_id, vars, ip, created, changed)        VALUES ('d9518d70b4524aabab3154cbaba3637c', 'RD3Mk0n...Fv69', '59.167.48.107', FROM_UNIXTIME(1243064114), FROM_UNIXTIME(1243064114))  

The apache-error.log and previous SQL command were repeated on the minute interval page refreshes and also when I navigated to:

[23/May/2009:07:48:23 +0000] "GET /roundcubemail-0.3-beta/?_task=addressbook

[alec]

I was not able to reproduce, but [dadefb80] should prevent from doubled inserts.

[dan]

ok - does fix the double inserts however I'm still getting a number of reloads after the login pages. I'll try to get more info in the next week.

[dan]

ok - after a painful amount of debugging I found that adding php_value suhosin.session.encrypt Off to the top .htaccess file stopped the multiple reloads and hence probably the original duplication insertion.

This directive is in the 0.3-beta release however following the UPGRADE instructions to not say to replace the .htaccess file. Could instructions that make this effect this be added to UPGRADE?

Thanks alec for the painful time you spent trying to work this one out.

[alec]

Added info in UPGRADE + some changes in Installer