Trac0.11.6 - Cannot operate on a closed cursor

[Grzegorz Sobanski]

Hi.

I upgraded my installations to latest 0.11 stable (8846).
Unfortunately it killed my custom plugin, tracking lead me to commit
8590 that enabled connetion pooling on linux.

In my plugin I'm reusing generating ticket group stats from roadmap to
display similar progress bars.

Some simplified code is here that triggers the error:
"Cannot operate on a closed cursor"

def process_request(self, req):
tickets = get_tickets_for_milestone(self.env, self.env.get_db_cnx(), "milestone2")
stats = get_ticket_stats(self.stats_provider, tickets)
[...]

I get a stacktrace:
File "/home/silk/devel/trac/trac/trac/web/main.py", line 450, in
_dispatch_request
dispatcher.dispatch(req)
File "/home/silk/devel/trac/trac/trac/web/main.py", line 206, in
dispatch
resp = chosen_handler.process_request(req)
File "/home/silk/devel/trac/bugtest/bugtest/web_ui.py", line 52, in
process_request
stats = get_ticket_stats(self.stats_provider, tickets)
File "/home/silk/devel/trac/trac/trac/ticket/roadmap.py", line 258, in
get_ticket_stats
return provider.get_ticket_group_stats([t['id'] for t in tickets])
File "/home/silk/devel/trac/trac/trac/ticket/roadmap.py", line 202, in
get_ticket_group_stats
",".join(str_ids))
File "/home/silk/devel/trac/trac/trac/db/util.py", line 65, in execute
return self.cursor.execute(sql)
File "/home/silk/devel/trac/trac/trac/db/sqlite_backend.py", line 80, in
execute
PyFormatCursor.execute(self, *args)
File "/home/silk/devel/trac/trac/trac/db/sqlite_backend.py", line 59, in
execute
args or [])
File "/home/silk/devel/trac/trac/trac/db/sqlite_backend.py", line 51, in
_rollback_on_error
return function(self, *args, **kwargs)

But the roadmap view is working fine, so it seems I'm doing something
totally wrong.

Simplifing more I came to this code, that gives the same error:

def process_request(self, req):
cursor = self.env.get_db_cnx().cursor()
cursor.execute("SELECT status, count(status) FROM ticket "
"WHERE id IN (3) GROUP BY status")

Anoyone has any clue what I'am doing wrong?
It seems to be an error very similar to #8569 (although roadmap and
timeline work fine for me). I have seens similar bugreports on
trac-hacks, but with no resolution.

I put a very simple module reproducing the crash at:
http://boktor.net/pliki/bugs/bugtest.tgz

System info:
debian sid
Trac: 0.11.6stable [8846]
Python: 2.5.4 (r254:67916, Sep 26 2009, 10:32:22) [GCC 4.3.4]
setuptools: 0.6c9
SQLite: 3.6.20
pysqlite: 2.5.5
Genshi: 0.5.1
Pygments: 1.1.1
Subversion: 1.6.6 (r40053)
jQuery: 1.2.6

hope someone can help me :)

greets
silk

[Christian Boos]

Grzegorz Sobanski wrote:
> ...

>
> Simplifing more I came to this code, that gives the same error:
>
> def process_request(self, req):
> cursor = self.env.get_db_cnx().cursor()
> cursor.execute("SELECT status, count(status) FROM ticket "
> "WHERE id IN (3) GROUP BY status")
>
> Anoyone has any clue what I'am doing wrong?
>

...

> It seems to be an error very similar to #8569 (although roadmap and
> timeline work fine for me). I have seens similar bugreports on
> trac-hacks, but with no resolution.
>
> I put a very simple module reproducing the crash at:
> http://boktor.net/pliki/bugs/bugtest.tgz
>

This should work... it worked for me on Windows (older SQLite and
Pysqlite versions, then same versions) and Linux (same SQLite and
Pysqlite versions as you), using Trac 0.11.6rc1.

Even with no poolable connections, that connection should normally end
up in the _active map, and stay there until the shutdown of the request.
Only with very intensive concurrent db usage will the connection be
kicked out of _active ... but then, the odds that this happens before
you use the cursor are quite low. If you see the error systematically,
it must be something else... which I don't see right now. Please
continue to debug this issue, I'm very interested in seeing the
explanation for this.

-- Christian

PS: I had to add the following lines to the process_request, in order to
get something in the browser, see slightly modified bugtest/web_ui.py
attached.

[Grzegorz Sobanski]

* Christian Boos <cb...@neuf.fr> [2009-11-23 18:22]:

> This should work... it worked for me on Windows (older SQLite and
> Pysqlite versions, then same versions) and Linux (same SQLite and
> Pysqlite versions as you), using Trac 0.11.6rc1.

Great. Thanks for testing. It seems something is broken in my
environment.

> you use the cursor are quite low. If you see the error systematically,
> it must be something else... which I don't see right now. Please
> continue to debug this issue, I'm very interested in seeing the
> explanation for this.

I can reproduce it with just a one request, 100% of time, so it is
either something really stupid or really bad setup somewhere.
I'll debug it more next week.


greets
silk

[Christian Boos]

Take 2, now I have no idea why it worked for me last time...

The "Cannot operate on a closed cursor" error happens everytime for me
as well...
What I wrote about the cache in my previous mail was correct, simply I
forgot about the following:
- when a connection is put back in the cache, or rather, as soon as the
connection wrapper you got from get_db_cnx() gets garbage collected, the
connection is rolled back
- rollback used to fail when there with active cursors, for old
pysqlite version (<= 2.3.3), so for each connection we maintain a list
of active cursors, and before the actual rollback we explicitly close
the cursors
- anyway, newer pysqlite versions would do that by themselves
(pysqlite:#197)

So... scratch the "This should work..." from my previous mail, this
should actually *not* work.
You have to keep a reference to the db connection while working with a
cursor.

-- Christian

[Grzegorz Sobanski]

* Christian Boos <cb...@neuf.fr> [2009-11-29 10:27]:

> > I can reproduce it with just a one request, 100% of time, so it is
> > either something really stupid or really bad setup somewhere.
> > I'll debug it more next week.

[...]

> So... scratch the "This should work..." from my previous mail, this
> should actually *not* work.
> You have to keep a reference to the db connection while working with a
> cursor.

Ahh, cool, thanks for info. I tried with a clean environemnt and I started
blaming debian meanwhile ;P

Attached is a patch fixing this in ticket/roadmap.py.
I greped for similar pattern through trac (stable-0.11) and trunk and
dind't find any.

greets
silk

[Christian Boos]

Oh, good catch!

This works there only because there are other references kept on that
"db" higher in the stack (if a db is active, get_db_cnx() from within
the same thread is guaranteed to return it), but nevertheless we should
fix it, of course.

-- Christian

[Grzegorz Sobanski]

* Christian Boos <cb...@neuf.fr> [2009-12-04 15:52]:

> > Attached is a patch fixing this in ticket/roadmap.py.
> > I greped for similar pattern through trac (stable-0.11) and trunk and
> > dind't find any.
>
> Oh, good catch!
>
> This works there only because there are other references kept on that
> "db" higher in the stack (if a db is active, get_db_cnx() from within
> the same thread is guaranteed to return it), but nevertheless we should
> fix it, of course.

Hmm, without this patch my plugin is not working, with patched
roadmap.py it works ok. So I think it would be good to patch it,
for plugins using DefaultTicketGroupStatsProvider.

greets
silk

[Christian Boos]

I've applied the patch in http://trac.edgewall.org/changeset/8878 but as
I explained, the usage Trac itself makes of that method is done in such
a way there's always a connection proxy kept alive thanks to a reference
higher in the call stack. I suppose this is not the case in your plugin,
so it's indeed better to make it robust. I've also written a note in
TracDev/DatabaseApi about this.

Thanks again,

-- Christian

[Grzegorz Sobanski]

* Christian Boos <cb...@neuf.fr> [2009-12-06 12:46]:

> I've applied the patch in http://trac.edgewall.org/changeset/8878 but as
> I explained, the usage Trac itself makes of that method is done in such
> a way there's always a connection proxy kept alive thanks to a reference
> higher in the call stack. I suppose this is not the case in your plugin,
> so it's indeed better to make it robust. I've also written a note in
> TracDev/DatabaseApi about this.

Yes, true.
Thanks for the fix.

greets
silk