Edgewall Software
Modify

Opened 8 years ago

Last modified 12 months ago

#8708 new defect

Operational Error: database is locked

Reported by: Thijs Triemstra <lists@…> Owned by:
Priority: normal Milestone: next-stable-1.2.x
Component: database backend Version: 0.11-stable
Severity: major Keywords: database lock pysqlite
Cc: lists@…, mikael@…, nulleke76@…, fbrettschneider@…
Release Notes:
API Changes:

Description

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.

Attachments (2)

db-locked.JPG (248.3 KB ) - added by Thijs Triemstra <lists@…> 8 years ago.
db-locked.log (9.2 KB ) - added by Thijs Triemstra <lists@…> 8 years ago.

Download all attachments as: .zip

Change History (34)

Changed 8 years ago by Thijs Triemstra <lists@…>

Attachment: db-locked.JPG added

comment:1 Changed 8 years ago by 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?

comment:2 in reply to:  1 ; Changed 8 years ago by anonymous

Cc: lists@… added

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.

comment:3 in reply to:  2 Changed 8 years ago by 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.

comment:4 Changed 8 years ago by 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.

comment:5 in reply to:  4 Changed 8 years ago by Christian Boos

Keywords: database lock pysqlite added
Milestone: 0.11.60.11.7

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.

comment:6 Changed 8 years ago by 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.

comment:7 Changed 8 years ago by 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

comment:8 Changed 8 years ago by 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.

Changed 8 years ago by Thijs Triemstra <lists@…>

Attachment: db-locked.log added

comment:9 in reply to:  6 ; Changed 8 years ago by Christian Boos

Milestone: 0.11.7next-minor-0.12.x

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.

comment:10 Changed 8 years ago by 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.

comment:11 in reply to:  9 ; Changed 8 years ago by 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!

comment:12 in reply to:  11 Changed 8 years ago by 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

comment:13 Changed 8 years ago by Carsten Klein <carsten.klein@…>

@with_transaction on f anyone?

comment:14 Changed 8 years ago by 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_contenttrue

query

default_anonymous_querystatus!=closed&cc~=$USER
default_querystatus!=closed&owner=$USER
items_per_page100
ticketlink_query?status=!closed

report

items_per_page100
items_per_page_rss0

sqlite

extensions

ticket

default_cc
default_componentother
default_description
default_keywords
default_milestonetodo
default_owner
default_prioritymajor
default_resolutionfixed
default_severity
default_summary
default_typetask
default_version
max_comment_size262144
max_description_size262144
preserve_newlinesyes
restrict_ownerfalse
workflowConfigurableTicketWorkflow

ticket-custom

changesetstext
changesets.formatwiki
changesets.labelChangesets
changesets.order3
changesets.value
referencestext
references.formatwiki
references.labelReferences
references.order1
references.value
reviewselect
review.labelPeer-review
review.options
review.order5
review.value
timeactualtext
timeactual.labelTime Actual
timeactual.order4
timeactual.value
timeestimatetext
timeestimate.labelTime Estimate
timeestimate.order0
timeestimate.value
timeremainingtext
timeremaining.labelTime Remaining
timeremaining.order2
timeremaining.value

ticket-workflow

closenew,started,suspended → closed
close.operationsset_resolution
close.permissionsTICKET_MODIFY
leave* → *
leave.default1
leave.operationsleave_status
restartsuspended → started
restart.permissionsTICKET_MODIFY
revertstarted,suspended,closed → new
revert.operationsdel_resolution,del_owner
revert.permissionsTICKET_MODIFY
setownernew,started,suspended → *
setowner.nameset owner
setowner.operationsset_owner
setowner.permissionsTICKET_MODIFY
startnew → started
start.operationsset_owner
start.permissionsTICKET_MODIFY
suspendstarted → suspended
suspend.permissionsTICKET_MODIFY

trac

auth_cookie_lifetime0
auth_cookie_path
auto_preview_timeout2
databasesqlite:db/trac.db
debug_sqlfalse
default_charsetiso-8859-15
default_timezone
genshi_cache_size128
request_filters
resizable_textareastrue
secure_cookiestrue
timeout20
use_base_url_for_redirectfalse

wiki

render_unsafe_contenttrue

comment:15 Changed 8 years ago by mrelbe <mikael@…>

Cc: mikael@… added

comment:16 Changed 8 years ago by Remy Blank

#9373 was closed as a duplicate.

comment:17 Changed 7 years ago by edgewall.p3u@…

Cc: edgewall.p3u@… added

Confirmed as it also happens on our server.

comment:18 Changed 7 years ago by nulleke76@…

Cc: nulleke76@… added

comment:19 Changed 7 years ago by HeX <edgewall.p3u@…>

Cc: edgewall.p3u@… removed

comment:20 Changed 7 years ago by HeX <edgewall.p3u@…>

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

comment:21 Changed 7 years ago by 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?

comment:22 in reply to:  21 Changed 7 years ago by 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

Last edited 7 years ago by Mikael Relbe (previous) (diff)

comment:23 Changed 7 years ago by 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)?

comment:24 in reply to:  23 Changed 7 years ago by 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.

comment:25 Changed 7 years ago by 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)?

comment:26 Changed 7 years ago by 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.

comment:27 in reply to:  26 Changed 7 years ago by 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 ;-)

comment:28 Changed 5 years ago by 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.

comment:29 Changed 5 years ago by fbrettschneider@…

Cc: fbrettschneider@… added

comment:30 Changed 5 years ago by 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.

comment:31 Changed 3 years ago by Ryan J Ollos

Milestone: next-minor-0.12.xnext-stable-1.0.x

comment:32 Changed 12 months ago by Ryan J Ollos

Milestone: next-stable-1.0.xnext-stable-1.2.x

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.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as new The ticket will remain with no owner.
The ticket will be disowned.
as The resolution will be set.
The owner will be changed from (none) to anonymous.

Add Comment


E-mail address and name can be saved in the Preferences .

 
Note: See TracTickets for help on using tickets.