edit old ticket comment error (ProgrammingError: no results to fetch)

[Christian Boos]

Comment reproduire

En exécutant une POST action sur /ticket/379, Trac a levé une erreur interne.

Actually any ticket edit seems to be broken, preview works but not saving.

Paramètres de la requête :

{'__FORM_TOKEN': u'd21e5e9891559d74358c4654',
 'cnum_edit': u'2',
 'edit_comment': u'Enregistrer les modifications',
 'edited_comment': u'... see #1660 (e-mail) and #2293 (RSS).',
 'id': u'379'}

Information système

Trac	0.12dev-r9050
Python	2.5.2 (r252:60911, Oct 5 2008, 19:29:17) [GCC 4.3.2]
setuptools	0.6c9
psycopg2	2.0.8
Genshi	0.6dev-r1092
Babel	0.9.4
Pygments	1.1.1dev-20091217
Subversion	1.5.1 (r32289)
Docutils	0.6

Extensions activées

Pile d'appel Python

Traceback (most recent call last):
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 495, in _dispatch_request
    dispatcher.dispatch(req)
  File "build/bdist.linux-x86_64/egg/trac/web/main.py", line 227, in dispatch
    resp = chosen_handler.process_request(req)
  File "build/bdist.linux-x86_64/egg/trac/ticket/web_ui.py", line 168, in process_request
    return self._process_ticket_request(req)
  File "build/bdist.linux-x86_64/egg/trac/ticket/web_ui.py", line 488, in _process_ticket_request
    ticket.modify_comment(change['date'], req.authname, comment)
  File "build/bdist.linux-x86_64/egg/trac/ticket/model.py", line 412, in modify_comment
    for old_comment, in cursor:
  File "build/bdist.linux-x86_64/egg/trac/db/util.py", line 42, in __iter__
    row = self.cursor.fetchone()
ProgrammingError: no results to fetch

[Christian Boos]

As the for old_comment, in cursor line was introduced in r9043, probably the bug as well ;-)

[Remy Blank]

Weird, I'm sure I tested the fix…

That "no results to fetch" is a bit strange. Shouldn't the construct:

cursor.execute("SELECT ...")
for column, in cursor:
    ...

just never execute the for loop when there are no columns returned?

[Remy Blank]

Oh, and that comment edit did actually get saved.

Testing it here, this one did as well.

[Christian Boos]

Right, I went back in the browser history, submitted again, and this time it worked.

The "no results to fetch" appears to be related to database disconnects, see ​http://lists.initd.org/pipermail/psycopg/2007-September/005626.html (but as they killed their Trac instance, I've no idea if that bug is supposed to be fixed). I don't know why we got a disconnect at this point in the code. Note that this was not a spurious error, as I tested several comment edit saves, all ending with the same error during that period of time, while at the same time the creation of this ticket worked.

[Christian Boos]

So I looked into the postgres log on t.e.o and now I see that the successful savings of comment edits I referred to in comment:4 (i.e. comment:2:ticket:379 and comment:9:ticket:8987) were done earlier than comment:3 (and even this ticket creation time), but I'm 99% confident I retried them only after reading comment:3 and 99.99% confident I did it after creating this ticket.

No idea what's going on. Bad morning, I need a coffee or a brain, probably both.

[Christian Boos]

Ha! Just got the error again, trying to modify comment:5 seconds ago.

And the postgres log shows that despite the error, the change was saved:

2010-01-22 10:27:14 CET LOG:  statement: INSERT INTO ticket_change (ticket,time,author,field,oldvalue,newvalue) VALUES (8993,1264152434,E'cboos','comment',E'5',E'So I looked into the postgres log on t.e.o and now I see that the successful savings of comment edits I referred to in comment:4 (i.e. comment:2:ticket:379 and comment:9:ticket:8987) were done ''''earlier'''' than comment:3 (and even this ticket creation time), but I''m 99% confident I retried them only after reading comment:3 and 99.99% confident I did it after creating this ticket. No idea what''s going on. Bad morning, I need a coffee or a brain, probably both.')
2010-01-22 10:27:14 CET LOG:  statement: UPDATE ticket SET changetime=1264152434 WHERE id=8993
2010-01-22 10:27:37 CET LOG:  statement: INSERT INTO ticket_change (ticket,time,author,field,oldvalue,newvalue) VALUES (8993,1264152434,E'cboos',E'_comment0',E'So I looked into the postgres log on t.e.o and now I see that the successful savings of comment edits I referred to in comment:4 (i.e. comment:2:ticket:379 and comment:9:ticket:8987) were done ''''earlier'''' than comment:3 (and even this ticket creation time), but I''m 99% confident I retried them only after reading comment:3 and 99.99% confident I did it after creating this ticket. No idea what''s going on. Bad morning, I need a coffee or a brain, probably both.',E'1264152457')
2010-01-22 10:27:37 CET LOG:  statement: UPDATE ticket_change SET newvalue=E'So I looked into the postgres log on t.e.o and now I see that the successful savings of comment edits I referred to in comment:4 (i.e. comment:2:ticket:379 and comment:9:ticket:8987) were done ''''earlier'''' than comment:3 (and even this ticket creation time), but I''m 99% confident I retried them only after reading comment:3 and 99.99% confident I did it after creating this ticket.

        No idea what''s going on. Bad morning, I need a coffee or a brain, probably both.' WHERE ticket=8993 AND time=1264152434 AND field='comment'

(the change was the introduction of a blank line before No idea).

Surprising, but comment:5 can then be explained rationally ;-)

[Remy Blank]

Oh, I did get the error as well when editing comment:3, so you didn't dream ;-)

What I don't understand is, if the exception happens where the traceback shows, the comment edit has not been saved yet. As the comment edit did get saved, it means we go through modify_comment() twice, where the first time it succeeds and the second time it fails.

[Christian Boos]

Could the redirect in source:trunk/trac/ticket/web_ui.py@9043#L489​ trigger a POST? Which browser were you using? (I'm using Chrome 4.0.249.64 (35722) beta, for Windows).

[Remy Blank]

Replying to cboos:

Could the redirect in source:trunk/trac/ticket/web_ui.py@9043#L489​ trigger a POST? Which browser were you using? (I'm using Chrome 4.0.249.64 (35722) beta, for Windows).

I would be very surprised if that was the case (using Firefox 3.5.6 on Linux). And even if that was the case, the second POST would be in a separate request, and hence get a new DB connection and all.

(Breakfast finished, now looking into this more seriously.)

[Christian Boos]

I think I got it!

Look again at the whole loop: source:trunk/trac/ticket/model.py@9043:412-430#L372​

trac/ticket/model.py

@@ -428 +428 @@
                            (comment, self.id, ts))
             if handle_ta:
                 db.commit()
+            break
 
     def get_comment_history(self, cnum, db=None):
         db = self._get_db(db)

Untested, but iterating on a cursor after a commit seems to be a bad idea and explains what we saw above ;-)

[Christian Boos]

+ break

or put back the 2 lines if ... db.commit back to the indentation level of pre-r9043, as you prefer.

[Remy Blank]

Replying to cboos:

I think I got it!

You win! I only just reproduced the issue here, and was wondering why all my SQL statements were doubled in the log…

Tested here, and works perfectly. Thanks!

[Remy Blank]

Patch applied in [9056].

[Christian Boos]

Thanks! t.e.o updated to r9056, and indeed it works!

[Remy Blank]

Replying to rblank:

… and was wondering why all my SQL statements were doubled in the log…

Speaking of which, we have been wrapping cursors from pooled connections in two layers of IterableCursor for some time, which would show if you enable [trac] debug_sql by listing all SQL queries twice. Fixed in [9057].

[Remy Blank]

Replying to rblank:

Fixed in [9057].

And fixed the MySQL backend, which actually benefited from the double-wrapping, in [9058].

[Remy Blank]

And finally wrap SQLite cursors in IterableCursor in [9059].

Suddenly, I'm not so sure the fix in [9057] is the right approach. Christian, could you please review [9057:9059] and let me know what you think? Thanks.

[Christian Boos]

Replying to rblank:

And finally wrap SQLite cursors in IterableCursor in [9059].

Suddenly, I'm not so sure the fix in [9057] is the right approach. Christian, could you please review [9057:9059] and let me know what you think? Thanks.

I think that if backends now start to wrap themselves their cursors in IterableCursor, then we should be consistent and the PostgreSQL backend should probably also do the same. The ConnectionWrapper should no longer deal with cursor() and IterableCursor.

What do you think?

[Christian Boos]

Suggested change on the secondary topic of comment:16

[Remy Blank]

Replying to cboos:

we should be consistent and the PostgreSQL backend should probably also do the same. The ConnectionWrapper should no longer deal with cursor() and IterableCursor.

I guess this makes sense. So ConnectionWrapper becomes a pure "attribute forwarder" for the database connection object.

[Christian Boos]

Replying to rblank:

Replying to cboos:

we should be consistent and the PostgreSQL backend should probably also do the same. The ConnectionWrapper should no longer deal with cursor() and IterableCursor.

I guess this makes sense. So ConnectionWrapper becomes a pure "attribute forwarder" for the database connection object.

Yep, and that was how it was used for the PooledConnection.

Thanks for the feedback, patch applied in r9061.