"ProgrammingError: library routine called out of sequence" in _rollback_on_error()

[ErikRose]

This is rather like #2969, but the traceback bears no resemblance, and I'm not using mod_python, so I'm opening a new ticket.

On Debian Testing, using Apache 2.0.55, FastCGI, SQLite, and Trac 0.10.2, I intermittently get this traceback when loading the front wiki page (or doing anything, probably):

  File "/var/lib/python-support/python2.4/trac/web/main.py", line 387, in dispatch_request
    dispatcher.dispatch(req)
  File "/var/lib/python-support/python2.4/trac/web/main.py", line 190, in dispatch
    req.authname = self.authenticate(req)
  File "/var/lib/python-support/python2.4/trac/web/main.py", line 146, in authenticate
    authname = authenticator.authenticate(req)
  File "/var/lib/python-support/python2.4/trac/web/auth.py", line 69, in authenticate
    authname = self._get_name_for_cookie(req, req.incookie['trac_auth'])
  File "/var/lib/python-support/python2.4/trac/web/auth.py", line 179, in _get_name_for_cookie
    (cookie.value, req.remote_addr))
  File "/var/lib/python-support/python2.4/trac/db/util.py", line 50, in execute
    return self.cursor.execute(sql_escape_percent(sql), args)
  File "/var/lib/python-support/python2.4/trac/db/sqlite_backend.py", line 56, in execute
    args or [])
  File "/var/lib/python-support/python2.4/trac/db/sqlite_backend.py", line 48, in _rollback_on_error
    return function(self, *args, **kwargs)
ProgrammingError: library routine called out of sequence

Once the error occurs, it happens on every request until I restart Apache. Then things are fine for another week or so.

[Christian Boos]

What SQLite and PySqlite versions are you using? Has SQLite been built with the --enable-threadsafe configuration flag?

[ErikRose]

SQLite 3.3.8 and PySqlite 2.3.2. It looks to me like --enable-threadsafe is on, though it's not straightforward to tell; I have to dig into the Debian package, and there's a lot of indirection. There's a…

DEB_CONFIGURE_EXTRA_FLAGS = --with-tcl=/usr/lib/tcl8.4 --enable-threadsafe

that ends up in a "rules" file which I assume makes its way into the configuration somehow.

[Christian Boos]

Ok, so everything is clean on this side. Do you have some plugins installed? One of them is maybe leaving the connection in some invalid state…

But from ​SQLite:LibraryRoutineCalledOutOfSequence, I currently don't see what could go wrong.

Maybe an issue with the statement cache… You could try to disable that, I think, to see if this is enough to avoid the issue. Unfortunately it doesn't seem possible to disable that cache in Python, this has to be done at the C level, or by downgrading to a version which didn't have the cache (i.e. 2.0.7).

(moving the milestone to 0.10.4 as this shouldn't block the 0.10.3 release due soon)

[ErikRose]

My only plugin is TracWebAdmin-0.1.2dev_r4240. It's conceivable but unlikely that it's causing the error; the only way I can think of is that it's sticking a DB connection into a module global or something and then using it across different threads (stupid, weird). It beats me.

Anybody else using my setup (including TracWebAdmin) with no problems?

[ErikRose]

I haven't been keeping strict track, but this seems to happen every Monday morning, which could well be the first hit after the logs rotate. Curious. I'll start keeping track.

[ErikRose]

Nope, it didn't happen today.

[ErikRose]

Just had another occurrence. The traceback was a little different this time (I'm now on 0.10.3):

Python Traceback

Traceback (most recent call last):
  File "/var/lib/python-support/python2.4/trac/web/main.py", line 387, in dispatch_request
    dispatcher.dispatch(req)
  File "/var/lib/python-support/python2.4/trac/web/main.py", line 191, in dispatch
    chosen_handler = self._pre_process_request(req, chosen_handler)
  File "/var/lib/python-support/python2.4/trac/web/main.py", line 263, in _pre_process_request
    chosen_handler = f.pre_process_request(req, chosen_handler)
  File "/var/lib/python-support/python2.4/trac/versioncontrol/api.py", line 73, in pre_process_request
    self.get_repository(req.authname) # triggers a sync if applicable
  File "/var/lib/python-support/python2.4/trac/versioncontrol/api.py", line 101, in get_repository
    repos = self._connector.get_repository(rtype, rdir, authname)
  File "/var/lib/python-support/python2.4/trac/versioncontrol/svn_fs.py", line 260, in get_repository
    crepos = CachedRepository(self.env.get_db_cnx(), repos, None, self.log)
  File "/var/lib/python-support/python2.4/trac/versioncontrol/cache.py", line 34, in __init__
    self.sync()
  File "/var/lib/python-support/python2.4/trac/versioncontrol/cache.py", line 56, in sync
    cursor.execute("SELECT value FROM system WHERE name='repository_dir'")
  File "/var/lib/python-support/python2.4/trac/db/util.py", line 51, in execute
    return self.cursor.execute(sql)
  File "/var/lib/python-support/python2.4/trac/db/sqlite_backend.py", line 56, in execute
    args or [])
  File "/var/lib/python-support/python2.4/trac/db/sqlite_backend.py", line 48, in _rollback_on_error
    return function(self, *args, **kwargs)
ProgrammingError: library routine called out of sequence

[ErikRose]

And again, with the same traceback as directly above.

[Christian Boos]

Yes, I've seen your first post, but I'm really at loss as why this could happen… I'll try to set up a test instance on Linux with the same environment as you have. You already said that you've checked that SQLite was compiled in a thread-safe way, but have you tried with the connection pool disabled (i.e. either using 0.10.4dev or 0.10.3 with r4494)?

[Christian Boos]

I'm now also seeing this issue. However it looks like I can't trigger it with the connection pool disable (as explain in the above comment).

[Christian Boos]

… so it looks like r4494 fixed this issue as well.

[ErikRose]

Sorry I've been away awhile. I patched my copy of 0.10.3. Let's see what happens.

[erose]

So far, so good.