Skip to Content.
Sympa Menu

freetds - [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 AT lists.ibiblio.org
  • Subject: [freetds] SQL-08S01 error in FreeTDS/Azure when executing stored proc for a few minutes from Linux (but not from Windows)
  • Date: Wed, 14 Nov 2012 21:39:35 -0600

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




Archive powered by MHonArc 2.6.24.

Top of Page