SQL logic error or missing database when database seems fine

[dangoor+trac@…]

This is in the TurboGears? trac http://trac.turbogears.org/

When trying to view the timeline or create a new ticket, the following exception appears:

17:42:52 Trac[__init__] DEBUG: Updating wiki page index
17:42:52 Trac[__init__] DEBUG: Opening subversion file-system at /home/kevin/svn
/turbogears with scope /
17:42:52 Trac[__init__] DEBUG: Checking whether sync with repository is needed
17:42:52 Trac[__init__] INFO: Syncing with repository (511 to 513)
17:42:52 Trac[__init__] ERROR: SQL logic error or missing database
Traceback (most recent call last):
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/web/standalone.p
y", line 303, in _do_trac_req
    dispatch_request(path_info, req, env)
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/web/main.py", li
ne 139, in dispatch_request
    dispatcher.dispatch(req)
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/web/main.py", line 107, in dispatch
    resp = chosen_handler.process_request(req)
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/Timeline.py", li
ne 139, in process_request
    filters)
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/versioncontrol/w
eb_ui/changeset.py", line 116, in get_timeline_events
    chgset = repos.get_changeset(rev)
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/versioncontrol/c
ache.py", line 42, in get_changeset
    self.sync()
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/versioncontrol/c
ache.py", line 84, in sync
    "VALUES (%s,%s,%s,%s)", (str(current_rev),
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/db.py", line 219
, in execute
    args or [])
  File "/usr/home/kevin/lib/python2.4/trac-0.9.3-py2.4.egg/trac/db.py", line 211
, in _rollback_on_error
    return function(self, *args, **kwargs)
OperationalError: SQL logic error or missing database
17:42:52 Trac[__init__] DEBUG: Closing subversion file-system at /home/kevin/svn
/turbogears

The database looks fine when I open it with sqlite3. The log message implies that something may be throwing it off between r511 and r513 in the repository.

[cboos]

Can you try to resync using TracAdmin?

But first make a backup copy of your DB, in case the resync solves the problem. It might be interesting to take a second look at the original DB to figure out what was wrong there.

Also, what is your PySqlite version?

[cboos]

Ok, wait, I see, you have the error for any attempt to update the DB, so this has nothing to do with the resync.

Is it possible that some SQL process has a lock on the $TRAC_ENV/db/trac.db file? (there would be a $TRAC_ENV/db/trac.db-journal file)

Or even ... do you have setup appropiate write permission on the trac.db file?

[dangoor+trac@…]

I don't see a journal file, and I do have write permission:

ls -l

total 12272 -rw-r--r-- 1 kevin kevin 4311040 Jan 13 16:37 trac.db -rw-r--r-- 1 kevin kevin 4087808 Dec 2 12:15 trac.db.7.bak -rw-r--r-- 1 kevin kevin 4090880 Dec 2 16:33 trac2.db

(I'm running tracd as myself)

It looks like I'm running pysqlite 2.0.5

[cboos]

Ok, and if you use the sqlite3 command line tool, are you able to modify the database?

[dangoor+trac@…]

Yes.

sqlite> select * from ticket where id=394;
394|enhancement|1137152351|1137152364|TurboGears|normal|normal|anonymous|kevin||0.8|0.9|new||Bundle eggs together for offline install||
sqlite> update ticket set version="0.9" where id=394;

[dangoor+trac@…]

err, add the following line to the above sample:

sqlite> select * from ticket where id=394;
394|enhancement|1137152351|1137152364|TurboGears|normal|normal|anonymous|kevin||0.9|0.9|new||Bundle eggs together for offline install||

[cboos]

What output does the following script produce?

import pysqlite2.dbapi2 as sqlite

def main(filename):
    cnx = sqlite.connect(filename, check_same_thread=True)
    cnx.cursor().execute("update ticket set version='0.8' where id=394")
    cnx.close()

if __name__ == '__main__':
    try:
        main(sys.argv[1])
        print "Checked db write: OK"
    except:
        print "Checked db write: FAILED"

[cboos]

Also, does the error still occur if you disable multithreading in tracd?

trac/web/standalone.py

@@ -189 +189 @@
         return auth['username']
 
 
-class TracHTTPServer(ThreadingMixIn, HTTPServer):
+class TracHTTPServer(HTTPServer):
 
     projects = None
 

[dangoor+trac@…]

after adding an import sys:

> bin/python test.py trac/turbogears/db/trac.db
Checked db write: OK

I'll check the threading.

[Kevin Dangoor <dangoor+trac@…>]

No difference after removing the ThreadingMixIn?.

I should note that this particular error just started today. We've been running Trac 0.9.x since early December (and Trac 0.8.x before that).

[cboos]

Well, that's weird. I'm a bit clueless at this point... Anything unusual/patched in your installation? SQLite version, Python version?

Also, you've repackaged Trac as an egg... could that be the difference? Can you attach the diff of your changes so that we could try to reproduce your setup?

[Kevin Dangoor <dangoor+trac@…>]

I actually didn't make any changes to Trac itself. I just ran easy_install after expanding the tarball. This is python 2.4.1. sqlite version 3.2.2.

This might be relevant... here is the comment from r513: r513 | ronald | 2006-01-13 11:05:20 -0500 (Fri, 13 Jan 2006) | 2 lines

Replace extraneous character that sneadked it's way instead of a space character.

I'm not sure what the character in question is. Could an odd character appearing in a diff cause a problem?

[cboos]

I don't think so... the same error appears whenever you try to save something in the DB (e.g. modify a wiki page). This should have nothing to do with the SVN cache.

[Kevin Dangoor <dangoor+trac@…>]

I could be wrong, but it *looked* like these failed requests all had this in the log:

18:07:45 Trac[__init__] DEBUG: Checking whether sync with repository is needed
18:07:45 Trac[__init__] INFO: Syncing with repository (511 to 513)
18:07:45 Trac[__init__] ERROR: SQL logic error or missing database

[Kevin Dangoor <dangoor+trac@…>]

Nope... you're right. trying to create a new ticket doesn't try to sync. (which makes sense.)

[Kevin Dangoor <dangoor+trac@…>]

If it would help, I could gzip and send you my database file. it's an open source project, so it's not like I have secrets locked away in the Trac ;)

[Kevin Dangoor <dangoor+trac@…>]

OK... here's a clue. someone on the turbogears mailing list just pointed out that we can view the timeline if repository checkins are turned off: timeline view without repository

[cboos]

I wouldn't mind to get your trac.db, hopefully this would help... In this case, please also include your trac.ini in the zip!

Another idea: as you're running on linux, it should be possible to run trac using strace or ltrace... That would maybe deliver additional hints about possible permissions issues...

You did run the Python script inlined above using the same user as the one running tracd, right?

Also, have you checked the permission of the trac/db directory itself?

[Kevin Dangoor <dangoor+trac@…>]

I did run that script as the same user as tracd (in fact, everything I do runs as the same user, because this is a shared server that I don't control!). I did also check the db directory's permissions. All of the permissions look fine.

I will attach my trac database file (with the ini included)

[Kevin Dangoor <dangoor+trac@…>]

The file was too big to upload here. So, I have temporarily put it here:

http://www.turbogears.org/tracfiles.tgz

[cboos]

Good news: I'm able to reproduce the error locally, using your trac.db

[cboos]

Trying to reproduce by hand a query that failed within Trac:

$ sqlite3 trac.db
SQLite version 3.2.8
Enter ".help" for instructions
sqlite> INSERT INTO WIKI (name,version,time,author,ipnr,text,comment,readonly) VALUES ('ApacheIntegration', 4, 1137403141.5150001, 'cboos', '127.0.0.1', '', '', 0);
SQL error: database disk image is malformed
sqlite>

[cboos]

Not sure how you got there, but the problem was a corrupted trac.db. Here's what you should do to recover the situation:

$ mv trac.db trac.db.damaged
$ sqlite3 trac.db.damaged .dump | sqlite3 trac.db

... and make sure you're using SQLite 3.2.8 (compiled with --enable-multithread, check the PySqlite page).

[Kevin Dangoor <dangoor+trac@…>]

Great! Thanks for tracking that down! I'll think about compiling my own sqlite so that I can up it to 3.2.8 right away.

[zaphodb@…]

I just had my trac.db corrupted too, lighttpd+fastcgi - no clue how that happened but i was unable to restore with the method above. I am now hoping on our backup. Anyway no big loss just some internal tickets. ;)

[cboos]

Replying to zaphodb@zaphods.net:

I just had my trac.db corrupted too, lighttpd+fastcgi - no clue how that happened but i was unable to restore with the method above

Can you mention the versions you had for pysqlite and sqlite?

[zaphodb@…]

I did a debian dist-upgrade while debugging before i stumbled over this ticket, but the versions are in the dpkg.log: I _did_ not have an sqlite3 binary installed. 2007-03-07 13:30:37 upgrade libsqlite3-0 3.3.8-1 3.3.8-1.1 2007-03-07 13:30:54 upgrade python-pysqlite2 2.3.2-2 2.3.3-1

^before

after

luckily i was able to squeeze a backup out of my hat: coax:~# cmp -b /home/trac/db/trac.db.damaged /tmp/trac.db /home/trac/db/trac.db.damaged /tmp/trac.db differ: byte 28, line 1 is 211 M-^{I 207 M-}G coax:~# file /home/trac/db/trac.db.damaged /tmp/trac.db /home/trac/db/trac.db.damaged: SQLite database (Version 3) /tmp/trac.db: SQLite database (Version 3) coax:~# sqlite3 /home/trac/db/trac.db.damaged .dump | wc

3879 22607 167945

coax:~# sqlite3 /tmp/trac.db .dump | wc

4820 29294 238326

The secone one is the sane database from backup.

[zaphodb@…]

sorry, should have put that in {'s i guess

[cboos]

Copy of zaphodb@zaphods.net:

I did a debian dist-upgrade while debugging before i stumbled over this ticket, but the versions are in the dpkg.log:
I _did_ not have an sqlite3 binary installed.
2007-03-07 13:30:37 upgrade libsqlite3-0 3.3.8-1 3.3.8-1.1
2007-03-07 13:30:54 upgrade python-pysqlite2 2.3.2-2 2.3.3-1
                                             ^^^^^^^before
                                                      ^^^^^^after
luckily i was able to squeeze a backup out of my hat:
coax:~# cmp -b /home/trac/db/trac.db.damaged /tmp/trac.db
/home/trac/db/trac.db.damaged /tmp/trac.db differ: byte 28, line 1 is 211 M-^I 207 M-^G
coax:~# file /home/trac/db/trac.db.damaged /tmp/trac.db
/home/trac/db/trac.db.damaged: SQLite database (Version 3)
/tmp/trac.db:                  SQLite database (Version 3)
coax:~# sqlite3 /home/trac/db/trac.db.damaged .dump | wc
   3879   22607  167945
coax:~# sqlite3 /tmp/trac.db .dump | wc
   4820   29294  238326

The secone one is the sane database from backup.