Edgewall Software
Modify

Opened 15 years ago

Closed 15 years ago

Last modified 15 years ago

#8993 closed defect (fixed)

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

Reported by: Christian Boos Owned by: Christian Boos
Priority: high Milestone: 0.12
Component: ticket system Version: 0.12dev
Severity: minor Keywords: comment edit
Cc: Branch:
Release Notes:
API Changes:
Internal Changes:

Description

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

Attachments (1)

followup9059-t8993.patch (2.0 KB ) - added by Christian Boos 15 years ago.
Suggested change on the secondary topic of comment:16

Download all attachments as: .zip

Change History (22)

comment:1 by Christian Boos, 15 years ago

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

comment:2 by Remy Blank, 15 years ago

Owner: set to 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?

comment:3 by Remy Blank, 15 years ago

Oh, and that comment edit did actually get saved.

Testing it here, this one did as well.

Last edited 15 years ago by Remy Blank (previous) (diff)

comment:4 by Christian Boos, 15 years ago

Keywords: weird added
Priority: highlow

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.

comment:5 by Christian Boos, 15 years ago

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.

Last edited 15 years ago by Christian Boos (previous) (diff)

comment:6 by Christian Boos, 15 years ago

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

comment:7 by Remy Blank, 15 years ago

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.

comment:8 by Christian Boos, 15 years ago

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

in reply to:  8 comment:9 by Remy Blank, 15 years ago

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

comment:10 by Christian Boos, 15 years ago

Keywords: weird removed
Priority: lowhigh

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

     
    428428                           (comment, self.id, ts))
    429429            if handle_ta:
    430430                db.commit()
     431            break
    431432
    432433    def get_comment_history(self, cnum, db=None):
    433434        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 ;-)

in reply to:  10 comment:11 by Christian Boos, 15 years ago

+ break

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

in reply to:  10 ; comment:12 by Remy Blank, 15 years ago

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!

comment:13 by Remy Blank, 15 years ago

Resolution: fixed
Status: newclosed

Patch applied in [9056].

comment:14 by Remy Blank, 15 years ago

Owner: changed from Remy Blank to Christian Boos

comment:15 by Christian Boos, 15 years ago

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

Last edited 15 years ago by Christian Boos (previous) (diff)

in reply to:  12 ; comment:16 by Remy Blank, 15 years ago

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

in reply to:  16 comment:17 by Remy Blank, 15 years ago

Replying to rblank:

Fixed in [9057].

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

comment:18 by Remy Blank, 15 years ago

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.

in reply to:  18 ; comment:19 by Christian Boos, 15 years ago

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?

by Christian Boos, 15 years ago

Attachment: followup9059-t8993.patch added

Suggested change on the secondary topic of comment:16

in reply to:  19 ; comment:20 by Remy Blank, 15 years ago

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.

in reply to:  20 comment:21 by Christian Boos, 15 years ago

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.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Christian Boos.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Christian Boos to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.