Discussion:
DBD::ODBC Destroy bug?
Joel Plotkin
2015-03-24 15:45:18 UTC
Permalink
Hi,

I have recently ported a large (1.4M line) perl application from:

Centos 6.6
DBI version 1.6.09
DBD::ODBC version 1.23

To:

Centos 6.6
DBI version 1.6.33
DBD::ODBC version 1.50 (and same issue with 1.50_4)

The error doesn't occur in the 1.23 version, only the later 1.50* versions.

This error occurs using MS SQL Server 2005, but I don't think it's db
server dependent.

The specific error occurs when one creates a statement handle in a
subroutine and returns the statement handle via a return value. Specific
test program attached. Sample code that generates error below:

************************************
#!/usr/bin/perl

use strict;

select((select(STDOUT), $|=1)[$[]);

package main;
BEGIN {
# Standard modules
use Carp;
use DBI;
};

my $dbh;

MAIN: {
# open data connection
my $attr = {};
my $odbc = "DBI:ODBC:XXXX_odbc";
my $db_nm="XXXXX";
my $db_user_nm="XXXXX";
my $db_user_passwd="XXXXX";

carp "opening new db connection\n";
$dbh = DBI->connect($odbc, $db_user_nm, $db_user_passwd, $attr) ||
carp "Error opening database";
my $trace_filename = "/tmp/dbi_trace.dat";
$dbh->trace(2, $trace_filename);

# run query
my $sql = "SELECT Name FROM Person WHERE p_id = 123";
* my ($sth) = &do_pexect($sql);*
my $rowcache = $sth->fetchall_arrayref();

#pop off all rows. destroys $rowcache structure.
while (my $row = shift @$rowcache) {
my ($last_nm) = @$row;
}
$sth->finish();

#
# Run same sql a 2nd time
#
# undef $sth;
* ($sth) = &do_pexect($sql);*
carp "This is a test 3\n";
$rowcache = $sth->fetchall_arrayref();
carp "This is a test 4\n";

#pop off all rows. destroys $rowcache structure
while (my $row = shift @$rowcache) {
my ($last_nm) = @$row;
}
$sth->finish();

undef $sth;
return;
}

sub do_pexect {

# input parameters
my($sql) = @_;

my $out;

$out = $dbh->prepare($sql) ||
carp "prepare ($sql): ".$dbh->errstr;

$out->execute() ||
carp "execute ($sql): ".$dbh->errstr;

return($out);
}

************************************

Basic trace error:

-> prepare for DBD::ODBC::db (DBI::db=HASH(0x13c8928)~0x1668428 '
SELECT name FROM Person WHERE p_id = 123') thr#139f010
<- prepare= DBI::st=HASH(0x156c370) at test12.pl line 92
-> execute for DBD::ODBC::st (DBI::st=HASH(0x156c370)~0x16e8898)
thr#139f010
<- execute= -1 at test12.pl line 95
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0x13c8c28)~INNER) thr#139f010
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test12.pl line 70
DBD::ODBC::st DESTROY failed: Unable to fetch information about the
error at test12.pl line 70.
This is a test 3
at test12.pl line 70.
main::joel_init() called at test12.pl line 36
!! The ERROR '1' was CLEARED by call to fetchall_arrayref method


***********************

The basic error is that when the handle is created the 2nd time in the
sub-routine, DBD destroys the original $sth attached to the $dbh. Then,
when the sub-routine finishes, perl auto-trash compactor tries to destroy
$sth a 2nd time as it's the left hand value of the equate statement:
($sth) = &do_pexec($sql); but this doesn't work as the $sth has already
been destroyed in the subroutine.

This trace/error didn't occur in the earlier versions of DBD but now do...
I can get rid of the error by doing: undef $sth; before the 2nd use of the
variable but this should not be necessary.

Has anyone else experienced this issue with the newer versions of DBD?

Thanks for any insight,

Joel
Martin J. Evans
2015-03-24 16:24:58 UTC
Permalink
Post by Joel Plotkin
Hi,
Centos 6.6
DBI version 1.6.09
DBD::ODBC version 1.23
Centos 6.6
DBI version 1.6.33
DBD::ODBC version 1.50 (and same issue with 1.50_4)
The error doesn't occur in the 1.23 version, only the later 1.50* versions.
This error occurs using MS SQL Server 2005, but I don't think it's db server dependent.
************************************
#!/usr/bin/perl
use strict;
select((select(STDOUT), $|=1)[$[]);
package main;
BEGIN {
# Standard modules
use Carp;
use DBI;
};
my $dbh;
MAIN: {
# open data connection
my $attr = {};
my $odbc = "DBI:ODBC:XXXX_odbc";
my $db_nm="XXXXX";
my $db_user_nm="XXXXX";
my $db_user_passwd="XXXXX";
carp "opening new db connection\n";
$dbh = DBI->connect($odbc, $db_user_nm, $db_user_passwd, $attr) ||
carp "Error opening database";
my $trace_filename = "/tmp/dbi_trace.dat";
$dbh->trace(2, $trace_filename);
# run query
my $sql = "SELECT Name FROM Person WHERE p_id = 123";
* my ($sth) = &do_pexect($sql);*
my $rowcache = $sth->fetchall_arrayref();
#pop off all rows. destroys $rowcache structure.
}
$sth->finish();
#
# Run same sql a 2nd time
#
# undef $sth;
* ($sth) = &do_pexect($sql);*
carp "This is a test 3\n";
$rowcache = $sth->fetchall_arrayref();
carp "This is a test 4\n";
#pop off all rows. destroys $rowcache structure
}
$sth->finish();
undef $sth;
return;
}
sub do_pexect {
# input parameters
my $out;
$out = $dbh->prepare($sql) ||
carp "prepare ($sql): ".$dbh->errstr;
$out->execute() ||
carp "execute ($sql): ".$dbh->errstr;
return($out);
}
************************************
-> prepare for DBD::ODBC::db (DBI::db=HASH(0x13c8928)~0x1668428 '
SELECT name FROM Person WHERE p_id = 123') thr#139f010
<- prepare= DBI::st=HASH(0x156c370) at test12.pl <http://test12.pl> line 92
-> execute for DBD::ODBC::st (DBI::st=HASH(0x156c370)~0x16e8898) thr#139f010
<- execute= -1 at test12.pl <http://test12.pl> line 95
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0x13c8c28)~INNER) thr#139f010
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test12.pl <http://test12.pl> line 70
DBD::ODBC::st DESTROY failed: Unable to fetch information about the error at test12.pl <http://test12.pl> line 70.
This is a test 3
at test12.pl <http://test12.pl> line 70.
main::joel_init() called at test12.pl <http://test12.pl> line 36
!! The ERROR '1' was CLEARED by call to fetchall_arrayref method
***********************
The basic error is that when the handle is created the 2nd time in the sub-routine, DBD destroys the original $sth attached to the $dbh. Then, when the sub-routine finishes, perl auto-trash compactor tries to destroy $sth a 2nd time as it's the left hand value of the equate statement: ($sth) = &do_pexec($sql); but this doesn't work as the $sth has already been destroyed in the subroutine.
This trace/error didn't occur in the earlier versions of DBD but now do... I can get rid of the error by doing: undef $sth; before the 2nd use of the variable but this should not be necessary.
Has anyone else experienced this issue with the newer versions of DBD?
Thanks for any insight,
Joel
Sorry Joel, I forgot about your email but in any case this list is a good place to send your issue. When I run your script as it stands (with edits below) I get:

opening new db connection
at mje/joel.pl line 23.
This is a test 3
at mje/joel.pl line 45.
This is a test 4
at mje/joel.pl line 47.
Can't return outside a subroutine at mje/joel.pl line 56.

perl 5.19.10
DBI 1.631
DBD::ODBC 1.53_3 (which is latest git)

I'm going to SQL Server enterprise edition via the Easysoft SQL Server driver.

Obviously I changed the logon details and the SQL.

BTW, I don't think you need those calls to finish (see finish in DBI docs).

Martin
Joel Plotkin
2015-03-24 18:04:07 UTC
Permalink
Hi,

A few notes:

1) the final "return;" at the end of Main was a typo... I was trying to
clean up the example and had consolidated an additional sub-routine into
one big main() function.... even w/ this typo, I still get the original
error as described previously.

2) I (just) tried to get the latest version from git, but I just see

$DBD::ODBC::VERSION = '1.51_4';

from ODBC.pm

I can't seem to find version 1.53_3 at git... I'm not a git expert, so I'll
ask my staff for help to see if they can find 1.53_3 for me.

3) *** I'm using perl 5.10.1 ... maybe this is the issue. I'll upgrade to
perl 5.19.10 and see if the issue goes away.

I'll keep you posted,

Joel
Post by Martin J. Evans
Post by Joel Plotkin
Hi,
Centos 6.6
DBI version 1.6.09
DBD::ODBC version 1.23
Centos 6.6
DBI version 1.6.33
DBD::ODBC version 1.50 (and same issue with 1.50_4)
The error doesn't occur in the 1.23 version, only the later 1.50* versions.
This error occurs using MS SQL Server 2005, but I don't think it's db server dependent.
The specific error occurs when one creates a statement handle in a
subroutine and returns the statement handle via a return value. Specific
************************************
#!/usr/bin/perl
use strict;
select((select(STDOUT), $|=1)[$[]);
package main;
BEGIN {
# Standard modules
use Carp;
use DBI;
};
my $dbh;
MAIN: {
# open data connection
my $attr = {};
my $odbc = "DBI:ODBC:XXXX_odbc";
my $db_nm="XXXXX";
my $db_user_nm="XXXXX";
my $db_user_passwd="XXXXX";
carp "opening new db connection\n";
$dbh = DBI->connect($odbc, $db_user_nm, $db_user_passwd, $attr) ||
carp "Error opening database";
my $trace_filename = "/tmp/dbi_trace.dat";
$dbh->trace(2, $trace_filename);
# run query
my $sql = "SELECT Name FROM Person WHERE p_id = 123";
* my ($sth) = &do_pexect($sql);*
my $rowcache = $sth->fetchall_arrayref();
#pop off all rows. destroys $rowcache structure.
}
$sth->finish();
#
# Run same sql a 2nd time
#
# undef $sth;
* ($sth) = &do_pexect($sql);*
carp "This is a test 3\n";
$rowcache = $sth->fetchall_arrayref();
carp "This is a test 4\n";
#pop off all rows. destroys $rowcache structure
}
$sth->finish();
undef $sth;
return;
}
sub do_pexect {
# input parameters
my $out;
$out = $dbh->prepare($sql) ||
carp "prepare ($sql): ".$dbh->errstr;
$out->execute() ||
carp "execute ($sql): ".$dbh->errstr;
return($out);
}
************************************
-> prepare for DBD::ODBC::db (DBI::db=HASH(0x13c8928)~0x1668428 '
SELECT name FROM Person WHERE p_id = 123') thr#139f010
<- prepare= DBI::st=HASH(0x156c370) at test12.pl <http://test12.pl> line 92
-> execute for DBD::ODBC::st (DBI::st=HASH(0x156c370)~0x16e8898) thr#139f010
<- execute= -1 at test12.pl <http://test12.pl> line 95
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0x13c8c28)~INNER) thr#139f010
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test12.pl <http://test12.pl> line 70
DBD::ODBC::st DESTROY failed: Unable to fetch information about the
error at test12.pl <http://test12.pl> line 70.
This is a test 3
at test12.pl <http://test12.pl> line 70.
main::joel_init() called at test12.pl <http://test12.pl> line 36
!! The ERROR '1' was CLEARED by call to fetchall_arrayref method
***********************
The basic error is that when the handle is created the 2nd time in the
sub-routine, DBD destroys the original $sth attached to the $dbh. Then,
when the sub-routine finishes, perl auto-trash compactor tries to destroy
($sth) = &do_pexec($sql); but this doesn't work as the $sth has already
been destroyed in the subroutine.
This trace/error didn't occur in the earlier versions of DBD but now
do... I can get rid of the error by doing: undef $sth; before the 2nd use
of the variable but this should not be necessary.
Has anyone else experienced this issue with the newer versions of DBD?
Thanks for any insight,
Joel
Sorry Joel, I forgot about your email but in any case this list is a good
place to send your issue. When I run your script as it stands (with edits
opening new db connection
at mje/joel.pl line 23.
This is a test 3
at mje/joel.pl line 45.
This is a test 4
at mje/joel.pl line 47.
Can't return outside a subroutine at mje/joel.pl line 56.
perl 5.19.10
DBI 1.631
DBD::ODBC 1.53_3 (which is latest git)
I'm going to SQL Server enterprise edition via the Easysoft SQL Server driver.
Obviously I changed the logon details and the SQL.
BTW, I don't think you need those calls to finish (see finish in DBI docs).
Martin
Joel Plotkin
2015-03-24 21:24:30 UTC
Permalink
Hi,

We've now tested it under Perl 5.20.2 (on Centos 6) and still get the same
error.

Joel

Ps. Yes- we now understand that $st->finish() is no longer needed. Even
if this is commented out, we still get the same issue.
Post by Joel Plotkin
Hi,
1) the final "return;" at the end of Main was a typo... I was trying to
clean up the example and had consolidated an additional sub-routine into
one big main() function.... even w/ this typo, I still get the original
error as described previously.
2) I (just) tried to get the latest version from git, but I just see
$DBD::ODBC::VERSION = '1.51_4';
from ODBC.pm
I can't seem to find version 1.53_3 at git... I'm not a git expert, so
I'll ask my staff for help to see if they can find 1.53_3 for me.
3) *** I'm using perl 5.10.1 ... maybe this is the issue. I'll upgrade
to perl 5.19.10 and see if the issue goes away.
I'll keep you posted,
Joel
On Tue, Mar 24, 2015 at 12:24 PM, Martin J. Evans <
Post by Martin J. Evans
Post by Joel Plotkin
Hi,
Centos 6.6
DBI version 1.6.09
DBD::ODBC version 1.23
Centos 6.6
DBI version 1.6.33
DBD::ODBC version 1.50 (and same issue with 1.50_4)
The error doesn't occur in the 1.23 version, only the later 1.50* versions.
This error occurs using MS SQL Server 2005, but I don't think it's db server dependent.
The specific error occurs when one creates a statement handle in a
subroutine and returns the statement handle via a return value. Specific
************************************
#!/usr/bin/perl
use strict;
select((select(STDOUT), $|=1)[$[]);
package main;
BEGIN {
# Standard modules
use Carp;
use DBI;
};
my $dbh;
MAIN: {
# open data connection
my $attr = {};
my $odbc = "DBI:ODBC:XXXX_odbc";
my $db_nm="XXXXX";
my $db_user_nm="XXXXX";
my $db_user_passwd="XXXXX";
carp "opening new db connection\n";
$dbh = DBI->connect($odbc, $db_user_nm, $db_user_passwd, $attr) ||
carp "Error opening database";
my $trace_filename = "/tmp/dbi_trace.dat";
$dbh->trace(2, $trace_filename);
# run query
my $sql = "SELECT Name FROM Person WHERE p_id = 123";
* my ($sth) = &do_pexect($sql);*
my $rowcache = $sth->fetchall_arrayref();
#pop off all rows. destroys $rowcache structure.
}
$sth->finish();
#
# Run same sql a 2nd time
#
# undef $sth;
* ($sth) = &do_pexect($sql);*
carp "This is a test 3\n";
$rowcache = $sth->fetchall_arrayref();
carp "This is a test 4\n";
#pop off all rows. destroys $rowcache structure
}
$sth->finish();
undef $sth;
return;
}
sub do_pexect {
# input parameters
my $out;
$out = $dbh->prepare($sql) ||
carp "prepare ($sql): ".$dbh->errstr;
$out->execute() ||
carp "execute ($sql): ".$dbh->errstr;
return($out);
}
************************************
-> prepare for DBD::ODBC::db (DBI::db=HASH(0x13c8928)~0x1668428 '
SELECT name FROM Person WHERE p_id = 123') thr#139f010
<- prepare= DBI::st=HASH(0x156c370) at test12.pl <http://test12.pl> line 92
-> execute for DBD::ODBC::st (DBI::st=HASH(0x156c370)~0x16e8898) thr#139f010
<- execute= -1 at test12.pl <http://test12.pl> line 95
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0x13c8c28)~INNER) thr#139f010
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test12.pl <http://test12.pl> line 70
DBD::ODBC::st DESTROY failed: Unable to fetch information about the
error at test12.pl <http://test12.pl> line 70.
This is a test 3
at test12.pl <http://test12.pl> line 70.
main::joel_init() called at test12.pl <http://test12.pl> line 36
!! The ERROR '1' was CLEARED by call to fetchall_arrayref method
***********************
The basic error is that when the handle is created the 2nd time in the
sub-routine, DBD destroys the original $sth attached to the $dbh. Then,
when the sub-routine finishes, perl auto-trash compactor tries to destroy
($sth) = &do_pexec($sql); but this doesn't work as the $sth has already
been destroyed in the subroutine.
This trace/error didn't occur in the earlier versions of DBD but now
do... I can get rid of the error by doing: undef $sth; before the 2nd use
of the variable but this should not be necessary.
Has anyone else experienced this issue with the newer versions of DBD?
Thanks for any insight,
Joel
Sorry Joel, I forgot about your email but in any case this list is a good
place to send your issue. When I run your script as it stands (with edits
opening new db connection
at mje/joel.pl line 23.
This is a test 3
at mje/joel.pl line 45.
This is a test 4
at mje/joel.pl line 47.
Can't return outside a subroutine at mje/joel.pl line 56.
perl 5.19.10
DBI 1.631
DBD::ODBC 1.53_3 (which is latest git)
I'm going to SQL Server enterprise edition via the Easysoft SQL Server driver.
Obviously I changed the logon details and the SQL.
BTW, I don't think you need those calls to finish (see finish in DBI docs).
Martin
Martin J. Evans
2015-03-25 14:50:26 UTC
Permalink
Hi,
1) the final "return;" at the end of Main was a typo... I was trying to clean up the example and had consolidated an additional sub-routine into one big main() function.... even w/ this typo, I still get the original error as described previously.
I guessed as much.
2) I (just) tried to get the latest version from git, but I just see
$DBD::ODBC::VERSION = '1.51_4';
from ODBC.pm
I can't seem to find version 1.53_3 at git... I'm not a git expert, so I'll ask my staff for help to see if they can find 1.53_3 for me.
sorry, typo from me - that is the version I am using.
3) *** I'm using perl 5.10.1 ... maybe this is the issue. I'll upgrade to perl 5.19.10 and see if the issue goes away.
I'll keep you posted,
Joel
I've since tried on a load of perlbrews and I still cannot duplicate your issue.

Martin
Hi,
Centos 6.6
DBI version 1.6.09
DBD::ODBC version 1.23
Centos 6.6
DBI version 1.6.33
DBD::ODBC version 1.50 (and same issue with 1.50_4)
The error doesn't occur in the 1.23 version, only the later 1.50* versions.
This error occurs using MS SQL Server 2005, but I don't think it's db server dependent.
******************************__******
#!/usr/bin/perl
use strict;
select((select(STDOUT), $|=1)[$[]);
package main;
BEGIN {
# Standard modules
use Carp;
use DBI;
};
my $dbh;
MAIN: {
# open data connection
my $attr = {};
my $odbc = "DBI:ODBC:XXXX_odbc";
my $db_nm="XXXXX";
my $db_user_nm="XXXXX";
my $db_user_passwd="XXXXX";
carp "opening new db connection\n";
$dbh = DBI->connect($odbc, $db_user_nm, $db_user_passwd, $attr) ||
carp "Error opening database";
my $trace_filename = "/tmp/dbi_trace.dat";
$dbh->trace(2, $trace_filename);
# run query
my $sql = "SELECT Name FROM Person WHERE p_id = 123";
* my ($sth) = &do_pexect($sql);*
my $rowcache = $sth->fetchall_arrayref();
#pop off all rows. destroys $rowcache structure.
}
$sth->finish();
#
# Run same sql a 2nd time
#
# undef $sth;
* ($sth) = &do_pexect($sql);*
carp "This is a test 3\n";
$rowcache = $sth->fetchall_arrayref();
carp "This is a test 4\n";
#pop off all rows. destroys $rowcache structure
}
$sth->finish();
undef $sth;
return;
}
sub do_pexect {
# input parameters
my $out;
$out = $dbh->prepare($sql) ||
carp "prepare ($sql): ".$dbh->errstr;
$out->execute() ||
carp "execute ($sql): ".$dbh->errstr;
return($out);
}
******************************__******
-> prepare for DBD::ODBC::db (DBI::db=HASH(0x13c8928)~__0x1668428 '
SELECT name FROM Person WHERE p_id = 123') thr#139f010
<- prepare= DBI::st=HASH(0x156c370) at test12.pl <http://test12.pl> <http://test12.pl> line 92
-> execute for DBD::ODBC::st (DBI::st=HASH(0x156c370)~__0x16e8898) thr#139f010
<- execute= -1 at test12.pl <http://test12.pl> <http://test12.pl> line 95
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0x13c8c28)~__INNER) thr#139f010
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test12.pl <http://test12.pl> <http://test12.pl> line 70
DBD::ODBC::st DESTROY failed: Unable to fetch information about the error at test12.pl <http://test12.pl> <http://test12.pl> line 70.
This is a test 3
at test12.pl <http://test12.pl> <http://test12.pl> line 70.
main::joel_init() called at test12.pl <http://test12.pl> <http://test12.pl> line 36
!! The ERROR '1' was CLEARED by call to fetchall_arrayref method
***********************
The basic error is that when the handle is created the 2nd time in the sub-routine, DBD destroys the original $sth attached to the $dbh. Then, when the sub-routine finishes, perl auto-trash compactor tries to destroy $sth a 2nd time as it's the left hand value of the equate statement: ($sth) = &do_pexec($sql); but this doesn't work as the $sth has already been destroyed in the subroutine.
This trace/error didn't occur in the earlier versions of DBD but now do... I can get rid of the error by doing: undef $sth; before the 2nd use of the variable but this should not be necessary.
Has anyone else experienced this issue with the newer versions of DBD?
Thanks for any insight,
Joel
opening new db connection
at mje/joel.pl <http://joel.pl> line 23.
This is a test 3
at mje/joel.pl <http://joel.pl> line 45.
This is a test 4
at mje/joel.pl <http://joel.pl> line 47.
Can't return outside a subroutine at mje/joel.pl <http://joel.pl> line 56.
perl 5.19.10
DBI 1.631
DBD::ODBC 1.53_3 (which is latest git)
I'm going to SQL Server enterprise edition via the Easysoft SQL Server driver.
Obviously I changed the logon details and the SQL.
BTW, I don't think you need those calls to finish (see finish in DBI docs).
Martin
Joel Plotkin
2015-03-25 16:29:04 UTC
Permalink
Hi,

Are you running under Windows or Linux? We don't see the issue under
ActiveState Perl- just under Linux/Centos.

Also, if it matters, we're running FreeTDS and UnixODBC.

unixODBC.x86_64 2.2.14-14.el6
@base
unixODBC-devel.x86_64 2.2.14-14.el6
@base
freetds.x86_64 0.91-2.el6
@epel
freetds-devel.x86_64 0.91-2.el6
@epel

I guess we can try installed a demo versoin of the EasySoft drivers and see
if that makes a difference.

Joel

Ps- we too used PerlBrew to install Perl 5.20 - specifically:
perl 5.20.2
DBI 1.633
DBD::ODBC = 1.50
Martin J. Evans
2015-03-25 17:36:07 UTC
Permalink
Hi,
Are you running under Windows or Linux? We don't see the issue under ActiveState Perl- just under Linux/Centos.
Linux Ubuntu 12.04.5 LTS
Also, if it matters, we're running FreeTDS and UnixODBC.
I am also running unixODBC.
I guess we can try installed a demo versoin of the EasySoft drivers and see if that makes a difference.
I really wouldn't bother right now.

Could you reduce the script to the smallest which demonstrates the problem but enable level 15 tracing and post the new script and the output?
Joel
perl 5.20.2
DBI 1.633
DBD::ODBC = 1.50
Martin
Joel Plotkin
2015-03-31 05:04:32 UTC
Permalink
Hi,

I've attached the sample test8.pl script (smallest one possible that
creates the problem) and a trace file at level 15.

Thanks for any insight,

Joel
Martin J. Evans
2015-03-31 08:23:32 UTC
Permalink
Hi,
I've attached the sample test8.pl <http://test8.pl> script (smallest one possible that creates the problem) and a trace file at level 15.
Thanks for any insight,
Joel
-dbd_st_execute(ac3cb0)=-1
<- execute= -1 at test8.pl line 74 via at test8.pl line 53
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0xac3818)~INNER) thr#974010
SQLFreeHandle(stmt)=-1
!!dbd_error2(err_rc=-1, what=st_destroy/SQLFreeHandle(stmt), handles=(c2abd0,c2b1c0,c802c0)
** No error found -1 **
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test8.pl line 54 via at test8.pl line 54
!! ERROR: 1 CLEARED by call to fetchall_arrayref method

This is suspicious - SQLFreeHandle failed and then the error was cleared.

I cannot reproduce and we need further clues.

Instead of starting tracing in the script could you rerun with DBI_TRACE=DBD=x.log

e.g.,
set DBI_TRACE=DBD=x.log
perl myscript.pl

This will put in the x.log file a load of ODBC info for the driver etc - could you send me the whole log file.

Another thing well worth doing is enabling tracing at the ODBC level as then we can try and find out why SQLFreeHandle is failing. You can do this by going to the ODBC administrator (make sure you pick the right one 32 bit or 64 bit depending on what your perl is) and selecting the tracing tab, enter a file and click on start then run your script.

Martin
Martin J. Evans
2015-04-01 14:20:31 UTC
Permalink
Hi Martin,
I've attached a odbc device driver log (sql.log) and the dbi trace log at level 15 (x.log).
Hope this helps,
Joel
Joel,

Thanks for the logs but I'm not sure you are going to be too pleased with my analysis.

There are a few points where I think Tim Bunce (or everyone else in dbi-dev) might comment on code in DBD::ODBC and DBI but I don't think they are related to your problem. (Tim and others, search for Tim).

The DBD::ODBC log clearly shows:

SQLFreeHandle(stmt)=-1
!!dbd_error2(err_rc=-1, what=st_destroy/SQLFreeHandle(stmt), handles=(1d371b0,1d377a0,1d88b90)

** No error found -1 **

!! ERROR: 1 ' Unable to fetch information about the error' (err#1)

<- DESTROY= undef at /ejpvfs22/sites22/ahatest_www/cgi-bin/test8b.pl line 54 via at /ejpvfs22/sites22/ahatest_www/cgi-bin/test8b.pl line 54

What this means is that during dbd_st_destroy, DBD::ODBC called SQLFreeHandle to throw away a statement handle and that ODBC call returned -1 (SQL_ERROR). Further, when that failed we tried to call SQLError with the database handle to find the error and no error was returned.

DBI's logging suggests this was inner handle 0x1b7d9b8 and other than calls to dbih_setup_attrib the only reference to this handle is:

-> execute for DBD::ODBC::st (DBI::st=HASH(0x1b7dc88)~0x1b7d9b8) thr#1a7b010
-> fetchall_arrayref for DBD::ODBC::st (DBI::st=HASH(0x1b7dc88)~0x1b7d9b8) thr#1a7b010
<> DESTROY(DBI::st=HASH(0x1b7dc88)) ignored for outer handle (inner DBI::st=HASH(0x1b7d9b8) has ref cnt 1)
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0x1b7d9b8)~INNER) thr#1a7b010
SQLFreeHandle(stmt)=-1
!!dbd_error2(err_rc=-1, what=st_destroy/SQLFreeHandle(stmt), handles=(1d371b0,1d377a0,1d88b90)
** No error found -1 **
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at /ejpvfs22/sites22/ahatest_www/cgi-bin/test8b.pl line 54 via at /ejpvfs22/sites22/ahatest_www/cgi-bin/test8b.pl line 54
dbih_clearcom 0x1b7d9b8 (com 0x1d87be0, type 3) done.

!! ERROR: 1 CLEARED by call to fetchall_arrayref method

So I can see no evidence that the handle was destroyed twice and in fact DBI says there is a reference count of 1. Also, the error is hidden by DBI because fetchall_arrayref cleared it - Tim?

There are a few things I don't understand like in your ODBC admin log I see:

[ODBC][19475][1427828862.899363][SQLColAttribute.c][657]

Exit:[SQL_SUCCESS]

[ODBC][19475][1427828862.899482][SQLFreeHandle.c][378]

Entry:

Handle Type = 3

Input Handle = 0x1d88b90

[ODBC][19475][1427828862.899574][SQLFreeHandle.c][480]

Exit:[SQL_SUCCESS]

[ODBC][19475][1427828862.899634][SQLError.c][348]

Entry:

Statement = 0x1d88b90

SQLState = 0x7fff58445840

Native = 0x7fff58445438

Message Text = 0x7fff58445440

Buffer Length = 1023

Text Len Ptr = 0x7fff5844543e

[ODBC][19475][1427828862.899660][SQLError.c][385]

Exit:[SQL_NO_DATA]

and I'm not sure why DBD::ODBC would call SQLError immediately after a successful SQLFreeHandle call. Also, the ODBC log does not seem to coincide with the DBI/DBD::ODBC log.

However, having said all that I didn't see you were using freeTDS until the last email. I've seen an issue with freeTDS returning and error status and then not supplying the reason before.

I have to say at this point I'm pointing a finger at your driver as whatever, if it returns SQL_ERROR from SQLFreeHandle it should tell us the error when we call SQLError. However, your ODBC log is strange as it does not show any SQLFreeHandle call failing (and it does not look long enough for what you do in your script).

The only bit I'm not too sure about (I doubt has anything to do with your problem) is that DBD::ODBC does the following at the end of dbd_st_destroy

if (imp_dbh->hdbc != SQL_NULL_HDBC && !PL_dirty) {

rc = SQLFreeHandle(SQL_HANDLE_STMT, imp_sth->hstmt);

if (DBIc_TRACE(imp_sth, DBD_TRACING, 0, 5))
TRACE1(imp_dbh, " SQLFreeHandle(stmt)=%d\n", rc);

if (!SQL_SUCCEEDED(rc)) {
dbd_error(sth, rc, "st_destroy/SQLFreeHandle(stmt)");
/* return 0; */
}
}

DBIc_IMPSET_off(imp_sth); /* let DBI know we've done it */

In this case, when no error can be found by dbd_error it does:

DBIh_SET_ERR_CHAR(
h, imp_xxh, Nullch, 1,
" Unable to fetch information about the error", "HY000", Nullch);

but of course then drops into DBIc_IMPSET_off(imp_sth) and returns which might not be ok. I don't know if Tim could comment on this.

So, in summary, I cannot reproduce your error, I've seen freeTDS error and fail to tell us the error before, your code works flawlessly with the Easysoft and MS ODBC drivers and your ODBC log contradicts the DBI/DBD::ODBC log so I'm going to suggest you've updated or changed your freeTDS driver and this one is broken.

Martin
Hi,
I've attached the sample test8.pl <http://test8.pl> <http://test8.pl> script (smallest one possible that creates the problem) and a trace file at level 15.
Thanks for any insight,
Joel
-dbd_st_execute(ac3cb0)=-1
<- execute= -1 at test8.pl <http://test8.pl> line 74 via at test8.pl <http://test8.pl> line 53
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0xac3818)~INNER) thr#974010
SQLFreeHandle(stmt)=-1
!!dbd_error2(err_rc=-1, what=st_destroy/SQLFreeHandle(__stmt), handles=(c2abd0,c2b1c0,c802c0)
** No error found -1 **
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test8.pl <http://test8.pl> line 54 via at test8.pl <http://test8.pl> line 54
!! ERROR: 1 CLEARED by call to fetchall_arrayref method
This is suspicious - SQLFreeHandle failed and then the error was cleared.
I cannot reproduce and we need further clues.
Instead of starting tracing in the script could you rerun with DBI_TRACE=DBD=x.log
e.g.,
set DBI_TRACE=DBD=x.log
perl myscript.pl <http://myscript.pl>
This will put in the x.log file a load of ODBC info for the driver etc - could you send me the whole log file.
Another thing well worth doing is enabling tracing at the ODBC level as then we can try and find out why SQLFreeHandle is failing. You can do this by going to the ODBC administrator (make sure you pick the right one 32 bit or 64 bit depending on what your perl is) and selecting the tracing tab, enter a file and click on start then run your script.
Martin
Tim Bunce
2015-04-08 12:55:50 UTC
Permalink
Post by Martin J. Evans
However, having said all that I didn't see you were using freeTDS
until the last email. I've seen an issue with freeTDS returning and
error status and then not supplying the reason before.
I have to say at this point I'm pointing a finger at your driver as
whatever, if it returns SQL_ERROR from SQLFreeHandle it should tell us
the error when we call SQLError. However, your ODBC log is strange as
it does not show any SQLFreeHandle call failing (and it does not look
long enough for what you do in your script).
The only bit I'm not too sure about (I doubt has anything to do with
your problem) is that DBD::ODBC does the following at the end of
dbd_st_destroy
if (imp_dbh->hdbc != SQL_NULL_HDBC && !PL_dirty) {
rc = SQLFreeHandle(SQL_HANDLE_STMT, imp_sth->hstmt);
if (DBIc_TRACE(imp_sth, DBD_TRACING, 0, 5))
TRACE1(imp_dbh, " SQLFreeHandle(stmt)=%d\n", rc);
if (!SQL_SUCCEEDED(rc)) {
dbd_error(sth, rc, "st_destroy/SQLFreeHandle(stmt)");
/* return 0; */
}
}
DBIc_IMPSET_off(imp_sth); /* let DBI know we've done it */
DBIh_SET_ERR_CHAR(
h, imp_xxh, Nullch, 1,
" Unable to fetch information about the error", "HY000", Nullch);
but of course then drops into DBIc_IMPSET_off(imp_sth) and returns which might not be ok. I don't know if Tim could comment on this.
DBIc_IMPSET_off is how the driver indicates that it's done all the
cleanup it can. The current code seems reasonable.

Tim.
Post by Martin J. Evans
So, in summary, I cannot reproduce your error, I've seen freeTDS error and fail to tell us the error before, your code works flawlessly with the Easysoft and MS ODBC drivers and your ODBC log contradicts the DBI/DBD::ODBC log so I'm going to suggest you've updated or changed your freeTDS driver and this one is broken.
Martin
Hi,
I've attached the sample test8.pl <http://test8.pl> <http://test8.pl> script (smallest one possible that creates the problem) and a trace file at level 15.
Thanks for any insight,
Joel
-dbd_st_execute(ac3cb0)=-1
<- execute= -1 at test8.pl <http://test8.pl> line 74 via at test8.pl <http://test8.pl> line 53
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0xac3818)~INNER) thr#974010
SQLFreeHandle(stmt)=-1
!!dbd_error2(err_rc=-1, what=st_destroy/SQLFreeHandle(__stmt), handles=(c2abd0,c2b1c0,c802c0)
** No error found -1 **
!! ERROR: 1 ' Unable to fetch information about the error' (err#1)
<- DESTROY= undef at test8.pl <http://test8.pl> line 54 via at test8.pl <http://test8.pl> line 54
!! ERROR: 1 CLEARED by call to fetchall_arrayref method
This is suspicious - SQLFreeHandle failed and then the error was cleared.
I cannot reproduce and we need further clues.
Instead of starting tracing in the script could you rerun with DBI_TRACE=DBD=x.log
e.g.,
set DBI_TRACE=DBD=x.log
perl myscript.pl <http://myscript.pl>
This will put in the x.log file a load of ODBC info for the driver etc - could you send me the whole log file.
Another thing well worth doing is enabling tracing at the ODBC level as then we can try and find out why SQLFreeHandle is failing. You can do this by going to the ODBC administrator (make sure you pick the right one 32 bit or 64 bit depending on what your perl is) and selecting the tracing tab, enter a file and click on start then run your script.
Martin
Joel Plotkin
2015-05-30 15:28:36 UTC
Permalink
Hi,

I think this issue can now be closed. Frediano Ziglio was able to add some
changes to the FreeTDS driver to fix the issues.

Here's the comments from applicable the Git changes (I think):

Allow to close cursors and prepared statement when connection is idle

Using ODBC is possible that closing a statement fails as connection
is now busy and is not possible to send requests to server.
Allow to post these close when connection goes to idle.
Just call tds_deferred_unprepare and tds_deferred_cursor_dealloc and
release cursor/dynamic.

Signed-off-by: Frediano Ziglio <***@gmail.com>

This was committed to git on/around May 20, 2015.

(I believe this is the fix, if not, it is certainly fixed on/around
May 20, 2015.)


I've now re-tested the original test case with the latest "master" git
branch of FreeTDS and the issues/errors no longer persist.

Best,


Joel
Post by Martin J. Evans
Post by Martin J. Evans
However, having said all that I didn't see you were using freeTDS
until the last email. I've seen an issue with freeTDS returning and
error status and then not supplying the reason before.
I have to say at this point I'm pointing a finger at your driver as
whatever, if it returns SQL_ERROR from SQLFreeHandle it should tell us
the error when we call SQLError. However, your ODBC log is strange as
it does not show any SQLFreeHandle call failing (and it does not look
long enough for what you do in your script).
The only bit I'm not too sure about (I doubt has anything to do with
your problem) is that DBD::ODBC does the following at the end of
dbd_st_destroy
if (imp_dbh->hdbc != SQL_NULL_HDBC && !PL_dirty) {
rc = SQLFreeHandle(SQL_HANDLE_STMT, imp_sth->hstmt);
if (DBIc_TRACE(imp_sth, DBD_TRACING, 0, 5))
TRACE1(imp_dbh, " SQLFreeHandle(stmt)=%d\n", rc);
if (!SQL_SUCCEEDED(rc)) {
dbd_error(sth, rc, "st_destroy/SQLFreeHandle(stmt)");
/* return 0; */
}
}
DBIc_IMPSET_off(imp_sth); /* let DBI know we've done it */
DBIh_SET_ERR_CHAR(
h, imp_xxh, Nullch, 1,
" Unable to fetch information about the error", "HY000",
Nullch);
Post by Martin J. Evans
but of course then drops into DBIc_IMPSET_off(imp_sth) and returns which
might not be ok. I don't know if Tim could comment on this.
DBIc_IMPSET_off is how the driver indicates that it's done all the
cleanup it can. The current code seems reasonable.
Tim.
Post by Martin J. Evans
So, in summary, I cannot reproduce your error, I've seen freeTDS error
and fail to tell us the error before, your code works flawlessly with the
Easysoft and MS ODBC drivers and your ODBC log contradicts the
DBI/DBD::ODBC log so I'm going to suggest you've updated or changed your
freeTDS driver and this one is broken.
Post by Martin J. Evans
Martin
On Tue, Mar 31, 2015 at 4:23 AM, Martin J. Evans <
Hi,
I've attached the sample test8.pl <http://test8.pl> <
http://test8.pl> script (smallest one possible that creates the problem)
and a trace file at level 15.
Post by Martin J. Evans
Thanks for any insight,
Joel
-dbd_st_execute(ac3cb0)=-1
<- execute= -1 at test8.pl <http://test8.pl> line 74 via at
test8.pl <http://test8.pl> line 53
Post by Martin J. Evans
-> DESTROY for DBD::ODBC::st (DBI::st=HASH(0xac3818)~INNER)
thr#974010
Post by Martin J. Evans
SQLFreeHandle(stmt)=-1
!!dbd_error2(err_rc=-1, what=st_destroy/SQLFreeHandle(__stmt),
handles=(c2abd0,c2b1c0,c802c0)
Post by Martin J. Evans
** No error found -1 **
!! ERROR: 1 ' Unable to fetch information about the error'
(err#1)
Post by Martin J. Evans
<- DESTROY= undef at test8.pl <http://test8.pl> line 54 via
at test8.pl <http://test8.pl> line 54
Post by Martin J. Evans
!! ERROR: 1 CLEARED by call to fetchall_arrayref method
This is suspicious - SQLFreeHandle failed and then the error was
cleared.
Post by Martin J. Evans
I cannot reproduce and we need further clues.
Instead of starting tracing in the script could you rerun with
DBI_TRACE=DBD=x.log
Post by Martin J. Evans
e.g.,
set DBI_TRACE=DBD=x.log
perl myscript.pl <http://myscript.pl>
This will put in the x.log file a load of ODBC info for the driver
etc - could you send me the whole log file.
Post by Martin J. Evans
Another thing well worth doing is enabling tracing at the ODBC
level as then we can try and find out why SQLFreeHandle is failing. You can
do this by going to the ODBC administrator (make sure you pick the right
one 32 bit or 64 bit depending on what your perl is) and selecting the
tracing tab, enter a file and click on start then run your script.
Post by Martin J. Evans
Martin
Loading...