internal error ("IntegrityError") when logging in after apache restart

[ssalmine@…]

Got following internal error when doing this:

1. setup trac
2. trying to login (pressing the login button)
3. that didn't work - no login configured, so added basicauth to apache, and restarted it
4. pressed login again

After trying again with new browser sessions things worked fine.

Traceback (most recent call last):
  File "/usr/lib/python2.3/site-packages/trac/web/modpython_frontend.py", line 206, in handler
    dispatch_request(mpr.path_info, mpr, env)
  File "/usr/lib/python2.3/site-packages/trac/web/main.py", line 139, in dispatch_request
    dispatcher.dispatch(req)
  File "/usr/lib/python2.3/site-packages/trac/web/main.py", line 107, in dispatch
    resp = chosen_handler.process_request(req)
  File "/usr/lib/python2.3/site-packages/trac/web/auth.py", line 81, in process_request
    self._do_login(req)
  File "/usr/lib/python2.3/site-packages/trac/web/auth.py", line 117, in _do_login
    "VALUES (%s, %s, %s, %s)", (cookie, remote_user,
  File "/usr/lib/python2.3/site-packages/sqlite/main.py", line 255, in execute
    self.rs = self.con.db.execute(SQL % parms)
IntegrityError: columns cookie, ipnr, name are not unique

[sid]

So the error was generated after (4), but then it worked when you cleared your browser session cache?

[prasana]

I am seeing a similar error - and didn't see any tickets that address it;

Traceback (most recent call last):

File "/var/lib/python-support/python2.4/trac/web/main.py", line 387, in dispatch_request

dispatcher.dispatch(req)

File "/var/lib/python-support/python2.4/trac/web/main.py", line 191, in dispatch

chosen_handler = self._pre_process_request(req, chosen_handler)

File "/var/lib/python-support/python2.4/trac/web/main.py", line 263, in _pre_process_request

chosen_handler = f.pre_process_request(req, chosen_handler)

File "/var/lib/python-support/python2.4/trac/versioncontrol/api.py", line 73, in pre_process_request

self.get_repository(req.authname) # triggers a sync if applicable

File "/var/lib/python-support/python2.4/trac/versioncontrol/api.py", line 101, in get_repository

repos = self._connector.get_repository(rtype, rdir, authname)

File "/var/lib/python-support/python2.4/trac/versioncontrol/svn_fs.py", line 260, in get_repository

crepos = CachedRepository?(self.env.get_db_cnx(), repos, None, self.log)

File "/var/lib/python-support/python2.4/trac/versioncontrol/cache.py", line 34, in init

self.sync()

File "/var/lib/python-support/python2.4/trac/versioncontrol/cache.py", line 100, in sync

(str(current_rev), path, kind, action,

File "/var/lib/python-support/python2.4/trac/db/util.py", line 50, in execute

return self.cursor.execute(sql_escape_percent(sql), args)

File "/var/lib/python-support/python2.4/trac/db/sqlite_backend.py", line 56, in execute

args or [])

File "/var/lib/python-support/python2.4/trac/db/sqlite_backend.py", line 48, in _rollback_on_error

return function(self, *args, kwargs)

IntegrityError?: columns rev, path, change_type are not unique

[prasana]

needed a resync and that fixed the problem. fyi

[sid]

Did the resync fix your problem as well (original author)?

[ssalmine]

Sorry, can't recall.

[sid]

Ahh, but it works then.

[cmlenz]

The error that was fixed by the resync was completely different, I don't think this issue is fixed as we're seeing it here with completely uptodate 0.11-stable.

[cboos]

So 0.11.1 or do you have a fix in mind for 0.11?

[cmlenz]

Marked #7096 as duplicate of this ticket.

I'll be looking into a fix because it annoys people here (including myself), don't know yet whether it would be possible to get into 0.11.

[cmlenz]

I've added some logging to trac.web.auth, and this is what I saw:

Removing login session with cookie <Morsel: trac_auth='00000000000000003e8bb9186df7a077'> for u'chris' 
Logging in 'chris' from '192.168.28.131' 
Generated random cookie value '0000000000000000750362a32dfadffd' for 'chris' 
Removing login session with cookie <Morsel: trac_auth='0000000000000000750362a32dfadffd'> for u'chris' 
Logging in 'chris' from '192.168.28.131' 
Generated random cookie value '0000000000000000750362a32dfadffd' for 'chris' 

Note the duplicate "random" cookie values. Something's seriously wrong with the randomness here. I also don't understand why the first two bytes are 0. Running trac.util.hex_entropy from the Python shell on the same machine gives results where the first two bytes are not all 0.

This is on Debian Etch with Python 2.4.4 and mod_wsgi.

[cmlenz]

Oh btw, I removed the timestamps from the above output, but the two "Generated random cookie" messages are actually 6 seconds apart.

[cmlenz]

Okay, I found the culprit here: apparently there's some kind of silent conflict between the Python md5 module and PHP's mhash library. References:

• ​http://www.modpython.org/pipermail/mod_python/2006-July/021548.html
• ​http://tjulo.blogspot.com/2007/03/problems-with-md5-and-modpython.html
• ​https://issues.apache.org/jira/browse/MODPYTHON-232
• ​http://code.djangoproject.com/wiki/ModPython#MD5Issues

Apparently the same problem exists with mod_wsgi:

• ​http://code.google.com/p/modwsgi/wiki/ApplicationIssues#Python_MD5_Hash_Module_Conflict

It all boils down to a bug in Debian:

• ​http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=440272#10

So… I'd suggest simply switching to sha for hex_entropy. It's a bit ​slower, but we're using it on very short random strings, so I think the difference should be negligible, especially as it's only used to generate auth cookies, session IDs, and form tokens which happens at most twice per request, and for most requests, never.

I'd normally suggest that Debian should clean up after this mess, but this problem is (a) hard to track down, (b) might not even show up that often, while Trac is silently generating supposedly unique enough secrets that are in fact totally insecure, and © it's very hard to work around when you really need PHP and Python running under Apache, via mod_python or mod_wsgi.

[cmlenz]

Patch to use SHA instead of MD5 in hex_entropy

[jonas]

Given the size of the patch I think would be both safe and a good idea to apply it. Even if the underlying issue is a vendor specific problem.

[cmlenz]

Applied in [7192].

[anonymous]

Same thing on 0.11.5

File "/usr/lib/python2.4/site-packages/Trac-0.11.5-py2.4.egg/trac/web/main.py", line 444, in _dispatch_request
  dispatcher.dispatch(req)
File "/usr/lib/python2.4/site-packages/Trac-0.11.5-py2.4.egg/trac/web/main.py", line 205, in dispatch
  resp = chosen_handler.process_request(req)
File "/usr/lib/python2.4/site-packages/Trac-0.11.5-py2.4.egg/trac/web/auth.py", line 101, in process_request
  self._do_login(req)
File "/usr/lib/python2.4/site-packages/Trac-0.11.5-py2.4.egg/trac/web/auth.py", line 140, in _do_login
  "VALUES (%s, %s, %s, %s)", (cookie, remote_user,
File "/usr/lib/python2.4/site-packages/Trac-0.11.5-py2.4.egg/trac/db/util.py", line 59, in execute
  return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib/python2.4/site-packages/sqlite/main.py", line 255, in execute
  self.rs = self.con.db.execute(SQL % parms)

on

User Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.1.7) Gecko/20100106 Ubuntu/9.10 (karmic) Firefox/3.5.7

Trac: 	0.11.5
Python: 	2.4.3 (#1, Sep 3 2009, 15:37:12) [GCC 4.1.2 20080704 (Red Hat 4.1.2-46)]
setuptools: 	0.6c5
SQLite: 	3.3.6
pysqlite: 	1.1.7
Genshi: 	0.5.1
mod_python: 	3.2.8
Subversion: 	1.4.2 (r22196)
jQuery:	1.2.6

[rblank]

This looks like the same symptom as the recently-opened #8969. Please follow up there.