Background:
I am running a TCP server on one machine with multiple clients on separate machines connecting over TCP, and I am monitoring network traffic with Wireshark, as well as with logging from within my server application, and through the System.Diagnostics tracelistener on System.Net.Sockets in verbose mode.
Problem:
Prompted to examine my logs due to some unexpected disconnects, I see some very strange behavior. According to the server application logs, and the System.Diagnostic output logs, my server is sending a 4 byte packet to a client using begin/end send. The BeginSend completes, and the EndSend also completes saying that it successfully sent the 4 byte packet.
However, when I look at the Wireshark logs, that packet never shows up. I am running Wireshark on the server machine, so there should be no reason for the packet to show up in my server and trace logs, but not in the Wireshark logs on the same machine.
Also, there is an unexpected disconnect that occurs soon after the supposedly successful packet send (~30 seconds later), which is caused by a SocketException on my server's EndReceive method. But during the time between the attempted send from the server, the server is acknowledging packets received from the client, so I know the connection is still active.
Has anyone out there had a similar experience, or know of a bug or something that might be causing this?
I would hate to think that this is occurring at the socket level, where TCP is saying that my packet is sent when it never even made it onto the wire, which would mean that I cannot rely on TCP as a reliable transport (which of course is the whole point of TCP).
Log Samples
From my server application:
2011-09-07 10:41:38,812 Attempting to send Packet (BeginSend - 4 bytes)
2011-09-07 10:41:38,812 Sent Packet (EndSend - 4 bytes)
From the System.Diagnostics trace log:
System.Net.Sockets Verbose: 0 : [4376] Socket#19699911::BeginSend()
DateTime=2011-09-07T17:41:38.8125000Z
System.Net.Sockets Verbose: 0 : [0980] Data from Socket#19699911::PostCompletion
DateTime=2011-09-07T17:41:38.8125000Z
System.Net.Sockets Verbose: 0 : [0980] 00000000 : 02 04 00 00 : ....
DateTime=2011-09-07T17:41:38.8125000Z
System.Net.Sockets Verbose: 0 : [4376] Socket#19699911::EndSend(OverlappedAsyncResult#44209720)
DateTime=2011-09-07T17:41:38.8125000Z
System.Net.Sockets Verbose: 0 : [4376] Exiting Socket#19699911::EndSend() -> 4#4
DateTime=2011-09-07T17:41:38.8125000Z
System.Net.Sockets Verbose: 0 : [4376] Exiting Socket#19699911::BeginSend() -> OverlappedAsyncResult#44209720
DateTime=2011-09-07T17:41:38.8125000Z
I would paste the Wireshark logs, too, but essentially there is nothing registering on the interface for that device at that time, except for the packets coming from the client, and the corresponding acknowledgments from the server.
Edit: As requested, here is the code for the send (shortened for space, and other reasons). Pretty simple, not much in the way of anything that could go wrong.
In my BeginSend method:
socket.BeginSend(data, 0, data.Length, SocketFlags.None, EndSend, state);
In my EndSend method:
bytesSent = socket.EndSend(ar);
Note: This is not my first rodeo, as they say... I have been writing servers and clients using TCP sockets for the last 15 years, and have never experienced this before.
Also, the version of .NET that I am using is 4.0... if that is of any relevance.
Help!
