FreeTDS Development Group

["James K. Lowden" <jklowden AT freetds.org>]

Jeff.Goodwin AT fairchildsemi.com wrote:
> 
> 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.  :+)

If you're looking for someone sharper than you on the Internet, you're not
as sharp as I thought.  ;-)

My analysis of the session is below.  I don't see any problem with the TDS
session.  Some of the data from longer packets is missing, but the server
responds normally to them and I have no reason to believe there's anything
wrong.  

It's as you and Craig both say.  The client sends a bog-standard ACK at
13:55:35 and ... sits.  The server disconnects at 14:13:25 with FIN.  It's
as though the server lost patience with the client.  

Note, it's the client's turn to speak.  The intervening 18 minutes of
silence (thank you, Rosemary Woods) is the client's to have at his
pleasure.  It's not CNN; there's no chatter requirement.  

In short:

1.  The TDS conversation looks perfectly OK. 
2.  The client has completed the tcp/ip acknowledgement.  
3.  The delay is also OK.  An idle connection can be quiet indefinitely.  
4.  The server disconnects the idle connection.  

>From a TDS point of view, there's *nothing* happening when the server
disconnects.  The server is waiting, and should continue to wait, for the
client to say something.  

I cannot explain the server's behavior yet.  If the server didn't see the
client's ACK, it would resend the prior packet (35:52(17) ack 270).  It
didn't resend, as far as we can tell.  

Hypothesis: The server didn't receive the ACK, and resent several times,
but we can't see those packets for the same reason the client can't. 
After 18 minutes or so, it gives up in disgust.  Resentfully, as it were. 


I have to study the packet headers and timings more carefully to verify
that possibility.  

Annotated log tail follows.  HTH.  

--jkl

[snip]
13:55:34.897000 172.21.141.242.52137 > 172.21.141.141.rfe: 
        P 28:242(214) ack 18 win 62780 (DF) (ttl 128, id 24546, len 254)
0x0000   4500 00fe 5fe2 4000 8006 266d ac15 8df2        E..._.@...&m....
0x0010   ac15 8d8d cba9 138a 3a12 dd0f 66f9 dfd4        ........:...f...
0x0020   5018 f53c fea0 0000 
                             0f01 00d6 0000 0000
                             ^^
>> TDS 5.0 packet, final, len 0xd6 (214 bytes)

>> Language  packet, len 0xc9 (201 bytes)
         vv
0x0030   21c9 0000 0000 7570 6461 7465 2049 4e46        !.....update.INF
0x0040   4f54 4150 2020 7365 7420 4652 4f4d 5f4c        OTAP..set.FROM_L
0x0050   4f43                                           OC

The decoded packet is only 82 of 254 bytes; 
we don't see the whole TDS packet.  

Need to increase the snarf size to get the whole thing.  

13:55:34.900000 172.21.141.141.rfe > 172.21.141.242.52137: 
        P 18:35(17) ack 242 win 49640 (DF) (ttl 64, id 4906, len 57)
0x0000   4500 0039 132a 4000 4006 b3ea ac15 8d8d        E..9.*@.@.......
0x0010   ac15 8df2 138a cba9 66f9 dfd4 3a12 dde5        ........f...:...
0x0020   5018 c1e8 3b08 0000 0401 0011 0000 0000        P...;...........
0x0030   fd10 0002 0001 0000 00   
         ^^
<< Result Set Done, rowcount OK, 1 row affected

13:55:35.020000 172.21.141.242.52137 > 172.21.141.141.rfe: 
        . ack 35 win 62780 (ttl 128, id 24547, len 40)
0x0000   4500 0028 5fe3 0000 8006 6742 ac15 8df2        E..(_.....gB....
0x0010   ac15 8d8d cba9 138a 3a12 dde5 66f9 dfe5        ........:...f...
0x0020   5010 f53c 08e2 0000                            P..<....

>> tcp/ip ack

13:55:35.052000 172.21.141.242.52137 > 172.21.141.141.rfe: 
        P 242:270(28) ack 35 win 62780 (ttl 128, id 24548, len 68)
0x0000   4500 0044 5fe4 0000 8006 6725 ac15 8df2        E..D_.....g%....
0x0010   ac15 8d8d cba9 138a 3a12 dde5 66f9 dfe5        ........:...f...
0x0020   5018 f53c 091f 0000 
                             0f01 001c 0000 0000        P..<............
                             ^^
>> TDS 5.0 packet, final, len 0x1c (28 bytes)

>> Language  packet, len 0x0f (15 bytes)
         vv
0x0030   210f 0000 0000 7365 7420 726f 7763 6f75        !.....set.rowcou
0x0040   6e74 2030                                      nt.0

>> "set rowcount 0"

13:55:35.053000 172.21.141.141.rfe > 172.21.141.242.52137: 
        P 35:52(17) ack 270 win 49640 (DF) (ttl 64, id 4907, len 57)
0x0000   4500 0039 132b 4000 4006 b3e9 ac15 8d8d        E..9.+@.@.......
0x0010   ac15 8df2 138a cba9 66f9 dfe5 3a12 de01        ........f...:...
0x0020   5018 c1e8 3aec 0000 0401 0011 0000 0000        P...:...........
0x0030   fd00 0002 0000 0000 00                         .........
         ^^
<< Result Set Done, no rowcount

13:55:35.220000 172.21.141.242.52137 > 172.21.141.141.rfe: 
        . ack 52 win 62780 (ttl 128, id 24549, len 40)
0x0000   4500 0028 5fe5 0000 8006 6740 ac15 8df2        E..(_.....g@....
0x0010   ac15 8d8d cba9 138a 3a12 de01 66f9 dff6        ........:...f...
0x0020   5010 f53c 08b5 0000                            P..<....

>> tcp/ip ack

14:13:25.438000 172.21.141.141.rfe > 172.21.141.242.52137: 
        F 52:52(0) ack 270 win 49640 (DF) (ttl 64, id 28897, len 40)
0x0000   4500 0028 70e1 4000 4006 5644 ac15 8d8d        E..(p.@.@.VD....
0x0010   ac15 8df2 138a cba9 66f9 dff6 3a12 de01        ........f...:...
0x0020   5011 c1e8 3c08 0000 0000 0000 0000             P...<.........

<< FIN!  Ciao, baby.  

14:13:25.438000 172.21.141.242.52137 > 172.21.141.141.rfe: 
        . ack 53 win 62780 (ttl 128, id 25876, len 40)
0x0000   4500 0028 6514 0000 8006 6211 ac15 8df2        E..(e.....b.....
0x0010   ac15 8d8d cba9 138a 3a12 de01 66f9 dff7        ........:...f...
0x0020   5010 f53c 08b4 0000                            P..<....

>> tcp/ip ack, can't say no....

14:25:31.620000 172.21.141.242.52137 > 172.21.141.141.rfe: 
        P 270:298(28) ack 53 win 62780 (ttl 128, id 27526, len 68)
0x0000   4500 0044 6b86 0000 8006 5b83 ac15 8df2        E..Dk.....[.....
0x0010   ac15 8d8d cba9 138a 3a12 de01 66f9 dff7        ........:...f...
0x0020   5018 f53c 08f0 0000 0f01 001c 0000 0000        P..<............
                             ^^
>> TDS 5.0 packet, final, len 0x1c (28 bytes)

>> Language  packet, len 0x0f (15 bytes)
         vv
0x0030   210f 0000 0000 7365 7420 726f 7763 6f75        !.....set.rowcou
0x0040   6e74 2031                                      nt.1

>> "set rowcount 1"

14:25:31.620000 172.21.141.141.rfe > 172.21.141.242.52137: 
        R 1727651831:1727651831(0) win 0 (DF) (ttl 64, id 28899, len 40)
0x0000   4500 0028 70e3 4000 4006 5642 ac15 8d8d        E..(p.@.@.VB....
0x0010   ac15 8df2 138a cba9 66f9 dff7 0000 0000        ........f.......
0x0020   5004 0000 1611 0000 0000 0000 0000             P.............

<< RESET 
[pins]