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

[cboos]

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)

[cboos]

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!

[cboos]

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.

[cboos]

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 ...

[cboos]

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]

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.

[ecarter]

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

[cboos]

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]

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]

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