From owner-freebsd-net@freebsd.org Fri Jun 21 10:26:52 2019 Return-Path: Delivered-To: freebsd-net@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id A4E8415D652F for ; Fri, 21 Jun 2019 10:26:52 +0000 (UTC) (envelope-from tuexen@freebsd.org) Received: from drew.franken.de (mail-n.franken.de [193.175.24.27]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "*.franken.de", Issuer "COMODO RSA Domain Validation Secure Server CA" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 07AAB89F41 for ; Fri, 21 Jun 2019 10:26:51 +0000 (UTC) (envelope-from tuexen@freebsd.org) Received: from [IPv6:2a02:8109:1140:c3d:f82e:99f:942f:fc66] (unknown [IPv6:2a02:8109:1140:c3d:f82e:99f:942f:fc66]) (Authenticated sender: macmic) by drew.franken.de (Postfix) with ESMTPSA id CEAB872106C12; Fri, 21 Jun 2019 12:26:47 +0200 (CEST) Content-Type: text/plain; charset=utf-8 Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.11\)) Subject: Re: unexpected TCP resets (RST) in 12.0-RELEASE From: Michael Tuexen In-Reply-To: <20190621081941.GM94573@sun.grinchenko.org> Date: Fri, 21 Jun 2019 12:26:46 +0200 Cc: freebsd-net@freebsd.org Content-Transfer-Encoding: quoted-printable Message-Id: References: <20190621081941.GM94573@sun.grinchenko.org> To: Igor Grinchenko X-Mailer: Apple Mail (2.3445.104.11) X-Spam-Status: No, score=-2.9 required=5.0 tests=ALL_TRUSTED,BAYES_00 autolearn=disabled version=3.4.1 X-Spam-Checker-Version: SpamAssassin 3.4.1 (2015-04-28) on mail-n.franken.de X-Rspamd-Queue-Id: 07AAB89F41 X-Spamd-Bar: -- Authentication-Results: mx1.freebsd.org X-Spamd-Result: default: False [-2.98 / 15.00]; local_wl_from(0.00)[freebsd.org]; NEURAL_HAM_MEDIUM(-1.00)[-0.999,0]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; NEURAL_HAM_SHORT(-0.98)[-0.980,0]; ASN(0.00)[asn:680, ipnet:193.174.0.0/15, country:DE] X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 21 Jun 2019 10:26:52 -0000 > On 21. Jun 2019, at 10:19, Igor Grinchenko = wrote: >=20 > Hello, >=20 > 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. >=20 > I ran several tests and here are a few samples and scenarios and a way = to replicate the problem. >=20 > ### > CASE 1 - RST after a SYN. >=20 > 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: >=20 > No. Time Source Destination = Protocol Length Info > 14717 6.240595 10.0.0.81 10.0.0.60 TCP = 74 60293 =E2=86=92 9000 [SYN] Seq=3D0 Win=3D65535 Len=3D0 = MSS=3D1460 WS=3D128 SACK_PERM=3D1 TSval=3D3108212602 TSecr=3D0 >=20 > 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 .... =3D Version: 4 > .... 0101 =3D 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 .... =3D 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] >=20 > No. Time Source Destination = Protocol Length Info > 14719 6.240617 10.0.0.60 10.0.0.81 TCP = 54 9000 =E2=86=92 60293 [RST, ACK] Seq=3D1 Ack=3D1 Win=3D0 Len=3D0= >=20 > 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 .... =3D Version: 4 > .... 0101 =3D 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 .... =3D 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] >=20 > 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. Hi Igor, could you do sudo sysctl net.inet.tcp.log_debug=3D1 on the host sending the RST segments and see if you get some messages in = /var/log/messages. Do you see these messages? If yes, what is logged? Do you have a way to reproduce this issue? Best regards Michael >=20 > ### > CASE 2 - packets processed out of order. and a simple way to replicate = it. >=20 > #setup: hostA(11.2-RELEASE with defaults) - switch - = hostB(12.0-RELEASE with defaults) > -install tcpkali from ports or via pkg on hostA.=20 > -start the tcpdump capture on any of the hosts: tcpdump -i em0 -n = -v 'tcp[tcpflags] & (tcp-rst) !=3D 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. >=20 > a fully captured pcap shows the following TCP stream which ends with = resets. >=20 > No. Time Source Destination = Protocol Length Info > 7023 76.041587 192.168.44.2 192.168.44.3 TCP = 74 27697 =E2=86=92 22 [SYN] Seq=3D0 Win=3D65535 Len=3D0 MSS=3D1460= WS=3D64 SACK_PERM=3D1 TSval=3D4283665081 TSecr=3D0 > 7024 76.041601 192.168.44.3 192.168.44.2 TCP = 74 22 =E2=86=92 27697 [SYN, ACK] Seq=3D0 Ack=3D1 Win=3D65535 = Len=3D0 MSS=3D1460 WS=3D64 SACK_PERM=3D1 TSval=3D1662309011 = TSecr=3D4283665081 > 7026 76.041919 192.168.44.2 192.168.44.3 TCP = 66 27697 =E2=86=92 22 [ACK] Seq=3D1 Ack=3D1 Win=3D65664 Len=3D0 = TSval=3D4283665081 TSecr=3D1662309011 > 7050 76.047586 192.168.44.2 192.168.44.3 TCP = 66 27697 =E2=86=92 22 [FIN, ACK] Seq=3D1 Ack=3D1 Win=3D65664 = Len=3D0 TSval=3D4283665086 TSecr=3D1662309011 > 7051 76.047590 192.168.44.3 192.168.44.2 TCP = 66 22 =E2=86=92 27697 [ACK] Seq=3D1 Ack=3D2 Win=3D65664 Len=3D0 = TSval=3D1662309017 TSecr=3D4283665086 > 7072 76.064230 192.168.44.3 192.168.44.2 TCP = 104 22 =E2=86=92 27697 [PSH, ACK] Seq=3D1 Ack=3D2 Win=3D65664 = Len=3D38 TSval=3D1662309033 TSecr=3D4283665086 > 7073 76.064415 192.168.44.3 192.168.44.2 TCP = 66 22 =E2=86=92 27697 [FIN, ACK] Seq=3D39 Ack=3D2 Win=3D65664 = Len=3D0 TSval=3D1662309034 TSecr=3D4283665086 > 7074 76.064538 192.168.44.2 192.168.44.3 TCP = 60 27697 =E2=86=92 22 [RST] Seq=3D2 Win=3D0 Len=3D0 > 7075 76.064710 192.168.44.2 192.168.44.3 TCP = 60 27697 =E2=86=92 22 [RST] Seq=3D2 Win=3D0 Len=3D0 >=20 >=20 > 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. >=20 > when the same tcpkali test is executed the other direction, = 11.2-RELEASE doesn't produce a single reset like that. > ## >=20 > 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). >=20 > 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. >=20 > Regards, >=20 > --=20 > Igor >=20 >=20 > _______________________________________________ > freebsd-net@freebsd.org mailing list > https://lists.freebsd.org/mailman/listinfo/freebsd-net > To unsubscribe, send any mail to "freebsd-net-unsubscribe@freebsd.org"