Skip Menu |

This queue is for tickets about the DBD-mysql CPAN distribution.

Report information
The Basics
Id: 38913
Status: rejected
Priority: 0/
Queue: DBD-mysql

People
Owner: MICHIELB [...] cpan.org
Requestors: ZMAN [...] cpan.org
Cc: pali [...] cpan.org
AdminCc:

Bug Information
Severity: Important
Broken in: 4.008
Fixed in: (no value)



Subject: t/76multi_statement failure & hang
On an Intel Mac with perl-5.8.6 and DBI-1.607 with a 4.1.22 server, I'm getting the following output from test t/76multi_statement ... then a hang ... that is, the output stops there and I have to ^C to get back to the Unix prompt. PERL_DL_NONLAZY=1 /usr/local/bin/perl "-MExtUtils::Command::MM" "-e" "test_harness(1, 'blib/lib', 'blib/arch')" t/76multi_statement.t t/76multi_statement....1..24 ok 1 - Connected to database with multi statement support ok 2 - clean up ok 3 - create table ok 4 - 2 inserts ok 5 - 2 more inserts ok 6 ok 7 - Execute updates ok 8 - First update affected 1 row ok 9 - First update had no warnings ok 10 - Statement handle is Active ok 11 ok 12 - Second update affected 2 rows not ok 13 - Second update had 2 warnings # Failed test 'Second update had 2 warnings' # at t/76multi_statement.t line 50. # got: '0' # expected: '2' ok 14 ok 15 ok 16 - Execute updates again ok 17 ok 18 - Delete all rows ok 19 - do() reports errors
On Tue Sep 02 09:58:50 2008, ZMAN wrote: Show quoted text
> On an Intel Mac with perl-5.8.6 and DBI-1.607 with a 4.1.22 server, > I'm getting the following > output from test t/76multi_statement ... then a hang ... that is, the > output stops there and I > have to ^C to get back to the Unix prompt. > > > PERL_DL_NONLAZY=1 /usr/local/bin/perl "-MExtUtils::Command::MM" "-e" > "test_harness(1, > 'blib/lib', 'blib/arch')" t/76multi_statement.t > t/76multi_statement....1..24 > ok 1 - Connected to database with multi statement support > ok 2 - clean up > ok 3 - create table > ok 4 - 2 inserts > ok 5 - 2 more inserts > ok 6 > ok 7 - Execute updates > ok 8 - First update affected 1 row > ok 9 - First update had no warnings > ok 10 - Statement handle is Active > ok 11 > ok 12 - Second update affected 2 rows > > not ok 13 - Second update had 2 warnings > # Failed test 'Second update had 2 warnings' > # at t/76multi_statement.t line 50. > # got: '0' > # expected: '2' > ok 14 > ok 15 > ok 16 - Execute updates again > ok 17 > ok 18 - Delete all rows > ok 19 - do() reports errors >
On Linux with DBD::mysql 4.008, perl-5.8.7 and DBI-1.607 with a 5.0.27 server. I'm getting the following output from test t/76multi_statement (below) and then a hang 1..24 ok 1 - Connected to database with multi statement support ok 2 - clean up ok 3 - create table ok 4 - 2 inserts ok 5 - 2 more inserts ok 6 ok 7 - Execute updates ok 8 - First update affected 1 row ok 9 - First update had no warnings ok 10 - Statement handle is Active ok 11 ok 12 - Second update affected 2 rows ok 13 - Second update had 2 warnings ok 14 ok 15 ok 16 - Execute updates again ok 17 ok 18 - Delete all rows ok 19 - do() reports errors In the Perl debugger I see it's hanging on: ok 19 - do() reports errors main::(t/76multi_statement.t:66): ok($sth = $dbh->prepare ("UPDATE $table SET a=2; UPDATE bad_$table SET a=3")); DBD::mysql::db::prepare(<removed>DBD-mysql- 4.008/blib/lib/DBD/mysql.pm:224): 224==> if (!DBD::mysql::st::_prepare($sth, $statement, $attribs)) { With DBI_TRACE set to 15 I see: ok 17 Show quoted text
>> do DISPATCH (DBI::db=HASH(0xa282724) rc1/1 @2 g0
ima3201 pid#28054) at t/76multi_statement.t line 59 -> do for DBD::mysql::db (DBI::db=HASH(0xa282724)~0xa28261c 'DELETE FROM t1') mysql.xs do() use_server_side_prepare 0 mysql_st_internal_execute MYSQL_VERSION_ID 50018 Show quoted text
>parse_params statement DELETE FROM t1
<- do= 4 at t/76multi_statement.t line 59 ok 18 - Delete all rows Show quoted text
>> STORE DISPATCH (DBI::db=HASH(0xa28261c) rc2/3 @3 g0 ima41c
pid#28054) at t/76multi_statement.t line 62 -> STORE for DBD::mysql::db (DBI::db=HASH(0xa28261c) ~INNER 'PrintError' 0) STORE DBI::db=HASH(0xa28261c) 'PrintError' => 0 <- STORE= 1 at t/76multi_statement.t line 62 Show quoted text
>> FETCH DISPATCH (DBI::db=HASH(0xa28261c) rc3/3 @2 g0 ima404
pid#28054) at t/76multi_statement.t line 62 -> FETCH for DBD::mysql::db (DBI::db=HASH(0xa28261c) ~INNER 'PrintError') .. FETCH DBI::db=HASH(0xa28261c) 'PrintError' = '' <- FETCH= '' at t/76multi_statement.t line 62 Show quoted text
>> STORE DISPATCH (DBI::db=HASH(0xa28261c) rc3/3 @3 g0 ima41c
pid#28054) at t/76multi_statement.t line 62 -> STORE for DBD::mysql::db (DBI::db=HASH(0xa28261c) ~INNER 'RaiseError' '') STORE DBI::db=HASH(0xa28261c) 'RaiseError' => '' <- STORE= 1 at t/76multi_statement.t line 62 Show quoted text
>> do DISPATCH (DBI::db=HASH(0xa282724) rc1/1 @2 g0
ima3201 pid#28054) at t/76multi_statement.t line 63 -> do for DBD::mysql::db (DBI::db=HASH(0xa282724)~0xa28261c 'INSERT INTO t1 VALUES (1); INSERT INTO bad_t1 VALUES (2);') mysql.xs do() use_server_side_prepare 0 mysql_st_internal_execute MYSQL_VERSION_ID 50018 Show quoted text
>parse_params statement INSERT INTO t1 VALUES (1); INSERT INTO bad_t1
VALUES (2); <- do() ERROR: Table 'test.bad_t1' doesn't exist --> do_error Table 'test.bad_t1' doesn't exist error 1146 recorded: Table 'test.bad_t1' doesn't exist <-- do_error !! ERROR: 1146 'Table 'test.bad_t1' doesn't exist' (err#0) <- do= undef at t/76multi_statement.t line 63 ok 19 - do() reports errors Show quoted text
>> prepare DISPATCH (DBI::db=HASH(0xa282724) rc1/1 @2 g0
imaa201 pid#28054) at t/76multi_statement.t line 66 !! ERROR: 1146 CLEARED by call to prepare method -> prepare for DBD::mysql::db (DBI::db=HASH(0xa282724) ~0xa28261c 'UPDATE t1 SET a=2; UPDATE bad_t1 SET a=3') New 'DBI::st' (for DBD::mysql::st, parent=DBI::db=HASH(0xa28261c), id=undef) dbih_setup_handle(DBI::st=HASH(0xa2ade7c)=>DBI::st=HASH(0xa2adee8), DBD::mysql::st, a2ae014, Null!) dbih_make_com(DBI::db=HASH(0xa28261c), a245498, DBD::mysql::st, 252, 0) thr#0 dbih_setup_attrib(DBI::st=HASH(0xa2adee8), Err, DBI::db=HASH (0xa28261c)) SCALAR(0xa1cf354) (already defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), State, DBI::db=HASH (0xa28261c)) SCALAR(0xa1cf3b4) (already defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), Errstr, DBI::db=HASH (0xa28261c)) SCALAR(0xa1cf384) (already defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), TraceLevel, DBI::db=HASH (0xa28261c)) 0 (already defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), FetchHashKeyName, DBI::db=HASH(0xa28261c)) 'NAME' (already defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), HandleSetErr, DBI::db=HASH(0xa28261c)) undef (not defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), HandleError, DBI::db=HASH (0xa28261c)) undef (not defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), ReadOnly, DBI::db=HASH (0xa28261c)) undef (not defined) dbih_setup_attrib(DBI::st=HASH(0xa2adee8), Profile, DBI::db=HASH (0xa28261c)) undef (not defined) -> dbd_st_prepare MYSQL_VERSION_ID 50018, SQL statement: UPDATE t1 SET a=2; UPDATE bad_t1 SET a=3 Show quoted text
>- dbd_st_free_result_sets
<- dbd_st_free_result_sets RC -1 The table t1 has the contents: select * from t1; +------+ | a | +------+ | 1 | +------+ Hope this is useful, let me know if I can provide more information. Cheers, Peter (Stig) Edwards
On Fri Sep 12 06:37:42 2008, cpan@pjedwards.co.uk wrote: Show quoted text
> On Tue Sep 02 09:58:50 2008, ZMAN wrote:
> > On an Intel Mac with perl-5.8.6 and DBI-1.607 with a 4.1.22 server, > > I'm getting the following > > output from test t/76multi_statement ... then a hang ... that is,
the Show quoted text
> > output stops there and I > > have to ^C to get back to the Unix prompt. > > > > > > PERL_DL_NONLAZY=1 /usr/local/bin/perl "-MExtUtils::Command::MM" "-e" > > "test_harness(1, > > 'blib/lib', 'blib/arch')" t/76multi_statement.t > > t/76multi_statement....1..24 > > ok 1 - Connected to database with multi statement support > > ok 2 - clean up > > ok 3 - create table > > ok 4 - 2 inserts > > ok 5 - 2 more inserts > > ok 6 > > ok 7 - Execute updates > > ok 8 - First update affected 1 row > > ok 9 - First update had no warnings > > ok 10 - Statement handle is Active > > ok 11 > > ok 12 - Second update affected 2 rows > > > > not ok 13 - Second update had 2 warnings > > # Failed test 'Second update had 2 warnings' > > # at t/76multi_statement.t line 50. > > # got: '0' > > # expected: '2' > > ok 14 > > ok 15 > > ok 16 - Execute updates again > > ok 17 > > ok 18 - Delete all rows > > ok 19 - do() reports errors > >
> > On Linux with DBD::mysql 4.008, perl-5.8.7 and DBI-1.607 > with a 5.0.27 server. > I'm getting the following output from test t/76multi_statement > (below) and then a hang > > 1..24 > ok 1 - Connected to database with multi statement support > ok 2 - clean up > ok 3 - create table > ok 4 - 2 inserts > ok 5 - 2 more inserts > ok 6 > ok 7 - Execute updates > ok 8 - First update affected 1 row > ok 9 - First update had no warnings > ok 10 - Statement handle is Active > ok 11 > ok 12 - Second update affected 2 rows > ok 13 - Second update had 2 warnings > ok 14 > ok 15 > ok 16 - Execute updates again > ok 17 > ok 18 - Delete all rows > ok 19 - do() reports errors > > In the Perl debugger I see it's hanging on: > > ok 19 - do() reports errors > main::(t/76multi_statement.t:66): ok($sth = $dbh->prepare > ("UPDATE $table SET a=2; UPDATE bad_$table SET a=3")); > DBD::mysql::db::prepare(<removed>DBD-mysql- > 4.008/blib/lib/DBD/mysql.pm:224): > 224==> if (!DBD::mysql::st::_prepare($sth, $statement,
$attribs)) { Show quoted text
> > With DBI_TRACE set to 15 I see: > > ok 17
> >> do DISPATCH (DBI::db=HASH(0xa282724) rc1/1 @2 g0
> ima3201 pid#28054) at t/76multi_statement.t line 59 > -> do for DBD::mysql::db (DBI::db=HASH(0xa282724)
~0xa28261c 'DELETE Show quoted text
> FROM t1') > mysql.xs do() use_server_side_prepare 0 > mysql_st_internal_execute MYSQL_VERSION_ID 50018
> >parse_params statement DELETE FROM t1
> <- do= 4 at t/76multi_statement.t line 59 > ok 18 - Delete all rows
> >> STORE DISPATCH (DBI::db=HASH(0xa28261c) rc2/3 @3 g0
ima41c Show quoted text
> pid#28054) at t/76multi_statement.t line 62 > -> STORE for DBD::mysql::db (DBI::db=HASH(0xa28261c) > ~INNER 'PrintError' 0) > STORE DBI::db=HASH(0xa28261c) 'PrintError' => 0 > <- STORE= 1 at t/76multi_statement.t line 62
> >> FETCH DISPATCH (DBI::db=HASH(0xa28261c) rc3/3 @2 g0
ima404 Show quoted text
> pid#28054) at t/76multi_statement.t line 62 > -> FETCH for DBD::mysql::db (DBI::db=HASH(0xa28261c) > ~INNER 'PrintError') > .. FETCH DBI::db=HASH(0xa28261c) 'PrintError' = '' > <- FETCH= '' at t/76multi_statement.t line 62
> >> STORE DISPATCH (DBI::db=HASH(0xa28261c) rc3/3 @3 g0
ima41c Show quoted text
> pid#28054) at t/76multi_statement.t line 62 > -> STORE for DBD::mysql::db (DBI::db=HASH(0xa28261c) > ~INNER 'RaiseError' '') > STORE DBI::db=HASH(0xa28261c) 'RaiseError' => '' > <- STORE= 1 at t/76multi_statement.t line 62
> >> do DISPATCH (DBI::db=HASH(0xa282724) rc1/1 @2 g0
> ima3201 pid#28054) at t/76multi_statement.t line 63 > -> do for DBD::mysql::db (DBI::db=HASH(0xa282724)
~0xa28261c 'INSERT Show quoted text
> INTO t1 VALUES (1); INSERT INTO bad_t1 VALUES (2);') > mysql.xs do() use_server_side_prepare 0 > mysql_st_internal_execute MYSQL_VERSION_ID 50018
> >parse_params statement INSERT INTO t1 VALUES (1); INSERT INTO bad_t1
> VALUES (2); > <- do() ERROR: Table 'test.bad_t1' doesn't exist > --> do_error > Table 'test.bad_t1' doesn't exist error 1146 recorded: > Table 'test.bad_t1' doesn't exist > <-- do_error > !! ERROR: 1146 'Table 'test.bad_t1' doesn't exist' (err#0) > <- do= undef at t/76multi_statement.t line 63 > ok 19 - do() reports errors
> >> prepare DISPATCH (DBI::db=HASH(0xa282724) rc1/1 @2 g0
> imaa201 pid#28054) at t/76multi_statement.t line 66 > !! ERROR: 1146 CLEARED by call to prepare method > -> prepare for DBD::mysql::db (DBI::db=HASH(0xa282724) > ~0xa28261c 'UPDATE t1 SET a=2; UPDATE bad_t1 SET a=3') > New 'DBI::st' (for DBD::mysql::st, parent=DBI::db=HASH
(0xa28261c), Show quoted text
> id=undef) > dbih_setup_handle(DBI::st=HASH(0xa2ade7c)=>DBI::st=HASH
(0xa2adee8), Show quoted text
> DBD::mysql::st, a2ae014, Null!) > dbih_make_com(DBI::db=HASH(0xa28261c), a245498, DBD::mysql::st, > 252, 0) thr#0 > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), Err, DBI::db=HASH > (0xa28261c)) SCALAR(0xa1cf354) (already defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), State, DBI::db=HASH > (0xa28261c)) SCALAR(0xa1cf3b4) (already defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), Errstr, DBI::db=HASH > (0xa28261c)) SCALAR(0xa1cf384) (already defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), TraceLevel,
DBI::db=HASH Show quoted text
> (0xa28261c)) 0 (already defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), FetchHashKeyName, > DBI::db=HASH(0xa28261c)) 'NAME' (already defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), HandleSetErr, > DBI::db=HASH(0xa28261c)) undef (not defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), HandleError,
DBI::db=HASH Show quoted text
> (0xa28261c)) undef (not defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), ReadOnly, DBI::db=HASH > (0xa28261c)) undef (not defined) > dbih_setup_attrib(DBI::st=HASH(0xa2adee8), Profile, DBI::db=HASH > (0xa28261c)) undef (not defined) > -> dbd_st_prepare MYSQL_VERSION_ID 50018, SQL statement:
UPDATE Show quoted text
> t1 SET a=2; UPDATE bad_t1 SET a=3
> >- dbd_st_free_result_sets
> <- dbd_st_free_result_sets RC -1 > > The table t1 has the contents: > > select * from t1; > +------+ > | a | > +------+ > | 1 | > +------+ > > Hope this is useful, let me know if I can provide more information. > Cheers, > Peter (Stig) Edwards
I neglected to mention the verion of the client mysql lib, it's 5.0.18.
If you leave it long enough, the test complete, but they fail (main ran for about 8 hours): t/76multi_statement.........20/24 # Failed test 'Execute updates' # at t/76multi_statement.t line 67. # Failed test 'Err was not set after execute' # at t/76multi_statement.t line 68. # Looks like you failed 2 tests of 24. t/76multi_statement......... Dubious, test returned 2 (wstat 512, 0x200) Failed 2/24 subtests t/80procs...................ok Test Summary Report ------------------- t/76multi_statement (Wstat: 512 Tests: 24 Failed: 2) Failed tests: 21-22 Non-zero exit status: 2 Files=34, Tests=673, 28808 wallclock secs ( 0.17 usr 0.59 sys + 1.19 cusr 3.72 csys = 5.67 CPU) Result: FAIL Failed 1/34 test programs. 2/673 subtests failed. make: *** [test_dynamic] Error 255
I can't reproduce these errors on recent DBD::mysql - if you can; please feel free to reopen this issue with enough info on how to reproduce this bug.
On Uto Sep 02 09:58:50 2008, ZMAN wrote: Show quoted text
> On an Intel Mac with perl-5.8.6 and DBI-1.607 with a 4.1.22 server, > I'm getting the following > output from test t/76multi_statement ... then a hang ... that is, the > output stops there and I > have to ^C to get back to the Unix prompt. > > > PERL_DL_NONLAZY=1 /usr/local/bin/perl "-MExtUtils::Command::MM" "-e" > "test_harness(1, > 'blib/lib', 'blib/arch')" t/76multi_statement.t > t/76multi_statement....1..24 > ok 1 - Connected to database with multi statement support > ok 2 - clean up > ok 3 - create table > ok 4 - 2 inserts > ok 5 - 2 more inserts > ok 6 > ok 7 - Execute updates > ok 8 - First update affected 1 row > ok 9 - First update had no warnings > ok 10 - Statement handle is Active > ok 11 > ok 12 - Second update affected 2 rows > > not ok 13 - Second update had 2 warnings > # Failed test 'Second update had 2 warnings' > # at t/76multi_statement.t line 50. > # got: '0' > # expected: '2' > ok 14 > ok 15 > ok 16 - Execute updates again > ok 17 > ok 18 - Delete all rows > ok 19 - do() reports errors
I was testing different MySQL versions in https://github.com/perl5-dbi/DBD-mysql/pull/85 and this problem appeared also in MySQL 5 versions. To my understanding there are two problems: 1) Bug in MySQL server which cause hanging server. See MySQL bug: 16581. 2) DBI statement objects and mysql protocol: Mysql protocol per one connection does not support parallel requests, so there can be only one "active" DBI statement. Before another statement is executed all previous must be finished and cleaned. If it is not done, some unexpected problems could happen (like waiting for connection reset or returning wrong output). And seems that there is bug in DBD::mysql code for multi statement mode and async mode which together with 1) cause that hang.