FreeTDS Development Group

[Jeff.Goodwin AT fairchildsemi.com]

freetds-bounces AT lists.ibiblio.org wrote on 03/17/2009 06:08:38 PM:

Thanks for your response.

> 
> Here's a wild theory.  Do you have a keepalive setting that expires 
> depending on whether anything shows up in your message queue within 
> a particular time frame?  Say the database connection dies if it has
> been inactive for 4 hours.  As long as you have messages in the 
> queue more frequently than that, you'll stay up, but if there is 
> ever more than 4 hours between messages you'll get disconnected.  Do
> you have a way to control how often you receive a message in your 
> test environment?

In general, the messages are fairly constant, but there are some gaps. 
More on this below.

> 
> $ tcpip show protocol tcp
> 
> should tell you whether there have been any connections dropped by 
keepalive.

I had some keepalive drops.  As the system is on the other side of the 
world, we do have occasional drops from our x-sessions.  I had a x-session 
drop last night when I was checking the counters.  Upon logging in again, 
I found the keepalive drop counter had incremented.

Anyway, I set up a detached process to write the counters out to a file 
every five minutes.  When the program failed today, I checked the before 
and after file.  The keepalive drop counter did not increment.

> 
> Can you reproduce the problem by simply logging in with tsql and 
> letting it sit overnight or do you have to have your whole 
> application/messaging setup running?

I'm trying this now and should know tomorrow.


As had been suggested earlier, I ran TCPDUMP to capture the packets during 
the disconnect.  When looking at the packets in Wireshark, this seemed to 
be the sequence:

Client -> TDS5 Query
Server -> Response
Client -> ACK
Client -> TDS5 Query
Server -> Response
Client -> ACK
...and so on until...
Client -> TDS5 Query
Server -> Response
Client -> ACK
Server -> FIN/ACK

This FIN/ACK seems to be in response to the previous ACK and comes 1070 
seconds later.  Looking back through the couple hours of capture data, 
there were other gaps of 800+ seconds, but none as large as the 1070 
second gap.  I looked through the program's logfile and found gaps much 
larger than the 1070 seconds recorded here (like 2220 seconds).

I've attached the pcap file that includes the last 21 packets of the 
capture.  If a sharper person than I knows what this means, I'd like to be 
enlightened.  :+)

I only captured the data between the server and client, so any packets 
from other systems are not included.

The log data is below.  I noticed from the time stamps that the last 
successful update and program termination are 30 minutes apart.  This 
corresponds to the time difference in the TCPDUMP capture.  I looked at 
several other logs and found the time difference between the last 
successful update and program termination varied from three minutes to 30 
minutes.

-Jeff

20090319015535 Frame Stock               : '                         '
20090319015535 Successfully inserted PTNO: ZS10242229
DB error = 20004,  Severity code = 9
DB error msg Read from the server failed
OS error # 54
OS error msg connection reset by peer
Error string is: connection reset by peer
DB error = 20047,  Severity code = 1
DB error msg DBPROCESS is dead or not enabled
OS error # 0
OS error msg error 0
Error string is: error 0
FreeTDS: db-lib: exiting because client error handler returned 0 for msgno 
20047
  SYSTEM       job terminated at 19-MAR-2009 02:25:31.77

  Charged CPU time:        0 00:01:42.64      Elapsed time:       1 
00:23:26.83


SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]util.c;3:162:Changed query 
state from IDLE to QUERYING
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]util.c;3:162:Changed query 
state from QUERYING to PENDING
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]net.c;5:784:Sending packet
0000 0f 01 00 1c 00 00 00 00-21 0f 00 00 00 00 73 65 |........ !.....se|
0010 74 20 72 6f 77 63 6f 75-6e 74 20 31             |t rowcou nt 1|

SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:4532:dbsqlok(BF9AB0)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]util.c;3:334:tdserror(BF9970, 
BF9DD0, 20004, 54)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:7782:dbperror(BF9AB0, 
20004, 54)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:7835:20004: "Read 
from the server failed"
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:4747:dbdead(BF9AB0) 
[alive]
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:7856:"Read from 
the server failed", client returns 2 (INT_CANCEL)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]util.c;3:368:tdserror: client 
library returned TDS_INT_CANCEL(2)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]util.c;3:389:tdserror: 
returning TDS_INT_CANCEL(2)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]util.c;3:162:Changed query 
state from PENDING to DEAD
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:4565:dbsqlok() not 
done, calling tds_process_tokens()
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]token.c;1:495:tds_process_tokens(BF9DD0,
 
7ACDFB00, 7ACDFB08, 0x6914)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.TDS]util.c;3:118:logic error: 
cannot change query state from DEAD to READING
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:1243:dbcmd(BF9AB0, 
update INFOTAP)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:7782:dbperror(BF9AB0, 
20047, 0)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:7835:20047: 
"DBPROCESS is dead or not enabled"
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:4747:dbdead(BF9AB0) 
[dead]
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:7856:"DBPROCESS is 
dead or not enabled", client returns 0 (INT_EXIT)
SYS$SYSDEVICE:[FREETDS.FREETDS-0_82.SRC.DBLIB]dblib.c;1:7903:FreeTDS: 
db-lib: exiting because client error handler returned 0 for ms
gno 20047

Attachment: tcpdump.pcap
Description: Binary data