Crash while doing a login/logout in the Timeline

[Christian Boos]

This is somehow reproductible, though I got slightly different stack traces

each time. But it always bombs in connection_commit, though.

Configuration:

• tracd on Linux
• python 2.3.4
• pysqlite 2.0.4 with sqlite 3.2.7.

With older versions of pysqlite, I got simply dead-locks, but this was not a good thing either…

Here's the stack trace:

dserver.bct.de - - [04/Oct/2005 15:59:05] "GET /stable-bct-trac/login HTTP/1.1" 401 -
[New Thread 557091 (LWP 12565)]
Trac[session] DEBUG: Promoting anonymous session 90d7a758b262bd4e88eced41 to authenticated session for user cboos

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 557091 (LWP 12565)]
0x40582056 in pysqlite_sleep (seconds=-21474836.48) at src/util.c:37
37          Py_DECREF(ret);
(gdb)
(gdb)
(gdb) bt
#0  0x40582056 in pysqlite_sleep (seconds=-21474836.48) at src/util.c:37
#1  0x4058222d in _sqlite_step_with_busyhandler (statement=0x8550dc8, _connection=0x4084e988) at src/util.c:86
#2  0x4057d940 in connection_commit (self=0x4084e988, args=0x0) at src/connection.c:230
#3  0x080c0c42 in call_function (pp_stack=0x45363450, oparg=0) at Python/ceval.c:3425
#4  0x080bd5d4 in eval_frame (f=0x844ee8c) at Python/ceval.c:2116
#5  0x080c102c in fast_function (func=0x40839e44, pp_stack=0x453635d0, n=2, na=2, nk=0) at Python/ceval.c:3518
#6  0x080c0e46 in call_function (pp_stack=0x453635d0, oparg=1) at Python/ceval.c:3458
#7  0x080bd5d4 in eval_frame (f=0x84b675c) at Python/ceval.c:2116
...

pyframe points to _do_login, in source:trunk/trac/web/auth.py@2326#L119​

[Christian Boos]

Ok, now I manage to reproduce the crash systematically:

• in Thunderbird, I refresh the Timeline feed
• half a second later, in Firefox, I reload the page which does a logout

Now, looking more closely to the pysqlite2 code within gdb, I located the cause of the crash itself:

util.c

@@ -80 +80 @@
         }
 
         how_long = 0.01* (1 << counter);
-        if (how_long > 1.0) {
+        if (how_long > 1.0 || counter > 30) {
             how_long = 1.0;
         }
         pysqlite_sleep(how_long);
 
         counter++;

… now I'm back with my database locks :)

Ok, it looks like a commit is not "atomic" at all, and with our database pool, we reuse database connections which are in a commit in progress, hence the deadlock.

[Christian Boos]

I disabled 2.0.4 and reinstalled pysqlite-1.1.6: Now I can still trigger the database lock by doing the operations described above but the database recovers from that state for subsequent queries, whereas with 2.0.4, the database remains locked forever.

[Christian Boos]

I just filled ​pysqlite:ticket:124, which contains some additional explanations about the issue: in short, we have to use 10 and not 10000 for the timeout value when using pysqlite2:

db.py

@@ -254 +254 @@
                                  'directory it is located in.' \
                                  % (getuser(), path)
 
-        timeout = int(params.get('timeout', 10000))
         if have_pysqlite == 2:
+            timeout = int(params.get('timeout', 10)) # 10 seconds
             # Convert unicode to UTF-8 bytestrings. This is case-sensitive, so
             # we need two converters
             sqlite.register_converter('text', str)
@@ -264 +264 @@
             cnx = sqlite.connect(path, detect_types=sqlite.PARSE_DECLTYPES,
                                  check_same_thread=False, timeout=timeout)
         else:
+            timeout = int(params.get('timeout', 10000)) # 10 seconds
             cnx = sqlite.connect(path, timeout=timeout)
         ConnectionWrapper.__init__(self, cnx)