tracd crash related to pysqlite

[Christian Boos]

After upgrading to [1862] (from [1850] or so), I got a crash while executing a custom query. Since this happened very quickly after startup, I include the full log.

Trac is brought to you by:
-----------------------------------------------------------------
                E d g e w a l l   S o f t w a r e
        Professional Linux and software development services
              Read more at http://www.edgewall.com/
-----------------------------------------------------------------
Running:
  D:/Workspace/install/lib/python/trac/devel/Scripts/tracd -p 8002         -a devel,D:/Workspace/local/trac/htdigest.BCT,BCT
    D:/Workspace/local/trac/devel

Trac[query] DEBUG: Query SQL: SELECT t.id AS id,t.summary AS summary,t.status AS status,t.owner AS owner,t.type AS type,t.priority AS priori
ty,t.milestone AS milestone,t.time AS time,t.changetime AS changetime,priority.value AS priority_value
FROM ticket AS t
  LEFT OUTER JOIN enum AS priority ON (priority.type='priority' AND priority.name=priority)
WHERE COALESCE(t.status,'') IN ('new','assigned','reopened')
ORDER BY COALESCE(t.priority,'')='',priority.value,t.id
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/query HTTP/1.1" 200 -
Trac[session] DEBUG: Adding variable query_time with value "1119906085" to session 865518019c9c2dcea885d966
Trac[session] DEBUG: Adding variable query_constraints with value "{'status': ('new', 'assigned', 'reopened')}" to session 865518019c9c2dcea
885d966
Trac[session] DEBUG: Adding variable query_href with value "/devel/query?status=new&status=assigned&status=reopened&order=priority" to sessi
on 865518019c9c2dcea885d966
Trac[session] DEBUG: Adding variable query_tickets with value "1 2 3 4 5 7 8 9" to session 865518019c9c2dcea885d966
Trac[session] DEBUG: Purging old, expired, sessions.
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/css/trac.css HTTP/1.1" 304 -
Trac[standalone] DEBUG: Total request time: 0.030000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/css/report.css HTTP/1.1" 304 -
Trac[standalone] DEBUG: Total request time: 0.040000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/css/code.css HTTP/1.1" 304 -
Trac[standalone] DEBUG: Total request time: 0.010000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/js/trac.js HTTP/1.1" 200 -
Trac[standalone] DEBUG: Total request time: 0.020000 s
0.0 10.0
Trac[main] ERROR: Failed to render pretty error page: object does not support item assignment
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/topbar_gradient.png HTTP/1.1" 500 -
0.0699999332428 10.0
Trac[main] ERROR: Failed to render pretty error page: object does not support item assignment
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/dots.gif HTTP/1.1" 500 -
Trac[standalone] DEBUG: Total request time: 0.550000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/topbar_gradient2.png HTTP/1.1" 200 -
Trac[standalone] DEBUG: Total request time: 0.030000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/js/query.js HTTP/1.1" 200 -
Trac[standalone] DEBUG: Total request time: 0.010000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/asc.png HTTP/1.1" 200 -
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/trac_banner.png HTTP/1.1" 200 -
Trac[standalone] DEBUG: Total request time: 0.020000 s
Trac[standalone] DEBUG: Total request time: 0.331000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/xml.png HTTP/1.1" 200 -
Trac[standalone] DEBUG: Total request time: 0.040000 s
cblaptop - - [27/Jun/2005 23:01:25] "GET /devel/chrome/trac_logo_mini.png HTTP/1.1" 200 -
Trac[standalone] DEBUG: Total request time: 0.030000 s
cblaptop - - [27/Jun/2005 23:01:34] "POST /devel/query HTTP/1.1" 302 -
Trac[standalone] DEBUG: Total request time: 0.040000 s
Trac[query] DEBUG: Query SQL: SELECT t.id AS id,t.summary AS summary,t.reporter AS reporter,t.status AS status,t.owner AS owner,t.type AS ty
pe,t.priority AS priority,t.time AS time,t.changetime AS changetime,priority.value AS priority_value
FROM ticket AS t
  LEFT OUTER JOIN enum AS priority ON (priority.type='priority' AND priority.name=priority)
WHERE COALESCE(t.status,'') IN ('new','assigned','reopened') AND COALESCE(t.reporter,'') LIKE '%body%'
ORDER BY COALESCE(t.priority,'')='',priority.value,t.id
cblaptop - - [27/Jun/2005 23:01:34] "GET /devel/query?status=new&status=assigned&status=reopened&group=&reporter=%7Ebody&order=priority HTTP
/1.1" 200 -
Trac[session] DEBUG: Changing variable query_time from "1119906085" to "1119906094" in session 865518019c9c2dcea885d966
Trac[session] DEBUG: Changing variable query_constraints from "{'status': ('new', 'assigned', 'reopened')}" to "{'status': ['new', 'assigned
', 'reopened'], 'reporter': ['~body']}" in session 865518019c9c2dcea885d966
Trac[session] DEBUG: Changing variable query_href from "/devel/query?status=new&status=assigned&status=reopened&order=priority" to "/devel/q
uery?status=new&status=assigned&status=reopened&group=&reporter=%7Ebody&order=priority" in session 865518019c9c2dcea885d966
Trac[session] DEBUG: Changing variable query_tickets from "1 2 3 4 5 7 8 9" to "" in session 865518019c9c2dcea885d966
Trac[session] DEBUG: Purging old, expired, sessions.
Trac[main] ERROR: Failed to render pretty error page: object does not support item assignment
cblaptop - - [27/Jun/2005 23:01:34] "GET /devel/chrome/topbar_gradient.png HTTP/1.1" 500 -
Exception _sqlite.ProgrammingError: 'library routine called out of sequence' in <bound method PooledConnection.__del__ of <trac.db.PooledCon
nection object at 0x00CB5D78>> ignored
cblaptop - - [27/Jun/2005 23:01:34] "GET /devel/chrome/dots.gif HTTP/1.1" 200 -
Trac[standalone] DEBUG: Total request time: 0.020000 s
Fatal Python error: PyEval_RestoreThread: NULL tstate

This application has requested the Runtime to terminate it in an unusual way.
Please contact the application's support team for more information.

There are several things to be noted in the above:

• there's an ERROR: Failed to render pretty error page: object does not support item assignment error. Maybe it's related.
• there is some race condition going on, as demonstrated by the 0.0 10.0 and 0.0699999332428 10.0 lines
• the obviously problematic Exception _sqlite.ProgrammingError: 'library routine called out of sequence' in <bound method PooledConnection.__del__ of <trac.db.PooledConnection object at 0x00CB5D78>> ignored

I initially got a crash with only the Fatal Python error: PyEval_RestoreThread: NULL tstate information, then I retried and got the above data. Afterwards, I couldn't reproduce the crash (well, except by doing fast refreshes, but that's the usual #1401 behavior :) ). Maybe it was because those first two times old expired sessions were purged concurrently to the ticket query, and after that, there are no more sessions to purge?

Configuration

• tracd on Windows
• Python 2.3.2
• SVN bindings 1.2.0
• PySqlite 1.1.6
• User agent: Firefox 1.0.4, Windows

[Christian Boos]

Note that this problem has been silenced since r1875 (removal of the ThreadingMixIn from the !TracHTTPServer).

Some ideas for a better fix:

• one db connection pool per thread: but is there really a need for a pool in that case?
• only use the db connection pool in non-threaded servers (cgi, tracd without the ThreadingMixIn, mod_python in apache prefork model)

[Christopher Lenz]

one db connection pool per thread: but is there really a need for a pool in that case?

Very much… the main point of the connection pool is actually to avoid having to pass around the DB connection to every component that may need it while processing a request, while avoiding the cost of having those components creating new connections.

[Christian Boos]

If it's actually possible to share db connections between threads, I understand the usefulness of the db connection pool.

But if we have to restrict the usage of a db connection to the thread which created it, couldn't we arrange to always reuse the same db connection, for instance by attaching it to the request object (IIUC, one request is always bound to one thread) and pass that request object around whereever needed?

[trac-form@…]

I am seeing this very frequently at home running r2318. I have tried pysqlite 1.6 and 2.0.4 without success, as would be supposed from the description of the errors.

[Christian Boos]

You may want to try again with the recent trunk (≥ r2355), which now won't share pysqlite db connections across threads. This and other changes made the database code more robust.

I would be very interested to know if there are still problems regarding pysqlite in the current trunk.

[Christopher Lenz]

This issue should really be fixed by now. Please reopen if you're still seeing it.