OperationalError: database is locked

[admin]

A lot of OperationalError: database is locked errors happen during saving of the session changes, after the request is processed and before the output is sent.

Typical traceback:

Traceback #most recent call last#:
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/web/main.py", line 435, in _dispatch_request
    dispatcher.dispatch#req#
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/web/main.py", line 230, in dispatch
    req.session.save##
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/web/session.py", line 97, in save
    #self.sid,##
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/db/util.py", line 50, in execute
    return self.cursor.execute#sql_escape_percent#sql#, args#
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/db/sqlite_backend.py", line 58, in execute
    args or [])
  File "/usr/lib/python2.4/site-packages/Trac-0.11.3-py2.4.egg/trac/db/sqlite_backend.py", line 50, in _rollback_on_error
    return function#self, *args, **kwargs#
OperationalError: database is locked

We should do better here than raising an internal error in this case, see comment:2.

[Emmanuel Blot]

See MostFrequentDuplicates (database is locked) + PluginIssue (Agilo plugin)

[Christian Boos]

I noticed that a good fraction of the recently reported tracebacks for the database is locked issue show that session.save() in dispatch to be the failing call.

But this failure is not a "critical" one, in the sense that it happens very late in the processing of a request, an eventual POST would already have succeeded and showing an internal error here is then somewhat misleading. So I think we could eventually catch this error and show it as a warning instead of an internal error.

For this, we need to save the session before calling render_template, which means that any session change happening during this rendering will not be taken into account.

Here's the patch:

trac/web/main.py

@@ -50 +50 @@
 from trac.util.text import exception_to_unicode, shorten_line, to_unicode
 from trac.util.translation import tag_, _
 from trac.web.api import *
-from trac.web.chrome import Chrome
+from trac.web.chrome import Chrome, add_warning
 from trac.web.clearsilver import HDFWrapper
 from trac.web.href import Href
 from trac.web.session import Session
@@ -220 +220 @@
                     else: # Genshi
                         template, data, content_type = \
                                   self._post_process_request(req, *resp)
+                        try:
+                            # Give the session a chance to persist changes
+                            req.session.save()
+                        except Exception, e: # TracDatabaseError (#6348)
+                            add_warning(
+                                req, _("Changes to user session couldn't be "
+                                       "saved (%(err)s)",
+                                       err=exception_to_unicode(e)))
                         if 'hdfdump' in req.args:
                             req.perm.require('TRAC_ADMIN')
                             # debugging helper - no need to render first
@@ -231 +239 @@
                             output = chrome.render_template(req, template,
                                                             data,
                                                             content_type)
-                            # Give the session a chance to persist changes
-                            req.session.save()
                             req.send(output, content_type or 'text/html')
                 else:
                     self._post_process_request(req)

I don't think anything in Trac changes the session during rendering, but if some plugins do, it remains to be seen if they really have to or if they could do this earlier.

[osimons]

I'm poking into this as part of ​bitten:ticket:269, and my regular development setup with some 20-25 active tabs is a consistent test-bed for Database is locked errors. I can have 25 Bitten tabs and 'Reload All Tabs' without issues. Add two tabs with Timeline, and things starting to lock up consistently. Here is what I find:

• My own Bitten-contained patches on the mentioned ticket helps a little, but is no solution.
• It does not matter what I select to render in the Timeline - it locks regardless of how many filters or what filters are selected.
• Your patch actually seems to help in that it makes all Bitten tabs render OK quite consistently, containing the locking error to the two Timeline tabs that still more or less always fails (sometimes with warning, sometimes never quite getting that far). And, as you correctly state: More or less always involving req.session.save().

So, either there is something fundamentally wrong with the Timeline, or the Timeline shows a symptom of something holding on to the db that then shows up when Timeline needs to save. That said, i don't understand why the session should try to save when nothing has changed in my session data for a simple reload? Is something flawed with Session? I haven't looked at the session code for a long time, but really we should store the _old_data on the session too and just check the object to see if it has been updated - without hitting the database.

The problem of templates not being able to store session data is fine by me - nothing in templates should have a need for persistence in my opinion.

/me really wanted to reschedule for 0.11.6, and tried hard to leave it alone for now… (patch more or less identical)

[Christian Boos]

Replying to osimons:

I'm poking into this as part of ​bitten:ticket:269,

Thanks for testing! I added some comments to that ticket as well.

Add two tabs with Timeline, and things starting to lock up consistently.

Yes, the timeline pages seem to be good triggers, if you have lots of events. What is especially a performance killer is the [timeline] changeset_show_files = location setting, due to the get_changes() done for each changeset (#6654 will help).

But I also need some pages modifying the session to the mix, otherwise it's no problem for me.

So, either there is something fundamentally wrong with the Timeline, or the Timeline shows a symptom of something holding on to the db that then shows up when Timeline needs to save.

The timeline queries probably hold a read lock for far too long , yes. We could "fix" that at the level of each timeline provider, or globally (i.e. what #3446 is about). I'd prefer globally, because:

• the iteration/yield might still be a superior solution for DB backends with better concurrency
• all the providers would be "fixed" at once; leaving one provider in one plugin do the wrong thing and you have essentially no benefit from fixing the others
• we could have a [trac] trade_memory_for_speed setting which could be used to make this feature optional

That said, i don't understand why the session should try to save when nothing has changed in my session data for a simple reload? Is something flawed with Session? I haven't looked at the session code for a long time, but really we should store the _old_data on the session too and just check the object to see if it has been updated - without hitting the database.

This is what should happen. But if you have timeline pages with different sets of providers or different daysback values, then you'll get session modifications.

The problem of templates not being able to store session data is fine by me - nothing in templates should have a need for persistence in my opinion.

/me really wanted to reschedule for 0.11.6, and tried hard to leave it alone for now… (patch more or less identical)

If no one has a concern about this change of behavior (which might impact Macros for example), then I'd be OK with that.

On a related note, I've been pondering whether to do all the remaining DB layer fixes on 0.11.6 first or on trunk first (and then eventually backport). What do you think?

[osimons]

Replying to cboos:

Yes, the timeline pages seem to be good triggers, if you have lots of events.

My 'Reload All Tabs' trigger this with just wiki pages that haven't changed since intial dev project creation, and don't even appear in timeline when the page is loaded (ie. too old for default criteria).

But if you have timeline pages with different sets of providers or different daysback values, then you'll get session modifications.

Well I don't. I've made sure (as above) that just 'wiki changes' are stored in (authenticated) session, and that my Timeline tabs just hits /timeline. Nothing at all should change for a simple load/reload as I see it?

On a related note, I've been pondering whether to do all the remaining DB layer fixes on 0.11.6 first or on trunk first (and then eventually backport). What do you think?

No idea, I haven't really merged merged much lately. Still, having come so far on 0.11.6, it is still easier to forward port changes that we know should hit 0.11? I of course say that because I still only use 0.11 for test and development… :-)

[Christian Boos]

Replying to osimons:

Replying to cboos:

Yes, the timeline pages seem to be good triggers, if you have lots of events.

My 'Reload All Tabs' trigger this with just wiki pages that haven't changed since intial dev project creation, and don't even appear in timeline when the page is loaded (ie. too old for default criteria).

Strange, maybe a plugin?

But if you have timeline pages with different sets of providers or different daysback values, then you'll get session modifications.

Well I don't. I've made sure (as above) that just 'wiki changes' are stored in (authenticated) session, and that my Timeline tabs just hits /timeline. Nothing at all should change for a simple load/reload as I see it?

I'm sure [trac] debug_sql = yes will do wonders here ;-)

On a related note, I've been pondering whether to do all the remaining DB layer fixes on 0.11.6 first or on trunk first (and then eventually backport). What do you think?

No idea, I haven't really merged merged much lately. Still, having come so far on 0.11.6, it is still easier to forward port changes that we know should hit 0.11?

Well, it's more a question of stability. In case we break something, maybe it's better to break trunk. OTOH, 0.11-stable certainly still sees more testing than trunk (see below…), so we might think everything is OK on trunk, see improvements there and decide to backport, and only then realize it's broken. So I'm actually tempted to go first on 0.11-stable, at the risk of some instability.

I of course say that because I still only use 0.11 for test and development… :-)

! (shock and horror ;-) ).

[osimons]

Replying to cboos:

Strange, maybe a plugin?

Just Trac & Bitten. Nothing else. And a local apache/mod_wsgi development install (ie. no other requests are made than mine).

I'm sure [trac] debug_sql = yes will do wonders here ;-)

Well, darn. Where did that come from? News to me - but very informative! I load a /timeline (no query arguments, ie. session default). Then I just hit reload (should be identical). This is the session related debug-output that happens for this request (curl-type request, so just the html):

2009-08-23 11:13:08,442 Trac[util] DEBUG: SQL: 'SELECT name FROM auth_cookie WHERE cookie=%s'
2009-08-23 11:13:08,442 Trac[util] DEBUG: args: ('5556c14b1999b22c1285edbeb1305ab4',)
2009-08-23 11:13:08,448 Trac[util] DEBUG: SQL: 'SELECT name FROM auth_cookie WHERE cookie=%s'
2009-08-23 11:13:08,448 Trac[util] DEBUG: args: ('5556c14b1999b22c1285edbeb1305ab4',)
2009-08-23 11:13:08,452 Trac[util] DEBUG: SQL: 'SELECT last_visit FROM session WHERE sid=%s AND authenticated=%s'
2009-08-23 11:13:08,453 Trac[util] DEBUG: args: (u'simon', 1)
2009-08-23 11:13:08,454 Trac[util] DEBUG: SQL: 'SELECT name,value FROM session_attribute WHERE sid=%s and authenticated=%s'
2009-08-23 11:13:08,454 Trac[util] DEBUG: args: (u'simon', 1)
2009-08-23 11:13:08,594 Trac[util] DEBUG: SQL: 'DELETE FROM session_attribute WHERE sid=%s'
2009-08-23 11:13:08,594 Trac[util] DEBUG: args: (u'simon',)
2009-08-23 11:13:08,596 Trac[util] DEBUG: SQL: 'INSERT INTO session_attribute (sid,authenticated,name,value) VALUES(%s,%s,%s,%s)'
2009-08-23 11:13:08,596 Trac[util] DEBUG: args: [(u'simon', 1, u'timeline.daysback', 30), (u'simon', 1, u'timeline.filter.ticket', u'1'), (u'simon', 1, u'timeline.filter.ticket_details', u'1'), (u'simon', 1, u'timeline.filter.build', u'1'), (u'simon', 1, u'timeline.filter.milestone', u'1'), (u'simon', 1, u'timeline.filter.wiki', u'1'), (u'simon', 1, u'timeline.filter.changeset', u'1')]

Notice the DELETE and new INSERT in particular….

[osimons]

And, just for the fun of it i added debug logging of old and new session contents to session.save():

2009-08-23 11:22:10,883 Trac[session] DEBUG: Old session: {u'timeline.filter.changeset': u'1', u'timeline.filter.wiki': u'1', u'timeline.daysback': u'30', u'timeline.filter.ticket': u'1', u'timeline.filter.ticket_details': u'1', u'timeline.filter.build': u'1', u'timeline.filter.milestone': u'1'}
2009-08-23 11:22:10,883 Trac[session] DEBUG: New session: {u'timeline.daysback': 30, u'timeline.filter.ticket': u'1', u'timeline.filter.ticket_details': u'1', u'timeline.filter.build': u'1', u'timeline.filter.milestone': u'1', u'timeline.filter.wiki': u'1', u'timeline.filter.changeset': u'1'}

Spot the difference? Loading this dicts in Python interpreter i tried:

>>> old == new
False

Here is the answer:

u'timeline.daysback': 30
# vs
u'timeline.daysback': u'30'

[Remy Blank]

Replying to osimons:

Here is the answer:

Heh, nice detective work, Simon!

[osimons]

Replying to rblank:

Replying to osimons:

Here is the answer:

Heh, nice detective work, Simon!

You're welcome - for the benefit of all, including me :-) I was thinking of the approach, and perhaps the general solution is for session to handle this internally - ensuring names and values are always unicode seeing that is how it is read from / written to database?

[Christian Boos]

Ah, well spotted indeed. We should probably enforce storing unicode values in the Session.

Like this:

Index: trac/web/session.py
===================================================================
--- trac/web/session.py (revision 8488)
+++ trac/web/session.py (working copy)
@@ -42,6 +42,9 @@
         else:
             self.authenticated = False

+    def __setitem__(self, key, value):
+        dict.__setitem__(self, key, unicode(value))
+
     def get_session(self, sid, authenticated=False):
         self.env.log.debug('Retrieving session for ID %r', sid)

to_unicode is probably not needed here, as if value is an UTF-8 string, we had a problem before that point.

As for the original proposal (comment:2), I think that's no longer needed, given that I can't reproduce the lock error with the fix for #3446 applied.

[Christian Boos]

Replying to osimons:

… ensuring names and values are always unicode

For names it's not needed I think, same remark as for values: if we have UTF-8 strings here, we've already got a problem before.

And no need for normalization between str and unicode, as:

>>> {u'key': 'value'} == {'key': u'value'}
True

[osimons]

That patch makes all the difference. I can now add ~6 Timeline tabs to my reload-mix without issues. No INSERT|UPDATE|DELETE in logs, and all tabs load fine.

When I increase that to ~10, I get OperationalError: unable to open database file like #8551, but that is likely just a concurrency limitation of SQLite3? Need to reasearch that now… :-)

[Christian Boos]

Replying to osimons:

That patch makes all the difference. I can now add ~6 Timeline tabs to my reload-mix without issues. No INSERT|UPDATE|DELETE in logs, and all tabs load fine.

But if you're forcing changes to the session (different daysback values) then you're getting back the problem, I imagine. Can you then try the #3446 patch? Does it solve the issue you described in comment:4?

When I increase that to ~10, I get OperationalError: unable to open database file like #8551, but that is likely just a concurrency limitation of SQLite3? Need to reasearch that now… :-)

Hm, that's new to me - thought #8551 was a permission issue. Can you follow-up there with a traceback of yours, and the versions of everything…

[osimons]

0.11 patch with early session save + strings as session values.

[osimons]

cboos, OK with committing the __setitem__() part of the patch for 0.11-stable? I think that is very important to get done, and hereby reschedule it…

I didn't want to jump in on your ticket in case you were still working on this - alternative approaches or futher research. I'll commit it unless you do it first, or tell me to wait for now.

[Christian Boos]

Replying to osimons:

cboos, OK with committing the __setitem__() part of the patch for 0.11-stable? I think that is very important to get done, and hereby reschedule it…

Done in [8518].

For the rest, let's keep that as a possible complementary solution, but I think focusing on #3446 will give more immediate benefit.

I'll only feel 100% confident about removing the possibility for plugins (notably for Macros) to change the session during rendering once there will be a call done before the rendering itself (i.e. not only expand_macro but also parse_content or similar), and that'll be 0.13 at earliest.

[osimons]

Thanks.

Just found an issue with the first patch (early saving of session) in that it does not clear the warnings saved before redirect. So the 'Changes saved.' warning will never be removed and kept being displayed on each request.