Database lock when updating timeline filters

[Christian Boos]

I've just noticed this db lock while changing timeline filters. The error appeared only in the logs, but I think we should not lend ourself to create a lock when performing a normal operation.

localhost - - [14/Apr/2006 17:31:29] "GET /devel/timeline HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/css/trac.css HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/css/timeline.css HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/trac.ico HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/js/trac.js HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/trac_banner.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/topbar_gradient.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/dots.gif HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/trac_logo_mini.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/wiki.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/trac.ico HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/topbar_gradient2.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/extlink.gif HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/changeset.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:30] "GET /devel/chrome/common/xml.png HTTP/1.1" 200 -
Trac[svn_fs] DEBUG: Opening subversion file-system at C:/Workspace/local/svn/trac-svnrepos with scope /
Trac[cache] DEBUG: Checking whether sync with repository is needed
Trac[svn_fs] DEBUG: Closing subversion file-system at C:/Workspace/local/svn/trac-svnrepos
Trac[api] DEBUG: Updating wiki page index
localhost - - [14/Apr/2006 17:31:47] "GET /devel/timeline?from=4%2F14%2F2006&daysback=30&milestone=on&ticket_details=on&
changeset=on&wiki=on&update=Update HTTP/1.1" 200 -
Trac[session] INFO: Refreshing session ca6b49eb53d04be055b54d53
Trac[session] DEBUG: Adding variable timeline.filter.changeset with value "1" to session ca6b49eb53d04be055b54d53
Trac[session] DEBUG: Adding variable timeline.filter.ticket_details with value "1" to session ca6b49eb53d04be055b54d53
Trac[session] DEBUG: Adding variable last_visit with value "1145028707" to session ca6b49eb53d04be055b54d53
Trac[session] DEBUG: Adding variable timeline.filter.milestone with value "1" to session ca6b49eb53d04be055b54d53
Trac[session] DEBUG: Adding variable timeline.filter.wiki with value "1" to session ca6b49eb53d04be055b54d53
Trac[session] DEBUG: Purging old, expired, sessions.
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/css/trac.css HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/css/timeline.css HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/trac.ico HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/js/trac.js HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/trac_banner.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/topbar_gradient.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/dots.gif HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/trac_logo_mini.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/wiki.png HTTP/1.1" 200 -
Trac[main] ERROR: database is locked
Traceback (most recent call last):
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\web\main.py", line 301, in dispatch_request
    dispatcher.dispatch(req)
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\web\main.py", line 151, in dispatch
    req.perm = PermissionCache(self.env, req.authname)
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\perm.py", line 276, in __init__
    self.perms = PermissionSystem(env).get_user_permissions(username)
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\perm.py", line 134, in get_user_permissions
    for perm in self.store.get_user_permissions(username):
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\perm.py", line 213, in get_user_permissions
    cursor.execute("SELECT username,action FROM permission")
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\db\util.py", line 48, in execute
    return self.cursor.execute(sql)
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\db\sqlite_backend.py", line 39, in execute
    args or [])
  File "C:\Workspace\install\lib\python\trac\devel\lib\site-packages\trac\db\sqlite_backend.py", line 31, in _rollback_o
n_error
    return function(self, *args, **kwargs)
OperationalError: database is locked
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/topbar_gradient2.png HTTP/1.1" 500 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/changeset.png HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/extlink.gif HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/trac.ico HTTP/1.1" 200 -
localhost - - [14/Apr/2006 17:31:47] "GET /devel/chrome/common/xml.png HTTP/1.1" 200 -

This is reproducible, though sometimes there are even two database is locked errors, and it's not always for the same request, of course. I think we never notice those request failures because those requested resources are anyway cached by the web browser (in the above, it's the wiki.png).

I'll investigate further.

[Christian Boos]

Forgot to mention that this problem is specific to front-ends serving themselves the static content using the Chrome component.

Therefore, in r3160, IRequestHandlers can now specify that they don't need user related information and also that they don't make use of templates and therefore don't need the HDF.

This not only fixes this problem, but also makes TracStandalone feel noticeably faster (and I bet it'll be the same for TracCgi).

Also, while working on this, I noticed that when the database lock occurs for some important resource, like trac.css, the problem becomes quite visible, as the layout is messed up. That might well be complementary explanation for the CSS intermittently applied issue (#2038)…

[Christian Boos]

He, I just realized that I have the above database locks only when I use my Python 2.3.5/PySqlite 2.0.5 installation, not when using Python 2.4.2 and PySqlite 2.2.0.

But nevertheless, the benefit of r3160 in term of speed is also noticeable with my Python 2.4.2 installation.