• How it works under the hood: A closer look at TCPIP and Winsock ETL tracing on Windows 7 and Windows 2008 R2 with an example

    Hi there,

     

    In this blog post, I would like to talk about TCPIP, Winsock ETL tracing a bit with an example to show you how powerful those tracing facilities could be when troubelshooting connectivity problems. Please note that it is to give you an idea about what kind of information could be retrieved from such ETL traces and not to talk about those tracing facilities inside out. But I’m pretty sure you’ll have an idea at the end.

     

    First of all, you need to be running on Windows 7 or Windows 2008 R2 in order to collect the ETL traces I mention here (at least at a detail level mentioned here - also the given netsh command only runs on Windows 7/2008 R2). Let me explain from scratch how I collected those ETL traces:

     

    1) I compiled two sample C# network applications from the following links:

     

    Server application:

    (A sample TCPListener class code taken from MSDN http://msdn.microsoft.com/en-us/library/system.net.sockets.tcplistener.aspx)

     

    Client application:

    (A sample TCPClient class code taken from MSDN http://msdn.microsoft.com/en-us/library/system.net.sockets.tcpclient.aspx)

     

    => You can see the complete code from server side below (to make it easier for you while following TCPIP and Winsock activity in the ETL trace below)

     

    ///////////////// SERVER CODE //////////////

    using System;

    using System.IO;

    using System.Net;

    using System.Net.Sockets;

    using System.Text;

     

    class MyTcpListener

    {

        public static void Main()

        {

            TcpListener server = null;

            try

            {

                // Set the TcpListener on port 13000.

                Int32 port = 13000;

                IPAddress localAddr = IPAddress.Parse("192.168.1.212");

     

                // TcpListener server = new TcpListener(port);

                server = new TcpListener(localAddr, port);

     

                // Start listening for client requests.

                server.Start();

     

                // Buffer for reading data

                Byte[] bytes = new Byte[256];

                String data = null;

     

                // Enter the listening loop.

                while (true)

                {

                    Console.Write("Waiting for a connection... ");

     

                    // Perform a blocking call to accept requests.

                    // You could also user server.AcceptSocket() here.

                    TcpClient client = server.AcceptTcpClient();

                    Console.WriteLine("Connected!");

     

                    data = null;

     

                                                                  

                    // Get a stream object for reading and writing

                    NetworkStream stream = client.GetStream();

     

                    int i;

     

                    // Loop to receive all the data sent by the client.

                    while ((i = stream.Read(bytes, 0, bytes.Length)) != 0)

                    {

                        // Translate data bytes to a ASCII string.

                        data = System.Text.Encoding.ASCII.GetString(bytes, 0, i);

                        Console.WriteLine("Received: {0}", data);

     

                        // Process the data sent by the client.

                        data = data.ToUpper();

     

                        byte[] msg = System.Text.Encoding.ASCII.GetBytes(data);

     

                        // Send back a response.

                        stream.Write(msg, 0, msg.Length);

                        Console.WriteLine("Sent: {0}", data);

                    }

     

                    // Shutdown and end connection

                    client.Close();

                }

            }

            catch (SocketException e)

            {

                Console.WriteLine("SocketException: {0}", e);

            }

            finally

            {

                // Stop listening for new clients.

                server.Stop();

            }

     

     

            Console.WriteLine("\nHit enter to continue...");

            Console.Read();

        }

    }

     

    ///////////////// SERVER CODE //////////////

     

     

    Server code does the following in simple terms:

     

    - It binds to and starts listening on 192.168.1.212:13000 locally via TcpListener()

    - Once there’s an incoming connection, it accepts the connection and reads the incoming data stream in 256 byte chunks and converts it to upper case and sends back to the client until a disconnect request is sent by the client (with a socket close at the client side which will be visible as a TCP FIN most of the time at the server side)

     

    2) Then I started ETL tracing with the following command at the server side:

     

    netsh trace start scenario=internetclient provider=Microsoft-Windows-TCPIP capture=yes tracefile=tcpip.etl

     

    Note: capture=yes parameter also starts a network trace which is also collected in ETL format. This is another cool feature of netsh trace command on Windows 7/2008 R2.

    Note: You need to run the above command from an elevated command prompt

     

    3) Then I started tcpserver.exe at the server side and then started tcpclient.exe at the client side. Once the tcpclient.exe is started, it connects to server and then sends a 13 bytes message “Test message1” and reads from the socket to get the response from the server and then closes the connection.

     

    4) Then I stopped ETL tracing with the following command at the server side:

     

    netsh trace stop

     

    5) As a result of this action, an ETL file named tcpip.etl was created and then I opened it with Network Monitor 3.4 since it supports decoding ETL files. You can see an example screenshot below:

     

    6) Now let’s focus on the session over which communication took place. You can find the relevant session by browsing the conversations at the left pane. In this scenario the right conversation was 12

     

    Note: I used the following color coding in order to better distinguish TCPIP driver, AFD driver activities and real network packets:

     

    Winsock activity

    TCPIP driver activity

    Network packets

     

    Note: You can also see below the network packets that belong to the given session for your convenience: (even though individual packets will be examined)

     

    196          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP          TCP:Flags=......S., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959134, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192

    199          Idle (0)    WIN7CLIENT1-2K8                 W2K8DC1               TCP          TCP: [Bad CheckSum]Flags=...A..S., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590241, Ack=260959135, Win=8192 ( Negotiated scale factor 0x8 ) = 8192

    200          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP          TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959135, Ack=2428590242, Win=513

    213          tcpserver.exe (2704)              W2K8DC1               WIN7CLIENT1-2K8                 TCP          TCP:Flags=...AP..., SrcPort=55908, DstPort=13000, PayloadLen=13, Seq=260959135 - 260959148, Ack=2428590242, Win=513

    223          tcpserver.exe (2704)              WIN7CLIENT1-2K8                 W2K8DC1               TCP          TCP: [Bad CheckSum]Flags=...AP..., SrcPort=13000, DstPort=55908, PayloadLen=13, Seq=2428590242 - 2428590255, Ack=260959148, Win=513 (scale factor 0x0) = 513

    227          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP          TCP:Flags=...A...F, SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959148, Ack=2428590255, Win=513

    235          Idle (0)    WIN7CLIENT1-2K8                 W2K8DC1               TCP          TCP: [Bad CheckSum]Flags=...A...., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

    239          tcpserver.exe (2704)              WIN7CLIENT1-2K8                 W2K8DC1               TCP          TCP: [Bad CheckSum]Flags=...A...F, SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

    245          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP          TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959149, Ack=2428590256, Win=513

     

     

    a) The following WinsockAFD/TCPIP activity is a result of the following code fragment at server:

     

    ...

                // Set the TcpListener on port 13000.

                Int32 port = 13000;

                IPAddress localAddr = IPAddress.Parse("192.168.1.212");

     

                // TcpListener server = new TcpListener(port);

                server = new TcpListener(localAddr, port);

     

     

    Calling TcpListener constructor triggers a socket creation and local bind activity at the server side behind the scenes. As can be seen from the following converted ETL lines, the server process (tcpserver.exe) is binding to 192.168.1.212:13000

     

    50            tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:socket: 0 (0x0): Process 0x893F92B0 (0x00000A90), Endpoint 0x8A28E2D8, Family 2 (0x2), Type SOCK_STREAM, Protocol 6 (0x6), Seq 1006 (0x3EE), Status Success

    51            tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (Family=IPV4 PID=2704 (0xA90)) created.

    52            tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint 0x89304008 (Family=IPV4, PID=2704 (0xA90)) created with status = Success.

    53            tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:socket: 1 (0x1): Process 0x893F92B0 (0x00000A90), Endpoint 0x8A28E2D8, Family 0 (0x0), Type Unknown value: 0, Protocol 0 (0x0), Seq 1013 (0x3F5), Status Success

    54            tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:bind: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.212:13000, Seq 7010 (0x1B62), Status Success

    55            tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x89304008 acquired port number 13000 (0x32C8).

    56            tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=192.168.1.212:13000) bound.

    57            tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:bind: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.212:13000, Seq 7022 (0x1B6E), Status Success

     

     

    b) Then the server makes the following call to start listening on the socket and accept any incoming connection requests:

     

     

    ...

                // Start listening for client requests.

                server.Start();

     

                // Buffer for reading data

                Byte[] bytes = new Byte[256];

                String data = null;

     

                // Enter the listening loop.

                while (true)

                {

                    Console.Write("Waiting for a connection... ");

     

                    // Perform a blocking call to accept requests.

                    // You could also user server.AcceptSocket() here.

                    TcpClient client = server.AcceptTcpClient();

    ...

     

    58            tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:Listen: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Backlog 200 (0xC8), Seq 13006 (0x32CE), Status Success

    59            tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint/connection 0x8A213398 replaced base endpoint 0x89304008 and acquired reference to port number 13000 (0x32C8).

    60            tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: listener 0x8A213398 (sockaddr=192.168.1.212:13000) activated.

    61            tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:Listen: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Backlog 200 (0xC8), Seq 13012 (0x32D4), Status Success

    62            tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=192.168.1.212:13000) closed.

    63            tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:Wait for listen: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6216 (0x1848), Status Success

     

     

    c) After some time, a remote client connects to server at TCP port 13000. This can be seen from the TCP SYN packet received from WIN7CLIENT1-2K8 (192.168.1.200)

     

    196          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP                                                         TCP:Flags=......S., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959134, Ack=0, Win=8192 ( Negotiating scale factor 0x8 ) = 8192

     

     

    d) TCPIP driver immediately responds to TCP SYN with a TCP SYN ACK and it also moves to SynRcvdState from ListenState:

     

    197          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from ListenState to SynRcvdState, SndNxt = 0 (0x0).

    198          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Sent data with number of bytes = 1 (0x1) and Sequence number = 2428590241 (0x90C158A1).

    199          Idle (0)    WIN7CLIENT1-2K8                 W2K8DC1               TCP                                                         TCP: [Bad CheckSum]Flags=...A..S., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590241, Ack=260959135, Win=8192 ( Negotiated scale factor 0x8 ) = 8192

    200          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP                                                         TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959135, Ack=2428590242, Win=513

     

     

    e) After receiving a TCP ACK from the client, the endpoint moves to EstablishedState which is the state where both parties could start exchanging data:

     

    201          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 0 (0x0). ThSeq = 260959135 (0xF8DEB9F).

    202          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from SynRcvdState to EstablishedState, SndNxt = 2428590242 (0x90C158A2).

     

     

     

    f) Now Winsock driver indicates a connection request to the application layer (tcpserver) and then the connection is accepted by the server process:

     

    203          Idle (0)    192.168.1.200        Wscore_MicrosoftWindowsWinsockAFD:Connect indication: 3 (0x3): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.200:55908, Backlog Count 0 (0x0), Seq 6501 (0x1965), Status Success

    204          Idle (0)                                   Wscore_MicrosoftWindowsWinsockAFD:Wait for listen: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6220 (0x184C), Status Success

    205          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: listener (local=192.168.1.212:13000 remote=192.168.1.200:55908) accept completed. TCB = 0x8921DD28. PID = 2704 (0xA90).

    206          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:socket: 0 (0x0): Process 0x893F92B0 (0x00000A90), Endpoint 0x892FB6D8, Family 2 (0x2), Type SOCK_STREAM, Protocol 6 (0x6), Seq 1006 (0x3EE), Status Success

    207          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (Family=IPV4 PID=2704 (0xA90)) created.

    208          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint 0x88BF7B08 (Family=IPV4, PID=2704 (0xA90)) created with status = Success.

    209          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:socket: 1 (0x1): Process 0x893F92B0 (0x00000A90), Endpoint 0x892FB6D8, Family 0 (0x0), Type Unknown value: 0, Protocol 0 (0x0), Seq 1013 (0x3F5), Status Success

    210          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:accept: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Address 192.168.1.200:55908, Accept Endpoint 0x892FB6D8, Current Backlog 0 (0x0), Seq 6010 (0x177A), Status Success

    211          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: endpoint (sockaddr=0.0.0.0:0) closed.

    212          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:accept: 1 (0x1): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6011 (0x177B), Status Success

     

     

     

    g) Remote client sends 13 bytes of data to the Server:

     

    213          tcpserver.exe (2704)             W2K8DC1               WIN7CLIENT1-2K8                                                TCP          TCP:Flags=...AP..., SrcPort=55908, DstPort=13000, PayloadLen=13, Seq=260959135 - 260959148, Ack=2428590242, Win=513

    54 65 73 74 20 6D 65 73 73 61 67 65 31  Test message1

     

     

     

    h) And this is reflected with a Data indication to the application:

     

    214          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:Data indication: 3 (0x3): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer 0x89C5BD88, Length 13 (0xD), Seq 9000 (0x2328)

    215          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 delivery 0x8921DE20 indicated 0x0000000D bytes accepted 0x0000000D bytes, status = Success. RcvNxt = 260959135 (0xF8DEB9F).

    216          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 13 (0xD). ThSeq = 260959135 (0xF8DEB9F).

     

     

     

    i) Now the client posts a Recv() with a buffer size of 256 bytes which is a result of the following server code fragment and it receives 13 bytes in return which was just received from the remote client:

     

    ...

                // Buffer for reading data

                Byte[] bytes = new Byte[256];

                String data = null;

    ...

     

                    // Loop to receive all the data sent by the client.

                    while ((i = stream.Read(bytes, 0, bytes.Length)) != 0)

                    {

    ...

     

     

    217          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:recv: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x0197F300, Length 256 (0x100), Seq 4115 (0x1013), Status Success

    218          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:recv: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x0197F300, Length 13 (0xD), Seq 4116 (0x1014), Status Success

     

     

     

    j) After receiving the data, server code converts it to upper case and send back to the client with the following code which is again 13 bytes in length:

     

    ...

                        data = data.ToUpper();

     

                        byte[] msg = System.Text.Encoding.ASCII.GetBytes(data);

     

                        // Send back a response.

                        stream.Write(msg, 0, msg.Length);

                        Console.WriteLine("Sent: {0}", data);

    ...

     

     

    219          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:send: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3047 (0xBE7), Status Success

    220          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:send: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3056 (0xBF0), Status Success

    221          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 send posted posted 13 (0xD) bytes at 2428590242 (0x90C158A2).

    222          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Sent data with number of bytes = 13 (0xD) and Sequence number = 2428590242 (0x90C158A2).

    223          tcpserver.exe (2704)             WIN7CLIENT1-2K8                 W2K8DC1               TCP                          TCP: [Bad CheckSum]Flags=...AP..., SrcPort=13000, DstPort=55908, PayloadLen=13, Seq=2428590242 - 2428590255, Ack=260959148, Win=513 (scale factor 0x0) = 513

    224          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:send: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3051 (0xBEB), Status Success

     

     

     

    k) Another Recv() with an 256 bytes buffer is posted by the application: (since the server is still in the while loop)

     

    225          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:recv: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x892810E8, Length 256 (0x100), Seq 4107 (0x100B), Status Success

    226          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28, delivery 0x8921DE20, Request 0x89E65020  posted for 0x00000100 bytes, flags = 0 (0x0). RcvNxt = 260959148 (0xF8DEBAC).

     

     

     

    l) The remote client sends a TCP FIN segment to the server and this is indicated up to the application and also the endpoint moves to CloseWaitState:

     

    227          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP                                                         TCP:Flags=...A...F, SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959148, Ack=2428590255, Win=513

    228          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 1 (0x1). ThSeq = 260959148 (0xF8DEBAC).

    229          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Cumulative ACK updated cwnd = 2920 (0xB68).

    230          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from EstablishedState to CloseWaitState, SndNxt = 2428590255 (0x90C158AF).

     

     

     

    m) Server process determines that the remote client wants to close the connection by getting 0 bytes out of recv(): (which was posted by stream.Read(bytes, 0, bytes.Length) call indirectly)

     

    231          Idle (0)                                   Wscore_MicrosoftWindowsWinsockAFD:recv: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x892810E8, Length 0 (0x0), Seq 4123 (0x101B), Status Success

    232          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 delivery 0x8921DE20 delivering FIN. RcvNxt = 260959149 (0xF8DEBAD).

     

     

     

    n) Server process also issues a disconnect by calling the following:

     

    ...

                    // Shutdown and end connection

                    client.Close();

    ...

     

     

    233          Idle (0)                                   Wscore_MicrosoftWindowsWinsockAFD:disconnect indicated: 3 (0x3): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 12001 (0x2EE1)

    234          Idle (0)                                   Wscore_MicrosoftWindowsWinsockAFD:send: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Buffer Count 1 (0x1), Buffer 0x8930165C, Length 13 (0xD), Seq 3024 (0xBD0), Status Success

    235          Idle (0)    WIN7CLIENT1-2K8                 W2K8DC1               TCP                                                         TCP: [Bad CheckSum]Flags=...A...., SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

    236          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection disconnect issued, length=0x00000000.

    237          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from CloseWaitState to LastAckState, SndNxt = 2428590255 (0x90C158AF).

    238          tcpserver.exe (2704)              TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Sent data with number of bytes = 1 (0x1) and Sequence number = 2428590255 (0x90C158AF).

    239          tcpserver.exe (2704)             WIN7CLIENT1-2K8                 W2K8DC1               TCP                          TCP: [Bad CheckSum]Flags=...A...F, SrcPort=13000, DstPort=55908, PayloadLen=0, Seq=2428590255, Ack=260959149, Win=513 (scale factor 0x0) = 513

     

     

     

    o) Finally the server does the socket cleanup:

     

    240          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:socket cleanup: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2002 (0x7D2), Status Success

    241          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:socket cleanup: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2003 (0x7D3), Status Success

    242          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:closesocket: 0 (0x0): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2000 (0x7D0), Status Success

    243          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:closesocket: 1 (0x1): Process 0x893F92B0, Endpoint 0x892FB6D8, Seq 2001 (0x7D1), Status Success

    244          tcpserver.exe (2704)              Wscore_MicrosoftWindowsWinsockAFD:Wait for listen: 0 (0x0): Process 0x893F92B0, Endpoint 0x8A28E2D8, Seq 6216 (0x1848), Status Success

     

     

     

    p) And after receiving an ACK to the FIN sent by the server, the session moves to ClosedState:

     

    245          Idle (0)    W2K8DC1               WIN7CLIENT1-2K8                 TCP                                                         TCP:Flags=...A...., SrcPort=55908, DstPort=13000, PayloadLen=0, Seq=260959149, Ack=2428590256, Win=513

    246          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Received data with number of bytes = 0 (0x0). ThSeq = 260959149 (0xF8DEBAD).

    247          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28: Cumulative ACK updated cwnd = 2933 (0xB75).

    248          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from LastAckState to ClosedState, SndNxt = 2428590256 (0x90C158B0).

    249          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 (local=192.168.1.212:13000 remote=192.168.1.200:55908) disconnect completed.

    250          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 (local=192.168.1.212:13000 remote=192.168.1.200:55908) close issued.

    251          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 (local=192.168.1.212:13000 remote=192.168.1.200:55908) shutdown initiated (0xC0000241 - STATUS_CONNECTION_ABORTED). PID = 2704 (0xA90).

    252          Idle (0)                                   TCPIP_MicrosoftWindowsTCPIP:TCP: connection 0x8921DD28 transition from ClosedState to ClosedState, SndNxt = 2428590256 (0x90C158B0).

     

     

     

    Hope this helps

     

    Thanks,

    Murat

  • SCCM packages may be distributed slower than standard file copy (xcopy/Windows Explorer)

    Hi there,

     

    In this post, I’m going to mention about another issue where I helped a colleague of mine to troubleshoot an SCCM package distribution scenario. The problem was that package distribution to clients were visibly slower compared to standard file copy methods (like using xcopy, Windows Explorer etc). In the given setup, the sccm client was accessing and retrieving the distribution package via SMB protocol so BITS was out of the picture. We requested the customer to collect the following logs while reproducing the problem:

     

    a) Create a distribution package which simply includes a 100 MB executable file

    b) Collect the following logs for two different scenarios:

     

    => For standard file copy scenario:

    - Start Network traces on the SCCM server (Windows 2008 R2) and the SCCM agent (Windows 7)

    - Start Process Explorer on the SCCM agent

    - Start file copy by using xcopy from a command prompt on Windows 7 client

     

    => For SCCM package distribution scenario:

    - Start Network traces on the SCCM server (Windows 2008 R2) and the SCCM agent (Windows 7)

    - Start Process Explorer on the SCCM agent

    - Trigger packet distribution

     

    After the above logs collected, I analzyed the network traces and Process monitor logs for both scenarios. Let us take a closer look for each scenario:

     

    A. SCCM PACKAGE DISTRIBUTION SCENARIO

     

    The package download activity was seen as below in Process Monitor:

    - Ccmexec posts about 4900 ReadFile()s with 64KB buffers each

    - This is also supported by the behavior seen in the network trace collected for ccmexec scenario:

     

     

    No.     Time        Source                Destination           Info                                                            Protocol

    ...

      16475 0.005513    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16121856 File: TEST\100MBFile.txt SMB2

      16476 0.000013    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16187392 File: TEST\100MBFile.txt SMB2

      16478 0.001872    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16538 0.005313    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16603 0.080443    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16252928 File: TEST\100MBFile.txt SMB2

      16604 0.000013    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16318464 File: TEST\100MBFile.txt SMB2

      16606 0.001229    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16666 0.005312    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16730 0.005827    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16384000 File: TEST\100MBFile.txt SMB2

      16731 0.000013    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16449536 File: TEST\100MBFile.txt SMB2

      16733 0.001193    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16795 0.005643    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16856 0.070364    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16515072 File: TEST\100MBFile.txt SMB2

      16857 0.000013    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16580608 File: TEST\100MBFile.txt SMB2

      16859 0.001037    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16919 0.005313    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      16982 0.005789    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16646144 File: TEST\100MBFile.txt SMB2

      16983 0.000014    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16711680 File: TEST\100MBFile.txt SMB2

      16985 0.001043    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      17045 0.005312    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      17108 0.048421    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16777216 File: TEST\100MBFile.txt SMB2

      17109 0.000019    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16842752 File: TEST\100MBFile.txt SMB2

      17111 0.002061    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      17171 0.005311    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      17236 0.055958    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16908288 File: TEST\100MBFile.txt SMB2

      17237 0.000015    192.168.1.7         192.168.2.77         Read Request Len:65536 Off:16973824 File: TEST\100MBFile.txt SMB2

      17239 0.002242    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

      17300 0.005311    192.168.2.77         192.168.1.7         Read Response                                                   SMB2

    ...

     

    Note: IP addresses are replaced for privacy purposes

     

    B. STANDARD FILE COPY SCENARIO

     

    The standard file copy with xcopy was seen as below in Process Monitor:

    - The xcopy tool posts only 100 ReadFile()s each with a 1 MB buffer each

    - This is also seen in the network trace collected for the xcopy scenario:

     

    No.     Time                       Source                Destination           Info                                                            Protocol

    ...

       5445 2010-09-21 15:59:29.436686 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:12582912 File: xcopytest\100MBFile.txt SMB2

       5446 2010-09-21 15:59:29.436701 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:12648448 File: xcopytest\100MBFile.txt SMB2

       5447 2010-09-21 15:59:29.436712 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:12713984 File: xcopytest\100MBFile.txt SMB2

       5448 2010-09-21 15:59:29.436723 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:12779520 File: xcopytest\100MBFile.txt SMB2

       5449 2010-09-21 15:59:29.436735 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:12845056 File: xcopytest\100MBFile.txt SMB2

       5450 2010-09-21 15:59:29.436748 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:12910592 File: xcopytest\100MBFile.txt SMB2

       5451 2010-09-21 15:59:29.436760 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:12976128 File: xcopytest\100MBFile.txt SMB2

       5452 2010-09-21 15:59:29.436772 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13041664 File: xcopytest\100MBFile.txt SMB2

       5453 2010-09-21 15:59:29.436784 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13107200 File: xcopytest\100MBFile.txt SMB2

       5457 2010-09-21 15:59:29.436798 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13172736 File: xcopytest\100MBFile.txt SMB2

       5458 2010-09-21 15:59:29.436813 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13238272 File: xcopytest\100MBFile.txt SMB2

       5459 2010-09-21 15:59:29.436824 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13303808 File: xcopytest\100MBFile.txt SMB2

       5460 2010-09-21 15:59:29.436835 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13369344 File: xcopytest\100MBFile.txt SMB2

       5461 2010-09-21 15:59:29.436845 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13434880 File: xcopytest\100MBFile.txt SMB2

       5462 2010-09-21 15:59:29.436857 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13500416 File: xcopytest\100MBFile.txt SMB2

       5463 2010-09-21 15:59:29.436869 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13565952 File: xcopytest\100MBFile.txt SMB2

       5509 2010-09-21 15:59:29.441113 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       5572 2010-09-21 15:59:29.446773 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       5632 2010-09-21 15:59:29.452104 192.168.2.77         192.168.1.7         [Unreassembled Packet]                                          SMB2

       5694 2010-09-21 15:59:29.457766 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       5755 2010-09-21 15:59:29.463095 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       5817 2010-09-21 15:59:29.468755 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       5878 2010-09-21 15:59:29.474076 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       5940 2010-09-21 15:59:29.479738 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6002 2010-09-21 15:59:29.485400 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6063 2010-09-21 15:59:29.490729 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6125 2010-09-21 15:59:29.496387 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6187 2010-09-21 15:59:29.502044 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6248 2010-09-21 15:59:29.507367 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6310 2010-09-21 15:59:29.513024 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6372 2010-09-21 15:59:29.518677 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6433 2010-09-21 15:59:29.523999 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6447 2010-09-21 15:59:29.525133 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13631488 File: xcopytest\100MBFile.txt SMB2

       6448 2010-09-21 15:59:29.525148 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13697024 File: xcopytest\100MBFile.txt SMB2

       6449 2010-09-21 15:59:29.525159 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13762560 File: xcopytest\100MBFile.txt SMB2

       6450 2010-09-21 15:59:29.525170 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13828096 File: xcopytest\100MBFile.txt SMB2

       6451 2010-09-21 15:59:29.525183 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13893632 File: xcopytest\100MBFile.txt SMB2

       6452 2010-09-21 15:59:29.525196 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:13959168 File: xcopytest\100MBFile.txt SMB2

       6453 2010-09-21 15:59:29.525207 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14024704 File: xcopytest\100MBFile.txt SMB2

       6454 2010-09-21 15:59:29.525219 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14090240 File: xcopytest\100MBFile.txt SMB2

       6455 2010-09-21 15:59:29.525231 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14155776 File: xcopytest\100MBFile.txt SMB2

       6456 2010-09-21 15:59:29.525243 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14221312 File: xcopytest\100MBFile.txt SMB2

       6457 2010-09-21 15:59:29.525255 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14286848 File: xcopytest\100MBFile.txt SMB2

       6458 2010-09-21 15:59:29.525267 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14352384 File: xcopytest\100MBFile.txt SMB2

       6459 2010-09-21 15:59:29.525280 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14417920 File: xcopytest\100MBFile.txt SMB2

       6460 2010-09-21 15:59:29.525292 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14483456 File: xcopytest\100MBFile.txt SMB2

       6461 2010-09-21 15:59:29.525304 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14548992 File: xcopytest\100MBFile.txt SMB2

       6462 2010-09-21 15:59:29.525316 192.168.1.7         192.168.2.77         Read Request Len:65536 Off:14614528 File: xcopytest\100MBFile.txt SMB2

       6511 2010-09-21 15:59:29.529653 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6573 2010-09-21 15:59:29.534977 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6635 2010-09-21 15:59:29.540629 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6697 2010-09-21 15:59:29.546286 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6758 2010-09-21 15:59:29.551606 192.168.2.77         192.168.1.7         [Unreassembled Packet]                                          SMB2

       6821 2010-09-21 15:59:29.557255 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6883 2010-09-21 15:59:29.562576 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       6945 2010-09-21 15:59:29.568234 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7007 2010-09-21 15:59:29.573893 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7068 2010-09-21 15:59:29.579219 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7130 2010-09-21 15:59:29.584876 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7192 2010-09-21 15:59:29.590530 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7253 2010-09-21 15:59:29.595858 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7315 2010-09-21 15:59:29.601517 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7377 2010-09-21 15:59:29.607173 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7438 2010-09-21 15:59:29.612499 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7500 2010-09-21 15:59:29.618155 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7561 2010-09-21 15:59:29.623478 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7623 2010-09-21 15:59:29.629132 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7685 2010-09-21 15:59:29.634785 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7746 2010-09-21 15:59:29.640111 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7808 2010-09-21 15:59:29.645771 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7871 2010-09-21 15:59:29.651433 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7932 2010-09-21 15:59:29.656750 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       7996 2010-09-21 15:59:29.662406 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       8058 2010-09-21 15:59:29.667728 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       8120 2010-09-21 15:59:29.673385 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       8182 2010-09-21 15:59:29.679045 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

       8243 2010-09-21 15:59:29.684367 192.168.2.77         192.168.1.7         Read Response                                                   SMB2

    ...

     

    Note: IP addresses are replaced for privacy purposes

    Note: The above 16 x 64 KB = 1 MB read requests are actually created as a result of 1 MB read requests at the application layer (xcopy)

     

     

    SUMMARY:

    =========

    The performance difference between sccm package distribution and xcopy stems from the fact that xcopy tool (and most probably Windows Explorer as well) posts Read requests with larger buffers (1 MB) compared to sccm agent process - ccmexec (64 KB) which results in a better performance in the xcopy scenario since better concurrency is achieved and the network bandwidth is better utilized that way. This is both seen in the network trace and Process Monitor activities. We shared the results with our SCCM colleagues to see if that behaviour could be changed or not, if I receive any update on that I’ll update this post.

     

    Hope this helps

     

    Thanks,

    Murat

  • SQL Browser may not be reachable through firewalls when it runs on a cluster

    Hi there,

     

    In this blog post, I would like to talk about a problem in which I was involved as a network engineer. The problem was that the SQL server instance name to port mapping wasn’t successfully done through a firewall if the SQL instance in question runs on a cluster. Let’s take a closer look at the problem and the resolution:

     

    I asked the customer to collect simultaneous network traces from the client and SQL server side when reproducing the problem. When I checked the client side trace, I saw that the client’s request sent to SQL Browser service were unresponded and hence the client wasn’t able to locate and connect to the SQL server:

     

    No.     Time                       Source                Destination           Protocol Info

      95534 2010-09-13 11:04:27.465978 192.168.1.7         192.168.29.47         UDP      Source port: 4309  Destination port: 1434

       |--> 0000   04 11 33 43 53 61 7c 00                          .SQLSER.  

      95568 2010-09-13 11:04:29.197423 192.168.1.7         192.168.29.47         UDP      Source port: 4310  Destination port: 1434

      95600 2010-09-13 11:04:31.131993 192.168.1.7         192.168.29.47         UDP      Source port: 4311  Destination port: 1434

      95635 2010-09-13 11:04:33.469884 192.168.1.7         192.168.29.47         UDP      Source port: 4312  Destination port: 1434

      95676 2010-09-13 11:04:36.012853 192.168.1.7         192.168.29.47         UDP      Source port: 4313  Destination port: 1434

      95734 2010-09-13 11:04:38.561297 192.168.1.7         192.168.29.47         UDP      Source port: 4316  Destination port: 1434

      95775 2010-09-13 11:04:41.106219 192.168.1.7         192.168.29.47         UDP      Source port: 4317  Destination port: 1434

     

    Note: IP addresses and SQL instance names were replaced on purpose for privacy reasons.

     

    As can be seen from the above traffic, client is constantly sending queries to the SQL browser from different source ports but no response is received and hence name resolution fails.

     

    Then I focused on the SQL server side trace. When we look at the same activity from SQL server perspective, we see that SQL browser running on the cluster side actually returns results to those queries sent by the client side but those responses are not visible at the client side because the hardware firewall running in between drops them:

     

    No.     Time                       Source                Destination           Protocol Info

       3876 2010-09-13 11:04:27.988640 192.168.1.7         192.168.29.47         UDP      Source port: 4309  Destination port: 1434

      3877 2010-09-13 11:04:27.988640 192.168.29.49          192.168.1.7         UDP      Source port: 1434  Destination port: 4309

       3914 2010-09-13 11:04:29.723015 192.168.1.7         192.168.29.47         UDP      Source port: 4310  Destination port: 1434

       3915 2010-09-13 11:04:29.723015 192.168.29.49         192.168.1.7         UDP      Source port: 1434  Destination port: 4310

       3945 2010-09-13 11:04:31.660515 192.168.1.7         192.168.29.47         UDP      Source port: 4311  Destination port: 1434

       3946 2010-09-13 11:04:31.660515 192.168.29.49         192.168.1.7         UDP      Source port: 1434  Destination port: 4311

       3991 2010-09-13 11:04:33.988640 192.168.1.7         192.168.29.47         UDP      Source port: 4312  Destination port: 1434

       3992 2010-09-13 11:04:33.988640 192.168.29.49         192.168.1.7         UDP      Source port: 1434  Destination port: 4312

       4040 2010-09-13 11:04:36.535515 192.168.1.7         192.168.29.47         UDP      Source port: 4313  Destination port: 1434

       4041 2010-09-13 11:04:36.535515 192.168.29.49         192.168.1.7         UDP      Source port: 1434  Destination port: 4313

       4103 2010-09-13 11:04:39.082390 192.168.1.7         192.168.29.47         UDP      Source port: 4316  Destination port: 1434

       4104 2010-09-13 11:04:39.082390 192.168.29.49         192.168.1.7         UDP      Source port: 1434  Destination port: 4316

       4147 2010-09-13 11:04:41.629265 192.168.1.7         192.168.29.47         UDP      Source port: 4317  Destination port: 1434

       4148 2010-09-13 11:04:41.629265 192.168.29.49         192.168.1.7         UDP      Source port: 1434  Destination port: 4317

     

    Those response UDP packets were dropped by the firewall because the source IP address (the SQL server’s dedicated IP address - 192.168.29.49) in the response packets was different from the destination IP address (SQL server instance’s virtual (cluster) IP address - 192.168.29.47) in the request packets. Since the firewall doesn’t evaluate the response packet as a response to previous request packet because destination IP address in the request packet doesn’t match the source IP address in the response packet, it silently drops them:

     

    4147 2010-09-13 11:04:41.629265 192.168.1.7         192.168.29.47         UDP      Source port: 4317  Destination port: 1434

       |--> 0000   04 11 33 43 53 61 7c 00                          .SQLSER.  

    4148 2010-09-13 11:04:41.629265 192.168.29.49         192.168.1.7         UDP      Source port: 1434  Destination port: 4317

     

    After our customer changed the firewall policies accordingly (by allowing UDP traffic from SQL server VLAN (with source port being set to 1434) to client VLAN), the issue was resolved. Regarding why the SQL Browser service might be returning responses from the dedicated IP address, my guess is that browser service doesn’t respond to the request within the same UDP socket but it creates a new socket to send the response back and while doing that dedicated IP address is selected instead of cluster IP address (the source address selection is OS responsibility and generally socket applications doesn’t indicate a specific source IP address when connecting to remote parties)

     

    Hope this helps

     

    Thanks,

    Murat

  • Bogus IP packets and Wireshark

    Hi there,

     

    In today’s blog post, I’m going to talk about an issue that I have come across several times while analyzing network traces with Wireshark. Let’s take the following example:

     

    I apply the following filter on a network trace:

     

    ip.addr==192.168.100.23 and ip.addr==192.168.121.51 and tcp.port==3268 and tcp.port==8081

     

    And I get the following traffic:

     

    No.     Time        Source                Destination           Protocol Info

       8773 17.458870   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [SYN] Seq=0 Win=65535 Len=0 MSS=1460

       8774 17.458988   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [SYN, ACK] Seq=0 Ack=1 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460

       8775 17.459239   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [ACK] Seq=1 Ack=1 Win=65535 Len=0

       8776 17.459239   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [PSH, ACK] Seq=1 Ack=1 Win=65535 Len=264

       8850 17.658922   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [ACK] Seq=1 Ack=265 Win=64240 [TCP CHECKSUM INCORRECT] Len=0

       8851 17.659108   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [PSH, ACK] Seq=265 Ack=1 Win=65535 Len=21

       8853 17.661356   192.168.100.23        192.168.121.51        TCP      [TCP ACKed lost segment] 3268 > 8081 [ACK] Seq=286 Ack=2581 Win=65535 Len=0

       8854 17.661404   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [FIN, ACK] Seq=2581 Ack=286 Win=64219 [TCP CHECKSUM INCORRECT] Len=0

       8855 17.661605   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [ACK] Seq=286 Ack=2582 Win=65535 Len=0

       8859 17.665981   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [FIN, ACK] Seq=286 Ack=2582 Win=65535 Len=0

       8860 17.666013   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [ACK] Seq=2582 Ack=287 Win=64219 [TCP CHECKSUM INCORRECT] Len=0

     

    When I take a closer look, I see that a TCP segment is missing from the list of packets and hence the next frame is displayed with a [TCP ACKed lost segment] comment by Wireshark. Interestingly if I apply the following filter, I can see the frame that’s missing from the TCP conversation:

     

    ip.addr==192.168.100.23 and ip.addr==192.168.121.51

     

    No.     Time        Source                Destination           Protocol Info

       8852 17.661030   HewlettP_12:34:56     Cisco_12:34:56        IP       Bogus IP length (0, less than header length 20)

     

    Frame 8852 (2634 bytes on wire, 2634 bytes captured)

    Ethernet II, Src: HewlettP_12:34:56 (00:17:a4:12:34:56), Dst: Cisco_12:34:56 (00:15:2c:12:34:56)

        Destination: Cisco_12:34:56 (00:15:2c:12:34:56)

        Source: HewlettP_12:34:56 (00:17:a4:12:34:56)

        Type: IP (0x0800)

    Internet Protocol

        Version: 4

        Header length: 20 bytes

        Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)

            0000 00.. = Differentiated Services Codepoint: Default (0x00)

            .... ..0. = ECN-Capable Transport (ECT): 0

            .... ...0 = ECN-CE: 0

        Total length: 0 bytes (bogus, less than header length 20)

     

    0000  00 15 2c 31 48 00 00 17 a4 77 00 24 08 00 45 00   ..,1H....w.$..E.

    0010  00 00 57 d0 40 00 80 06 00 00 c0 a8 79 33 c0 a8   ..W.@.......y3..

    0020  64 17 1f 91 0c c4 52 83 a3 f2 a2 a2 06 be 50 18   d.....R.......P.

    0030  fa db 5e a2 00 00 48 54 54 50 2f 31 2e 31 20 32   ..^...HTTP/1.1 2

    0040  30 30 20 4f 4b 0d 0a 50 72 61 67 6d 61 3a 20 6e   00 OK..Pragma: n

    0050  6f 2d 63 61 63 68 65 0d 0a 43 6f 6e 74 65 6e 74   o-cache..Content

    0060  2d 54 79 70 65 3a 20 74 65 78 74 2f 68 74 6d 6c   -Type: text/html

    0070  3b 63 68 61 72 73 65 74 3d 75 74 66 2d 38 0d 0a   ;charset=utf-8..

    0080  53 65 72 76 65 72 3a 20 4d 69 63 72 6f 73 6f 66   Server: Microsof

    0090  74 2d 49 49 53 2f 37 2e 35 0d 0a 58 2d 50 6f 77   t-IIS/7.5..X-Pow

    ...

     

    Even though the total length field is set to 0, I see that the IP packet has some payload (probably including a TCP header).

     

    The problem occurs because the Wireshark doesn’t fully parse the IP and TCP headers because of total length field in the IP header is 0. This also explains why we don’t see the same packet when TCP filter is applied.

     

    After some testing, I realized that this issue could be fixed by setting the following value in Wireshark settings:

     

      

    After I enable “Support packet-capture from IP TSO-enabled hardware”, Wireshark also started to correctly display the frames even when the TCP session filter is applied:

     

    ip.addr==192.168.100.23 and ip.addr==192.168.121.51 and tcp.port==3268 and tcp.port==8081

     

    No.     Time        Source                Destination           Protocol Info

       8771 17.458870   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 SACK_PERM=1

       8772 17.458988   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [SYN, ACK] Seq=0 Ack=1 Win=8192 [TCP CHECKSUM INCORRECT] Len=0 MSS=1460 SACK_PERM=1

       8773 17.459239   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [ACK] Seq=1 Ack=1 Win=65535 Len=0

       8774 17.459239   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [PSH, ACK] Seq=1 Ack=1 Win=65535 Len=264

       8848 17.658922   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [ACK] Seq=1 Ack=265 Win=64240 [TCP CHECKSUM INCORRECT] Len=0

       8849 17.659108   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [PSH, ACK] Seq=265 Ack=1 Win=65535 Len=21

       8850 17.661030   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [PSH, ACK] Seq=1 Ack=286 Win=64219 [TCP CHECKSUM INCORRECT] Len=2580

       8851 17.661356   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [ACK] Seq=286 Ack=2581 Win=65535 Len=0

       8852 17.661404   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [FIN, ACK] Seq=2581 Ack=286 Win=64219 [TCP CHECKSUM INCORRECT] Len=0

       8853 17.661605   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [ACK] Seq=286 Ack=2582 Win=65535 Len=0

       8857 17.665981   192.168.100.23        192.168.121.51        TCP      3268 > 8081 [FIN, ACK] Seq=286 Ack=2582 Win=65535 Len=0

       8858 17.666013   192.168.121.51        192.168.100.23        TCP      8081 > 3268 [ACK] Seq=2582 Ack=287 Win=64219 [TCP CHECKSUM INCORRECT] Len=0

     

    When TSO (TCP segmentation offloading) is in place, TCPIP stack doesn’t deal with segmentation at TCP layer and leave it to NIC driver for effienciency purposes. Since Wireshark does see the packet before the NIC, we see the total length as 0 in the packet but when that packet is segmented accordingly by the NIC, there will be correct length field set in the packet. This can also be proved by collecting a network trace at the other end of the session

     

    Note: Network Monitor already takes that into account and hence you don’t need to take any corrective action if you’re checking the trace with it.

     

    Hope this helps

     

    Thanks,

    Murat

     

     

  • How to decrypt an SSL or TLS session by using Wireshark

    [Updated on 26th October 2013]

    The following blog post is the newer version of this blog post:

    http://blogs.technet.com/b/nettracer/archive/2013/10/12/decrypting-ssl-tls-sessions-with-wireshark-reloaded.aspx

    Hi there,

     

    In this blog post, I would like to talk about decrypting SSL/TLS sessions by using Wireshark provided that you have access to the server certificate’s private key. In some cases it may be quite useful to see what is exchanged under the hood of an SSL/TLS session from troubleshooting purposes. You’ll find complete steps to do this on Windows systems. Even though there’re a couple of documentations around (you can find the references at the end of the blog post), all steps from one document doesn’t fully apply and you get stuck at some point. I tested the following steps a couple of times on a Windows 2008 server and it seems to be working fine.

     

    Here are the details of the process:

     

    First of all we’ll need the following tools for that process: (At least I tested with these versions)

     

    http://www.wireshark.org/download.html

    Wireshark -> Version 1.2.8

     

    http://www.slproweb.com/products/Win32OpenSSL.html

    (Win32 OpenSSL v1.0.0.a Light)

    openssl                  -> 1.0.0a

     

    1) We first need to export the certificate that is used by the server side in SSL/TLS session with the following steps:

     

    Note: The Certificate export wizard could be started by right clicking the related certificate from certificates mmc and selecting “All Tasks > Export” option.

     

     

     

    2) In the second stage, we’ll need to convert the private key file in PKCS12 format to PEM format (which is used by Wireshark) in two stages by using the openssl tool:

     

    c:\OpenSSL-Win32\bin> openssl pkcs12 -nodes -in iis.pfx -out key.pem -nocerts -nodes

    Enter Import Password: <<Password used when exporting the certificate in PKCS12 format>>

     

    c:\OpenSSL-Win32\bin> openssl rsa -in key.pem -out keyout.pem

    writing RSA key

     

    => After the last command, the outfile “keyout.pem” should be seen in the following format:

     

    -----BEGIN RSA PRIVATE KEY-----

    jffewjlkfjelkjfewlkjfew.....

    ...

    akfhakdfhsakfskahfksjhgkjsah

    -----END RSA PRIVATE KEY-----

     

    3) Now we can use the private key file in Wireshark as given below:

     

    Note: The following dialog box could be seen by first selecting Edit > Preferences and then selecting “Protocols” from the left pane and selecting SSL at the left pane again:

     

    Notes:

     

    - 172.17.1.1 is server IP address. This is the server using the certificate that we extracted the private key from.

    - 443 is the TCP port at the server side.

    - http is the protocol carried inside the SSL/TLS session

    - c:\tls\keyout.pem is the name of the file which includes the converted private key

    - c:\tls\debug2.txt is the name of the file which includes information about the decryption process

     

    4) Once all is ready, you can click “Apply” to start the decryption process. Wireshark will show you the packets in the given session in an unencrypted fashion. Here is the difference between the encrypted and unencrypted versions:

     

    a) How it is seen before Wireshark decrypts SSL/TLS session:

     

     

    b) How it is seen after Wireshark decrypts SSL/TLS session:

      

     

    5) Since the private key of a certificate could be considered as a password, we couldn’t ask for that from our customers given that you're troubleshooting a problem on behalf of your customers not for your environment . The following alternatives could be used in that case:

     

    Note: It looks like a capture file decrypted by using the private key couldn’t be saved as a different capture file in unencrypted format.

     

    - After decrypting the traffic, we could examine it in a live meeting session where the customer shares his desktop

    - The decrypted packets could be printed to a file from File > Print option (by choosing the “Output to file” option)

    - By right clicking one of the decrypted packets and selecting “Follow SSL Stream”, we can save the session content to a text file. The following is an example of such a file created that way:

     

    6) More information could be found at the following links:

     

    Citrix

    http://support.citrix.com/article/CTX116557

     

    Wireshark

    http://wiki.wireshark.org/SSL

     

     

    Hope this helps

     

    Thanks,

    Murat