mysql + InnoDB + auth_cookie == Bad.
|Reported by:||Owned by:|
Description (last modified by )
It appears that Trac using MySQL, InnoDB and the AccountManagerPlugin login page has a race condition with the auth_cookie table. This problem manifested itself when we migrated from sqlite to MySQL. While this uses the AccountManagerPlugin, the calls being used are w/in Trac proper:
- database: MySQL and InnoDB tables
- authentication using LDAP via AccountManagerPlugin
- Configured to route user to '/trac/login' if there is not authentication
- user logs in
- commit starts for auth_cookie update
- second thread looks for the cookie, doesn't find and expires the cookie
- user returned to login screen
I inserted quite a bit of logging to find this..
2015-07-27 16:49:29,097 Trac[util] DEBUG: SQL: INSERT INTO auth_cookie (cookie, name, ipnr, time) VALUES (%s, %s, %s, %s) 2015-07-27 16:49:29,097 Trac[util] DEBUG: SQL args: ('cb4a763b891fa64c0ea38817226d39d6', u'branson', '172.16.20.34', 1438008569) 2015-07-27 16:49:29,098 Trac[util] DEBUG: SQL: completed, 1 2015-07-27 16:49:29,098 Trac[util] DEBUG: SQL: DELETE FROM auth_cookie WHERE time < %s 2015-07-27 16:49:29,099 Trac[util] DEBUG: SQL args: (1437144569,) 2015-07-27 16:49:29,099 Trac[util] DEBUG: SQL: completed, 0 2015-07-27 16:49:31,267 Trac[main] DEBUG: Dispatching <RequestWithSession "GET ''"> 2015-07-27 16:49:31,275 Trac[util] DEBUG: SQL: SELECT name FROM auth_cookie WHERE cookie=%s 2015-07-27 16:49:31,275 Trac[util] DEBUG: SQL args: ('cb4a763b891fa64c0ea38817226d39d6',) 2015-07-27 16:49:31,276 Trac[util] DEBUG: SQL: completed, 0 2015-07-27 16:49:31,276 Trac[auth] DEBUG: no user found for cookie cb4a763b891fa64c0ea38817226d39d6 expiring it.
My read .. is the write is not completing before the read happens on a different thread and the read is returning 0 results.. so auth.py expires the cookie. This is because InnoDB does row level locking and we're doing a transaction, the update to the table does NOT lockout the read .. the read returns with 'old_Data' as designed in the case of a transaction, and therefore doesn't find the cookie.
I couldn't find a way to tell InnoDB to lock the table or row for read during update.. however to cheat.. I changed that one table to MyISAM which enforces table level locks for read on transaction and that resolved the problem ( I also had to comment out the error in db/mysql_backend.py for now )
According to https://dev.mysql.com/doc/refman/5.0/en/set-transaction.html#isolevel_read-committed this is standard behavior. There may be a way to cause serialized SELECT's against a locked table by setting autocommit=0 (bottom of that page)… however I want to see if this is a recommended way to resolve this issue.
Else I am not sure how/what can be used consistently if you can't block a table for read on a commit in this particular case.