Edgewall Software
Modify

Opened 10 years ago

Closed 10 years ago

Last modified 10 years ago

#8468 closed defect (fixed)

OperationalError: database is locked

Reported by: admin Owned by: Christian Boos
Priority: high Milestone: 0.11.6
Component: general Version: 0.11.3
Severity: major Keywords: database lock
Cc: osimons Branch:
Release Notes:
API Changes:

Description (last modified by Christian Boos)

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.

Attachments (1)

t8468-session_save-r8488-011.diff (2.1 KB ) - added by osimons 10 years ago.
0.11 patch with early session save + strings as session values.

Download all attachments as: .zip

Change History (20)

comment:1 by Emmanuel Blot, 10 years ago

Resolution: invalid
Status: newclosed

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

comment:2 by Christian Boos, 10 years ago

Keywords: lock added
Milestone: 0.12
Resolution: invalid
Severity: normalmajor
Status: closedreopened

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

    diff --git a/trac/web/main.py b/trac/web/main.py
    a b  
    5050from trac.util.text import exception_to_unicode, shorten_line, to_unicode
    5151from trac.util.translation import tag_, _
    5252from trac.web.api import *
    53 from trac.web.chrome import Chrome
     53from trac.web.chrome import Chrome, add_warning
    5454from trac.web.clearsilver import HDFWrapper
    5555from trac.web.href import Href
    5656from trac.web.session import Session
     
    220220                    else: # Genshi
    221221                        template, data, content_type = \
    222222                                  self._post_process_request(req, *resp)
     223                        try:
     224                            # Give the session a chance to persist changes
     225                            req.session.save()
     226                        except Exception, e: # TracDatabaseError (#6348)
     227                            add_warning(
     228                                req, _("Changes to user session couldn't be "
     229                                       "saved (%(err)s)",
     230                                       err=exception_to_unicode(e)))
    223231                        if 'hdfdump' in req.args:
    224232                            req.perm.require('TRAC_ADMIN')
    225233                            # debugging helper - no need to render first
     
    231239                            output = chrome.render_template(req, template,
    232240                                                            data,
    233241                                                            content_type)
    234                             # Give the session a chance to persist changes
    235                             req.session.save()
    236242                            req.send(output, content_type or 'text/html')
    237243                else:
    238244                    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.

comment:3 by Christian Boos, 10 years ago

Owner: set to Christian Boos
Status: reopenednew

comment:4 by osimons, 10 years ago

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)

in reply to:  4 ; comment:5 by Christian Boos, 10 years ago

Description: modified (diff)
Keywords: database added
Priority: normalhigh
Status: newassigned

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?

in reply to:  5 ; comment:6 by osimons, 10 years ago

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… :-)

comment:7 by osimons, 10 years ago

Cc: osimons added

in reply to:  6 ; comment:8 by Christian Boos, 10 years ago

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 ;-) ).

in reply to:  8 comment:9 by osimons, 10 years ago

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….

comment:10 by osimons, 10 years ago

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'

in reply to:  10 ; comment:11 by Remy Blank, 10 years ago

Replying to osimons:

Here is the answer:

Heh, nice detective work, Simon!

in reply to:  11 ; comment:12 by osimons, 10 years ago

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?

in reply to:  10 comment:13 by Christian Boos, 10 years ago

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.

in reply to:  12 comment:14 by Christian Boos, 10 years ago

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

comment:15 by osimons, 10 years ago

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… :-)

in reply to:  15 comment:16 by Christian Boos, 10 years ago

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…

by osimons, 10 years ago

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

comment:17 by osimons, 10 years ago

Milestone: 0.120.11.6

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.

in reply to:  17 comment:18 by Christian Boos, 10 years ago

Resolution: fixed
Status: assignedclosed

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.

comment:19 by osimons, 10 years ago

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.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Christian Boos.
The resolution will be deleted. Next status will be 'reopened'.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.