- Joined
- Mar 20, 2004
- Location
- Southeastern NC
Hey guys. We have an app at my work that was developed in-house, and are experiencing a strange intermittent timeout issue with it. I have tried everything I can think of to figure this out and we are about to open a case with Microsoft. Our developer posted this same question up on the MSDN forums and has not received any useful response. I figured I would try my luck here as well.
The app in question is .NET and talks to a SQL 2005 server.
Intermittently, the app will throw an exception citing a network timeout. This happens when the user makes changes to a record and clicks the submit button. There is no apparent pattern that the timeout follows, and it is happening across multiple machines, both XP and Win7.
I have run some netmon traces as well as SQL traces and here is where it gets interesting.
Regarding the SQL traces, I see nothing abnormal. The queries and updates made to the DB run in less than a second, so I know it's not a long DB operation causing the timeout.
The strange parts comes with the netmon traces. When the application is working normally, the TDS prelogin packet sends specific version information. In this case, version 7.2 (0x72090002) along with the proper HEX code. The server responds normally with a TDS response packet. Then the TLS handshake occurs, and all subsequent queries and updates within the app work properly.
When the app times out, there is a totally different sequence of events. To start, the client sends a TDS packet with an unspecified version and no HEX code as follows: Version = 7.300000(No version information available, using the default version).
Once the client sends this strange TDS prelogin packet, the server does not respond with a TDS response as it should. It simply sends a generic TCP Ack. The client then sends a Fin, followed by several packets that are seen as dropped. The server finally resets the TCP session. This is when the timeout exception is thrown within the app.
Here are some trace snippets.
Working Session:
Failed Session:
I guess my biggest question at this point is what determines the TDS versioning when the client sends the prelogin packet? Why would the same app send one version of the TDS prelogin 99% of the time, and use another version which fails seemingly at random?
TIA for any insight
The app in question is .NET and talks to a SQL 2005 server.
Intermittently, the app will throw an exception citing a network timeout. This happens when the user makes changes to a record and clicks the submit button. There is no apparent pattern that the timeout follows, and it is happening across multiple machines, both XP and Win7.
I have run some netmon traces as well as SQL traces and here is where it gets interesting.
Regarding the SQL traces, I see nothing abnormal. The queries and updates made to the DB run in less than a second, so I know it's not a long DB operation causing the timeout.
The strange parts comes with the netmon traces. When the application is working normally, the TDS prelogin packet sends specific version information. In this case, version 7.2 (0x72090002) along with the proper HEX code. The server responds normally with a TDS response packet. Then the TLS handshake occurs, and all subsequent queries and updates within the app work properly.
When the app times out, there is a totally different sequence of events. To start, the client sends a TDS packet with an unspecified version and no HEX code as follows: Version = 7.300000(No version information available, using the default version).
Once the client sends this strange TDS prelogin packet, the server does not respond with a TDS response as it should. It simply sends a generic TCP Ack. The client then sends a Fin, followed by several packets that are seen as dropped. The server finally resets the TCP session. This is when the timeout exception is thrown within the app.
Here are some trace snippets.
Working Session:
Code:
17259 4:23:16 PM 3/21/2012 1813.9734517 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:Flags=......S., SrcPort=56245, DstPort=1433, PayloadLen=0, Seq=2125041766, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:675, IPv4:35}
17260 4:23:16 PM 3/21/2012 1813.9736238 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:Flags=...A..S., SrcPort=1433, DstPort=56245, PayloadLen=0, Seq=1248727534, Ack=2125041767, Win=64240 ( Negotiated scale factor 0x0 ) = 64240 {TCP:675, IPv4:35}
17261 4:23:16 PM 3/21/2012 1813.9736471 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:Flags=...A...., SrcPort=56245, DstPort=1433, PayloadLen=0, Seq=2125041767, Ack=1248727535, Win=256 (scale factor 0x8) = 65536 {TCP:675, IPv4:35}
17262 4:23:16 PM 3/21/2012 1813.9740502 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TDS TDS:Prelogin, Version = 7.2 (0x72090002), SPID = 0, PacketID = 1, Flags=...AP..., SrcPort=56245, DstPort=1433, PayloadLen=47, Seq=2125041767 - 2125041814, Ack=1248727535, Win=65536 {TDS:676, TCP:675, IPv4:35}
17263 4:23:16 PM 3/21/2012 1813.9743167 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TDS TDS:Response, Version = 7.2 (0x72090002), SPID = 0, PacketID = 1, Flags=...AP..., SrcPort=1433, DstPort=56245, PayloadLen=43, Seq=1248727535 - 1248727578, Ack=2125041814, Win=64193 {TDS:676, TCP:675, IPv4:35}
17264 4:23:16 PM 3/21/2012 1813.9744721 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TLS TLS:TLS Rec Layer-1 HandShake: Client Hello. {TLS:678, SSLVersionSelector:677, TDS:676, TCP:675, IPv4:35}
17265 4:23:16 PM 3/21/2012 1813.9750008 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TLS TLS:TLS Rec Layer-1 HandShake: Server Hello.; TLS Rec Layer-2 Cipher Change Spec; TLS Rec Layer-3 HandShake: Encrypted Handshake Message. {TLS:678, SSLVersionSelector:677, TDS:676, TCP:675, IPv4:35}
17266 4:23:16 PM 3/21/2012 1813.9751784 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TLS TLS:TLS Rec Layer-1 Cipher Change Spec; TLS Rec Layer-2 HandShake: Encrypted Handshake Message. {TLS:678, SSLVersionSelector:677, TDS:676, TCP:675, IPv4:35}
17267 4:23:16 PM 3/21/2012 1813.9794838 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TLS TLS:TLS Rec Layer-1 SSL Application Data {TLS:678, SSLVersionSelector:677, TDS:676, TCP:675, IPv4:35}
17268 4:23:16 PM 3/21/2012 1813.9796939 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:Flags=...A...., SrcPort=1433, DstPort=56245, PayloadLen=0, Seq=1248727715, Ack=2125042468, Win=63539 (scale factor 0x0) = 63539 {TCP:675, IPv4:35}Failed Session:
Code:
17301 4:23:17 PM 3/21/2012 1814.3444957 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:Flags=......S., SrcPort=56246, DstPort=1433, PayloadLen=0, Seq=126092483, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192 {TCP:679, IPv4:35}
17302 4:23:17 PM 3/21/2012 1814.3446760 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:Flags=...A..S., SrcPort=1433, DstPort=56246, PayloadLen=0, Seq=2574830508, Ack=126092484, Win=64240 ( Negotiated scale factor 0x0 ) = 64240 {TCP:679, IPv4:35}
17303 4:23:17 PM 3/21/2012 1814.3446969 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:Flags=...A...., SrcPort=56246, DstPort=1433, PayloadLen=0, Seq=126092484, Ack=2574830509, Win=256 (scale factor 0x8) = 65536 {TCP:679, IPv4:35}
17304 4:23:17 PM 3/21/2012 1814.3450322 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TDS TDS:Prelogin, Version = 7.300000(No version information available, using the default version), SPID = 0, PacketID = 1, Flags=...AP..., SrcPort=56246, DstPort=1433, PayloadLen=47, Seq=126092484 - 126092531, Ack=2574830509, Win=65536 {TDS:680, TCP:679, IPv4:35}
17310 4:23:17 PM 3/21/2012 1814.5473148 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:Flags=...A...., SrcPort=1433, DstPort=56246, PayloadLen=0, Seq=2574830509, Ack=126092531, Win=64193 (scale factor 0x0) = 64193 {TCP:679, IPv4:35}
17350 4:23:32 PM 3/21/2012 1829.3411547 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:Flags=...A...F, SrcPort=56246, DstPort=1433, PayloadLen=0, Seq=126092531, Ack=2574830509, Win=256 (scale factor 0x8) = 65536 {TCP:679, IPv4:35}
17351 4:23:32 PM 3/21/2012 1829.3413104 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:Flags=...A...., SrcPort=1433, DstPort=56246, PayloadLen=0, Seq=2574830509, Ack=126092532, Win=64193 (scale factor 0x0) = 64193 {TCP:679, IPv4:35}
17502 4:24:02 PM 3/21/2012 1859.3551578 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:[Segment Lost]Flags=...A...., SrcPort=56246, DstPort=1433, PayloadLen=1, Seq=126092531 - 126092532, Ack=2574830509, Win=256 (scale factor 0x8) = 65536 {TCP:679, IPv4:35}
17503 4:24:02 PM 3/21/2012 1859.3553354 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:[Dup Ack #17351]Flags=...A...., SrcPort=1433, DstPort=56246, PayloadLen=0, Seq=2574830509, Ack=126092532, Win=64193 (scale factor 0x0) = 64193 {TCP:679, IPv4:35}
17510 4:24:02 PM 3/21/2012 1859.5096117 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:[Segment Lost]Flags=...A...., SrcPort=1433, DstPort=56246, PayloadLen=1, Seq=2574830508 - 2574830509, Ack=126092532, Win=64193 (scale factor 0x0) = 64193 {TCP:679, IPv4:35}
17511 4:24:02 PM 3/21/2012 1859.5096217 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:Flags=...A...., SrcPort=56246, DstPort=1433, PayloadLen=0, Seq=126092532, Ack=2574830509, Win=256 (scale factor 0x8) = 65536 {TCP:679, IPv4:35}
17633 4:24:32 PM 3/21/2012 1889.3695647 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:[ReTransmit #17502]Flags=...A...., SrcPort=56246, DstPort=1433, PayloadLen=1, Seq=126092531 - 126092532, Ack=2574830509, Win=256 (scale factor 0x8) = 65536 {TCP:679, IPv4:35}
17634 4:24:32 PM 3/21/2012 1889.3701087 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:[Dup Ack #17351]Flags=...A...., SrcPort=1433, DstPort=56246, PayloadLen=0, Seq=2574830509, Ack=126092532, Win=64193 (scale factor 0x0) = 64193 {TCP:679, IPv4:35}
17640 4:24:32 PM 3/21/2012 1889.5857530 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:[ReTransmit #17510]Flags=...A...., SrcPort=1433, DstPort=56246, PayloadLen=1, Seq=2574830508 - 2574830509, Ack=126092532, Win=64193 (scale factor 0x0) = 64193 {TCP:679, IPv4:35}
17641 4:24:32 PM 3/21/2012 1889.5857622 CustomApp.exe CLIENTPCNAME FULLSERVERNAME TCP TCP:[Dup Ack #17511]Flags=...A...., SrcPort=56246, DstPort=1433, PayloadLen=0, Seq=126092532, Ack=2574830509, Win=256 (scale factor 0x8) = 65536 {TCP:679, IPv4:35}
17740 4:24:57 PM 3/21/2012 1915.2723721 CustomApp.exe FULLSERVERNAME CLIENTPCNAME TCP TCP:Flags=...A.R.., SrcPort=1433, DstPort=56246, PayloadLen=0, Seq=2574830509, Ack=126092532, Win=0 (scale factor 0x0) = 0 {TCP:679, IPv4:35}I guess my biggest question at this point is what determines the TDS versioning when the client sends the prelogin packet? Why would the same app send one version of the TDS prelogin 99% of the time, and use another version which fails seemingly at random?
TIA for any insight
