[Trac-tickets] Re: [The Trac Project] #2170: Crash while doing a login/logout in the Timeline

[The Trac Project]

#2170: Crash while doing a login/logout in the Timeline
----------------------+-----------------------------------------------------
 Reporter:  cboos     |        Owner:  cboos   
     Type:  defect    |       Status:  assigned
 Priority:  high      |    Milestone:  0.9     
Component:  general   |      Version:  devel   
 Severity:  critical  |   Resolution:          
 Keywords:            |  
----------------------+-----------------------------------------------------
Old description:

> 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 at 2326#L119

New description:

 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 at 2326#L119

Comment (by cboos):

 Found some relevant discussion about the problem:
  * The SQLite API for
 [http://cvstrac.org/capi3ref.html#sqlite3_busy_handler
 sqlite3_busy_handler] describes a similar scenario[[BR]]
    In particular:
      ''Consider a scenario where one process is holding a read lock that
 it is trying to promote to a reserved lock and a second process is holding
 a reserved lock that it is trying to promote to an exclusive lock. The
 first process cannot proceed because it is blocked by the second and the
 second process cannot proceed because it is blocked by the first. If both
 processes invoke the busy handlers, neither will make any progress.''
  * Karl Mierle had a similar issue back in June with Argon, which he
 describe there [http://www.third-bit.com/trac/argon/wiki/Locking Locking]
  * The SQLite author was contacted by the PySQLite author about the former
 problem, and he
 [http://article.gmane.org/gmane.comp.db.sqlite.general/13002 replied]
     * use `EXCLUSIVE` transactions, but this reduce the amount of
 concurrency
     * one of the involved threads must `ROLLBACK`

-- 
Ticket URL: <http://projects.edgewall.com/trac/ticket/2170>
The Trac Project <http://trac.edgewall.com/>