Sample Header Ad - 728x90

SQL-08S01 error in FreeTDS/Azure when executing stored proc for a few minutes from Linux (but not from Windows)

6 votes
1 answer
3088 views
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 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 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 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 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 Application Data(23) with length: 8 net.c:1257:GNUTLS: level 4: REC[0x96ed3c8]: Received Packet 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 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)
Asked by Cade Roux (6684 rep)
Nov 14, 2012, 10:04 PM
Last activity: Aug 16, 2022, 05:54 PM