On Thu, Jul 16, 2015 at 10:46:35AM -0700, David E. Wheeler wrote:
> On Jul 16, 2015, at 6:40 AM, Tim Bunce <tim.bu...@pobox.com> wrote:
>
> > Well, this contains lots more light! ...
> >
> >>> -> dbd_st_execute for 03fdf4e0
> >>>> parse_params statement
> >>> SELECT c.change_id ...
> >
> >>> Binding parameters: SELECT c.change_id
> >
> >>> --> do_error
> >>> Out of sort memory, consider increasing server sort buffer size error
> >>> 1038 recorded: Out of sort memory, consider increasing server sort buffer
> >>> size
> >>> <-- do_error
> >>> <- dbd_st_execute returning imp_sth->row_num 18446744073709551615
> >>> !! ERROR: 1038 'Out of sort memory, consider increasing server sort
> >>> buffer size' (err#0)
> >>> <- execute= ( -1 ) [1 items] at /usr/lib/perl5/DBI.pm line 1632 via
> >>> at /usr/local/share/perl/5.18.2/App/Sqitch/Role/DBIEngine.pm line 149
> >
> > So execute failed. Note the crazy row_num. Execute seems to have
> > returned -1, which is a true value.
> >
> >>> !! The ERROR '1038' was CLEARED by call to fetchrow_hashref method
> >>> -> fetchrow_hashref for DBD::mysql::st
> >>> (DBI::st=HASH(0x42cfcc0)~0x4231cf8) thr#2603010
> >
> > Then the higher-level code called fetchrow_hashref, which cleared the
> > error recorded by execute().
>
> FWIW, the database handle is created like this:
>
> my $dbh = DBI->connect($uri->dbi_dsn, scalar $self->username, $pass, {
> PrintError => 0,
> RaiseError => 0,
> AutoCommit => 1,
> mysql_enable_utf8 => 1,
> mysql_auto_reconnect => 0,
> mysql_use_result => 0, # Prevent "Commands out of sync" error.
> HandleError => sub {
> my ($err, $dbh) = @_;
> $@ = $err;
> @_ = ($dbh->state || 'DEV' => $dbh->errstr);
> goto &hurl;
> },
>
> Context:
> https://github.com/theory/sqitch/blob/master/lib/App/Sqitch/Engine/mysql.pm#L59
>
> So I’m a little confused as to why the execute failure was ignored. Is this
> an issue with DBD::mysql?
Note the "row_num 18446744073709551615" above, that's -1 as an unsigned 64 bit
long.
DBD::mysql's handling of row_num seems less than ideal (prompted in part by
baggage of the DBI's ancient driver API).
int dbd_st_execute(SV* sth, imp_sth_t* imp_sth) <== XXX int (forced by DBI API)
{
...
imp_sth->row_num= mysql_st_internal_execute(...) <== row_num is declared as
my_ulonglong
...
if (imp_sth->row_num+1 != (my_ulonglong)-1) { ... } <== XXX
...
...
sprintf(actual_row_num, "%llu", imp_sth->row_num);
PerlIO_printf(DBIc_LOGPIO(imp_xxh), " <- dbd_st_execute returning
imp_sth->row_num %s\n", actual_row_num);
}
return (int)imp_sth->row_num; # <== XXX
}
my_ulonglong mysql_st_internal_execute(...) <== unsigned
{
my_ulonglong rows= 0; <== unsigned
if (!slen) {
do_error(h, JW_ERR_QUERY, "Missing table name" ,NULL);
return -2; <== signed
}
if (!(table= malloc(slen+1))) {
do_error(h, JW_ERR_MEM, "Out of memory" ,NULL);
return -2; <== signed
}
if (!(*result)) {
do_error(h, mysql_errno(svsock),
mysql_error(svsock),mysql_sqlstate(svsock));
return -2; <== signed
}
if(rows == -2) { <== signed
do_error(h, mysql_errno(svsock), mysql_error(svsock),
mysql_sqlstate(svsock));
if (DBIc_TRACE_LEVEL(imp_xxh) >= 2)
PerlIO_printf(DBIc_LOGPIO(imp_xxh), "IGNORING ERROR errno %d\n", errno);
rows = -2; <== signed
}
return(rows);
}
mysql_st_internal_execute41(...) has very similar issues
Looks to me like you've hit some latent bugs in the DBD::mysql code (e.g., it's
not safe/reliable to throw negative numbers around in unsigned types) compounded
by the limitations of the ancient DBI driver API:
https://github.com/perl5-dbi/dbi/blob/1486773ec0bf357661d756cf37ff2988b5eaf24d/Driver.xst#L585-L601
Seems like there's a need to separate "row count" from "execute return value".
Internally the DBI has a DBIc_ROW_COUNT(sth) macro that has an IV type.
That's a signed int that would be 64 bits on most modern systems.
On many of those systems the plain int type might be 32 bits.
I've just pushed an experimental change that might help in general
https://github.com/perl5-dbi/dbi/commit/29f6b9b76e9c637be31cb80f1a262ff68b42ef43#diff-cb6af96fe009d6f8d9d682415e1ab755
but probably wouldn't in your case.
At the moment I'd view this as a DBD::mysql bug.
Tim.
p.s. These open DBD::mysql issues might also be more or less related:
https://rt.cpan.org/Public/Bug/Display.html?id=48158
https://rt.cpan.org/Public/Bug/Display.html?id=80394
https://rt.cpan.org/Public/Bug/Display.html?id=75570
