Operational Error: database is locked

[Thijs Triemstra <lists@…>]

Today we hit the database locked error again. After reading on IRC earlier this week that this particular error was fixed, we upgraded to the trac 0.11.x stable branch, hoping it would be fixed, but unfortunately it seems it isn't..

So as described in #3446, I'm opening a new ticket and attaching as much info as I can find.

System Information

Trac:	0.11.6stable-r8631
Python:	2.5.4 (r254:67916, Dec 25 2008, 15:04:44) [GCC 4.0.3 (Ubuntu 4.0.3-1ubuntu5)]
setuptools:	0.6c9
SQLite:	3.6.13
pysqlite:	2.5.5
Genshi:	0.6dev-r1064
mod_wsgi:	2.4
Pygments:	1.0
Subversion:	1.5.7 (r36142)
RPC:	1.0.6

This is the error I grabbed from the Apache log, not sure if it's related:

[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4] mod_wsgi (pid=11176): Exception occurred processing W                                          SGI script '/var/www/wsgi/trac.wsgi'.
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4] Traceback (most recent call last):
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]   File "/usr/local/src/trac-0.11stable/trac/web/main.                                          py", line 415, in dispatch_request
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]     return _dispatch_request(req, env, env_error)
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]   File "/usr/local/src/trac-0.11stable/trac/web/main.                                          py", line 523, in _dispatch_request
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]     req.send_error(exc_info, status=500, env=env, dat                                          a=data)
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]   File "/usr/local/src/trac-0.11stable/trac/web/api.p                                          y", line 396, in send_error
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]     exc_info)
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]   File "/usr/local/src/trac-0.11stable/trac/web/main.                                          py", line 445, in _dispatch_request
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]     dispatcher.dispatch(req)
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]   File "/usr/local/src/trac-0.11stable/trac/web/main.                                          py", line 230, in dispatch
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]     req.send(output, content_type or 'text/html')
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]   File "/usr/local/src/trac-0.11stable/trac/web/api.p                                          y", line 359, in send
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]     self.write(content)
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]   File "/usr/local/src/trac-0.11stable/trac/web/api.p                                          y", line 463, in write
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4]     self._write(data)
[Thu Oct 01 10:43:26 2009] [error] [client 77.247.9.4] IOError: failed to write data

And I attached a screenshot of the error.

[Christian Boos]

Thanks for the report. Can you also please attach the trac.log? Maybe also the trac.ini and the list of plugins you're using…

Is the problem reproducible without plugins as well?

Btw, tell us more about the conditions in which the lock happens: is it easy to get one, or do you have to take some specific steps?

[anonymous]

Replying to cboos:

Thanks for the report. Can you also please attach the trac.log?

Here's the relevant part of the trac.log:

2009-10-01 10:43:07,998 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 445, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 229, in dispatch
    req.session.save()
  File "/usr/local/src/trac-0.11stable/trac/web/session.py", line 127, in save
    (self.last_visit, self.sid, authenticated))
  File "/usr/local/src/trac-0.11stable/trac/db/util.py", line 64, in execute
    return self.cursor.execute(sql_escape_percent(sql), args)
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 80, in execute
    PyFormatCursor.execute(self, *args)
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 59, in execute
    args or [])
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 51, in _rollback_on_error
    return function(self, *args, **kwargs)
OperationalError: database is locked
2009-10-01 10:43:14,571 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 445, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 230, in dispatch
    req.send(output, content_type or 'text/html')
  File "/usr/local/src/trac-0.11stable/trac/web/api.py", line 359, in send
    self.write(content)
  File "/usr/local/src/trac-0.11stable/trac/web/api.py", line 463, in write
    self._write(data)
IOError: failed to write data
2009-10-01 10:43:19,222 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 445, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 229, in dispatch
    req.session.save()
  File "/usr/local/src/trac-0.11stable/trac/web/session.py", line 100, in save
    (self.sid,))
  File "/usr/local/src/trac-0.11stable/trac/db/util.py", line 64, in execute
    return self.cursor.execute(sql_escape_percent(sql), args)
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 80, in execute
    PyFormatCursor.execute(self, *args)
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 59, in execute
    args or [])
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 51, in _rollback_on_error
    return function(self, *args, **kwargs)
ProgrammingError: Cannot operate on a closed cursor.
2009-10-01 10:43:25,714 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 445, in _dispatch_request
    dispatcher.dispatch(req)
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 230, in dispatch
    req.send(output, content_type or 'text/html')
  File "/usr/local/src/trac-0.11stable/trac/web/api.py", line 359, in send
    self.write(content)
  File "/usr/local/src/trac-0.11stable/trac/web/api.py", line 463, in write
    self._write(data)
IOError: failed to write data

Maybe also the trac.ini and the list of plugins you're using…

Can I email you this, I'm not comfortable posting that info here tbh.

Is the problem reproducible without plugins as well?

I'm not sure how to test this since it's a ​live site and disabling the plugins will damage the functionality of our site.

Btw, tell us more about the conditions in which the lock happens: is it easy to get one, or do you have to take some specific steps?

Ok so I started my local machine and it always takes a while before the wifi connection is established. So Firefox showed 'Connecting to pyamf.org…' while it was waiting for the wifi to properly connect to the network. This took about 30 secs and once it was done it showed the trac site with the OperationalError. It's probably unrelated but I don't have any other steps/info that can trigger this error I'm afraid.

[Christian Boos]

Replying to anonymous:

Replying to cboos:

Thanks for the report. Can you also please attach the trac.log?

Here's the relevant part of the trac.log:

Maybe also the trac.ini and the list of plugins you're using…

Can I email you this, I'm not comfortable posting that info here tbh.

No problem (see TracTeam for the e-mail) and then also please the full trac.log, as the "Cannot operate on a closed cursor" looks suspicious and maybe predates the "database is locked" error.

Is the problem reproducible without plugins as well?

I'm not sure how to test this since it's a ​live site and disabling the plugins will damage the functionality of our site.

Easy: simply cp -a pyamf-trac-env test-pyamf-trac and use tracd to serve that second test environment, on some 8xxx port for example. Once you reproduce the lock there, start turning off plugins.

[Thijs Triemstra <lists@…>]

I emailed you the trac log and config files. I'll see if I can reproduce it in a local test environment as you suggested.

[Christian Boos]

Replying to Thijs Triemstra <lists@…>:

I emailed you the trac log and config files.

In fact this didn't help me much, I was not able to see what could have caused the issue.

I'll see if I can reproduce it in a local test environment as you suggested.

Yes, this is really needed in order to get any progress on this.

[reggiebigmonkey@…]

Looks like some timeline-related plugins can cause this error, has seen in these two trac-hacks tickets: ​http://trac-hacks.org/ticket/6302 and ​http://trac-hacks.org/ticket/6341

If someone can point out what is wrong in that code, I'll patch it (and test it):

# Created by Noah Kantrowitz on 2008-05-16.
# Copyright (c) 2008 Noah Kantrowitz. All rights reserved.
import itertools
import re


from trac.core import *
from trac.web.api import ITemplateStreamFilter
from trac.web.chrome import ITemplateProvider, add_stylesheet
from trac.config import Option, OrderedExtensionsOption
from genshi.builder import tag
from genshi.filters.transform import Transformer
from pkg_resources import resource_filename

from hackergotchi.api import IHackergotchiProvider

class HackergotchiModule(Component):
    """A stream filter to add hackergotchi emblems to the timeline."""

    providers = OrderedExtensionsOption('hackergotchi', 'providers', 
                                        IHackergotchiProvider,
                                        default='GravatarHackergotchiProvider, IdenticonHackergotchiProvider')

    implements(ITemplateStreamFilter, ITemplateProvider)
    
    anon_re = re.compile('([^<]+?)\s+<([^>]+)>', re.U)
    
    # ITemplateStreamFilter methods
    def filter_stream(self, req, method, filename, stream, data):
        if req.path_info.startswith('/timeline'):
            closure_state = [0]
            db = self.env.get_db_cnx()
            cursor = db.cursor()
            cache = {}
            def f(stream):
                # Update the closed value
                n = closure_state[0]
                closure_state[0] += 1
                
                # Extract the user information
                author = data['events'][n]['author'].strip()
                user_info = cache.get(author)
                if user_info is not None:
                    author, name, email = user_info
                else:
                    user_info = self._get_info(author, cursor)
                    cache[author] = user_info
                    author, name, email = user_info
                
                # Try to find a provider
                for provider in self.providers:
                    href = provider.get_hackergotchi(req.href, author, name, email)
                    if href is not None:
                        break
                else:
                    href = req.href.chrome('hackergotchi', 'default.png')
                
                # Build our element
                elm = tag.img(src=href, alt='Hackergotchi for %s'%author, 
                              class_='hackergotchi') 
                
                # Output the combined stream
                return itertools.chain(elm.generate(), stream)
            
            stream |= Transformer('//div[@id="content"]/dl/dt/a/span[@class="time"]').filter(f)
            add_stylesheet(req, 'hackergotchi/hackergotchi.css')
        return stream

I think it's crashing on "self.env.get_db_cnx()" or on "cursor = db.cursor()" but hey, I am no guru.

[Thijs Triemstra <lists@…>]

It's still happening, thought I'd post a traceback cause I noticed a reference to the accountmanager plugin and trac-stable0.11 r9132

Traceback (most recent call last):
  File "/usr/local/src/trac-0.11stable/trac/web/api.py", line 377, in send_error
    'text/html')
  File "/usr/local/src/trac-0.11stable/trac/web/chrome.py", line 733, in render_template
    message = req.session.pop('chrome.%s.%d' % (type_, i))
  File "/usr/local/src/trac-0.11stable/trac/web/api.py", line 195, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 265, in _get_session
    return Session(self.env, req)
  File "/usr/local/src/trac-0.11stable/trac/web/session.py", line 149, in __init__
    if req.authname == 'anonymous':
  File "/usr/local/src/trac-0.11stable/trac/web/api.py", line 195, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/local/src/trac-0.11stable/trac/web/main.py", line 134, in authenticate
    authname = authenticator.authenticate(req)
  File "/usr/src/trac-plugins/accountmanagerplugin/acct_mgr/web_ui.py", line 430, in wrap
    return func(self, *args, **kwds)
  File "/usr/src/trac-plugins/accountmanagerplugin/acct_mgr/web_ui.py", line 441, in authenticate
    return auth.LoginModule.authenticate(self, req)
  File "/usr/local/src/trac-0.11stable/trac/web/auth.py", line 70, in authenticate
    authname = self._get_name_for_cookie(req, req.incookie['trac_auth'])
  File "/usr/local/src/trac-0.11stable/trac/web/auth.py", line 189, in _get_name_for_cookie
    (cookie.value, req.remote_addr))
  File "/usr/local/src/trac-0.11stable/trac/db/util.py", line 64, in execute
    return self.cursor.execute(sql_escape_percent(sql), args)
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 80, in execute
    result = PyFormatCursor.execute(self, *args)
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 59, in execute
    args or [])
  File "/usr/local/src/trac-0.11stable/trac/db/sqlite_backend.py", line 51, in _rollback_on_error
    return function(self, *args, **kwargs)
OperationalError: database is locked

[Thijs Triemstra <lists@…>]

Btw, that last traceback was displayed as plain text in the browser, no trac site skin, which I'd normally see. More tracebacks from the Trac log are attached, hth.

[Christian Boos]

Replying to reggiebigmonkey@…:

...
            db = self.env.get_db_cnx()
            cursor = db.cursor()
            cache = {}
            def f(stream):
                ...
                    user_info = self._get_info(author, cursor)
            ...
            stream |=  ... .filter(f)
        return stream

Here, the db will be garbage collected long before the cursor itself will be used, hence likely ProgrammingError: Cannot operate on a closed cursor. Keeping the db itself inside the filter would also be bad, as this will prevent sharing the same db across requests. Better instantiate the db in the filter f when needed, as retrieving the extra information about the authors beforehand would be too expensive I suppose.

Still, the initial question remains: can this be triggered without plugins?

Deferring to some later milestone.

[Christian Boos]

Got one, this morning:

2010-03-02 10:23:00,746 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 499, in _dispatch_request
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 255, in dispatch
  File "build/bdist.linux-x86_64/egg/trac/web/session.py", line 88, in save
  File "build/bdist.linux-x86_64/egg/trac/db/util.py", line 37, in transaction_wrapper
OperationalError: database is locked

Python 2.4.4, SQLite 3.6.20, pysqlite 2.5.6.

Looking back in the log, there was another one on 2010-02-22, and before tha, on 2009-06-05.

Oh well, I suppose this simply can still happen, only very seldom now.

[Christian Boos]

Follow-up to comment:9:

Here, the db will be garbage collected long before the cursor itself will be used,

Precision: this happens because db is nowhere used within f(). Python doesn't need to and therefore won't keep a reference to db in the closure for f.

>>> class A(object):
...   def __del__(self): print 'collected!'
...
>>> def g():
...   a = A()
...   def f():
...     print 'do it!'
...   return f
...
>>> g()()
collected!
do it!

[reggiebigmonkey@…]

Follow-up to comment:9 and comment:11 by cbos:

You were right about this.

Like you said, better instantiate the db in the filter f when needed…

In the end, the original creator of that plugin created a ​small patch, doing pretting much exactly what you said (fetching a db/context/cursor but only when necessary).

Thanks for your help!

-Reggie

[Carsten Klein <carsten.klein@…>]

@with_transaction on f anyone?

[mrelbe <mikael@…>]

I am not sure if this is related… I am currently using Trac 0.12dev-r9444 with mod_wsgi 3.0 and no plugin activated (just for this note, details provided below).

The only error I am currently seeing is exactly the same as reported by the OP but only when viewing tickets, and only intermittently.

This note is a wild shot from me, since I cannot provide much details, and I cannot see any pattern except from that this seem to happen every now and then when viewing tickets.

The error can happen when a ticket is opened, or during live-preview of ticket comments being edited (edit the comment, wait 2 secs and the error log is sometimes updated in sync with the preview), or when a ticket comment is submitted. But I cannot repeat the error with certainty, sometimes no error occurs, sometimes it does…

From Apache error log we have this typical info (stripped):

mod_wsgi (pid=1572): Exception occurred processing WSGI script 'C:/Program/Apache Software Foundation/Apache2.2/cgi-bin/trac.wsgi'., referer: http://<domain>/ticket/37
Traceback (most recent call last):, referer: http://<domain>/ticket/37
  File "build\\bdist.win32\\egg\\trac\\web\\main.py", line 478, in dispatch_request, referer: http://<domain>/ticket/37
    return _dispatch_request(req, env, env_error), referer: http://<domain>/ticket/37
  File "build\\bdist.win32\\egg\\trac\\web\\main.py", line 594, in _dispatch_request, referer: http://<domain>/ticket/37
    req.send_error(exc_info, status=500, env=env, data=data), referer: http://<domain>/ticket/37
  File "build\\bdist.win32\\egg\\trac\\web\\api.py", line 458, in send_error, referer: http://<domain>/ticket/37
    exc_info), referer: http://<domain>/ticket/37
  File "build\\bdist.win32\\egg\\trac\\web\\main.py", line 510, in _dispatch_request, referer: http://<domain>/ticket/37
    dispatcher.dispatch(req), referer: http://<domain>/ticket/37
  File "build\\bdist.win32\\egg\\trac\\web\\main.py", line 256, in dispatch, referer: http://<domain>/ticket/37
    req.send(output, content_type or 'text/html'), referer: http://<domain>/ticket/37
  File "build\\bdist.win32\\egg\\trac\\web\\api.py", line 412, in send, referer: http://<domain>/ticket/37
    self.write(content), referer: http://<domain>/ticket/37
  File "build\\bdist.win32\\egg\\trac\\web\\api.py", line 532, in write, referer: http://<domain>/ticket/37
    self._write(data), referer: http://<domain>/ticket/37
IOError: failed to write data, referer: http://<domain>/ticket/37

This looks to be equivalent to the error log provided by the OP.

Here is the corresponding Trac log:

2010-04-08 12:14:54,578 Trac[main] DEBUG: Dispatching <Request "GET '/search'">
2010-04-08 12:14:54,578 Trac[session] DEBUG: Retrieving session for ID 'mikael'
2010-04-08 12:14:54,578 Trac[main] DEBUG: Negociated locale: [u'en-GB'] -> en_GB
2010-04-08 12:14:54,687 Trac[main] DEBUG: Dispatching <Request "GET '/ticket/37'">
2010-04-08 12:14:54,687 Trac[session] DEBUG: Retrieving session for ID 'mikael'
2010-04-08 12:14:54,687 Trac[main] DEBUG: Negociated locale: [u'en-GB'] -> en_GB
2010-04-08 12:14:54,765 Trac[default_workflow] DEBUG: render_ticket_action_control: action "leave"
2010-04-08 12:14:54,765 Trac[default_workflow] DEBUG: render_ticket_action_control: action "suspend"
2010-04-08 12:14:54,765 Trac[default_workflow] DEBUG: render_ticket_action_control: action "setowner"
2010-04-08 12:14:54,765 Trac[default_workflow] DEBUG: render_ticket_action_control: action "revert"
2010-04-08 12:14:54,765 Trac[default_workflow] DEBUG: render_ticket_action_control: action "close"
2010-04-08 12:14:54,765 Trac[chrome] DEBUG: Prepare chrome data for request
2010-04-08 12:14:56,217 Trac[main] DEBUG: Dispatching <Request "GET '/ticket/38'">
2010-04-08 12:14:56,217 Trac[session] DEBUG: Retrieving session for ID 'mikael'
2010-04-08 12:14:56,233 Trac[main] DEBUG: Negociated locale: [u'en-GB'] -> en_GB
2010-04-08 12:14:56,312 Trac[default_workflow] DEBUG: render_ticket_action_control: action "leave"
2010-04-08 12:14:56,312 Trac[default_workflow] DEBUG: render_ticket_action_control: action "revert"
2010-04-08 12:14:56,312 Trac[chrome] DEBUG: Prepare chrome data for request
2010-04-08 12:14:56,640 Trac[formatter] DEBUG: Executing Wiki macro Image by provider <trac.wiki.macros.ImageMacro object at 0x07A88D30>
2010-04-08 12:14:56,640 Trac[formatter] DEBUG: Executing Wiki macro Image by provider <trac.wiki.macros.ImageMacro object at 0x07A88D30>
2010-04-08 12:14:56,750 Trac[formatter] DEBUG: Executing Wiki macro Image by provider <trac.wiki.macros.ImageMacro object at 0x07A88D30>
2010-04-08 12:14:56,765 Trac[formatter] DEBUG: Executing Wiki macro Image by provider <trac.wiki.macros.ImageMacro object at 0x07A88D30>
2010-04-08 12:14:57,030 Trac[main] ERROR: Internal Server Error: 
Traceback (most recent call last):
  File "build\bdist.win32\egg\trac\web\main.py", line 510, in _dispatch_request
    dispatcher.dispatch(req)
  File "build\bdist.win32\egg\trac\web\main.py", line 256, in dispatch
    req.send(output, content_type or 'text/html')
  File "build\bdist.win32\egg\trac\web\api.py", line 412, in send
    self.write(content)
  File "build\bdist.win32\egg\trac\web\api.py", line 532, in write
    self._write(data)
IOError: failed to write data

Comment: The ticket does not contain attached images!

However, there is no visual clue to the problem, the ticket web page is presented just fine! (That's why I am not sure if this note is related to the OT or not, since I don't get a "Database Locked Error" warning. I guess it is related to mod_wsgi 3.0?)

Anyway, here follows some details about my setup. I hope this is to some help (at least I got to practice the new wiki table formatting — thanks to cboos for that awesome format).

System Information

Trac	0.12dev-r9444
Babel	0.9.5
Docutils	0.6
Genshi	0.6dev-r1096
mod_wsgi	3.0 (WSGIProcessGroup WSGIApplicationGroup proj.relbe.se|/trac)
Pygments	1.3.1
pysqlite	2.4.1
Python	2.6.5 (r265:79096, Mar 19 2010, 21:48:26) [MSC v.1500 32 bit (Intel)]
pytz	2010g
setuptools	0.6c11
SQLite	3.5.9
Subversion	1.6.6 (r40053)
jQuery	1.4.2

Installed Plugins

All plugins are de-activated, but listed here for completeness.

footnotemacro	1.02
graphviz	0.7.5
tracaccountmanager	0.2.1dev-r234 (patched by me, inactivated here)
tracextracturl	0.2.7032
trachtgroupeditorplugin	2.0
tracincludemacro	2.1-eis-1.0 (patched by me, inactivated here)
tracmindmapmacro	0.3.7097
tracnewsflash	1.0.1
tracsubversionlocation	1.0.1
tracsvnauthz	0.11.1.1
tracwysiwyg	0.2-r7949

Configuration

Someone asked for configuration settings, so I'll provide some of these as well:

Section	Name	Value
browser	render_unsafe_content	true
query	default_anonymous_query	status!=closed&cc~=$USER
	default_query	status!=closed&owner=$USER
	items_per_page	100
	ticketlink_query	?status=!closed
report	items_per_page	100
	items_per_page_rss	0
sqlite	extensions
ticket	default_cc
	default_component	other
	default_description
	default_keywords
	default_milestone	todo
	default_owner
	default_priority	major
	default_resolution	fixed
	default_severity
	default_summary
	default_type	task
	default_version
	max_comment_size	262144
	max_description_size	262144
	preserve_newlines	yes
	restrict_owner	false
	workflow	ConfigurableTicketWorkflow
ticket-custom	changesets	text
	changesets.format	wiki
	changesets.label	Changesets
	changesets.order	3
	changesets.value
	references	text
	references.format	wiki
	references.label	References
	references.order	1
	references.value
	review	select
	review.label	Peer-review
	review.options	…
	review.order	5
	review.value
	timeactual	text
	timeactual.label	Time Actual
	timeactual.order	4
	timeactual.value
	timeestimate	text
	timeestimate.label	Time Estimate
	timeestimate.order	0
	timeestimate.value
	timeremaining	text
	timeremaining.label	Time Remaining
	timeremaining.order	2
	timeremaining.value
ticket-workflow	close	new,started,suspended → closed
	close.operations	set_resolution
	close.permissions	TICKET_MODIFY
	leave	* → *
	leave.default	1
	leave.operations	leave_status
	restart	suspended → started
	restart.permissions	TICKET_MODIFY
	revert	started,suspended,closed → new
	revert.operations	del_resolution,del_owner
	revert.permissions	TICKET_MODIFY
	setowner	new,started,suspended → *
	setowner.name	set owner
	setowner.operations	set_owner
	setowner.permissions	TICKET_MODIFY
	start	new → started
	start.operations	set_owner
	start.permissions	TICKET_MODIFY
	suspend	started → suspended
	suspend.permissions	TICKET_MODIFY
trac	auth_cookie_lifetime	0
	auth_cookie_path
	auto_preview_timeout	2
	database	sqlite:db/trac.db
	debug_sql	false
	default_charset	iso-8859-15
	default_timezone
	genshi_cache_size	128
	request_filters
	resizable_textareas	true
	secure_cookies	true
	timeout	20
	use_base_url_for_redirect	false
wiki	render_unsafe_content	true

[Remy Blank]

#9373 was closed as a duplicate.

[edgewall.p3u@…]

Confirmed as it also happens on our server.

[HeX <edgewall.p3u@…>]

Found out that a Google bot was causing the database lockup in our case. So unsubscribing.

[Christian Boos]

Ok, trying to summarize:

• comment:9 traces the problem to a misuse of our db API, fixing this (comment:12) solves the original issue
• however, Mikael reported a similar issue in comment:14, without plugins. That was on 0.12dev though, so it might be the case that we did a similar mistake in Trac core, at that time (?). So what's the current status, does that still happen?

[Mikael Relbe]

Replying to cboos:

Ok, trying to summarize:

• comment:9 traces the problem to a misuse of our db API, fixing this (comment:12) solves the original issue
• however, Mikael reported a similar issue in comment:14, without plugins. That was on 0.12dev though, so it might be the case that we did a similar mistake in Trac core, at that time (?). So what's the current status, does that still happen?

I still occasionally see errors in my logs that happens when rendering tickets, here's an example with 0.13dev r10218 (without any plugin) using mod_wsgi and Apache:

Trac log-file:

2010-10-11 19:30:27,905 Trac[main] DEBUG: Dispatching <Request "GET '/ticket/3'">
2010-10-11 19:30:27,921 Trac[session] DEBUG: Retrieving session for ID 'mikael'
2010-10-11 19:30:27,937 Trac[main] DEBUG: Negotiated locale: None -> en_US
2010-10-11 19:30:28,030 Trac[default_workflow] DEBUG: /.../
2010-10-11 19:30:28,062 Trac[chrome] DEBUG: Prepare chrome data for request
2010-10-11 19:30:28,546 Trac[main] ERROR: Internal Server Error: 
Traceback (most recent call last):
  File "build\bdist.win32\egg\trac\web\main.py", line 511, in _dispatch_request
    dispatcher.dispatch(req)
  File "build\bdist.win32\egg\trac\web\main.py", line 261, in dispatch
    req.send(output, content_type or 'text/html')
  File "build\bdist.win32\egg\trac\web\api.py", line 413, in send
    self.write(content)
  File "build\bdist.win32\egg\trac\web\api.py", line 533, in write
    self._write(data)
IOError: failed to write data

However, this seem to happen only when I stress the requests, i.e. intensively pressing the 'Next Ticket' link from within a ticket query. No errors are logged if I allow the web page to be received and rendered by my browser, before pressing 'Next Ticket'.

But this does not seem to be an issue when using tracd…

[Remy Blank]

Doesn't the error "IOError: failed to write data" just mean that the client has closed the connection to the web server? How is this related to the database issue (other than a secondary symptom)?

[Mikael Relbe]

Replying to rblank:

Doesn't the error "IOError: failed to write data" just mean that the client has closed the connection to the web server?

Oh, of course. (From memory I recall that the remark in comment:14 happened very often, which is not the case any more.)

How is this related to the database issue (other than a secondary symptom)?

Probably not then, sorry for the noise.

[Christian Boos]

Well, as long as we have internal errors in the log, it's not noise, it's something we have to fix ;-)

So for the IOError, it really looks like it's something that can happen if mod_wsgi can't write back to the client due to some unspecified reasons (Graham, ​here and ​there). A proper disconnect is already trapped (#3819), maybe we should catch this form as well.

---

Thijs, is the problem fixed on your side (regarding the db errors)?

[alexander.papaspyrou@…]

I am also getting this problem, using quite recent versions (over apache2 and mod_python):

[ ~ ]
alexp@forge:0<!534,j0>$ dpkg -l | grep trac
ii  trac  0.11.7-1  Enhanced wiki and issue tracking system for 

[ ~ ]
alexp@forge:0<!535,j0>$ cat /etc/lsb-release 
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=10.04
DISTRIB_CODENAME=lucid
DISTRIB_DESCRIPTION="Ubuntu 10.04.1 LTS"

and

Python 2.6.5 (r265:79063, Apr 16 2010, 13:09:56) 
[GCC 4.4.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import trac.db.sqlite_backend as test
>>> test._ver
(3, 6, 22)
>>> test.have_pysqlite
2
>>> test.sqlite.version
'2.5.5'

Accessing the login page constantly (even over apache2 restarts)

Traceback (most recent call last):
  File "/usr/lib/python2.6/dist-packages/trac/web/api.py", line 376, in send_error
    'text/html')
  File "/usr/lib/python2.6/dist-packages/trac/web/chrome.py", line 733, in render_template
    message = req.session.pop('chrome.%s.%d' % (type_, i))
  File "/usr/lib/python2.6/dist-packages/trac/web/api.py", line 195, in __getattr__
    value = self.callbacks[name](self)
  File "/usr/lib/python2.6/dist-packages/trac/web/main.py", line 265, in _get_session
    return Session(self.env, req)
  File "/usr/lib/python2.6/dist-packages/trac/web/session.py", line 161, in __init__
    self.promote_session(sid)
  File "/usr/lib/python2.6/dist-packages/trac/web/session.py", line 248, in promote_session
    db.commit()
OperationalError: database is locked

Same in the logs. The only thing that comes up to my mind is that the trac environments live on an NFS share…

Thoughts? -Alexander ps. Sorry for ticketing this to #3503 (wrong place) as well; my mistake.

[Christian Boos]

Replying to alexander.papaspyrou@…:

… Accessing the login page constantly (even over apache2 restarts) …

This suggests something is keeping a lock? Can you open your trac.db with sqlite3 and attempt to modify the database (e.g.

insert into system values ('test123', '123')

). If this fails, one process must be stuck with a read or write lock. Try running lsof on the trac.db file.

… The only thing that comes up to my mind is that the trac environments live on an NFS share…

Of course, you also have to take the usual caveats about SQLite and NFS into account (e.g. ​http://www.sqlite.org/faq.html#q5), i.e. don't do this ;-)

[fbrettschneider@…]

Since Trac-1.0.0 I use WSGI, and I also often see such IOError: failed to write data like mentioned above in my logging now.

Searching the internet recommends to ​fix it this way.

[fbrettschneider@…]

This ticket is quite related to #10879 because usually when I have such slow performance like described there I also see those "IOError: failed to write data" logging. So creating 100 milestones (including some graphical charts) and clicking on Roadmap triggers the problem.

[Ryan J Ollos]

Moved ticket assigned to next-stable-1.0.x since maintenance of 1.0.x is coming to a close. Please move the ticket back if it's critical to fix on 1.0.x.

[Ryan J Ollos]

Milestone renamed