Skip to Content.
Sympa Menu

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

freetds AT lists.ibiblio.org

Subject: FreeTDS Development Group

List archive

Chronological Thread  
  • From: Frediano Ziglio <freddy77 AT gmail.com>
  • To: FreeTDS Development Group <freetds AT lists.ibiblio.org>
  • Subject: Re: [freetds] SQL-08S01 error in FreeTDS/Azure when executing stored proc for a few minutes from Linux (but not from Windows)
  • Date: Sat, 17 Nov 2012 19:48:29 +0000

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




Archive powered by MHonArc 2.6.24.

Top of Page