#2902 closed defect (fixed)
OperationalError: SQL logic error or missing database
| Reported by: | Alec Thomas | Owned by: | Christian Boos |
|---|---|---|---|
| Priority: | normal | Milestone: | 0.10.4 |
| Component: | general | Version: | devel |
| Severity: | major | Keywords: | pysqlite resync post-commit-hook |
| Cc: | Branch: | ||
| Release Notes: | |||
| API Changes: | |||
| Internal Changes: | |||
Description
I'm getting the following error very frequently on TracHacks:
Ticket changes, Ticket details event provider failed: OperationalError: SQL logic error or missing database
Unfortunately the only thing in the log is one line, although it always seems to occur immediately after a repo sync, as the previous line attests:
11:52:09 Trac[svn_fs] DEBUG: Closing subversion file-system at /srv/trac-hacks/svn 11:52:09 Trac[main] WARNING: 500 Internal Error (Wiki changes event provider failed:<br /><br />OperationalError: SQL logic error or missing database<p>You may want to see the other kind of events from the <a href="/timeline?format=rss&max=50&daysback=90&ticket=on&ticket_details=on&changeset=on">Timeline</a></p>) 11:52:29 Trac[api] DEBUG: Updating wiki page index
Attachments (0)
Change History (29)
comment:1 by , 19 years ago
comment:2 by , 19 years ago
I've performed the same action as was suggested in #2598, which I should have done before opening this ticket really. I'll close this if I don't see any more issues.
comment:5 by , 19 years ago
Okay, I've mailed you a link to the DB. As I mentioned before, this only appears to happen immediately after a commit, if that's any help.
comment:6 by , 19 years ago
I found this in the logs this morning:
12:17:08 Trac[session] DEBUG: Purging old, expired, sessions.
12:17:08 Trac[session] DEBUG: Adding variable name with value "Russ Brown" to session pickscrape
12:17:08 Trac[main] ERROR: SQL logic error or missing database
Traceback (most recent call last):
File "/usr/lib/python2.4/site-packages/trac/web/main.py", line 283, in dispatch_request
dispatcher.dispatch(req)
File "/usr/lib/python2.4/site-packages/trac/web/main.py", line 183, in dispatch
req.session.save()
File "/usr/lib/python2.4/site-packages/trac/web/session.py", line 158, in save
(self.sid, authenticated, k, v))
File "/usr/lib/python2.4/site-packages/trac/db/util.py", line 47, in execute
return self.cursor.execute(sql_escape_percent(sql), args)
File "/usr/lib/python2.4/site-packages/trac/db/sqlite_backend.py", line 39, in execute
args or [])
File "/usr/lib/python2.4/site-packages/trac/db/sqlite_backend.py", line 31, in _rollback_on_error
return function(self, *args, **kwargs)
OperationalError: SQL logic error or missing database
Not sure whether it's the same thing or not.
comment:7 by , 19 years ago
So far, I've not been able to reproduce the issue, using your db and svn repos, with the following setup: Trac trunk, Python 2.4.2 SQLite 3.3.4 and Pysqlite 2.1.3.
From some of your mails in the TracML, I know that you're
using sqlite3 3.3.4-1. Does that mean that you've not
recompiled SQLite by yourself? If so, maybe that prebuilt
version was not built using the --enable-threadsafe
configuration switch… That would explain the problems
you're seeing, which manifest themselves slightly differently
than they used to with SQLite 3.2.x (see #2170), but seem
to occur in the same circumstances.
So please check how your SQLite package was built, and if
unsure, rebuild it yourself using the --enable-threadsafe
configure option.
comment:9 by , 19 years ago
I came across this same error, which seems to be a generic (completely useless IMO) catch-all error, when creating the unit tests for Trac Tags. In that case, the unique constraint on a table was being violated because multiple ticket changes were being inserted for the same timestamp.
Perhaps something similar is happening here with duplicate session columns, or some other constraint violation.
Presumably if I switched to Postgres, I might get more useful errors that might help track this down.
comment:10 by , 19 years ago
| Keywords: | session added |
|---|
Perhaps something similar is happening here with duplicate session columns, or some other constraint violation.
Thanks for the insight! I did some search in the ticket db, and it seems we have still one ticket opened concerning constraint violations: #2570 (I'm not too familiar with the session code, though)
comment:11 by , 18 years ago
Does the problem still happen now that the session code has been improved?
comment:12 by , 18 years ago
| Resolution: | → fixed |
|---|---|
| Status: | new → closed |
Nope, I haven't seen this error for quite some time. I'll close it off.
comment:13 by , 18 years ago
| Milestone: | → 0.11 |
|---|---|
| Resolution: | fixed |
| Status: | closed → reopened |
This error seems to be related to r2990 (and the fact that this introduced the use of the repository inside the changeset syntax provider) and its recent reincarnation r3971.
I'm seeing this problem too now and that's not really surprising if we allow a repository resync to occur during a wiki parsing, while we're iterating on timeline events (e.g. the ticket provider, as in the example).
Moving the wiki_to_* call to the templates would probably fix this as a side-effect. Note that the ITimelineEventProvider would probably have to be modified in order to allow for this. E.g. the message in each event would be the unprocessed message, and each ITimelineEventProvider would have to indicate how to process it (shorten, wiki_to_x, etc.).
follow-up: 15 comment:14 by , 18 years ago
| Keywords: | session removed |
|---|---|
| Resolution: | → fixed |
| Status: | reopened → closed |
Ok, this should probably be fixed for trunk, after the recent Timeline refactoring [4212:4229/trunk].
Now the problem stays open for 0.10.x, see #4132.
Note that even for trunk, the problem can happen again if repos.get_changeset() gets called while a statement is in progress (e.g. called within the body of a select loop).
follow-up: 16 comment:15 by , 18 years ago
comment:16 by , 18 years ago
comment:17 by , 18 years ago
| Resolution: | fixed |
|---|---|
| Status: | closed → reopened |
(anonymous was eblot)
And twice more on the next commits ;-(
I'm re-opening this ticket as the problem seems to occur more frequently for post-commit hooks with the latest 0.10.3 release.
Feel free to close this ticket if there is a known workaround for post-commit hooks.
follow-up: 19 comment:18 by , 18 years ago
| Keywords: | pysqlite resync added |
|---|---|
| Milestone: | 0.11 → 0.10.4 |
He, I was about to reopen it ;)
I think it's because the sync operation is not "atomic", so there can be a race between two writers attempting the sync (see related #4043). Possibly the one which fails to commit will later see the "SQL logic error".
Can you try the following patch on 0.10.3?
Index: trac/versioncontrol/cache.py
===================================================================
--- trac/versioncontrol/cache.py (revision 4448)
+++ trac/versioncontrol/cache.py (working copy)
@@ -31,7 +31,11 @@
Repository.__init__(self, repos.name, authz, log)
self.db = db
self.repos = repos
- self.sync()
+ try:
+ self.sync()
+ except Exception, e:
+ self.db.rollback()
+ self.log.error("Sync failed: %s", e)
def close(self):
self.repos.close()
Manu, if you have a backtrace, you can attach it here.
comment:19 by , 18 years ago
Replying to cboos:
Can you try the following patch on 0.10.3?
I will, thanks.
Manu, if you have a backtrace, you can attach it here.
Log trace (DEBUG level)
2006-12-13 15:43:35,560 Trac[__init__] INFO: Syncing with repository (1589 to 1590) 2006-12-13 15:43:35,589 Trac[__init__] DEBUG: Caching node change in [1590]: (u'branches/grac15-exp-3/src/.../proto.cpp', 'file', 'edit', u'branches/grac15-exp-3/.../proto.cpp',1588) 2006-12-13 15:43:35,591 Trac[__init__] DEBUG: Caching node change in [1590]: (u'branches/grac15-exp-3/src/.../glappseb.cpp', 'file', 'edit', u'branches/grac15-exp-3/.../glappseb.cpp', 1491)
no related traces after this line (I've edited the path to shorten the log lines)
I also received the following email (that reports the exact error):
Wed Dec 13 15:43:34 CET 2006 Revision: 1590 Unexpected error while processing ticket ID 904: SQL logic error or missing database
The actual post-commit hook script looks like
# wrapper on top of SVN bindings self.proxy = RepositoryProxy(rep) self.rev = int(rev) self.log = self.proxy.get_revision_log_message(self.rev) self.author = self.proxy.get_revision_author(self.rev) self.msg = "(In [%d]) %s" % (self.rev, self.log) self.now = int(time.time()) self.rep = rep self.project = project os.environ['PYTHON_EGG_CACHE'] = os.path.join(project, 'eggs') self.env = open_environment(project) if url is None: url = self.env.config.get('project', 'url') self.env.href = Href(url) self.env.abs_href = Href(url) # here, a regex is used to extract the ticket numbers from the # commit message, then the following method is called def _cmdRefs(self, tickets): for tkt_id in tickets: try: ticket = Ticket(self.env, tkt_id) ticket.save_changes(self.author, self.msg, self.now) tn = TicketNotifyEmail(self.env) tn.notify(ticket, newticket=0, modtime=self.now) return OK except Exception, e: print>>sys.stderr, 'Unexpected error while processing ticket ' \ 'ID %s: %s' % (tkt_id, e) return ERROR
follow-up: 21 comment:20 by , 18 years ago
Unfortunately, the patch did not help: the last two commits failed as well (30 minutes after the patch has been applied and the Apache server restarted).
However, the log traces now show an error:
2006-12-13 17:09:04,147 Trac[__init__] ERROR: Sync failed: SQL logic error or missing database
Something weird (?) is that the Sync failed message added in the patch never showed up.
comment:21 by , 18 years ago
Replying to eblot:
.. However, the log traces now show an error:
2006-12-13 17:09:04,147 Trac[__init__] ERROR: Sync failed: SQL logic error or missing databaseSomething weird (?) is that the Sync failed message added in the patch never showed up.
Just in the log. So the above is correct.
What is strange is that you still get the exception from the notification script. Could it be that the notification script uses another installation of Trac?
In any case, just add the following lines in the exception handler of your post-commit-hook, so that we can get to see the backtrace:
... from trac.util import get_last_traceback print>>sys.stderr, 'Traceback:\n', get_last_traceback() return ERROR
comment:22 by , 18 years ago
I will add the code for the backtrace.
Meanwhile, I've gathered the Apache log file with the Trac log files. Here they are:
- Apache
- [18:37:34] "OPTIONS .../asspreg/dyntest HTTP/1.1" 401 553 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "OPTIONS .../asspreg/dyntest HTTP/1.1" 200 191 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "MKACTIVITY .../!svn/act/0459c3f2-5be6-7b45-9dda-640bb9d83a36 HTTP/1.1" 201 384 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "PROPFIND .../asspreg/dyntest HTTP/1.1" 207 509 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "PROPFIND .../!svn/vcc/default HTTP/1.1" 207 407 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "CHECKOUT .../!svn/bln/1593 HTTP/1.1" 201 401 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "PROPPATCH .../!svn/wbl/0459c3f2-5be6-7b45-9dda-640bb9d83a36/1593 HTTP/1.1" 207 359 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "PROPFIND .../asspreg/dyntest HTTP/1.1" 207 533 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "PROPFIND .../asspreg/dyntest/regdtp HTTP/1.1" 207 547 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "CHECKOUT .../!svn/ver/1591/...asspreg/dyntest/regdtp/reghandler.cpp HTTP/1.1" 201 489 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "PROPFIND .../asspreg/dyntest/scripts HTTP/1.1" 207 549 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "CHECKOUT .../!svn/ver/1591/...asspreg/dyntest/scripts/regtrc.dtf HTTP/1.1" 201 486 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:34] "PUT .../!svn/wrk/0459c3f2-5be6-7b45-9dda-640bb9d83a36/...asspreg/dyntest/regdtp/reghandler.cpp HTTP/1.1" 204 - "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:35] "PUT .../!svn/wrk/0459c3f2-5be6-7b45-9dda-640bb9d83a36/...asspreg/dyntest/scripts/regtrc.dtf HTTP/1.1" 204 - "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:35] "MERGE .../asspreg/dyntest HTTP/1.1" 200 1308 "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:37:38] "DELETE .../!svn/act/0459c3f2-5be6-7b45-9dda-640bb9d83a36 HTTP/1.1" 204 - "-" "SVN/1.4.2 (r22196) neon/0.26.2" blote [18:41:12] "GET /trac/project/report HTTP/1.1" 200 14969 ...
- Trac
18:37:35,565 Trac[__init__] DEBUG: Loading egg plugin webadmin.logging from /local/engine/trac/plugins/TracWebAdmin-0.1.2dev_r4240-py2.4.egg 18:37:35,571 Trac[__init__] DEBUG: Loading egg plugin webadmin.ticket from ... 18:37:35,575 Trac[__init__] DEBUG: Loading egg plugin webadmin.basics from ... 18:37:35,578 Trac[__init__] DEBUG: Loading egg plugin webadmin.perm from ... 18:37:35,582 Trac[__init__] DEBUG: Loading egg plugin webadmin.web_ui from ... 18:37:35,584 Trac[__init__] DEBUG: Loading egg plugin webadmin.plugin from ... 18:37:36,737 Trac[__init__] DEBUG: Loading egg plugin TracXMLRPC from ... 18:37:36,790 Trac[__init__] DEBUG: Loading egg plugin graphviz from ... 18:37:36,809 Trac[__init__] DEBUG: Loading egg plugin goodies from ... 18:37:36,843 Trac[__init__] DEBUG: Loading egg plugin revtree.web_ui ... 18:37:37,865 Trac[__init__] DEBUG: Loading egg plugin webadmin.logging from ... 18:37:37,870 Trac[__init__] DEBUG: Loading egg plugin webadmin.ticket from ... 18:37:37,875 Trac[__init__] DEBUG: Loading egg plugin webadmin.basics from ... 18:37:37,878 Trac[__init__] DEBUG: Loading egg plugin webadmin.perm from ... 18:37:37,881 Trac[__init__] DEBUG: Loading egg plugin webadmin.web_ui from ... 18:37:37,883 Trac[__init__] DEBUG: Loading egg plugin webadmin.plugin from ... 18:37:37,901 Trac[__init__] DEBUG: Loading egg plugin TracXMLRPC from ... 18:37:37,949 Trac[__init__] DEBUG: Loading egg plugin graphviz from ... 18:37:37,967 Trac[__init__] DEBUG: Loading egg plugin goodies from ... 18:37:38,001 Trac[__init__] DEBUG: Loading egg plugin revtree.web_ui ... 18:37:38,203 Trac[__init__] INFO: Syncing with repository (1593 to 1594) 18:37:38,234 Trac[__init__] DEBUG: Caching node change in [1594]: (u'...asspreg/dyntest/regdtp/reghandler.cpp', 'file', 'edit', u'...asspreg/dyntest/regdtp/reghandler.cpp', 1591) 18:37:38,236 Trac[__init__] DEBUG: Caching node change in [1594]: (u'...asspreg/dyntest/scripts/regtrc.dtf', 'file', 'edit', u'...asspreg/dyntest/scripts/regtrc.dtf', 1591) 18:37:38,239 Trac[__init__] ERROR: Sync failed: SQL logic error or missing database 18:41:12,705 Trac[__init__] INFO: Syncing with repository (1593 to 1594)
Plugins are loaded twice (I guess once from the pre-commit script, once from the post-commit script).
No other access to the database has been made during the commit sequence, as you can see in the Apache log file (the server do not use HTTPS, and I'm using a simple log configuration so all the accesses are logged into the very same file). I've kept the log of the first next request (18:41:12) after the error on purpose.
Just in the log. So the above is correct.
I feel stupid here ;-)
follow-ups: 24 26 comment:23 by , 18 years ago
| Keywords: | post-commit-hook added |
|---|---|
| Priority: | high → normal |
Ok, I think I see what's going on. It's really the same as #4120 but now outside of the context of a Web request. So of course, there's no pre-request filter and no initial get_repository() and sync().
Somehow here the get_repository() happens at the wrong time. I'm still interested in the backtrace, in order to understand what's the exact sequence of events. Maybe there's something we can do about it in TicketNotifyEmail.
The workaround is easy: add a self.env.get_repository() call at the beginning of the script (e.g. just after self.env = ...).
comment:24 by , 18 years ago
Replying to cboos:
I'm still interested in the backtrace, in order to understand what's the exact sequence of events. Maybe there's something we can do about it in TicketNotifyEmail.
I'll try to generate one (I've updated the hook script with the backtrace code, but as the exception has been catched in the sync() try/except block (first patch), no back trace has been produced.
The workaround is easy: add a
self.env.get_repository()call at the beginning of the script (e.g. just afterself.env = ...).
Ok, I do that has soon as I can get a useful backtrace for the record. I need to commit some work in a couple of minutes anyway.
comment:25 by , 18 years ago
Here it is (I don't think it brings any piece of information, though)
2006-12-13 21:02:30,182 Trac[__init__] INFO: Syncing with repository (1596 to 1597)
2006-12-13 21:02:30,212 Trac[__init__] DEBUG: Caching node change in [1597]: (u'branches/t902b/.../denc.dtf', 'file', 'edit', u'branches/t902b/.../denc.dtf', 1572)
2006-12-13 21:02:30,213 Trac[__init__] DEBUG: Caching node change in [1597]: (u'branches/t902b/.../twihandler.cpp', 'file', 'edit', u'trunk/.../twihandler.cpp', 1552)
2006-12-13 21:02:30,217 Trac[__init__] ERROR: Sync failed: SQL logic error or missing database
2006-12-13 21:02:30,218 Trac[__init__] ERROR: Traceback: Traceback (most recent call last):
File "/local/engine/trac/trac/versioncontrol/cache.py", line 35, in __init__
self.sync()
File "/local/engine/trac/trac/versioncontrol/cache.py", line 109, in sync
self.db.commit()
OperationalError: SQL logic error or missing database
Same trace from the commit script failture notification (once the try/except block has been removed)
self.sync()
File "/local/engine/trac/trac/versioncontrol/cache.py", line 109, in sync
self.db.commit()
OperationalError: SQL logic error or missing database
comment:26 by , 18 years ago
Replying to cboos:
The workaround is easy: add a
self.env.get_repository()call at the beginning of the script (e.g. just afterself.env = ...).
It works ! Thanks a million, cboos.
(I do not close the ticket as the same update may need to be made in the /contrib post-commit hook scripts; sorry, I really have no time by now to cross check)
comment:27 by , 18 years ago
Great, had the same SQL logic error or missing database error in my post-commit script!
Now it works, please update the post-commit scripts in the /contrib scripts, that would have saved me a lot of time.
regards
ramin
follow-up: 29 comment:28 by , 18 years ago
| Resolution: | → fixed |
|---|---|
| Status: | reopened → closed |
comment:29 by , 18 years ago
Replying to cboos:
But I'm still curious about what sequence of code could trigger the sync itself: the stacktrace given by eblot don't show that part, and from the code, it's not obvious (at least to me ;) ).
Can't tell neither…
PS. I didn't think this was the same as #2598, as I'm not getting any kind of back trace. It could be the same issue I guess…