Edgewall Software

Ticket #2902 (closed defect: fixed)

Opened 3 years ago

Last modified 23 months ago

OperationalError: SQL logic error or missing database

Reported by: athomas Owned by: cboos
Priority: normal Milestone: 0.10.4
Component: general Version: devel
Severity: major Keywords: pysqlite resync post-commit-hook
Cc:

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&amp;max=50&amp;daysback=90&amp;ticket=on&amp;ticket_details=on&amp;changeset=on">Timeline</a></p>)
11:52:29 Trac[api] DEBUG: Updating wiki page index

Attachments

Change History

  Changed 3 years ago by athomas

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...

  Changed 3 years ago by athomas

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.

  Changed 3 years ago by athomas

Nope, it's still occurring. I can provide the DB if necessary.

  Changed 3 years ago by cboos

  • owner changed from jonas to cboos

Yes, I could have a try.

  Changed 3 years ago by athomas

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.

  Changed 3 years ago by athomas

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.

  Changed 3 years ago by cboos

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.

  Changed 3 years ago by athomas

It is built with --enable-threadsafe.

  Changed 3 years ago by anonymous

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.

  Changed 3 years ago by cboos

  • 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)

  Changed 3 years ago by cboos

Does the problem still happen now that the session code has been improved?

  Changed 3 years ago by athomas

  • status changed from new to closed
  • resolution set to fixed

Nope, I haven't seen this error for quite some time. I'll close it off.

  Changed 2 years ago by cboos

  • status changed from closed to reopened
  • resolution fixed deleted
  • milestone set to 0.11

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   Changed 2 years ago by cboos

  • keywords session removed
  • status changed from reopened to closed
  • resolution set to fixed

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).

in reply to: ↑ 14 ; follow-up: ↓ 16   Changed 2 years ago by cboos

Now the problem stays open for 0.10.x, see #4132.

I meant #4120, though #4132 is probably related to this as well.

in reply to: ↑ 15   Changed 2 years ago by anonymous

Replying to cboos:

Now the problem stays open for 0.10.x, see #4132.

I meant #4120, though #4132 is probably related to this as well.

I've upgraded to 0.10.3 this morning, and just got bitten by this issue (from a post-commit hook)

  Changed 2 years ago by eblot

  • status changed from closed to reopened
  • resolution fixed deleted

(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   Changed 2 years ago by cboos

  • keywords pysqlite resync added
  • milestone changed from 0.11 to 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.

in reply to: ↑ 18   Changed 2 years ago by eblot

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   Changed 2 years ago by eblot

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.

in reply to: ↑ 20   Changed 2 years ago by cboos

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 database Something 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

  Changed 2 years ago by eblot

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   Changed 2 years ago by cboos

  • keywords post-commit-hook added
  • priority changed from high to 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 = ...).

in reply to: ↑ 23   Changed 2 years ago by eblot

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 after self.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.

  Changed 2 years ago by eblot

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

in reply to: ↑ 23   Changed 2 years ago by eblot

Replying to cboos:

The workaround is easy: add a self.env.get_repository() call at the beginning of the script (e.g. just after self.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)

  Changed 23 months ago by ramin

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   Changed 23 months ago by cboos

  • status changed from reopened to closed
  • resolution set to fixed

Ok, implemented the workaround in r4510 (trunk) and r4511 (0.10-stable).

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 ;) ).

in reply to: ↑ 28   Changed 23 months ago by eblot

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...

Add/Change #2902 (OperationalError: SQL logic error or missing database)

Author



Change Properties
<Author field>
Action
as closed
Next status will be 'reopened'
to The owner will change from cboos. Next status will be 'closed'
 
Note: See TracTickets for help on using tickets.