FreeTDS Development Group

[Cade Roux <cade AT roux.org>]

I posted this question on dba.stackexchange.com:

http://dba.stackexchange.com/questions/28692/sql-08s01-error-in-freetds-azure-when-executing-stored-proc-for-a-few-minutes-fr

But figured I'd also post it here:

I get this error on Linux (Ubuntu and CentOS) when executing a stored
proc from Perl/DBI/ODBC/FreeTDS to SQL Azure:

    [unixODBC][FreeTDS][SQL Server]Read from the server failed (SQL-08S01)

I don't get this error running the same Perl script on Windows
(ODBC/Native) connecting to the same SQL Azure database, and although
the proc takes a couple minutes to run, it does complete.  Obviously a
completely different client/driver environment, but they are both
going to the same SQL Azure database and there is no difference in the
Perl script itself.  Both Perl environments should be similar but
obviously the client/drivers will be different.

The line which fails is simple - a proc with no parameters which takes
data from a staging table and processes it - at the time of failure
from Linux call, the environment on SQL Azure is not significantly
different than when I test called from Windows (it is completely
reproducible when the staging table is loaded with certain data and
invoked from Linux):

    $dbh->do("EXEC procname;") or die $DBI::errstr ;

Indications from my searches are that this is some kind of connection
issue or timeout.

I'm working to improve the proc performance, but the timeout is not
set on the Linux machines (so should default to 0).

Is there something I can do to stop this error?

Here is the log from FreeTDS of a bad run:


    util.c:156:Changed query state from IDLE to QUERYING
    write.c:140:tds_put_string converting 27 bytes of "EXEC
DWTOOLS.LoadFromStage;"
    write.c:168:tds_put_string wrote 54 bytes
    util.c:156:Changed query state from QUERYING to PENDING
    net.c:741:Sending packet
    0000 01 01 00 3e 00 00 01 00-45 00 58 00 45 00 43 00 |...>.... E.X.E.C.|
    0010 20 00 44 00 57 00 54 00-4f 00 4f 00 4c 00 53 00 | .D.W.T. O.O.L.S.|
    0020 2e 00 4c 00 6f 00 61 00-64 00 46 00 72 00 6f 00 |..L.o.a. d.F.r.o.|
    0030 6d 00 53 00 74 00 61 00-67 00 65 00 3b 00       |m.S.t.a. g.e.;.|

    net.c:1257:GNUTLS: level 4:
      REC[0x9a833c8]: Sending Packet[5] Application Data(23) with length: 62
    net.c:1257:GNUTLS: level 7:
      WRITE: enqueued 101 bytes for 0x9a574b8. Total 101 bytes.
    net.c:1257:GNUTLS: level 7:
      WRITE FLUSH: 101 bytes in buffer.
    net.c:1240:in tds_push_func
    net.c:1257:GNUTLS: level 7:
      WRITE: wrote 101 bytes, 0 bytes left.
    net.c:1257:GNUTLS: level 4:
      REC[0x9a833c8]: Sent Packet[6] Application Data(23) with length: 101
    token.c:540:tds_process_tokens(0x9a574b8, 0xbfcb9ca8, 0xbfcb9cac, 0x6914)
    util.c:156:Changed query state from PENDING to READING
    net.c:1199:in tds_pull_func
    util.c:331:tdserror(0x9a54e80, 0x9a574b8, 20004, 104)
    odbc.c:2270:msgno 20004 20003
    util.c:361:tdserror: client library returned TDS_INT_CANCEL(2)
    util.c:384:tdserror: returning TDS_INT_CANCEL(2)
    util.c:156:Changed query state from READING to DEAD
    net.c:1257:GNUTLS: level 7:
      READ: -1 returned from 0x9a574b8, errno=104 gerrno=0
    net.c:1257:GNUTLS: level 2:
      ASSERT: gnutls_buffers.c:344
    net.c:1257:GNUTLS: level 2:
      ASSERT: gnutls_buffers.c:625
    net.c:1257:GNUTLS: level 2:
      ASSERT: gnutls_record.c:969
    token.c:555:processing result tokens.  marker is  0()
    token.c:122:tds_process_default_tokens() marker is 0()
    token.c:125:leaving tds_process_default_tokens() connection dead
    util.c:104:logic error: cannot change query state from DEAD to PENDING
    odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 0
    odbc.c:3535:    result_type=4055, TDS_DONE_COUNT=0, TDS_DONE_ERROR=0
    odbc.c:3374:_SQLExecute: odbc_process_tokens returned result_type 4048
    odbc.c:3450:SQLExecute: bad results
    error.c:517:SQLGetDiagRec(3, 0x9a89fe8, 1, 0xbfcb9ce6, 0xbfcb98b8,
0xbfcb9ae6, 512, 0xbfcb98bc)
    error.c:566:SQLGetDiagRec: "[FreeTDS][SQL Server]Read from the
server failed"
    error.c:517:SQLGetDiagRec(3, 0x9a89fe8, 2, 0xbfcb9ce6, 0xbfcb98b8,
0xbfcb9ae6, 512, 0xbfcb98bc)
    odbc.c:3980:SQLFreeHandle(3, 0x9a89fe8)
    odbc.c:4075:_SQLFreeStmt(0x9a89fe8, 1, 0)
    odbc.c:4718:_SQLGetConnectAttr(0x9a55d78, 102, 0xbfcb9e90, -5, (nil))
    odbc.c:2240:SQLDisconnect(0x9a55d78)
    mem.c:615:tds_free_all_results()
    net.c:1257:GNUTLS: level 6:
      BUF[HSK]: Cleared Data from buffer
    net.c:1257:GNUTLS: level 4:
      REC[0x9a833c8]: Epoch #1 freed
    odbc.c:3980:SQLFreeHandle(2, 0x9a55d78)
    odbc.c:4006:_SQLFreeConnect(0x9a55d78)
    odbc.c:3980:SQLFreeHandle(1, 0x9a552f0)
    odbc.c:4050:_SQLFreeEnv(0x9a552f0)

Here is the log from a good run - the same proc, just slightly
different data - there seems to be no error running the proc from
Windows:

    util.c:156:Changed query state from IDLE to QUERYING
    write.c:140:tds_put_string converting 27 bytes of "EXEC
DWTOOLS.LoadFromStage;"
    write.c:168:tds_put_string wrote 54 bytes
    util.c:156:Changed query state from QUERYING to PENDING
    net.c:741:Sending packet
    0000 01 01 00 3e 00 00 01 00-45 00 58 00 45 00 43 00 |...>.... E.X.E.C.|
    0010 20 00 44 00 57 00 54 00-4f 00 4f 00 4c 00 53 00 | .D.W.T. O.O.L.S.|
    0020 2e 00 4c 00 6f 00 61 00-64 00 46 00 72 00 6f 00 |..L.o.a. d.F.r.o.|
    0030 6d 00 53 00 74 00 61 00-67 00 65 00 3b 00       |m.S.t.a. g.e.;.|

    net.c:1257:GNUTLS: level 4:
      REC[0x96ed3c8]: Sending Packet[5] Application Data(23) with length: 62
    net.c:1257:GNUTLS: level 7:
      WRITE: enqueued 101 bytes for 0x96c14b8. Total 101 bytes.
    net.c:1257:GNUTLS: level 7:
      WRITE FLUSH: 101 bytes in buffer.
    net.c:1240:in tds_push_func
    net.c:1257:GNUTLS: level 7:
      WRITE: wrote 101 bytes, 0 bytes left.
    net.c:1257:GNUTLS: level 4:
      REC[0x96ed3c8]: Sent Packet[6] Application Data(23) with length: 101
    token.c:540:tds_process_tokens(0x96c14b8, 0xbfd5aeb8, 0xbfd5aebc, 0x6914)
    util.c:156:Changed query state from PENDING to READING
    net.c:1199:in tds_pull_func
    net.c:1257:GNUTLS: level 7:
      READ: Got 5 bytes from 0x96c14b8
    net.c:1257:GNUTLS: level 7:
      READ: read 5 bytes from 0x96c14b8
    net.c:1257:GNUTLS: level 7:
      RB: Have 0 bytes into buffer. Adding 5 bytes.
    net.c:1257:GNUTLS: level 7:
      RB: Requested 5 bytes
    net.c:1257:GNUTLS: level 4:
      REC[0x96ed3c8]: Expected Packet[5] Application Data(23) with length: 8
    net.c:1257:GNUTLS: level 4:
      REC[0x96ed3c8]: Received Packet[5] Application Data(23) with length: 48
    net.c:1199:in tds_pull_func
    net.c:1257:GNUTLS: level 7:
      READ: Got 48 bytes from 0x96c14b8
    net.c:1257:GNUTLS: level 7:
      READ: read 48 bytes from 0x96c14b8
    net.c:1257:GNUTLS: level 7:
      RB: Have 5 bytes into buffer. Adding 48 bytes.
    net.c:1257:GNUTLS: level 7:
      RB: Requested 53 bytes
    net.c:1257:GNUTLS: level 4:
      REC[0x96ed3c8]: Decrypted Packet[5] Application Data(23) with length: 22
    net.c:1257:GNUTLS: level 6:
      BUF[REC]: Inserted 22 bytes of Data(23)
    net.c:1257:GNUTLS: level 6:
      BUFFER[REC][AD]: Read 8 bytes of Data(23)
    net.c:555:Received header
    0000 04 01 00 16 03 2f 01 00-                        |...../..|

    net.c:1257:GNUTLS: level 6:
      BUFFER[REC][AD]: Read 14 bytes of Data(23)
    net.c:609:Received packet
    0000 04 01 00 16 03 2f 01 00-79 00 00 00 00 fe 00 00 |...../.. y.......|
    0010 e0 00 00 00 00 00      -                        |......|

    token.c:555:processing result tokens.  marker is  79(RETURNSTATUS)
    token.c:690:tds_process_tokens: return status is 0
    util.c:156:Changed query state from READING to PENDING
    odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 1
    odbc.c:3535:    result_type=4043, TDS_DONE_COUNT=0, TDS_DONE_ERROR=0
    token.c:540:tds_process_tokens(0x96c14b8, 0xbfd5aeb8, 0xbfd5aebc, 0x6914)
    util.c:156:Changed query state from PENDING to READING
    token.c:555:processing result tokens.  marker is  fe(DONEPROC)
    token.c:2339:tds_process_end: more_results = 0
    was_cancelled = 0
    error = 0
    done_count_valid = 0
    token.c:2355:tds_process_end() state set to TDS_IDLE
    util.c:156:Changed query state from READING to IDLE
    token.c:2370:                rows_affected = 0
    util.c:104:logic error: cannot change query state from IDLE to PENDING
    odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 1
    odbc.c:3535:    result_type=4053, TDS_DONE_COUNT=0, TDS_DONE_ERROR=0
    odbc.c:3578:odbc_process_tokens: processed TDS_DONEPROC_RESULT
    token.c:540:tds_process_tokens(0x96c14b8, 0xbfd5aeb8, 0xbfd5aebc, 0x26914)
    token.c:543:tds_process_tokens() state is COMPLETED
    odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 2
    odbc.c:3535:    result_type=4052, TDS_DONE_COUNT=0, TDS_DONE_ERROR=0
    odbc.c:3374:_SQLExecute: odbc_process_tokens returned result_type 4046
    odbc.c:4506:_SQLRowCount(0x96f3fe8, 0xbfd5b0b8)
    odbc.c:4525:SQLRowCount returns 0, row count -1
    odbc.c:3980:SQLFreeHandle(3, 0x96f3fe8)
    odbc.c:4075:_SQLFreeStmt(0x96f3fe8, 1, 0)
    odbc.c:4718:_SQLGetConnectAttr(0x96bfd78, 102, 0xbfd5b240, -5, (nil))
    odbc.c:2240:SQLDisconnect(0x96bfd78)
    mem.c:615:tds_free_all_results()
    net.c:1257:GNUTLS: level 6:
      BUF[HSK]: Cleared Data from buffer
    net.c:1257:GNUTLS: level 4:
      REC[0x96ed3c8]: Epoch #1 freed
    util.c:156:Changed query state from IDLE to DEAD
    odbc.c:3980:SQLFreeHandle(2, 0x96bfd78)
    odbc.c:4006:_SQLFreeConnect(0x96bfd78)
    odbc.c:3980:SQLFreeHandle(1, 0x96bf2f0)
    odbc.c:4050:_SQLFreeEnv(0x96bf2f0)

I've isolated it to just running the proc with slightly different sets
of data. EXECing the proc from Perl on Windows or in SSMS with all
datasets works.  The proc works on most datasets in Linux, except when
it gets this error.

Thanks,

Cade

Cade Roux
cade AT roux.org
504-717-4887