Debugging TCP connections with tcptrace

Debugging TCP problems can be difficult and time consuming, especially when the connection end-points lack tools to observe connection behavior. One such tool that should be on every system is tcptrace(1). This awesome utility can assist with pinpointing network issues, and can help with debugging TCP performance and reliability problems.

tcptrace(1) operates on tcpdump and snoop binary files, and provides numerous statistics and connection details for each capture file passed as an argument. To get started with tcptrace(1), tcpdump(1) or snoop(1m) needs to be run to collect raw packet information. This information can be saved to a file with tcpdump(1)’s “-w” option, and complex filters can be applied to limit which hosts and ports data is collected from.

The following example shows how to capture connections to TCP port 80 on the prefetch.net web server, and save the captured contents to a file named “tcpdump.out”:

$ tcpdump -i hme1 -w tcpdump.out -s 1520 port 80
tcpdump: listening on hme1, link-type EN10MB
^C
259 packets received by filter
0 packets dropped by kernel

Once data is collected with snoop(1m) or tcpdump(1m), tcptrace(1m) can be run to display the TCP connections that were captured:

$ tcptrace tcpdump.out

1 arg remaining, starting with 'tcpdump.out'
Ostermann's tcptrace -- version 6.2.0 -- Fri Jul 26, 2002

44 packets seen, 44 TCP packets traced
elapsed wallclock time: 0:00:00.025033, 1757 pkts/sec analyzed
trace file elapsed time: 0:00:00.435121
TCP connection info:
   1: c-24-98-83-96.hsd1.ga.comcast.net:63807 - prefetch.net:www (a2b)    7>    6< 
   2: c-24-98-83-96.hsd1.ga.comcast.net:62941 - prefetch.net:www (c2d)    6>    4< 
   3: c-24-98-83-96.hsd1.ga.comcast.net:57312 - prefetch.net:www (e2f)    6>    5< 
   4: c-24-98-83-96.hsd1.ga.comcast.net:55792 - prefetch.net:www (g2h)    6>    4< 

Each connection will contain a unique connection number, the SRC and DST IP address or hostname, a unique descriptor to identify the connection, an integer value with directional brackets to indicate how many segments were sent in each direction, and an optional value to indicate if the connection was reset (RST), or closed normally (FIN). To print information specific to the first TCP connection (e.g., connection number 1), the connection number can be passed to tcptrace(1m)'s "-o" option:

$ tcptrace -o1 tcpdump.out

1 arg remaining, starting with 'tcpdump.out'
Ostermann's tcptrace -- version 6.2.0 -- Fri Jul 26, 2002

44 packets seen, 44 TCP packets traced
elapsed wallclock time: 0:00:00.023074, 1906 pkts/sec analyzed
trace file elapsed time: 0:00:00.435121
TCP connection info:
  1: c-24-98-83-96.hsd1.ga.comcast.net:63807 - prefetch.net:www (a2b)    7>    6<

If you are debugging problematic TCP connections, tcptrace(1m)'s "-l" (long output) option can be used to summarize connection details, and pinpoint connection problems. The following example shows how to display detailed connection data for TCP connection 1:

$ tcptrace -l -o1 tcpdump.out

 
1 arg remaining, starting with 'tcpdump.out'
Ostermann's tcptrace -- version 6.2.0 -- Fri Jul 26, 2002

44 packets seen, 44 TCP packets traced
elapsed wallclock time: 0:00:00.022843, 1926 pkts/sec analyzed
trace file elapsed time: 0:00:00.435121
TCP connection info:
4 TCP connections traced:
TCP connection 1:
        host a:        c-1-2-3-4.hsd1.ga.comcast.net:63807
        host b:        prefetch.net:www
        complete conn: no       (SYNs: 2)  (FINs: 0)
        first packet:  Wed Dec 31 19:00:00.362901 1969
        last packet:   Wed Dec 31 19:00:00.798022 1969
        elapsed time:  0:00:00.435121
        total packets: 13
        filename:      tcpdump.out
   a->b:                              b->a:
     total packets:             7           total packets:             6      
     ack pkts sent:             6           ack pkts sent:             6      
     pure acks sent:            2           pure acks sent:            0      
     sack pkts sent:            0           sack pkts sent:            0      
     max sack blks/ack:         0           max sack blks/ack:         0      
     unique bytes sent:      1097           unique bytes sent:      4609      
     actual data pkts:          4           actual data pkts:          5      
     actual data bytes:      1097           actual data bytes:      4609      
     rexmt data pkts:           0           rexmt data pkts:           0      
     rexmt data bytes:          0           rexmt data bytes:          0      
     zwnd probe pkts:           0           zwnd probe pkts:           0      
     zwnd probe bytes:          0           zwnd probe bytes:          0      
     outoforder pkts:           0           outoforder pkts:           0      
     pushed data pkts:          4           pushed data pkts:          4      
     SYN/FIN pkts sent:       1/0           SYN/FIN pkts sent:       1/0      
     req 1323 ws/ts:          Y/Y           req 1323 ws/ts:          Y/Y      
     adv wind scale:            0           adv wind scale:            1      
     urgent data pkts:          0 pkts      urgent data pkts:          0 pkts 
     urgent data bytes:         0 bytes     urgent data bytes:         0 bytes
     mss requested:          1460 bytes     mss requested:          1460 bytes
     max segm size:           288 bytes     max segm size:          1448 bytes
     min segm size:           236 bytes     min segm size:           418 bytes
     avg segm size:           274 bytes     avg segm size:           921 bytes
     max win adv:           65535 bytes     max win adv:           66608 bytes
     min win adv:           65535 bytes     min win adv:           66608 bytes
     zero win adv:              0 times     zero win adv:              0 times
     avg win adv:           65535 bytes     avg win adv:           66429 bytes
     initial window:          236 bytes     initial window:         2594 bytes
     initial window:            1 pkts      initial window:            2 pkts 
     ttl stream length:        NA           ttl stream length:        NA      
     missed data:              NA           missed data:              NA      
     truncated data:            0 bytes     truncated data:            0 bytes
     truncated packets:         0 pkts      truncated packets:         0 pkts 
     data xmit time:        0.197 secs      data xmit time:        0.195 secs 
     idletime max:          212.8 ms        idletime max:          181.2 ms   
     throughput:             2521 Bps       throughput:            10592 Bps  

Each value listed in the tcptrace(1) long output is described in the tcptrace(1) "-houtput" screen:

$ tcptrace -houtput

OK, here's a sample output (using -l) and what each line means:

1 connection traced:
              ####   how many distinct TCP connections did I see pieces of
13 packets seen, 13 TCP packets traced
              ####   how many packets did I see, how many did I trace
connection 1:
              #### I'll give you a separate block for each connection,
              #### here's the first one
        host a:        132.235.3.133:1084
        host b:        132.235.1.2:79 
              #### Each connection has two hosts.  To shorten output
              #### and file names, I just give them letters.
              #### Connection 1 has hosts 'a' and 'b', connection 2
              #### has hosts 'c' and 'd', etc.
        complete conn: yes
              #### Did I see the starting FINs and closing SYNs?  Was it reset?
        first packet:  Wed Jul 20 16:40:30.688114
              #### At what time did I see the first packet from this connection?
        last packet:   Wed Jul 20 16:40:41.126372
              #### At what time did I see the last packet from this connection?
        elapsed time:  0:00:10.438257
              #### Elapsed time, first packet to last packet
        total packets: 13
              #### total packets this connection

              #### ... Now, there's two columns of output (TCP is
              #### duplex) one for each direction of packets.
              #### I'll just explain one column...
   a->b:                              b->a:
     total packets:             7           total packets:             6
              #### packets sent in each direction
     ack pkts sent:             6           ack pkts sent:             6
              #### how many of the packets contained a valid ACK
     unique bytes sent:        11           unique bytes sent:      1152
              #### how many data bytes were sent (not counting retransmissions)
     actual data pkts:          2           actual data pkts:          1
              #### how many packets did I see that contained any amount of data
     actual data bytes:        11           actual data bytes:      1152
              #### how many data bytes did I see (including retransmissions)
     rexmt data pkts:           0           rexmt data pkts:           0
              #### how many data packets were retransmissions
     rexmt data bytes:          0           rexmt data bytes:          0
              #### how many bytes were retransmissions
     outoforder pkts:           0           outoforder pkts:           0
              #### how many packets were out of order (or I didn't see the first transmit!)
     SYN/FIN pkts sent:       1/1           SYN/FIN pkts sent:       1/1
              #### how many SYNs and FINs were sent in each direction
     mss requested:          1460 bytes     mss requested:          1460 bytes
              #### What what the requested Maximum Segment Size
     max segm size:             9 bytes     max segm size:          1152 bytes
              #### What was the largest segment that I saw
     min segm size:             2 bytes     min segm size:          1152 bytes
              #### What was the smallest segment that I saw
     avg segm size:             5 bytes     avg segm size:          1150 bytes
              #### What was the average segment that I saw
     max win adv:            4096 bytes     max win adv:            4096 bytes
              #### What was the largest window advertisement that I sent
     min win adv:            4096 bytes     min win adv:            4085 bytes
              #### What was the smallest window advertisement that I sent
     zero win adv:              0 times     zero win adv:              0 times
              #### How many times did I sent a zero-sized window advertisement
     avg win adv:            4096 bytes     avg win adv:            4092 bytes
              #### What was the average window advertisement that I sent
     initial window:            9 bytes     initial window:         1152 bytes
              #### How many bytes in the first window (before the first ACK)
     initial window:            1 pkts      initial window:            1 pkts
              #### How many packets in the first window (before the first ACK)
     throughput:                1 Bps       throughput:              110 Bps
              #### What was the data throughput (Bytes/second)
     ttl stream length:        11 bytes     ttl stream length:      1152 bytes
              #### What was the total length of the stream (from FIN to SYN)
              #### Note that this might be larger than unique data bytes because
              #### I might not have captured every segment!!!
     missed data:               0 bytes     missed data:               0 bytes
              #### How many bytes of data were in the stream that I didn't see?
     RTT samples:               2           RTT samples:               1
              #### How many ACK's could I use to get an RTT sample
     RTT min:                45.9 ms        RTT min:                19.4 ms
              #### What was the smallest RTT that I saw
     RTT max:               199.0 ms        RTT max:                19.4 ms
              #### What was the largest RTT that I saw
     RTT avg:               122.5 ms        RTT avg:                19.4 ms
              #### What was the average RTT that I saw
     RTT stdev:               0.0 ms        RTT stdev:               0.0 ms
              #### What was the standard deviation of the RTT that I saw
     segs cum acked:            0           segs cum acked:            0
              #### How many segments were cumulatively ACKed (the ACK that I saw
              #### was for a later segment.  Might be a lost ACK or a delayed ACK
     duplicate acks:            2           duplicate acks:            0
              #### How many duplicate ACKs did I see
     max # retrans:             0           max # retrans:             0
              #### What was the most number of times that a single segment
              #### was retransmitted
     min retr time:           0.0 ms        min retr time:           0.0 ms
              #### What was the minimum time between retransmissions of a
              #### single segment
     max retr time:           0.0 ms        max retr time:           0.0 ms
              #### What was the maximum time between retransmissions of a
              #### single segment
     avg retr time:           0.0 ms        avg retr time:           0.0 ms
              #### What was the average time between retransmissions of a
              #### single segment
     sdv retr time:           0.0 ms        sdv retr time:           0.0 ms
              #### What was the stdev between retransmissions of a
              #### single segment

Version: Ostermann's tcptrace -- version 6.2.0 -- Fri Jul 26, 2002
  Compiled by 'root' at 'Thu Oct  6 00:53:41 EDT 2005' on machine 'oscar.matty.com'

I regularly use the retransmission, mss, bytes transmitted, segment size., window advertisement and duplicate ACK values to debug problematic TCP connections. In addition to printing connection statistics, tcptrace(1) can display RTT (round trip times) values when invoked with the "-r" (print rtt statistics) option:

$ tcptrace -r -l -o1 tcpdump.out

1 arg remaining, starting with 'tcpdump.out'
Ostermann's tcptrace -- version 6.2.0 -- Fri Jul 26, 2002

44 packets seen, 44 TCP packets traced
elapsed wallclock time: 0:00:00.023206, 1896 pkts/sec analyzed
trace file elapsed time: 0:00:00.435121
TCP connection info:
4 TCP connections traced:
TCP connection 1:
        host a:        c-1-2-3-4.hsd1.ga.comcast.net:63807
        host b:        prefetch.net:www
        complete conn: no       (SYNs: 2)  (FINs: 0)
        first packet:  Wed Dec 31 19:00:00.362901 1969
        last packet:   Wed Dec 31 19:00:00.798022 1969
        elapsed time:  0:00:00.435121
        total packets: 13
        filename:      tcpdump.out
   a->b:                              b->a:
     total packets:             7           total packets:             6      
     ack pkts sent:             6           ack pkts sent:             6      
     pure acks sent:            2           pure acks sent:            0      
     sack pkts sent:            0           sack pkts sent:            0      
     max sack blks/ack:         0           max sack blks/ack:         0      
     unique bytes sent:      1097           unique bytes sent:      4609      
     actual data pkts:          4           actual data pkts:          5      
     actual data bytes:      1097           actual data bytes:      4609      
     rexmt data pkts:           0           rexmt data pkts:           0      
     rexmt data bytes:          0           rexmt data bytes:          0      
     zwnd probe pkts:           0           zwnd probe pkts:           0      
     zwnd probe bytes:          0           zwnd probe bytes:          0      
     outoforder pkts:           0           outoforder pkts:           0      
     pushed data pkts:          4           pushed data pkts:          4      
     SYN/FIN pkts sent:       1/0           SYN/FIN pkts sent:       1/0      
     req 1323 ws/ts:          Y/Y           req 1323 ws/ts:          Y/Y      
     adv wind scale:            0           adv wind scale:            1      
     urgent data pkts:          0 pkts      urgent data pkts:          0 pkts 
     urgent data bytes:         0 bytes     urgent data bytes:         0 bytes
     mss requested:          1460 bytes     mss requested:          1460 bytes
     max segm size:           288 bytes     max segm size:          1448 bytes
     min segm size:           236 bytes     min segm size:           418 bytes
     avg segm size:           274 bytes     avg segm size:           921 bytes
     max win adv:           65535 bytes     max win adv:           66608 bytes
     min win adv:           65535 bytes     min win adv:           66608 bytes
     zero win adv:              0 times     zero win adv:              0 times
     avg win adv:           65535 bytes     avg win adv:           66429 bytes
     initial window:          236 bytes     initial window:         2594 bytes
     initial window:            1 pkts      initial window:            2 pkts 
     ttl stream length:        NA           ttl stream length:        NA      
     missed data:              NA           missed data:              NA      
     truncated data:            0 bytes     truncated data:            0 bytes
     truncated packets:         0 pkts      truncated packets:         0 pkts 
     data xmit time:        0.197 secs      data xmit time:        0.195 secs 
     idletime max:          212.8 ms        idletime max:          181.2 ms   
     throughput:             2521 Bps       throughput:            10592 Bps  

     RTT samples:               5           RTT samples:               5      
     RTT min:                24.6 ms        RTT min:                 0.4 ms   
     RTT max:                43.4 ms        RTT max:               181.2 ms   
     RTT avg:                33.3 ms        RTT avg:                53.4 ms   
     RTT stdev:               6.7 ms        RTT stdev:              79.6 ms   

     RTT from 3WHS:          24.6 ms        RTT from 3WHS:           0.4 ms   

     RTT full_sz smpls:         1           RTT full_sz smpls:         1      
     RTT full_sz min:        24.6 ms        RTT full_sz min:         0.4 ms   
     RTT full_sz max:        24.6 ms        RTT full_sz max:         0.4 ms   
     RTT full_sz avg:        24.6 ms        RTT full_sz avg:         0.4 ms   
     RTT full_sz stdev:       0.0 ms        RTT full_sz stdev:       0.0 ms   

     post-loss acks:            0           post-loss acks:            0      
     segs cum acked:            0           segs cum acked:            1      
     duplicate acks:            1           duplicate acks:            1      
     triple dupacks:            0           triple dupacks:            0      
     max # retrans:             0           max # retrans:             0      
     min retr time:           0.0 ms        min retr time:           0.0 ms   
     max retr time:           0.0 ms        max retr time:           0.0 ms   
     avg retr time:           0.0 ms        avg retr time:           0.0 ms   
     sdv retr time:           0.0 ms        sdv retr time:           0.0 ms   

The round trip metrics are invaluable for debugging long haul connection problems, especially connection problems caused by retransmissions and misconfigured window avertisement sizes. Since the RTT measurements are provided in each direction, this can also be used to measure the impact of routing problems. tcptrace(1) provides dozens of useful options, and comes with an awesome manual page to describe the meaning and purpose of each tcptrace(1m) option.

5 thoughts on “Debugging TCP connections with tcptrace”

  1. Hello,
    I am trying to filter my tcpdump file with server port number using tcptrace. Could you please share me the commands to filter?

    Also could you tell me does http.times will be generated based on the filter?

    Thanks in advance

Leave a Reply

Your email address will not be published. Required fields are marked *