Bug #53755 for DBIx-Log4perl: fetchrow_array ignoring calling context

Sat Jan 16 17:47:03 2010 brios777 [...] gmail.com - Ticket created

CC:	brios777 [...] gmail.com
Subject:	proposed patch for DBIx::Log4perl
Date:	Sat, 16 Jan 2010 17:45:27 -0500
To:	bug-DBIx-Log4perl [...] rt.cpan.org
From:	Bill Rios <brios777 [...] gmail.com>

Hi, This module has proved to be a great way to log queries from my perl apps without having to turn on mysql's query log (which would be huge and probably hurt the server's performance quite a bit). I came across this issue though after changing the DBI->connect() calls to DBIx::Log4perl->connect() in a fairly large perl application. There were several places in the perl code where the return value of the fetchrow_array() function was being set to a scalar instead of an array. This was being done as a quick way to grab the value for a query that only returns one value (that is, one row with one column). So the DBI module returns the value in the database (actually it apparently returns the last column of the row). The DBIx::Log4perl module returns the number of columns in the row. Example DB table: Show quoted text

mysql> desc t1;

+-------+-------------+------+-----+---------+----------------+ | Field | Type | Null | Key | Default | Extra | +-------+-------------+------+-----+---------+----------------+ | id | int(11) | NO | PRI | NULL | auto_increment | | str1 | varchar(25) | NO | | NULL | | +-------+-------------+------+-----+---------+----------------+ 2 rows in set (0.00 sec) Show quoted text

mysql> select * from t1;

+----+-------+ | id | str1 | +----+-------+ | 1 | test | | 2 | hello | +----+-------+ 2 rows in set (0.00 sec) test.pl (using the DBI module): #!/usr/bin/perl use strict; use DBI; my $dbh = DBI->connect("dbi:mysql:test:localhost", "root", "") or die DBI->errstr(); my $q = "select id, str1 from t1"; my $sth = $dbh->prepare($q); $sth->execute(); my $val = $sth->fetchrow_array(); $sth->finish(); $dbh->disconnect(); print "val=$val\n"; output from test.pl: val=test test2.pl (using DBIx::Log4perl) #!/usr/bin/perl use strict; use DBIx::Log4perl; my $dbh = DBIx::Log4perl->connect("dbi:mysql:test:localhost", "root", "", {DBIx_l4p_init => "/etc/mylog.conf", DBIx_l4p_class => "DBIx::Log4perl"}) or die DBI->errstr(); my $q = "select id, str1 from t1"; my $sth = $dbh->prepare($q); $sth->execute(); my $val = $sth->fetchrow_array(); $sth->finish(); $dbh->disconnect(); print "val=$val\n"; output from test2.pl: val=2 Proposed patch to st.pm: 244c244 < return @row; --- Show quoted text

> return wantarray() ? @row : $row[@row - 1];

After applying this patch, test.pl and test2.pl produce the same output as expected. BTW, thanks for writing this module! :-) Regards, Bill Rios

Download face-smile.png
image/png 873b

Message body is not shown because sender requested not to inline it.

Sun Jan 17 06:09:13 2010 bohica [...] ntlworld.com - Correspondence added

On Sat Jan 16 17:47:03 2010, brios777@gmail.com wrote: Show quoted text

> Hi, > > This module has proved to be a great way to log queries from my perl > apps without having to turn on mysql's query log (which would be huge > and probably hurt the server's performance quite a bit). I came > across > this issue though after changing the DBI->connect() calls to > DBIx::Log4perl->connect() in a fairly large perl application. There > were several places in the perl code where the return value of the > fetchrow_array() function was being set to a scalar instead of an > array. > This was being done as a quick way to grab the value for a query that > only returns one value (that is, one row with one column). So the DBI > module returns the value in the database (actually it apparently > returns > the last column of the row). The DBIx::Log4perl module returns the > number of columns in the row. > > > Example DB table: >

> mysql> desc t1;

> +-------+-------------+------+-----+---------+----------------+ > | Field | Type | Null | Key | Default | Extra | > +-------+-------------+------+-----+---------+----------------+ > | id | int(11) | NO | PRI | NULL | auto_increment | > | str1 | varchar(25) | NO | | NULL | | > +-------+-------------+------+-----+---------+----------------+ > 2 rows in set (0.00 sec) >

> mysql> select * from t1;

> +----+-------+ > | id | str1 | > +----+-------+ > | 1 | test | > | 2 | hello | > +----+-------+ > 2 rows in set (0.00 sec) > > > > > test.pl (using the DBI module): > > #!/usr/bin/perl > > use strict; > use DBI; > > my $dbh = DBI->connect("dbi:mysql:test:localhost", "root", "") or die > DBI->errstr(); > > my $q = "select id, str1 from t1"; > my $sth = $dbh->prepare($q); > $sth->execute(); > > my $val = $sth->fetchrow_array(); > > $sth->finish(); > $dbh->disconnect(); > > print "val=$val\n"; > > > > output from test.pl: > > val=test > > > > > test2.pl (using DBIx::Log4perl) > > #!/usr/bin/perl > > use strict; > use DBIx::Log4perl; > > my $dbh = DBIx::Log4perl->connect("dbi:mysql:test:localhost", "root", > "", {DBIx_l4p_init => "/etc/mylog.conf", DBIx_l4p_class => > "DBIx::Log4perl"}) or die DBI->errstr(); > > my $q = "select id, str1 from t1"; > my $sth = $dbh->prepare($q); > $sth->execute(); > > my $val = $sth->fetchrow_array(); > > $sth->finish(); > $dbh->disconnect(); > > print "val=$val\n"; > > > output from test2.pl: > > val=2 > > > Proposed patch to st.pm: > > 244c244 > < return @row; > ---

> > return wantarray() ? @row : $row[@row - 1];

> > > After applying this patch, test.pl and test2.pl produce the same > output > as expected. > > BTW, thanks for writing this module! :-) > > Regards, > > Bill Rios > > > >

Thanks for this report. I guess this happened because of this quote from DBI docs: "If called in a scalar context for a statement handle that has more than one column, it is undefined whether the driver will return the value of the first column or the last. So don't do that. Also, in a scalar context, an undef is returned if there are no more rows or if an error occurred. That undef can't be distinguished from an undef returned because the first field value was NULL. For these reasons you should exercise some caution if you use fetchrow_array in a scalar context." The code at present in DBIx::Log4perl looks like this: sub fetchrow_array { my ($sth, @args) = @_; my $h = _unseen_sth($sth); my @row = $sth->SUPER::fetchrow_array(@args); $sth->_dbix_l4p_debug($h, 2, sub {Data::Dumper->Dump( [\@row], ["fetchrow_array($h->{dbh_no}.$sth->{private_DBIx_st_no})"])}) if ($h->{logmask} & DBIX_L4P_LOG_OUTPUT); return @row; } I don't think I could make this change as in your patch since I don't know "it is undefined whether the driver will return the value of the first column or the last". I think we need to test wantarray before calling fetchrow_array so the driver can return whatever it does (first or last) as mysql might return the last but some other dbds might return the first. As such I'd propose something like (untested): sub fetchrow_array { my ($sth, @args) = @_; my $h = _unseen_sth($sth); # due to dbi specs we don't know if the driver will # return the first of last value in scalar context # so we have to do different things depending on context. if (wantarray) { my @row = $sth->SUPER::fetchrow_array(@args); $sth->_dbix_l4p_debug($h, 2, sub {Data::Dumper->Dump( [\@row], ["fetchrow_array($h->{dbh_no}.$sth->{private_DBIx_st_no})"])}) if ($h->{logmask} & DBIX_L4P_LOG_OUTPUT); return @row; } else { my $row = $sth->SUPER::fetchrow_array(@args); $sth->_dbix_l4p_debug($h, 2, sub {Data::Dumper->Dump( [$row], ["fetchrow_array($h->{dbh_no}.$sth->{private_DBIx_st_no})"])}) if ($h->{logmask} & DBIX_L4P_LOG_OUTPUT); return $row; } } If you try this out and let me know how you get on I'll do a new release next week. Thanks again for spotting this and diagnosing the problem. Martin -- Martin J. Evans Wetherby, UK

Sun Jan 17 06:09:16 2010 The RT System itself - Status changed from 'new' to 'open'

Sun Jan 17 06:09:55 2010 bohica [...] ntlworld.com - Subject changed from 'proposed patch for DBIx::Log4perl' to 'fetchrow_array ignoring calling context'

Mon Jan 25 12:33:35 2010 bohica [...] ntlworld.com - Correspondence added

On Sun Jan 17 06:09:13 2010, MJEVANS wrote: Show quoted text

> On Sat Jan 16 17:47:03 2010, brios777@gmail.com wrote:

> > Hi, > > > > This module has proved to be a great way to log queries from my perl > > apps without having to turn on mysql's query log (which would be huge > > and probably hurt the server's performance quite a bit). I came > > across > > this issue though after changing the DBI->connect() calls to > > DBIx::Log4perl->connect() in a fairly large perl application. There > > were several places in the perl code where the return value of the > > fetchrow_array() function was being set to a scalar instead of an > > array. > > This was being done as a quick way to grab the value for a query that > > only returns one value (that is, one row with one column). So the DBI > > module returns the value in the database (actually it apparently > > returns > > the last column of the row). The DBIx::Log4perl module returns the > > number of columns in the row.

<snipped examples> This should be fixed now in 0.18 which I've just uploaded to CPAN. Martin -- Martin J. Evans Wetherby, UK

Tue Jan 26 03:57:02 2010 bohica [...] ntlworld.com - Status changed from 'open' to 'resolved'

Tue Jan 26 03:57:04 2010 bohica [...] ntlworld.com - Fixed in 0.18 added