Re: DBD::ODBC Destroy bug?

On 01/04/15 05:36, Joel Plotkin wrote:
> 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

>
> On Tue, Mar 31, 2015 at 4:23 AM, Martin J. Evans <[email protected] <mailto:[email protected]>> wrote:
>
>     On 31/03/15 06:04, Joel Plotkin wrote:
>
>         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
>
>