Intermittent constraint violation

[exarkun@…]

The following traceback appears in my logs once or twice a day:

          File "/home/trac/Run/trac/external.py", line 115, in tracApplication
            return trac.web.main.dispatch_request(environ, start_response)
          File "/home/trac/Projects/trac/trunk/trac/web/main.py", line 367, in dispatch_request
            req.send_error(sys.exc_info(), status=500)
          File "/home/trac/Projects/trac/trunk/trac/web/api.py", line 365, in send_error
            exc_info)
          File "/home/trac/Projects/trac/trunk/trac/web/main.py", line 335, in dispatch_request
            dispatcher.dispatch(req)
          File "/home/trac/Projects/trac/trunk/trac/web/main.py", line 236, in dispatch
            req.session.save()
          File "/home/trac/Projects/trac/trunk/trac/web/session.py", line 173, in save
            (self.sid, self.last_visit, authenticated))
          File "/home/trac/Projects/trac/trunk/trac/db/util.py", line 47, in execute
            return self.cursor.execute(sql_escape_percent(sql), args)
          File "/home/trac/Projects/trac/trunk/trac/db/sqlite_backend.py", line 44, in execute
            args or [])
          File "/home/trac/Projects/trac/trunk/trac/db/sqlite_backend.py", line 36, in _rollback_on_error
            return function(self, *args, **kwargs)
        pysqlite2.dbapi2.OperationalError: columns sid, authenticated are not unique

[Christian Boos]

Hm, yes, it can happen for two simultaneous "first" requests…

As an interesting side note, while trying out a fix, I noticed a buglet which might well explain our incredibly high level of locks ;) (see #3446)

[Christian Boos]

Recipe to reproduce:

1. prepare a Firefox window with two Timeline tabs
2. change a filter and update, in each
3. clear the session table (if you don't mind doing so, of course ;) — do this for real only in a test environment

   $ sqlite3 $TRAC_ENV/db/trac.db 'delete from session;'
   

4. Select Reload all tabs

You have then two nearly simultaneous requests to save the session; each request will believe it is _new.

I'm looking for a fix…

[jenn@…]

This looks like it's still happening. I just had one of my users report this exact situation — constraint violations when opening a set of tabs into Trac. He's not a brand-new visitor, though; it happens when he logs on in the morning and opens a fresh browser, even though he was in Trac the previous day.

Pretty much just a minor annoyance, but I'll be interested in knowing when there's a fix. Thanks!

[Christian Boos]

When I looked at the problem last year, I didn't find a simple fix. Anyway, I think this code should be reworked in the future: if I'm right, it looks like that whenever req.auth is retrieved for the first time, we could trigger a db write. That's potentially problematic, like if for some reason this would occur while a SQL query is in progress.

[Christian Boos]

The PostgreSQL variant of this error seem to happen much more frequently now, see #7007:

...
  File "/usr/local/virtualenv/lib/python2.4/site-packages/Trac-0.11dev_r6683-py2.4.egg/trac/web/session.py", line 175, in save
    (self.sid, self.last_visit, authenticated))
...
IntegrityError: duplicate key violates unique constraint "session_pk"

There have been lots of other duplicates recently: #7125, #7110, #7097, #7045, #7027, #7024 …

[Christian Boos]

We need to fix that for the rc1 as well, though I have no idea why this can be triggered now by a single request. Do the chrome requests come into play?

Suggested fix would be to simply catch the error (we'll need #6348 for that as well) and inform the user with a warning that the session couldn't be saved, showing what was about to be saved but couldn't as well.

[Jonas Borgström]

I've had another look at this and even found similar constraint violations for the session_attribute table. Looking at that part of the code makes it even more obvious that concurrent access and not an ordinary "bug" is causing this race condition.

cboos, I also have a theory how a "single request" can cause this. I think it might be caused by the browser deciding to update the opensearch description at the same time the original url is accessed. And this might trigger this race condition.

[Eli Carter]

Is there a way to consistently reproduce this problem? If we could create a testcase to cover this, I think it would help.

[Christian Boos]

jonas: yes, this is tricky. The render_template of opensearch will call populate_data which will retrieve req.tz which in turn will retrieve the req.session (traceback.print_stack() helps here…). Then, what happens is that both Session (the opensearch request and the other request) consider themselves to be _new sessions and attempt to do the insert (now at line 82​).

eli: if Twill can do this, starting two asynchronous /timeline requests at the same time when the session and session_attribute tables are empty should do it (here, the chances of failures are even greater because both Session objects will think they have some new session data to save).

I'm still wondering whether checking for the simultaneous write attempt wouldn't actually result in the same thing in the end as trapping the duplicate insert attempt.

[osimons]

Closed #7387 as duplicate.

When searching for tickets with IntegrityError and session_pk a very interesting pattern occured: This ticket mentions it (in discussion), and 13 other identical tickets with #7007 being the oldest (and #7387 as of now the newest).

Each of those tickets are basically identical - same version of Python on Ubuntu, same Subversion and so on. That has to be t.e.o itself, right? Why does no other Trac user report this error? Is it related to the issue cmlenz looked into recently and fixed in [7192] for #2570? Or the t.e.o database itself? Other Trac users surely must have the traffic to make such errors appear if it is a general problem?

[Jonas Borgström]

Ok, I've finally figured out what's causing this and how to reproduce it. Anonymous sessions without any stored attributes exists only as cookies and not in the database.

When an anonymous user for the first time click on a link to a page that sets session attributes (timeline, query result or report for example) a session is inserted into the database at the end of the request.

If this page does not respond fast enough the user might be tempted to click on the link again before the first request has completed (and inserted the session). And this second request will then trigger an IntegrityError exception since the session in question has been inserted by the first request.

[Jonas Borgström]

Fixed in r7310 for 0.11-stable and r7311 for trunk.

[osimons]

There is a regression. The graceful handling of this is no longer present in 0.12+ code. Haven't checked to see when it was removed, but current code will raise this as an error like any other - bringing back the IntegrityError: columns sid, authenticated, name are not unique error.

Example logged on IRC today: ​http://paste.debian.net/plain/105917

[osimons]

Oh. Was I looking in the wrong place perhaps - seems we still handle it in save(), but not in promote_session() which we likely never have done before either. As such this is an additional fix that complements the original fix by Jonas.

[Christian Boos]

Replying to osimons:

There is a regression. … Example logged on IRC today: ​http://paste.debian.net/plain/105917

It's not really a regression, the present issue was about Session.save(), the r7311 code is still present and working as expected.

The issue you forwarded (copying the interesting bits below) is about a race in the promote_session code, something which is a "known issue".

Traceback (most recent call last):
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1-py2.6.egg/trac/web/api.py", line 436, in send_error
...
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1-py2.6.egg/trac/web/main.py", line 300, in _get_session
    return Session(self.env, req)
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1-py2.6.egg/trac/web/session.py", line 166, in __init__
    self.promote_session(sid)
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1-py2.6.egg/trac/web/session.py", line 225, in promote_session
    @self.env.with_transaction()
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1-py2.6.egg/trac/db/api.py", line 77, in transaction_wrapper
    fn(ldb)
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1-py2.6.egg/trac/web/session.py", line 257, in update_session_id
    """, (self.req.authname, sid))
...
  File "/usr/local/lib/python2.6/dist-packages/Trac-0.12.1-py2.6.egg/trac/db/sqlite_backend.py", line 48, in _rollback_on_error
    return function(self, *args, **kwargs)
IntegrityError: columns sid, authenticated, name are not unique

That's actually a duplicate of #7094, we should rather reopen that one, as there were no conclusive resolution for it.

[Remy Blank]

I seem to be getting this error more often here on t.e.o lately, actually I had never seen it before. It always happens when I start my browser, which opens two tabs with a ticket query on each. Maybe some of the recent changes in the session code do make it more likely to happen?