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: Cade Roux <cade AT roux.org>
  • 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: Sun, 18 Nov 2012 20:14:37 -0600

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




Archive powered by MHonArc 2.6.24.

Top of Page