#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)
Change History (22)
comment:1 by , 15 years ago
comment:2 by , 15 years ago
Owner: | set to |
---|
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 , 15 years ago
Oh, and that comment edit did actually get saved.
Testing it here, this one did as well.
comment:4 by , 15 years ago
Keywords: | weird added |
---|---|
Priority: | high → low |
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 , 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.
comment:6 by , 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 , 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.
follow-up: 9 comment:8 by , 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).
comment:9 by , 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.)
follow-ups: 11 12 comment:10 by , 15 years ago
Keywords: | weird removed |
---|---|
Priority: | low → high |
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)) 429 429 if handle_ta: 430 430 db.commit() 431 break 431 432 432 433 def get_comment_history(self, cnum, db=None): 433 434 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 ;-)
comment:11 by , 15 years ago
+ break
or put back the 2 lines if ... db.commit
back to the indentation level of pre-r9043, as you prefer.
follow-up: 16 comment:12 by , 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:14 by , 15 years ago
Owner: | changed from | to
---|
follow-up: 17 comment:16 by , 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].
comment:17 by , 15 years ago
follow-up: 19 comment:18 by , 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.
follow-up: 20 comment:19 by , 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 , 15 years ago
Attachment: | followup9059-t8993.patch added |
---|
Suggested change on the secondary topic of comment:16
follow-up: 21 comment:20 by , 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 withcursor()
andIterableCursor
.
I guess this makes sense. So ConnectionWrapper
becomes a pure "attribute forwarder" for the database connection object.
comment:21 by , 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 withcursor()
andIterableCursor
.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.
As the
for old_comment, in cursor
line was introduced in r9043, probably the bug as well ;-)