As I was testing another module that used DBI, I found some interesting
behaviour while trying to trace/debug my DBI interactions. Rather than
posting a bunch of code, I managed to find that I could reproduce this
with the DBI 1.42 distribution directly.
The problem is that turning on trace seems to throw the entire DBI
stack (including the caller) out of whack. Here's a snippet from doing
that with just the DBI tests. The actual problem I got was similar to
the printf problem at the bottom.
Note that if I leave off trace, the entire test suite runs absolutely
perfectly ... as does my module (now that I got a fix from the DBD
owner to fix the original problem).
# DBI_TRACE=9=dbitrace.log make test
PERL_DL_NONLAZY=1 /home/share/perl5/bin/perl5.8.3 "-MExtUtils::Command::MM"
"-e" "test_harness(0, 'blib/lib', 'blib/arch')" t/*.t
t/01basics.............ok
t/02dbidrv.............ok
t/03handle.............ok 25/52SV = PVMG(0x8263448) at 0x831ce80
REFCNT = 1
FLAGS = (OBJECT)
IV = 0
NV = 0
PV = 0x831d5a0 ""
CUR = 0
LEN = 113
STASH = 0x8264720 "DBD::ExampleP::db_mem"
t/03handle.............ok
t/04mods...............ok
t/05thrclone...........skipped
all skipped: this linux perl 5.008003 not configured to support
iThreads
t/06attrs..............# Failed test (t/06attrs.t at line 46)
# got: '0'
# expected: '9'
# Failed test (t/06attrs.t at line 99)
# got: '0'
# expected: '9'
# Failed test (t/06attrs.t at line 153)
# got: '0'
# expected: '9'
t/06attrs..............ok 107/143# Looks like you failed 3 tests of 143.
t/06attrs..............dubious
Test returned status 3 (wstat 768, 0x300)
DIED. FAILED tests 22, 61, 98
Failed 3/143 tests, 97.90% okay
t/07kids...............ok
t/08keeperr............ok
t/09trace..............# Failed test (t/09trace.t at line 26)
# got: '0'
# expected: '9'
# Failed test (t/09trace.t at line 54)
# got: '265'
# expected: '256'
# Failed test (t/09trace.t at line 54)
# got: '16777225'
# expected: '16777216'
# Failed test (t/09trace.t at line 54)
# got: '33554441'
# expected: '33554432'
# Failed test (t/09trace.t at line 54)
# got: '67108873'
# expected: '67108864'
# Failed test (t/09trace.t at line 54)
# got: '134217737'
# expected: '134217728'
# Failed test (t/09trace.t at line 54)
# got: '268435465'
# expected: '268435456'
t/09trace..............NOK 49 <- trace= 9 at t/09trace.t line 98
>> disconnect DISPATCH (DBI::db=HASH(0x8145874) rc1/1 @1 g0 imac01
pid#9044) at t/09trace.t line 21 via t/09trace.t line 0
-> disconnect for DBD::ExampleP::db (DBI::db=HASH(0x8145874)~0x82d86cc)
>> STORE DISPATCH (DBI::db=HASH(0x82d86cc) rc1/1 @3 g0 ima41c
pid#9044) at /root/.cpan/build/DBI-1.42/blib/lib/DBD/ExampleP.pm line 199 via
t/09trace.t line 21
1 -> STORE for DBD::ExampleP::db (DBI::db=HASH(0x82d86cc)~INNER 'Active' 0)
STORE DBI::db=HASH(0x82d86cc) 'Active' => 0
1 <- STORE= 1 at /root/.cpan/build/DBI-1.42/blib/lib/DBD/ExampleP.pm line
199 via t/09trace.t line 21
<- disconnect= 1 at t/09trace.t line 21 via t/09trace.t line 0
-- DBI::END
>> disconnect_all DISPATCH (DBI::dr=HASH(0x8257eb4) rc1/4 @1 g0 ima801
pid#9044) at /root/.cpan/build/DBI-1.42/blib/lib/DBI.pm line 657 via
t/09trace.t line 0
-> disconnect_all for DBD::ExampleP::dr
(DBI::dr=HASH(0x8257eb4)~0x8145838)
<- disconnect_all= (not implemented) at
/root/.cpan/build/DBI-1.42/blib/lib/DBI.pm line 657 via t/09trace.t line 0
# Looks like you failed 7 tests of 65.
>> DESTROY DISPATCH (DBI::db=HASH(0x8145874) rc1/1 @1 g0 ima4
pid#9044)
<> DESTROY ignored for outer handle DBI::db=HASH(0x8145874) (inner
DBI::db=HASH(0x82d86cc) has ref cnt 1)
>> DESTROY DISPATCH (DBI::db=HASH(0x82d86cc) rc1/1 @1 g0 ima4
pid#9044)
-> DESTROY for DBD::ExampleP::db (DBI::db=HASH(0x82d86cc)~INNER)
>> FETCH DISPATCH (DBI::db=HASH(0x82d86cc) rc1/2 @2 g0 ima404
pid#9044) at /root/.cpan/build/DBI-1.42/blib/lib/DBD/ExampleP.pm line 236 via
t/09trace.t line 0
-> FETCH for DBD::ExampleP::db (DBI::db=HASH(0x82d86cc)~INNER 'Active')
.. FETCH DBI::db=HASH(0x82d86cc) 'Active' = ''
<- FETCH= '' at /root/.cpan/build/DBI-1.42/blib/lib/DBD/ExampleP.pm line
236 via t/09trace.t line 0
<- DESTROY= undef
DESTROY (dbih_clearcom) (dbh 0x8145874, com 0x8219c38, imp
DBD::ExampleP::db):
FLAGS 0x100291: COMSET Warn RaiseError PrintWarn AutoCommit
PARENT DBI::dr=HASH(0x8145838)
KIDS 0 (0 Active)
IMP_DATA undef
dbih_clearcom 0x8145874 (com 0x8219c38, type 2) done.
! >> DESTROY DISPATCH (DBI::dr=HASH(0x8145838) rc1/1 @1 g0 ima4
pid#9044) during global destruction
! -> DESTROY for DBD::ExampleP::dr (DBI::dr=HASH(0x8145838)~INNER)
! <- DESTROY= undef during global destruction
DESTROY (dbih_clearcom) (drh 0x8257eb4, com 0x82c7428, imp global
destruction):
FLAGS 0x100215: COMSET Active Warn PrintWarn AutoCommit
PARENT undef
KIDS 0 (0 Active)
IMP_DATA ARRAY(0x81457d8)
dbih_clearcom 0x8257eb4 (com 0x82c7428, type 1) done.
! >> DESTROY DISPATCH (DBI::dr=HASH(0x8257eb4) rc1/1 @1 g0 ima4
pid#9044) during global destruction
! <> DESTROY for DBI::dr=HASH(0x8257eb4) ignored (inner handle gone)
t/09trace..............dubious
Test returned status 7 (wstat 1792, 0x700)
DIED. FAILED tests 2, 9, 17, 25, 33, 41, 49
Failed 7/65 tests, 89.23% okay
t/10examp..............ok
t/15array..............ok
t/20meta...............ok
t/30subclass...........ok
t/40profile............ok
t/41prof_dump..........ok
t/42prof_data..........ok
t/50dbm................ok
t/60preparse...........ok
t/80proxy..............skipped
all skipped: modules required for proxy are probably not installed
(e.g., RPC/PlClient.pm)
t/zz_01basics_pp....... Using DBI::PurePerl (DBI_PUREPERL=2) on i686-linux
t/zz_01basics_pp.......ok
t/zz_02dbidrv_pp.......Use of uninitialized value in printf at
DBI::dr::default_user line 23.
Use of uninitialized value in printf at DBI::dr::disconnect_all line 23.
