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

Discussion:

Cade Roux

2012-11-15 03:39:35 UTC

Permalink

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

Frediano Ziglio

2012-11-17 19:48:29 UTC

Permalink

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

Post by Cade Roux
http://dba.stackexchange.com/questions/28692/sql-08s01-error-in-freetds-azure-when-executing-stored-proc-for-a-few-minutes-fr
I get this error on Linux (Ubuntu and CentOS) when executing a stored
[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
$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?
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.;.|
REC[0x9a833c8]: Sending Packet[5] Application Data(23) with length: 62
WRITE: enqueued 101 bytes for 0x9a574b8. Total 101 bytes.
WRITE FLUSH: 101 bytes in buffer.
net.c:1240:in tds_push_func
WRITE: wrote 101 bytes, 0 bytes left.
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
READ: -1 returned from 0x9a574b8, errno=104 gerrno=0
ASSERT: gnutls_buffers.c:344
ASSERT: gnutls_buffers.c:625
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()
BUF[HSK]: Cleared Data from buffer
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
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.;.|
REC[0x96ed3c8]: Sending Packet[5] Application Data(23) with length: 62
WRITE: enqueued 101 bytes for 0x96c14b8. Total 101 bytes.
WRITE FLUSH: 101 bytes in buffer.
net.c:1240:in tds_push_func
WRITE: wrote 101 bytes, 0 bytes left.
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
READ: Got 5 bytes from 0x96c14b8
READ: read 5 bytes from 0x96c14b8
RB: Have 0 bytes into buffer. Adding 5 bytes.
RB: Requested 5 bytes
REC[0x96ed3c8]: Expected Packet[5] Application Data(23) with length: 8
REC[0x96ed3c8]: Received Packet[5] Application Data(23) with length: 48
net.c:1199:in tds_pull_func
READ: Got 48 bytes from 0x96c14b8
READ: read 48 bytes from 0x96c14b8
RB: Have 5 bytes into buffer. Adding 48 bytes.
RB: Requested 53 bytes
REC[0x96ed3c8]: Decrypted Packet[5] Application Data(23) with length: 22
BUF[REC]: Inserted 22 bytes of Data(23)
BUFFER[REC][AD]: Read 8 bytes of Data(23)
net.c:555:Received header
0000 04 01 00 16 03 2f 01 00- |...../..|
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()
BUF[HSK]: Cleared Data from buffer
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

Cade Roux

2012-11-19 02:14:37 UTC

Permalink

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

Post by Frediano Ziglio
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

_______________________________________________
FreeTDS mailing list
FreeTDS at lists.ibiblio.org
http://lists.ibiblio.org/mailman/listinfo/freetds

James K. Lowden

2012-11-19 13:55:25 UTC

Permalink

On Sun, 18 Nov 2012 20:14:37 -0600

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).

What does TDSDUMP indicate about the first batch of rows?

I suspect the error messages aren't being printed.

--jkl

Cade Roux

2012-11-21 15:03:28 UTC

Permalink

It took a large number of batches in the loop to get to one which
showed the problem, so I've got a 160MB log now, and somewhere before
the row count check and the last 12 inserts is the clue. I might set
up another test. I'm thinking that Azure "pauses" the connection at
some point and the inserts fail and then the connection starts working
again (I reuse the same connection for all the files). Why this
happens only on the start of a file is a bit of a mystery, although
obviously there is a small time gap between files for the count to be
take, the file to be close, the new file to be opened, and the table
to be truncated before the next set of inserts. Also weird is that
the first truncate step always seems to be working - just the first
few inserts are failing. I'm wondering if SQL Azure can do the
truncate out of order on the connection? That doesn't seem possible
on the same connection. But that would definitely explain the
behavior - if all the inserts are actually working but the TRUNCATE
comes at the wrong time. Never saw this behavior in the same script
on Windows, though. None of this really make any sense.

Perhaps the suggestion on my StackOverflow Q to count the rows after
every insert wasn't such a bad idea (although obviously not feasible
in practice).

Thanks,

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

Post by James K. Lowden
On Sun, 18 Nov 2012 20:14:37 -0600

What does TDSDUMP indicate about the first batch of rows?
I suspect the error messages aren't being printed.
--jkl
_______________________________________________
FreeTDS mailing list
FreeTDS at lists.ibiblio.org
http://lists.ibiblio.org/mailman/listinfo/freetds

James K. Lowden

2012-11-21 20:36:33 UTC

Permalink

On Wed, 21 Nov 2012 09:03:28 -0600

Post by Cade Roux
I'm thinking that Azure "pauses" the connection at
some point and the inserts fail and then the connection starts working
again (I reuse the same connection for all the files). Why this
happens only on the start of a file is a bit of a mystery, although
obviously there is a small time gap between files for the count to be
take, the file to be close, the new file to be opened, and the table
to be truncated before the next set of inserts.

Looking back at your first message, I see this error in your log:

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

tds_pull_func reads encrypted data. From the log messages, it would
appear it called tds_goodread, which eventually called read(2), which
failed with errno 104. Unfortunately the error processing doesn't
write the error message associated with 104 for your system. However,
it seems that the server drops the connection, and SQLExecute then fails
with "Read from SQL Server failed".

The server closed the connection. Why? It doesn't say. Searching
Google for "azure timeout", I found

http://blogs.msdn.com/b/avkashchauhan/archive/2011/11/12/windows-azure-load-balancer-timeout-details.aspx

which suggests that Azure will close the connection after some
time, depending on load. Hard to tell exactly what's going on between
all the HTTP and .Net frou-frou.

There is of course no need to silently terminate the connection. The
client is patiently waiting for the server to send data. If the server
wishes to close the connection for any reason, it's still free to issue
an error message first, allowing the client to notify the user.

--jkl

Cade Roux

2012-11-21 20:50:05 UTC

Permalink

I see - that explains the problem when the flat->star-model transform
proc after the load was taking a long time (but again, that was
working from a Windows-based run of the identical script, but if there
is similar one-sided termination for some reason only Azure knows,
then that is explained).

Now that the flat->star transform is basically instant, and there
should be constant client traffic from the truncate, the inserts, the
row count and the transform, I need to break down the log from a
reproduced case adding some timings to make it easier to post here.

Thanks,

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

Post by James K. Lowden
On Wed, 21 Nov 2012 09:03:28 -0600

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
READ: -1 returned from 0x9a574b8, errno=104 gerrno=0
tds_pull_func reads encrypted data. From the log messages, it would
appear it called tds_goodread, which eventually called read(2), which
failed with errno 104. Unfortunately the error processing doesn't
write the error message associated with 104 for your system. However,
it seems that the server drops the connection, and SQLExecute then fails
with "Read from SQL Server failed".
The server closed the connection. Why? It doesn't say. Searching
Google for "azure timeout", I found
http://blogs.msdn.com/b/avkashchauhan/archive/2011/11/12/windows-azure-load-balancer-timeout-details.aspx
which suggests that Azure will close the connection after some
time, depending on load. Hard to tell exactly what's going on between
all the HTTP and .Net frou-frou.
There is of course no need to silently terminate the connection. The
client is patiently waiting for the server to send data. If the server
wishes to close the connection for any reason, it's still free to issue
an error message first, allowing the client to notify the user.
--jkl
_______________________________________________
FreeTDS mailing list
FreeTDS at lists.ibiblio.org
http://lists.ibiblio.org/mailman/listinfo/freetds

Frediano Ziglio

2012-11-21 21:36:42 UTC

Permalink

Can you try this patch?

It decrease keepalive times to 30 seconds. Well.. where supported
(Linux for sure).

Frediano

Post by Cade Roux
I see - that explains the problem when the flat->star-model transform
proc after the load was taking a long time (but again, that was
working from a Windows-based run of the identical script, but if there
is similar one-sided termination for some reason only Azure knows,
then that is explained).
Now that the flat->star transform is basically instant, and there
should be constant client traffic from the truncate, the inserts, the
row count and the transform, I need to break down the log from a
reproduced case adding some timings to make it easier to post here.
Thanks,
Cade
Cade Roux
cade at roux.org
504-717-4887

Post by James K. Lowden
On Wed, 21 Nov 2012 09:03:28 -0600

_______________________________________________
FreeTDS mailing list
FreeTDS at lists.ibiblio.org
http://lists.ibiblio.org/mailman/listinfo/freetds

-------------- next part --------------
A non-text attachment was scrubbed...
Name: more_keepalive.diff
Type: application/octet-stream
Size: 1270 bytes
Desc: not available
Url : http://lists.ibiblio.org/pipermail/freetds/attachments/20121121/d6ca26d3/attachment.obj

James K. Lowden

2012-11-21 22:18:08 UTC

Permalink

On Wed, 21 Nov 2012 14:50:05 -0600

Post by Cade Roux
Now that the flat->star transform is basically instant, and there
should be constant client traffic from the truncate, the inserts, the
row count and the transform, I need to break down the log from a
reproduced case adding some timings to make it easier to post here.

Yes. I would time each call to SQLExecute. You may find that "long"
running queries end in 20004 errors, and may be able to guesstimate the
value of "long".

FWIW, FreeTDS does call setsockopt(2) with SO_KEEPALIVE if the host
system supports it, cf. net.c around line 217. You might want to check
your build log carefully to make sure it's enabled in case it matters.

--jkl

Frediano Ziglio

2012-11-21 22:53:44 UTC

Permalink

Post by James K. Lowden
On Wed, 21 Nov 2012 14:50:05 -0600

Yes. I would time each call to SQLExecute. You may find that "long"
running queries end in 20004 errors, and may be able to guesstimate the
value of "long".
FWIW, FreeTDS does call setsockopt(2) with SO_KEEPALIVE if the host
system supports it, cf. net.c around line 217. You might want to check
your build log carefully to make sure it's enabled in case it matters.

Yes,
however MS requirements are more strictly that Unix. By default many
systems starts sending keepalive after 2 hours idle, much more that 1
minute!

I send a patch (was not on ML? strange!) that lower the limit. Linux,
AIX, FreeBSD and HP-UX should support these options.

Frediano

James K. Lowden

2012-11-23 17:40:45 UTC

Permalink

On Wed, 21 Nov 2012 22:53:44 +0000

Post by Frediano Ziglio
Yes,
however MS requirements are more strictly that Unix. By default many
systems starts sending keepalive after 2 hours idle, much more that 1
minute!

Do you have a reference for Microsoft's keepalive requirements?

I remember we had a problem with a long-running idle watchdog process
that would occasionally end with "read from SQL Server failed". I
never determined why.

--jkl

Frediano Ziglio

2012-11-23 18:34:34 UTC

Permalink

Post by James K. Lowden
On Wed, 21 Nov 2012 22:53:44 +0000

Post by Frediano Ziglio
Yes,
however MS requirements are more strictly that Unix. By default many
systems starts sending keepalive after 2 hours idle, much more that 1
minute!

Do you have a reference for Microsoft's keepalive requirements?
I remember we had a problem with a long-running idle watchdog process
that would occasionally end with "read from SQL Server failed". I
never determined why.

Yes, have a look at
http://blogs.msdn.com/b/sql_protocols/archive/2006/03/09/546852.aspx

However this is confirmed by the settings. They should be settings on
server side so client "could" avoid them but in case server was not
configured in such way the MS load balanced would hit and do its job.

The configuration at end seems
- idle timeout (first keepalive after idle) 30 seconds
- interval (time it try to send another keepalive if acknowledge is
not received) 1 second
- keepalive count (number of retry without acknowledge before disconnection) 5.

The default under Linux is 7200, 75, 9 while on FreeBSD is 7200, 75, 8.

Frediano

James K. Lowden

2012-11-23 23:16:23 UTC

Permalink

On Fri, 23 Nov 2012 18:34:34 +0000

Post by Frediano Ziglio

Post by James K. Lowden
Do you have a reference for Microsoft's keepalive requirements?
I remember we had a problem with a long-running idle watchdog
process that would occasionally end with "read from SQL Server
failed". I never determined why.

Yes, have a look at
http://blogs.msdn.com/b/sql_protocols/archive/2006/03/09/546852.aspx

Thank you. That description is at least concrete in what they do. As
for why they do it, it's a vague as anything else I've seen. The link
provided in that blog post

http://support.microsoft.com/kb/137983/?sd=RMVP&fr=1

says

"If the connection processes are not cleared up for any reason,
they become "orphaned" or "ghost" processes. These processes may use up
valuable resources such as locks and user connections. "

I have just one quibble: there isn't any reason.

A process holding locks is resumably executing a query and will in time
respond to the client. If the client has disconnected at that time,
the server will receive ECONNRESET, "Connection reset by peer" when it
sends the DONE packet.

A process not holding locks -- an idle connection -- should use very
few resources on a TDS server, measured in kilobytes of memory. On the
client side we devote less than 10 KB to a connection; surely the
server has little reason to hold much more. Idle connections have good
reason to exist. Setting up the server to disconnect them does more
harm than good because for most needs it creates administrative work
disproportionate to the spared resources. (Bear in mind that most
disconnections, including an application crash, are detected
through normal TCP/IP mechanisms.)

In the instant case, Azure is executing a query. Instead of finishing
the job and sending the DONE packet and letting tcp/ip tell it if the
client has disconnected, Azure periodically checks via keep-alive and
aborts the connection. Transient failures, the very thing tcp/ip was
designed to cope with, thus lead to unusable sessions. Only the
innocent are surprised the vendor would do that without documenting it
and without using available end-to-end TDS messages instead.

Richard Stevens correctly observed that "keep alive" is misnamed.
It's more properly called "make dead" because it never keeps a
connection alive; it can only kill one.

--jkl