261821 - DBI::db=HASH: either destroy statement handles or call finish on them before

Status: RESOLVED FIXED

(Bugzilla :: Bugzilla-General, defect)

Description

[Phu Nguyen]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.0; rv:1.7.3) Gecko/20040913 Firefox/0.10
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.0; rv:1.7.3) Gecko/20040913 Firefox/0.10

Hello,

I found bunch of errors like this in my apache ssl log, can you spot me out what
cause this?

[Fri Sep 24 00:56:52 2004] [error] [client 69.224.23.182] [Fri Sep 24 00:56:52
2004] show_bug.cgi: DBI::db=HASH(0x87b174c)->disconnect invalidates 1 active
statement handle (either destroy statement handles or call finish on them before
disconnecting) at Bugzilla.pm line 164., referer:
https://prdatabase/report/buglist.cgi?query_format=specific&bug_status=__all__&product=AP&content=&order=bugs.bug_status

Is this affect perform of bugzilla? Is there a patch to fix this. I'm using
bugzilla ver 1.8rc2

Thank you,
Nguyen. 

Reproducible: Always
Steps to Reproduce:
1. 
2.
3.

Comment 1

[Phu Nguyen]

Sorry, to correct the version of bugzilla to 2.18rc2, not 1.18rc2.

Thanks.

Comment 2

[GavinS]

This was first mentioned in bug#192531, and moved to this new bug.

I've seen this in CVS post_bug.cgi sometime in summer 2004.

We rarely call $sth->finish, and just wait for the $sth to go out of scope, but
I suspect there may be some routine somewhere which needs to do a $sth->finish

I'll try and poke around (in a few weeks, when I'm back from holiday)

Comment 3

[GavinS]

Attachment: DBI trace showing the problem

Here is DBI trace level 3 showing the problem - I'm trying to decipher this,
but maybe someone else can decode this quicker??

Comment 4

[GavinS]

CanSeeBug() is to blame - I reckon.

Comment 5

[GavinS]

Attachment: fix to CanSeeBug() v1

I think that this a fix to what I think is the problem :)

(It gets rid of my log error anyway, and there is definitiely a potential
problem here if CanSeeBug() is called twice in any script, as $sth->execute can
be called again on a statement handle which was not tidied up correctly.

2 questions:

1) Why does no-one else see this?

2) If my understanding is correct, we probably want to start forcing a call to
$sth->finish() throughout the codebase, don't we, at least for library
calls/global routines.

(I'm on holiday from thursday, so won't be able to update this patch for a few
weeks - sorry)

Comment 6

[Myk Melez [:myk] [@mykmelez]]

The DBI docs have this to say:

    "When all the data has been fetched from a "SELECT" statement, the
     driver should automatically call "finish" for you. So you should
     not normally need to call it explicitly except when you know that
     you’ve not fetched all the data from a statement handle.  The most
     common example is when you only want to fetch one row, but in that
     case the "selectrow_*" methods are usually better anyway."

So I think calling finish() here is not the right solution.  We should instead
figure out why the query is returning more than one row, or, if it isn't, why
the driver doesn't call finish().

Comment 7

[GavinS]

Comment on attachment 160409 [details] [diff] [review]
fix to CanSeeBug() v1

Ummm, maybe I have a suspect version of dbi/perl, or a screwed up DB -- I'll
try and check when I get home...

Comment 8

[GavinS]

I'm running Perl 5.8.1, DBI 1.39, on OSX.

On my version, after CanSeeBug has done it's first fetchrow_array(), $sth->{Active} is still true, but a 
subsequent fetchrow_array() does not return any more data. After that 2nd fetchrow_array(), then $sth-
>{Active} is false.

Comment 9

[Dave Miller [:justdave]]

which DBD::mysql?

Comment 10

[Joel Peshkin]

OK,  I'm on....

Checking perl modules ...
Checking for       AppConfig (v1.52)   ok: found v1.55
Checking for             CGI (v2.93)   ok: found v3.00
Checking for    Data::Dumper (any)     ok: found v2.12
Checking for    Date::Format (v2.21)   ok: found v2.22
Checking for             DBI (v1.36)   ok: found v1.38
Checking for      DBD::mysql (v2.1010) ok: found v2.9002
Checking for      File::Spec (v0.82)   ok: found v0.85
Checking for      File::Temp (any)     ok: found v0.13
Checking for        Template (v2.08)   ok: found v2.13
Checking for      Text::Wrap (v2001.0131) ok: found v2001.0929

The following Perl modules are optional:
Checking for              GD (v1.20)   ok: found v2.07
Checking for     Chart::Base (v1.0)    ok: found v2.2
Checking for     XML::Parser (any)     ok: found v2.34
Checking for       GD::Graph (any)     ok: found v1.43
Checking for GD::Text::Align (any)     ok: found v1.18
Checking for     PatchReader (v0.9.4)   found v0.9.2


and I got the same problem.

I implemented the same fix and it takes care of it.

Comment 11

[Joel Peshkin]

Comment on attachment 160409 [details] [diff] [review]
fix to CanSeeBug() v1

This is certainly correct.  Why it is needed is still a mystery.

Comment 12

[GavinS]

(In reply to comment #9)
> which DBD::mysql?

Mine are:

Checking for             DBI (v1.36)   ok: found v1.39
Checking for      DBD::mysql (v2.1010) ok: found v2.9003

Comment 13

[Phu Nguyen]

Mine are:

Checking perl modules ...
Checking for       AppConfig (v1.52)   ok: found v1.56
Checking for             CGI (v2.93)   ok: found v3.05
Checking for    Data::Dumper (any)     ok: found v2.121
Checking for    Date::Format (v2.21)   ok: found v2.22
Checking for             DBI (v1.36)   ok: found v1.43
Checking for      DBD::mysql (v2.1010) ok: found v2.9003
Checking for      File::Spec (v0.82)   ok: found v0.88
Checking for      File::Temp (any)     ok: found v0.14
Checking for        Template (v2.08)   ok: found v2.13
Checking for      Text::Wrap (v2001.0131) ok: found v2001.09291

The following Perl modules are optional:
Checking for              GD (v1.20)    found v1.19
Checking for     Chart::Base (v1.0)     found v0.99
Checking for     XML::Parser (any)     ok: found v2.34
Checking for       GD::Graph (any)     ok: found v1.43
Checking for GD::Text::Align (any)     ok: found v1.18
Checking for     PatchReader (v0.9.4)   found v0.9.2

Comment 14

[GavinS]

Ok then, 3 DBI/DBD::mysql combinations which show this are:

1.43/2.9003
1.38/2.9002
1.39/2.9003

The latest versions are 1.45/2.9004.

The only recent possibly related changelog item for these that I can see is maybe the following, but that 
was included in DBI 1.43:

>    Changed selectall_arrayref() to call finish() if $attr->{MaxRows} is defined.

What are the versions of some of the installs which don't see this?

Comment 15

[Dave Miller [:justdave]]

(In reply to comment #14)

> >    Changed selectall_arrayref() to call finish() if $attr->{MaxRows} is
> >    defined.

OK, This is probably a cross-db compatibility thing.  selectall_arrayref() only
returns all available results of the current query result set.  Some databases
(not MySQL) let you have more than one result to the same ->execute().  Usually
this is the results of a stored procedure, which may return multiple tables.

This patch is obviously the right thing to do.  Do we have anywhere else using
selectall_arrayref() without a finish?

Comment 16

[GavinS]

(In reply to comment #15)
> Do we have anywhere else using selectall_arrayref() without a finish?

can_see_bug() is actually calling fetchrow_array(), so either fetchrow_array()
is using selectall_arrayref() underneath (likely?) and so we have to look
further afield to fix any other warnings we may have, or the problem is a
different one.

(Note that I did need a call to $sth->finish() in editmilestones.cgi when I did
the templatisation and converted it to use DBI.)

Comment 17

[Dave Miller [:justdave]]

OK, reading this over again, I'm not so sure anymore...  bbaetz, if you've got a
minute, I'd love to get an opinion from you on this one...

Comment 18

[Dave Miller [:justdave]]

following up on questions asked on IRC, here's why I'm not sure:

The driver is supposed to call finish() for you when all the data has been
retrieved, according to the docs.  We are retrieving all the data by virtue of
feeding it to the hash.  The changelog note that was pointed out only applies to
MaxRows...  saying if maxrows is set, it calls finish() when it reaches MaxRows
instead of waiting till the end.  That shouldn't have any effect on multiple
result sets or queries that don't use MaxRows....

Comment 19

[Bradley Baetz (:bbaetz)]

I don't have a current tree any more; try turning on the trace opts, and see
where you get to.

Comment 20

[GavinS]

I have compared the versions of DBI and DBD::mysql reported as failing with the
latest available versions, and could not see anything obviously related to this
problem (but I'm probably stretching my Perl skills quite a bit in doing that --
so I could well have missed something).

One thing we do not have is reports of which combinations of Perl module
versions, Perl versions and OSes which do not show this problem (on
installations with warnings enabled).

As this is a rare occurance, perhaps it should not block the release?

Comment 21

[Max Kanat-Alexander]

If anybody cares, this also seems to happen on landfill's bugzilla-tip fairly
frequently. (I know because I do patch development on there and I'm always
watching the httpd error_log.)

Comment 22

[GavinS]

(In reply to comment #21)
> If anybody cares, this also seems to happen on landfill's bugzilla-tip fairly
> frequently. (I know because I do patch development on there and I'm always
> watching the httpd error_log.)

Maybe it is more common than I thought - any idea of the version numbers for
bz-tip on landfill? (DBI,DBD::mysql,Perl)

Comment 23

[Max Kanat-Alexander]

On landfill, in use by bugzilla-tip:

DBI (v1.36)   ok: found v1.41
DBD::mysql (v2.1010) ok: found v2.9003
MySQL Server (v3.23.41) ok: found v3.23.58
perl-5.8.3

Comment 24

[Jacob Steenhagen]

(In reply to comment #20)
> As this is a rare occurance, perhaps it should not block the release?

My vote would be that it not block the release. I think if the fix is found
before release happens, it should be included. If not, it should be a part of
2.18.1.

Comment 25

[Jacob Steenhagen]

This bug is currently blocking 2.18. It has a patch w/r+, so requesting approval.

If this isn't the right solution, than attachment 160409 [details] [diff] [review] probably shouldn't have
a positive review.

Comment 26

[Jacob Steenhagen]

Checked into tip. However, this patch doesn't apply to the 2.18 branch.


Checking in User.pm;
/cvsroot/mozilla/webtools/bugzilla/Bugzilla/User.pm,v  <--  User.pm
new revision: 1.31; previous revision: 1.30
done

Comment 27

[GavinS]

(In reply to comment #26)
> Checked into tip. However, this patch doesn't apply to the 2.18 branch.

2.18 still seems to be using SendSQL(), so this problem should not be an issue -
is anyone seeing this on 2.18?

Comment 28

[Jacob Steenhagen]

(In reply to comment #27)
> 2.18 still seems to be using SendSQL(), so this problem should not be an issue -
> is anyone seeing this on 2.18?

The original report was for 2.18rc2 (comment 0 and comment 1). This is also a
blocking2.18+ bug... if it never effected 2.18, then it shouldn't block it ;).

Comment 29

[GavinS]

(In reply to comment #28)
> The original report was for 2.18rc2 (comment 0 and comment 1). This is also a
> blocking2.18+ bug... if it never effected 2.18, then it shouldn't block it ;).

Ummm.. good point! All my poking around and fixing has been on the tip - I will
double check 2.18 when I get home this afternoon. I assumed that the same error
message came from the same problem - but maybe not...

Comment 30

[Vlad Dascalu]

2.18 has modern DB code in it that was converted from SendSQL into the modern 
$dbh stuff.

justdave, mkanat: can you check the landfill error log to see if this is still 
happening after Jake's checkin?

Comment 31

[GavinS]

I do not see this on my 2.18.

The problem I have seen (and Joel (and Max via landfill?)) has been in post_bug.

The problem in 2.18 is on show_bug, like the original report in bug#192531.

Max (or someone else) - could you check the landfill 2.18 error log?

Reporter, is this still reproducable? If we cannot get the trace elsewhere,
would you be able to quickly tweak your install to add in some database trace? 

You would have to add:

     DBI->trace(9);

just before the return statement in Bugzilla/DB.pm:_connect()

Comment 32

[GavinS]

(In reply to comment #6)
> The DBI docs have this to say: [stuff removed]
> 
> So I think calling finish() here is not the right solution.  We should instead
> figure out why the query is returning more than one row, or, if it isn't, why
> the driver doesn't call finish().

I'm beginning to think that the explicit call to finish() (that has now been
checked in) is maybe an OK thing to do (for 2.19).

See this thread: 

http://www.mail-archive.com/[e-mail]/msg03248.html

especially the last 2 comments. Using selectrow_array() as mentioned in the last
posting of that thread also fixes the issue

Comment 33

[Max Kanat-Alexander]

(In reply to comment #31)
> Max (or someone else) - could you check the landfill 2.18 error log?

  I no longer see that happen when posting a new bug, nor do I see it anywhere
in the logs as being reported from bugzilla-tip or bugzilla-2.18-branch
installations for the past week or so.

Comment 34

[Gervase Markham [:gerv]]

So we don't need this for 2.19.x then?

Gerv

Comment 35

[GavinS]

(In reply to comment #34)
> So we don't need this for 2.19.x then?

Gerv: This has been fixed on the tip. We are currently trying to decide if this
actually does affect 2.18

Comment 36

[Marc Schumann [:Wurblzap]]

May I understand comment 31 and comment 33 to mean that this is not an issue on
2.18? Fwiw, I don't see it on 2.18rc3... Neither on

Checking for             DBI (v1.36)   ok: found v1.40
Checking for      DBD::mysql (v2.1010) ok: found v2.9003
Checking for    MySQL Server (v3.23.41) ok: found v4.1.1-alpha

nor on

Checking for             DBI (v1.36)   ok: found v1.42
Checking for      DBD::mysql (v2.1010) ok: found v2.9003
Checking for    MySQL Server (v3.23.41) ok: found v4.0.18-nt

Comment 37

[GavinS]

From my current [admittedly incomplete] understanding, I can see where this bug
maybe could happen in 2.18, and possibly in other places in the trunk code,
subject to certain code paths being exercised.

There are places in Bugzilla where we use just one call to one of the
fetchrow_XXX variants when we only want/expect one row from the DB. That seems
to leave the statement 'active'. We usually get away with this because the
statement will be closed/finished/tidied up when the statement handle goes out
of scope, but when the statement handle is a global, then we can get the
situation described in this bug. [The statement handle used in SendSQL() is a
global.]

Some possibilities for further action:

1) Add a call to finish() in PopGlobalSQLState(). This would be good, but we
know that PopGlobalSQLState() is not used for every DB access, so it would not
fix everything

2) Add a call to finish() in Bugzilla.pm::_cleanup for the global statement
handle(s)?

3) Call finish() explicitly in the code in all the cases where we just call
fetchrow_XXX once

4) Change the single calls from fetchrow_XXX into selectrow_XXX variants

So, in summary, more info is still needed (trace from a failing 2.18 case,
someone to agree ot disagree with my understanding), but I doubt this is really
worthy of blocking 2.18. It doesn't look like a dataloss or security issue, and
if someone else happens across this bug in a released 2.18, then we may be able
to get some trace and fix it...

Comment 38

[Max Kanat-Alexander]

(In reply to comment #36)
> May I understand comment 31 and comment 33 to mean that this is not an issue on
> 2.18? Fwiw, I don't see it on 2.18rc3... Neither on

  Yes, this is not an issue on 2.18. I just tested it and confirmed it. The way
that code path works that was fixed, the warning message should pop up every
time I look at a bug, and it doesn't happen on the 2.18 branch installation on
landfill.

  So I think this can be considered FIXED. Fixing any other *possible* instances
of this bug should probably wait until we actually see them.

Comment 39

[Max Kanat-Alexander]

Actually, the patch has already been checked-in to the tip, and it doesn't apply
to 2.18.

I believe that that makes this bug RESOLVED FIXED.

The checkin is in comment 26, from Jake.

Comment 40

[Marc Schumann [:Wurblzap]]

(In reply to comment #39)
> Actually, the patch has already been checked-in to the tip, and it doesn't apply
> to 2.18.

In that case, is the target milestone off?

Comment 41

[Dave Miller [:justdave]]

"doesn't apply" as in the patch isn't clean and needs to be re-rolled, the one
from the tip can't be used.

2.18 still needs this, as the bug was initially reported against 2.18rc2.

Comment 42

[Marc Schumann [:Wurblzap]]

Here's my findings from trying to port it back to 2.18... It's been not as easy
as I thought.

This was reported against 2.18rc2, but it didn't happen there. It seems to me
that the reporter accidentally specified an incorrect version.

(In reply to comment #0)
> [Fri Sep 24 00:56:52 2004] [error] [client 69.224.23.182] [Fri Sep 24 00:56:52
> 2004] show_bug.cgi: DBI::db=HASH(0x87b174c)->disconnect invalidates 1 active
> statement handle (either destroy statement handles or call finish on them before
> disconnecting) at Bugzilla.pm line 164., referer:

For 2.18x, Buzilla.pm is rev1.10, and line 164 of reads

   if (Param('shadowdb')) {

which doesn't raise the warning. We need to advance to at least rev1.13, where
line 164 reads

   $_dbh_shadow->disconnect if $_dbh_shadow and Param("shadowdb");

I think the reporter experienced the warning on 2.19.1 (Bugzilla.pm rev1.15),
where line 164 reads

   $_dbh_main->disconnect if $_dbh_main;

Unless I'm mistaken, the backport of the patch to 2.18 is not necessary as
can_see_bug (which is called CanSeeBug there and lives in globals.pl) uses
SendSQL and FetchSQLData, so the global statement handle cleanly goes out of
scope in _cleanup in Bugzilla.pm.

Comment 43

[Vlad Dascalu]

Reporter specified by mistake an invalid version.

This can't be reproduced on landfill since the checkin, and landfill is one of
our largest test-beds.

The patch which landed on trunk can't be backported to 2.18.

The patch landed on trunk resolved the behaviour reported in comment #0, which
was approved for blocking.

Yes, this can be tweaked further, per comment #37, but that's not approved yet
for blocking, so I suggest opening a new bug about it.

Comment 44

[Vlad Dascalu]

This still has approval2.18 and blocking2.18 on it, while it's still targetted
at 2.20. The approval/blocking flags should be cleared.