IntegrityError: columns cookie, ipnr, name are not unique

[sistemas@…]

First of all, I have read tickets #2570, #7096 and #8052. The solution proposed is to upgrade to 0.11, which we are already using.

I have confirmed trac/util/init.py uses sha instead of md5.

We have been using 0.11.1 for a few months already. This error has appeared at a time when we have started to try out SSL client authentication, but won't disappear after we have disabled it, so we aren't sure whether there is a cause-effect relationship.

Cleaning up the browser cookies or restarting the apache server won't help.

Trac detected an internal error:

IntegrityError: columns cookie, ipnr, name are not unique

Cookie ID has been deliberately obscured in the following traceback:

Python Traceback
Most recent call last:

    * File "/usr/lib/python2.4/site-packages/trac/web/main.py", line 423, in _dispatch_request
      Code fragment:
       418. try:
       419. if not env and env_error:
       420. raise HTTPInternalError(env_error)
       421. try:
       422. dispatcher = RequestDispatcher(env)
       423. dispatcher.dispatch(req)
       424. except RequestDone:
       425. pass
       426. resp = req._response or []
       427.  
       428. except HTTPException, e:
      Local variables:
      Name	Value
      after 	[u' except RequestDone:', u' pass', u' resp = ...
      before 	[u' try:', u' if not env and env_error:', u' raise ...
      dispatcher 	<trac.web.main.RequestDispatcher object at 0x2ad92d151050>
      e 	<_sqlite.IntegrityError instance at 0x2ad92f4a80e0>
      env 	<trac.env.Environment object at 0x2ad92b8a1810>
      env_error 	None
      exc_info 	(<class _sqlite.IntegrityError at 0x2ad92ca71d10>, <_sqlite.IntegrityError ...
      filename 	'/usr/lib/python2.4/site-packages/trac/web/main.py'
      frames 	[{'function': '_dispatch_request', 'lines_before': [u' try:', u' ...
      has_admin 	True
      line 	u' dispatcher.dispatch(req)'
      lineno 	422
      message 	u'IntegrityError: columns cookie, ipnr, name are not unique'
      req 	<Request "GET u'/login'">
      resp 	[]
      tb 	<traceback object at 0x2ad92f4a81b8>
      tb_hide 	None
      traceback 	'Traceback (most recent call last):\n File ...
    * File "/usr/lib/python2.4/site-packages/trac/web/main.py", line 197, in dispatch
      Code fragment:
       192. req.args.get('__FORM_TOKEN') != req.form_token:
       193. raise HTTPBadRequest('Missing or invalid form token. '
       194. 'Do you have cookies enabled?')
       195.  
       196. # Process the request and render the template
       197. resp = chosen_handler.process_request(req)
       198. if resp:
       199. if len(resp) == 2: # Clearsilver
       200. chrome.populate_hdf(req)
       201. template, content_type = \
       202. self._post_process_request(req, *resp)
      Local variables:
      Name	Value
      chosen_handler 	<trac.web.auth.LoginModule object at 0x2ad92d151590>
      chrome 	<trac.web.chrome.Chrome object at 0x2ad92bf777d0>
      err 	(<class _sqlite.IntegrityError at 0x2ad92ca71d10>, <_sqlite.IntegrityError ...
      handler 	<trac.web.auth.LoginModule object at 0x2ad92d151590>
      req 	<Request "GET u'/login'">
      self 	<trac.web.main.RequestDispatcher object at 0x2ad92d151050>
    * File "/usr/lib/python2.4/site-packages/trac/web/auth.py", line 101, in process_request
      Code fragment:
        96. def match_request(self, req):
        97. return re.match('/(login|logout)/?$', req.path_info)
        98.  
        99. def process_request(self, req):
       100. if req.path_info.startswith('/login'):
       101. self._do_login(req)
       102. elif req.path_info.startswith('/logout'):
       103. self._do_logout(req)
       104. self._redirect_back(req)
       105.  
       106. # Internal methods
      Local variables:
      Name	Value
      req 	<Request "GET u'/login'">
      self 	<trac.web.auth.LoginModule object at 0x2ad92d151590>
    * File "/usr/lib/python2.4/site-packages/trac/web/auth.py", line 140, in _do_login
      Code fragment:
       135.  
       136. cookie = hex_entropy()
       137. db = self.env.get_db_cnx()
       138. cursor = db.cursor()
       139. cursor.execute("INSERT INTO auth_cookie (cookie,name,ipnr,time) "
       140. "VALUES (%s, %s, %s, %s)", (cookie, remote_user,
       141. req.remote_addr, int(time.time())))
       142. db.commit()
       143.  
       144. req.authname = remote_user
       145. req.outcookie['trac_auth'] = cookie
      Local variables:
      Name	Value
      cookie 	'af8b74xxxxxxxxxxxxxxxx4039'
      cursor 	<trac.db.util.IterableCursor object at 0x2ad92f4a5408>
      db 	<trac.db.pool.PooledConnection object at 0x2ad92f4a2ea8>
      remote_user 	'myuser'
      req 	<Request "GET u'/login'">
      self 	<trac.web.auth.LoginModule object at 0x2ad92d151590>
    * File "/usr/lib/python2.4/site-packages/trac/db/util.py", line 50, in execute
      Code fragment:
        45. def execute(self, sql, args=None):
        46. # -- In case of SQL errors, uncomment the following 'print' statements
        47. # print 'execute', repr(sql)
        48. if args:
        49. # print repr(args)
        50. return self.cursor.execute(sql_escape_percent(sql), args)
        51. return self.cursor.execute(sql)
        52.  
        53. def executemany(self, sql, args=None):
        54. # print 'executemany', repr(sql)
        55. if args:
      Local variables:
      Name	Value
      args 	('af8b74xxxxxxxxxxxxxxxx4039', 'myuser', '10.0.0.105', 1263479383)
      self 	<trac.db.util.IterableCursor object at 0x2ad92f4a5408>
      sql 	'INSERT INTO auth_cookie (cookie,name,ipnr,time) VALUES (%s, %s, %s, %s)'
    * File "/usr/lib64/python2.4/site-packages/sqlite/main.py", line 255, in execute
      Code fragment:
       250. parms = _quoteall(parms[0])
       251. else:
       252. parms = self._unicodeConvert(parms)
       253. parms = tuple(map(_quote, parms))
       254.  
       255. self.rs = self.con.db.execute(SQL % parms)
       256.  
       257. self.closed = 0
       258. self.current_recnum = 0
       259.  
       260. self.rowcount, self._real_rowcount = [len(self.rs.row_list)] * 2
      Local variables:
      Name	Value
      SQL 	'INSERT INTO auth_cookie (cookie,name,ipnr,time) VALUES (%s, %s, %s, %s)'
      parms 	("'af8b74047249852d148c3da0590b4039'", "'myuser'", "'10.0.0.105'", ...
      self 	<trac.db.sqlite_backend.SQLiteUnicodeCursor instance at 0x2ad92f4a2fc8>

File "/usr/lib/python2.4/site-packages/trac/web/main.py", line 423, in _dispatch_request
  dispatcher.dispatch(req)
File "/usr/lib/python2.4/site-packages/trac/web/main.py", line 197, in dispatch
  resp = chosen_handler.process_request(req)
File "/usr/lib/python2.4/site-packages/trac/web/auth.py", line 101, in process_request
  self._do_login(req)
File "/usr/lib/python2.4/site-packages/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/db/util.py", line 50, in execute
  return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib64/python2.4/site-packages/sqlite/main.py", line 255, in execute
  self.rs = self.con.db.execute(SQL % parms)

System Information:

User Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1.6) Gecko/20091216 Fedora/3.5.6-1.fc11 Firefox/3.5.6
Trac: 	0.11.1
Python: 	2.4.3 (#1, May 24 2008, 13:57:05) [GCC 4.1.2 20070626 (Red Hat 4.1.2-14)]
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

[Remy Blank]

What happens if you remove the offending row from auth_cookie by hand, and try to log in again? Does the issue pop up again?

What I'd like to find out is whether the issue is transient, or if it can be reproduced consistently, even starting from a known good point.

[sistemas@…]

There are 8 cookies for the same user in the table. Is that a correct behaviour? I'll try deleting all of them manually and post what happens.

Just to throw in another avenue of thought, I don't know if this will have anything to do with the issue, but we have detected we are a bit short of entropy on that server, there's quite a bit of SSL eating it out. I don't know what the effects of momentarily running out of entropy would have in random.random() and how that would affect trac.

cat /proc/sys/kernel/random/entropy_avail 
871

[sistemas@…]

I emptied out the auth_cookie table and could log in again. After some time fiddling with logging in and out, restarting the browser with and without logging out, etc., the condition reoccurred.

At least now I know the workaround to make logging in possible again so we can continue using the trac.

I have turned on the logging module and added some debug lines to web/auth.py. I will keep an eye on it to see if I can isolate a pattern to reproduce this consistently.

[Remy Blank]

(From #2570)

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

[sistemas@…]

Seems more or less the same version. It is, of course, possible that the problem lies not in trac but elsewhere (python, httpd…) If someone wants to reproduce our environment our server is an OpenVZ virtual machine running CentOS 5 and we installed trac using the RPM package at the rpmforge repository (latest version available there is 0.11.5 but we haven't updated yet.)

Trying logging in and out from two different browsers on the same machine seems to help trigger the problem more quickly, but I still don't find a pattern, perhaps there's some race condition involved.

[sistemas@…]

I think I have traced it to the hex_entropy function generating repeated values.

I had modified web/auth.py so it would echo the cookie to the log on each login attempt. After those days of editing the trac wiki without pressing the logout button my user had accumulated 13 cookies in the auth_cookie table.

Today the condition reproduced, so I checked the cookie trac was trying to insert into the table and turns out it was exactly the same as one stored on Jan 20, 16 days ago.

Clearly there is something wrong somewhere with how the cookies are generated, cookies shouldn't repeat themselves in such a short amount of time.

Anyway, isn't the shelf life of trac cookies perhaps a bit too long? Under heavy use that table can get unnecessarily cluttered. One cannot expect the user to remember logging out every session so his cookies cleared, and there are other reasons the cookies might remain lingering on, like browser crashes.

[Remy Blank]

At this point, I'm not sure if this is an InstallationIssue, considering that a random number generator really shouldn't be repeating itself that fast, or if there's really an issue in Trac. Even if we purge the session table more often (currently 90 days), if random numbers repeat that fast the issue will still occur.

Ideas?

[sistemas@…]

Chances are good that the root of this problem is not in Trac, but somewhere in the RNG infrastructure, perhaps even at kernel level, I'll have to check this out more thoroughly. I'll post at the user list to see if someone has encountered the same problem and has a similar setup to ours.

Anyway, regarding Trac specifics, what's the reason for keeping old cookies after a new one is generated? Would it be a good idea if the _do_login function deleted any stored cookies for that user before inserting the new one, or would it affect negatively other use cases?

[Remy Blank]

Replying to sistemas@…:

Anyway, regarding Trac specifics, what's the reason for keeping old cookies after a new one is generated? Would it be a good idea if the _do_login function deleted any stored cookies for that user before inserting the new one, or would it affect negatively other use cases?

That's a good question, I don't know. I'll have to review the login and session code to find that out. Unless somebody beats me to it.

[Christian Boos]

Replying to rblank:

Replying to sistemas@…:

Anyway, regarding Trac specifics, what's the reason for keeping old cookies after a new one is generated? Would it be a good idea if the _do_login function deleted any stored cookies for that user before inserting the new one, or would it affect negatively other use cases?

That's a good question, I don't know. I'll have to review the login and session code to find that out. Unless somebody beats me to it.

Isn't that feature useful when you log in to the same account using different browsers? (or from different hosts?)

Disclaimer: I don't know this part of the code well.

[sistemas@…]

Phew! I think I got it, and it is definitely not a Trac bug.

According to ​http://docs.python.org/library/random.html:

current system time is also used to initialize the generator when the module is first imported

But if you execute this script twice in our virtual server it will generate the same sequence both times:

#!/usr/bin/python2.4
import random,sha
for i in range(10):
  print sha.new(str(random.random())).hexdigest()[:32]

Incidentally one of these first 10 'cookies' was the one that triggered the error on our server on 2010-02-05 that I reported in comment6.

However, if I execute this script in the hardware server which is running our Trac virtual server (same kernel, same python version) it yields a different sequence every time I run it.

The obvious conclusion is that there is something in our virtual server configuration that interferes with python's ability to seed its random number generator. I have had problems in the past with this virtualization technology and software that makes use of /dev/random and /dev/urandom, like openssl, so I guess this is yet another one of those.

Sorry for the noise, guys. Ah, well, at least now we know that Trac's cookie system might exhibit this problem if the random module is not seeded properly.

[Remy Blank]

Replying to sistemas@…:

The obvious conclusion is that there is something in our virtual server configuration that interferes with python's ability to seed its random number generator. I have had problems in the past with this virtualization technology and software that makes use of /dev/random and /dev/urandom, like openssl, so I guess this is yet another one of those.

That's highly dangerous, that. If openssl, openssh and friends are seeded with a predictable input, I'm not sure how secure your communications are.

Sorry for the noise, guys. Ah, well, at least now we know that Trac's cookie system might exhibit this problem if the random module is not seeded properly.

No worries. You're not the first person to report these symptoms, but AFAIK you're the first to really find the root cause, so thanks for that!

I'd still like to keep this ticket open as a reminder to check if we shouldn't purge the session tables on login, as you suggested in comment:8.

[sistemas@…]

OK, fixed it. For one reason or another /dev/urandom was a regular file instead of a device one, probably because some of my previous fiddling with the problems with openssl I mentioned in comment:11, perhaps I was trying to feed entropy manually and forgot to revert it to a device. I'll have to keep an eye on this, least there is something else that is breaking it. Thankfully it was just an internal server, but this could have been definitely a serious security issue on a public one.

[root@trac ~]# ll /dev/urandom 
-rw-r--r-- 1 root root 512 Feb  8 20:57 /dev/urandom
[root@trac ~]# rm -f /dev/urandom 
[root@trac ~]# MAKEDEV /dev/urandom
[root@trac ~]# ll /dev/urandom 
crw-r--r-- 1 root root 1, 9 Feb  8 21:06 /dev/urandom

[Carsten Klein <carsten.klein@…>]

I think this can be closed, no?

And better still, maybe we should include this in the FAQ, stating that for cookie ID generation the system's random or urandom device must be present and also be capable of generating enough entropy in order for making the sequence of IDs generated from it unique.

More information on this can be found under:

• ​http://en.wikipedia.org/wiki/Hardware_random_number_generator
• ​http://www.linuxfromscratch.org/hints/downloads/files/entropy.txt

[AlexK|Ventuz]

We also had problems with hex_entropy generating the same cookies again and again, resulting in people being logged in as other users. But in our case the thing had a more indeterministic manner. Running the test from "sistemas" worked alright and the problem sometimes occurred multiple times a day and then not for a week.

What caused the problem in my case was that a plug-in (to be more specific the RevTree-plugin, I've added a ticket for that bug) had a line "seed(0)" in it when rendering its SVG output. So when someone accessed that functionality, the seed was reset and of course the same sequence of cookies was created as after the last time someone used that RevTree.

Took about 3 weeks to track this down, so I thought I add a comment in case someone has a similar problem. Same as other commentators I added some logging to the TRAC source code that put the result of hex_entropy into the log file. Once it was verified the RNG was the problem and the test script above could not reproduce the problem, I started looking through the TRAC and python source code without finding anything. It was just by chance that I searched the source code directory of all installed plugins for use of the words "random" and "seed"…

[Remy Blank]

Replying to AlexK|Ventuz:

What caused the problem in my case was that a plug-in (to be more specific the RevTree-plugin, I've added a ticket for that bug) had a line "seed(0)" in it when rendering its SVG output.

That's pretty bad, thanks for the heads-up. I have changed hex_entropy() to use a distinct random generator to guard against this bad practice in [10115].

[Remy Blank]

Replying to cboos:

Replying to rblank:

Replying to sistemas@…:

Anyway, regarding Trac specifics, what's the reason for keeping old cookies after a new one is generated? Would it be a good idea if the _do_login function deleted any stored cookies for that user before inserting the new one, or would it affect negatively other use cases?

That's a good question, I don't know. I'll have to review the login and session code to find that out. Unless somebody beats me to it.

Isn't that feature useful when you log in to the same account using different browsers? (or from different hosts?)

Indeed, logging in from two different browsers generates two different auth cookies. If we removed the previous cookie when logging in with a browser, the other browser would be automatically logged out.

However, with the current implementation, logging out with one browser will automatically log out all other sessions. I find that very surprising, and would suggest we change that.

The cookie lifetime is currently 10 days, but old cookies are only cleaned out when a user logs out, so if no user ever logs out, the cookies accumulate. Maybe we should move that cleanup to the login method, so that it is run more often?

[Remy Blank]

I suggest the following patch, which:

• deletes obsolete auth cookies on login instead of logout, to make sure deletion is actually performed
• deletes only the cookie associated with the current session, instead of all cookies for the current user

trac/web/auth.py

@@ -153 +153 @@
         @self.env.with_transaction()
         def store_session_cookie(db):
             cursor = db.cursor()
+            # Delete cookies older than 10 days
+            cursor.execute("DELETE FROM auth_cookie WHERE time < %s",
+                           (int(time.time()) - 86400 * 10,))
             cursor.execute("INSERT INTO auth_cookie (cookie,name,ipnr,time) "
                            "VALUES (%s, %s, %s, %s)",
                            (cookie, remote_user, req.remote_addr,
@@ -175 +178 @@
             # Not logged in
             return
 
-        # While deleting this cookie we also take the opportunity to delete
-        # cookies older than 10 days
         @self.env.with_transaction()
         def delete_session_cookie(db):
             cursor = db.cursor()
-            cursor.execute("DELETE FROM auth_cookie "
-                           "WHERE name=%s OR time < %s",
-                           (req.authname, int(time.time()) - 86400 * 10))
+            cursor.execute("DELETE FROM auth_cookie WHERE cookie=%s",
+                           (req.incookie['trac_auth'].value,))
         self._expire_cookie(req)
         custom_redirect = self.config['metanav'].get('logout.redirect')
         if custom_redirect:

Thoughts?

[Christian Boos]

Patch looks good to me.

Do we still have ms time values in auth_cookie?

[Remy Blank]

Thanks for reviewing. Yes, we still have second time values (we never had milliseconds) in auth_cookie, and in the session table, too. Re-reading #6466, I think I only converted the columns where we use datetime objects to represent times. Also, the usefulness of microsecond timestamps in the auth_cookie and session tables is about zero, so I didn't bother.

[Remy Blank]

The patch wasn't handling correctly the case where the whole Trac instance requires authentication. In that case, no auth cookie is sent to the client (unless the user clicks the "Login" link, but most won't), and clicking the "Logout" link would generate a 500.

I have applied a fixed patch in [10271], where the cookie is removed if it was sent by the client, or all cookies for the user if not (i.e. the same behavior as before).