mysql + InnoDB + auth_cookie == Bad.

[branson@…]

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:

• trac/web/auth.py
• trac/db/util.py
• trac/db/mysql_backend.py

Configuration

• database: MySQL and InnoDB tables
• authentication using LDAP via ​AccountManagerPlugin
• Configured to route user to '/trac/login' if there is not authentication

Test Case

1. user logs in
2. commit starts for auth_cookie update
3. second thread looks for the cookie, doesn't find and expires the cookie
4. 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.

[Ryan J Ollos]

Which version of Trac are you running?

[branson@…]

1.0.8 .. tested on several versions prior and upgraded as I went to see if that may have resolved it.

[Jun Omae]

I suppose ​th:LdapAuthStorePlugin and/or ​th:AccountManagerPlugin are broken.