Re: DBD::ODBC fails after "Execute immediate success with info"

On 06/11/13 10:57, Jan Holčapek wrote:> Hello there,
>
> I've been using DBD::ODBC to connect to Vertica 6.1 for some time now,
> yet updating (quite old 1.23) DBD::ODBC to a recent one (1.45) introduced
> an issue. Frankly, I'm not sure if it's really a bug or not.
>
> My environment:
>
> Arch: x86_64
> OS: Scientific Linux 6.4
> Perl: 5.10.1
> DBI: 1.630 (updated from 1.609)
> DBD::ODBC 1.45 (updated from 1.23)
> unixODBC: 2.3.2
>
> Simple script reproducing the issue is this:
>
> --cut--
> #!/usr/bin/perl
> use strict;
> use warnings;
> use DBI;
> my $dbh = DBI->connect(
>          'dbi:ODBC:driver=vertica;database=verticadb;server=localhost',
>          'vertica',
>          undef,
>          {
>                  PrintError => 0,
>                  RaiseError => 1,
>                  AutoCommit => 1,
>          } );
> $dbh->trace(5);
> $dbh->begin_work;
> $dbh->do("drop table if exists foo");
> $dbh->commit;
> --cut--
>
> It fails and produces the following trace:
>
> --cut--
>      DBI::db=HASH(0x270e1d0) trace level set to 0x0/5 (DBI @ 0x0/0) in
> DBI 1.630-ithread (pid 27687)
>      -> begin_work in DBD::_::db for DBD::ODBC::db
> (DBI::db=HASH(0x270e2a8)~0x270e1d0) thr#249b010
> 1   -> FETCH for DBD::ODBC::db (DBI::db=HASH(0x270e1d0)~INNER
> 'AutoCommit') thr#249b010
> 1   <- FETCH= 1 at /usr/local/lib64/perl5/DBI.pm line 1732 via  at
> ./odbctest.pl line 15
> 1   -> STORE for DBD::ODBC::db (DBI::db=HASH(0x270e1d0)~INNER
> 'AutoCommit' 0) thr#249b010
>      setting AutoCommit
> 1   <- STORE= 1 at /usr/local/lib64/perl5/DBI.pm line 1734 via  at
> ./odbctest.pl line 15
> 1   -> STORE for DBD::ODBC::db (DBI::db=HASH(0x270e1d0)~INNER
> 'BegunWork' 1) thr#249b010
>      !!DBD::ODBC unsupported attribute passed (BegunWork)
>      STORE DBI::db=HASH(0x270e1d0) 'BegunWork' => 1
> 1   <- STORE= 1 at /usr/local/lib64/perl5/DBI.pm line 1735 via  at
> ./odbctest.pl line 15
>      <- begin_work= 1 at ./odbctest.pl line 15
>      -> do for DBD::ODBC::db (DBI::db=HASH(0x270e2a8)~0x270e1d0 'drop
> table if exists foo') thr#249b010
> 1   -> STORE for DBD::ODBC::db (DBI::db=HASH(0x270e1d0)~INNER
> 'Statement' 'drop table if exists foo') thr#249b010
>      !!DBD::ODBC unsupported attribute passed (Statement)
>      STORE DBI::db=HASH(0x270e1d0) 'Statement' => 'drop table if exists foo'
> 1   <- STORE= 1 at /usr/local/lib64/perl5/DBD/ODBC.pm line 433 via  at
> ./odbctest.pl line 16
>      SQLExecDirect drop table if exists foo
>      SQLExecDirect = 1

This means the ODBC API SQLExecDirect was called and it returned 1 (SQL_SUCCESS_WITH_INFO). According to the ODBC spec, when a driver returns SQL_SUCCESS_WITH_INFO there should be a diagnostic available to tell us what the informational state is.

>      !!dbd_error2(err_rc=1, what=Execute immediate success with info,
> handles=(2727670,2727c60,28f6480)
>      ** No error found 1 **

but we called the ODBC API SQLError and DBD::ODBC thinks there was none.

>      !! ERROR: 1 '    Unable to fetch information about the error' (err#1)
>      <- do= -1 at ./odbctest.pl line 16

so it is telling you, SQLExecute returned SQL_SUCCESS_WITH_INFO and then there was no error - which is an error.


> DBD::ODBC::db do failed:     Unable to fetch information about the
> error at ./odbctest.pl line 16.
>      -> DESTROY for DBD::ODBC::db (DBI::db=HASH(0x270e1d0)~INNER) thr#249b010
> Issuing rollback() due to DESTROY without explicit disconnect() of
> DBD::ODBC::db handle
> driver=vertica;database=verticadb;server=localhost at ./odbctest.pl
> line 16.
>         ERROR: 1 '    Unable to fetch information about the error' (err#1)
>      <- DESTROY= undef at ./odbctest.pl line 16 via  at ./odbctest.pl line 16
> --cut--
>
> If I comment out begin_work and commit, there is no error:
>
> --cut--
>      DBI::db=HASH(0x24ef420) trace level set to 0x0/5 (DBI @ 0x0/0) in
> DBI 1.630-ithread (pid 29782)
>      -> do for DBD::ODBC::db (DBI::db=HASH(0x24ef4f8)~0x24ef420 'drop
> table if exists foo') thr#24bd010
> 1   -> STORE for DBD::ODBC::db (DBI::db=HASH(0x24ef420)~INNER
> 'Statement' 'drop table if exists foo') thr#24bd010
>      !!DBD::ODBC unsupported attribute passed (Statement)
>      STORE DBI::db=HASH(0x24ef420) 'Statement' => 'drop table if exists foo'
> 1   <- STORE= 1 at /usr/local/lib64/perl5/DBD/ODBC.pm line 433 via  at
> ./odbctest.pl line 16
>      SQLExecDirect drop table if exists foo
>      SQLExecDirect = 1
>      !!dbd_error2(err_rc=1, what=Execute immediate success with info,
> handles=(25e89d0,27492f0,2917f70)
>      !SQLError(25e89d0,27492f0,2917f70) = (01000, 4185, NOTICE 4185:
> Nothing was dropped
> )
>      !! info: '' 'NOTICE 4185:  Nothing was dropped

This is the difference between an ODBC API saying it succeeded but with an issue you should be made aware of (SQL_SUCCESS_WITH_INFO) and I'll tell you what it is and it succeeded but with an issue and I refuse to tell you what it is (a bug either in the driver or DBD::ODBC).

In the first case the driver said it succeeded but then against the ODBC API, would not tell us the informational part. DBD::ODBC posted an error saying this.

In the second case the same happened but the driver told us it succeeded but it did not really drop anything. Because DBD::ODBC got the informational message it happily posted it and by default informationals in DBI just not print or raise an error.

>   (SQL-01000)' (err#0)
>      <- do= -1 at ./odbctest.pl line 16
>      -> DESTROY for DBD::ODBC::db (DBI::db=HASH(0x24ef420)~INNER) thr#24bd010
>         info: '' 'NOTICE 4185:  Nothing was dropped
>   (SQL-01000)' (err#0)
>      <- DESTROY= undef
> --cut--
>
> Both worked with DBD::ODBC 1.23. Through binary searching DBD::ODBC releases,
> I was able to figure out that release 1.31 introduced this behavior,
> namely this change
> https://metacpan.org/pod/release/MJEVANS/DBD-ODBC-1.45/Changes#pod1.30_6-2011-06-04
>
> So my question is: is it me, ODBC manager, DBD::ODBC or Vertica doing
> something wrong?
>
> Any insight is more than welcome!
>
> Thanks
> Jan
>

To rule out DBD::ODBC being at fault in its ODBC calls I'd need to see a ODBC driver manager trace. You can do this by:

1. run odbcinst -j to find out where your odbcinst file is located

e.g.,

$ odbcinst -j
unixODBC 2.2.14
DRIVERS............: /etc/odbcinst.ini   <------------- this file
SYSTEM DATA SOURCES: /etc/odbc.ini
FILE DATA SOURCES..: /etc/ODBCDataSources
USER DATA SOURCES..: /home/martin/.odbc.ini
SQLULEN Size.......: 4
SQLLEN Size........: 4
SQLSETPOSIROW Size.: 2

2. add to the top of the odbcinst.ini file:

[ODBC]
Trace=yes
TraceFile=/tmp/unixodbc.log

3. now run your basic script and send me /tmp/unixodbc.log

As to whether DBD::ODBC should issue an error if the driver says there is a problem and then won't tell us what it is - that is another issue I prepared to debate.

Martin--
Martin J. Evans
Easysoft Limited
http://www.easysoft.com