unexpected TCP resets (RST) in 12.0-RELEASE

Fri Jun 21 08:19:50 UTC 2019

Hello,

I have been trying to debug several issues where a 12.0-RELEASE (all the way from p0 to p6) server would unexpectedly send RST packets to clients either some time after the initial 3-way handshake is completed or right after it gets the first SYN on an open port.

I ran several tests and here are a few samples and scenarios and a way to replicate the problem.

###
CASE 1 - RST after a SYN.

this is when I noticed the issue after upgrading to 12.0-RELEASE. Port is open by an app with plenty of somaxconn and there is a lot of healthy traffic exchanging. Once every few minutes I would see this:

No.     Time           Source                Destination           Protocol Length Info
  14717 6.240595       10.0.0.81             10.0.0.60             TCP      74     60293 → 9000 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 WS=128 SACK_PERM=1 TSval=3108212602 TSecr=0

Frame 14717: 74 bytes on wire (592 bits), 74 bytes captured (592 bits)
Ethernet II, Src: IntelCor_f1:7f:8c (a0:36:9f:f1:7f:8c), Dst: IntelCor_d4:36:d0 (a0:36:9f:d4:36:d0)
Internet Protocol Version 4, Src: 10.0.0.81, Dst: 10.0.0.60
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
    Total Length: 60
    Identification: 0x0000 (0)
    Flags: 0x4000, Don't fragment
    Time to live: 64
    Protocol: TCP (6)
    Header checksum: 0x2630 [validation disabled]
    [Header checksum status: Unverified]
    Source: 10.0.0.81
    Destination: 10.0.0.60
Transmission Control Protocol, Src Port: 60293, Dst Port: 9000, Seq: 0, Len: 0
    Source Port: 60293
    Destination Port: 9000
    [Stream index: 1548]
    [TCP Segment Len: 0]
    Sequence number: 0    (relative sequence number)
    [Next sequence number: 0    (relative sequence number)]
    Acknowledgment number: 0
    1010 .... = Header Length: 40 bytes (10)
    Flags: 0x002 (SYN)
    Window size value: 65535
    [Calculated window size: 65535]
    Checksum: 0xa7f7 [unverified]
    [Checksum Status: Unverified]
    Urgent pointer: 0
    Options: (20 bytes), Maximum segment size, No-Operation (NOP), Window scale, SACK permitted, Timestamps
    [Timestamps]

No.     Time           Source                Destination           Protocol Length Info
  14719 6.240617       10.0.0.60             10.0.0.81             TCP      54     9000 → 60293 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0

Frame 14719: 54 bytes on wire (432 bits), 54 bytes captured (432 bits)
Ethernet II, Src: IntelCor_d4:36:d0 (a0:36:9f:d4:36:d0), Dst: IntelCor_f1:7f:8c (a0:36:9f:f1:7f:8c)
Internet Protocol Version 4, Src: 10.0.0.60, Dst: 10.0.0.81
    0100 .... = Version: 4
    .... 0101 = Header Length: 20 bytes (5)
    Differentiated Services Field: 0x00 (DSCP: CS0, ECN: Not-ECT)
    Total Length: 40
    Identification: 0x0000 (0)
    Flags: 0x4000, Don't fragment
    Time to live: 64
    Protocol: TCP (6)
    Header checksum: 0x0000 [validation disabled]
    [Header checksum status: Unverified]
    Source: 10.0.0.60
    Destination: 10.0.0.81
Transmission Control Protocol, Src Port: 9000, Dst Port: 60293, Seq: 1, Ack: 1, Len: 0
    Source Port: 9000
    Destination Port: 60293
    [Stream index: 1548]
    [TCP Segment Len: 0]
    Sequence number: 1    (relative sequence number)
    [Next sequence number: 1    (relative sequence number)]
    Acknowledgment number: 1    (relative ack number)
    0101 .... = Header Length: 20 bytes (5)
    Flags: 0x014 (RST, ACK)
    Window size value: 0
    [Calculated window size: 0]
    [Window size scaling factor: -1 (unknown)]
    Checksum: 0x14a7 [unverified]
    [Checksum Status: Unverified]
    Urgent pointer: 0
    [SEQ/ACK analysis]
    [Timestamps]

It doesn't seem to matter what app that is, doesn't matter what event mechanism is used (kqueue or select). TCP stack just refuses to handshake from time to time. The rate of these increases with the rate of incoming connections. 12.0-RELEASE-p6 seems to be producing fewer of these, it could be due to the fix in https://www.freebsd.org/security/advisories/FreeBSD-EN-19:11.net.asc . While my guess is not very scientific, it seems to be related to the new epoch(9) based synchronization. A 11.2-RELEASE host, serving the same exact traffic, which I kept for baselining is rock-solid and doesn't produce TCP resets like these.

###
CASE 2 - packets processed out of order. and a simple way to replicate it.

#setup:  hostA(11.2-RELEASE with defaults) - switch - hostB(12.0-RELEASE with defaults)
-install tcpkali from ports or via pkg on hostA. 
-start the tcpdump capture on any of the hosts:     tcpdump -i em0 -n -v 'tcp[tcpflags] & (tcp-rst) != 0' and port 22
-run on hostA:   tcpkali -c 100 --connect-rate 50 --channel-lifetime 1 hostB:22 -T 120
- wait up to 2 minutes. you will see sshd logging successful empty connections and then you will see resets returned to the client for some of the connections. Those same connections would not be logged by sshd.

a fully captured pcap shows the following TCP stream which ends with resets.

No.     Time           Source                Destination           Protocol Length Info
   7023 76.041587      192.168.44.2          192.168.44.3          TCP      74     27697 → 22 [SYN] Seq=0 Win=65535 Len=0 MSS=1460 WS=64 SACK_PERM=1 TSval=4283665081 TSecr=0
   7024 76.041601      192.168.44.3          192.168.44.2          TCP      74     22 → 27697 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1460 WS=64 SACK_PERM=1 TSval=1662309011 TSecr=4283665081
   7026 76.041919      192.168.44.2          192.168.44.3          TCP      66     27697 → 22 [ACK] Seq=1 Ack=1 Win=65664 Len=0 TSval=4283665081 TSecr=1662309011
   7050 76.047586      192.168.44.2          192.168.44.3          TCP      66     27697 → 22 [FIN, ACK] Seq=1 Ack=1 Win=65664 Len=0 TSval=4283665086 TSecr=1662309011
   7051 76.047590      192.168.44.3          192.168.44.2          TCP      66     22 → 27697 [ACK] Seq=1 Ack=2 Win=65664 Len=0 TSval=1662309017 TSecr=4283665086
   7072 76.064230      192.168.44.3          192.168.44.2          TCP      104    22 → 27697 [PSH, ACK] Seq=1 Ack=2 Win=65664 Len=38 TSval=1662309033 TSecr=4283665086
   7073 76.064415      192.168.44.3          192.168.44.2          TCP      66     22 → 27697 [FIN, ACK] Seq=39 Ack=2 Win=65664 Len=0 TSval=1662309034 TSecr=4283665086
   7074 76.064538      192.168.44.2          192.168.44.3          TCP      60     27697 → 22 [RST] Seq=2 Win=0 Len=0
   7075 76.064710      192.168.44.2          192.168.44.3          TCP      60     27697 → 22 [RST] Seq=2 Win=0 Len=0

it seems like the actual packet with the payload(#7072) is processed after the FIN is received and that is not the order they are sent by tcpkali running on hostA.
this doesn't seem to be replicatable over lo0, there has to be physical exchange of packets via the NICs. I have not tried running it in bhyve.

when the same tcpkali test is executed the other direction, 11.2-RELEASE doesn't produce a single reset like that.
##

11.2-RELEASE (any patch level) doesn't have any of these problems, so this must be a regression somewhere in the TCP stack. In all these cases OS was installed with all defaults untouched. NICs are either ix or em (tried stock drivers and intel-ix-kmod and intel-em-kmod, which didn't seem to matter).

I can provide dmesgs, raw pcaps, etc, if necessary. I am curious why this hasn't been reported by now(checked mailing lists and open bugs) as it seems like a relatively serious issue. But then again, maybe I'm missing something obvious, in which case, I'd like to get educated.

Regards,

-- 
Igor