FreeTDS Development Group

[Cade Roux <cade AT roux.org>]

I ended up refactoring the stored procedure proc and it's much quicker
and I'm not able to see this problem occur on Linux now.  In any case,
it's allowed a different problem to be visible in later batches: I'm
finding problems with the inserts now where prepare and/or execute are
failing without giving any indication of an error
(http://stackoverflow.com/questions/13435327/perl-dbi-freetds-sqlazure-some-inserts-ignored).

Thanks,

Cade

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


On Sat, Nov 17, 2012 at 1:48 PM, Frediano Ziglio <freddy77 AT gmail.com> wrote:
> Hi,
>   20004 (TDSEREAD) indicate read error while 104 indicate connection
> reset (ECONNRESET) which confirm that server seem to have closed the
> connection for some reason. Could you enable times in dump to and see
> if the problem usually happen at same time?
>
> This could happen for network settings like firewall that timeout the
> connection after a while.
>
> Frediano
>
> 2012/11/15 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
>> _______________________________________________
>> FreeTDS mailing list
>> FreeTDS AT lists.ibiblio.org
>> http://lists.ibiblio.org/mailman/listinfo/freetds
> _______________________________________________
> FreeTDS mailing list
> FreeTDS AT lists.ibiblio.org
> http://lists.ibiblio.org/mailman/listinfo/freetds