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 <martin.ev...@easysoft.com 
<mailto:martin.ev...@easysoft.com>> 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



Reply via email to