From owner-freebsd-net@freebsd.org Thu Feb 25 18:21:02 2021 Return-Path: Delivered-To: freebsd-net@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 6FD4A56B5C9 for ; Thu, 25 Feb 2021 18:21:02 +0000 (UTC) (envelope-from tuexen@freebsd.org) Received: from mailman.nyi.freebsd.org (mailman.nyi.freebsd.org [IPv6:2610:1c1:1:606c::50:13]) by mx1.freebsd.org (Postfix) with ESMTP id 4Dmh1V2fZ8z582G for ; Thu, 25 Feb 2021 18:21:02 +0000 (UTC) (envelope-from tuexen@freebsd.org) Received: by mailman.nyi.freebsd.org (Postfix) id 5928356B6BE; Thu, 25 Feb 2021 18:21:02 +0000 (UTC) Delivered-To: net@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 58DCF56B990 for ; Thu, 25 Feb 2021 18:21:02 +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 "Sectigo RSA Domain Validation Secure Server CA" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4Dmh1V167vz57lH; Thu, 25 Feb 2021 18:21:01 +0000 (UTC) (envelope-from tuexen@freebsd.org) Received: from [IPv6:2a02:8109:1140:c3d:501:db77:ef42:1a77] (unknown [IPv6:2a02:8109:1140:c3d:501:db77:ef42:1a77]) (Authenticated sender: macmic) by mail-n.franken.de (Postfix) with ESMTPSA id D11DC7220B81C; Thu, 25 Feb 2021 19:20:56 +0100 (CET) Content-Type: text/plain; charset=utf-8 Mime-Version: 1.0 (Mac OS X Mail 14.0 \(3654.60.0.2.21\)) Subject: Re: panic: sackhint bytes rtx >= 0 From: Michael Tuexen In-Reply-To: Date: Thu, 25 Feb 2021 19:20:55 +0100 Cc: "Scheffenegger, Richard" , "net@FreeBSD.org" Content-Transfer-Encoding: quoted-printable Message-Id: <58AED4F6-FBA4-46D5-98D4-DD31BD9A946B@freebsd.org> References: <960081ac-2839-a226-3142-5a4666eb54ad@FreeBSD.org> <8BB910F9-B828-49A2-8941-4F6C6419D8EA@freebsd.org> To: Andriy Gapon X-Mailer: Apple Mail (2.3654.60.0.2.21) 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: 4Dmh1V167vz57lH X-Spamd-Bar: ---- Authentication-Results: mx1.freebsd.org; none X-Spamd-Result: default: False [-4.00 / 15.00]; REPLY(-4.00)[] X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.34 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 25 Feb 2021 18:21:02 -0000 > On 25. Feb 2021, at 19:08, Andriy Gapon wrote: >=20 > On 24/02/2021 00:40, Scheffenegger, Richard wrote: >> Hi Andriy, >>=20 >> I guess I am currently the person who has the most recent knowledge = about that >> part of the base stack=E2=80=A6 >>=20 >> Do you happen to have more (preceding) information about this, or a = way to >> reproduce this? >=20 > Unfortunately, no. It "just happened". > There was no unusual activity at the time of the crash. > At least, from a user / administrator perspective. So you did not use specific TCP stacks or congestion control modules? >=20 >> Are you running any special stack (RACK, BBR) which may have switched = back to >> the base stack in the middle of a loss recovery (I suspected at one = point that >> this may cause issues, potentially)? >=20 > I do not have any customizations to the network stack, everything at = defaults. >=20 >> Or was something done with the ipfw that may have temporarily = impacted a tcp >> session? >=20 > I use pf as a firewall. I did not touch it at the time of the crash. Does pf change the packets? >=20 >> The accounting with sack_bytes_rexmit is rather old, and not touched = recently >> (but the sackhint struct was changed recently, and other/additional = scoreboard >> accounting was added). >>=20 >> (kgdb) p *cur >> $1 =3D {start =3D 3846347980, end =3D 3846352300, rxmit =3D = 3846352300, scblink =3D >> {tqe_next =3D 0xfffff8013da5a220, tqe_prev =3D 0xfffff80754818930}} >>=20 >> This indicates, that the current hole in the SACK scoreboard (3 = segments of size >> 1440 bytes) were retransmitted (rxmit =3D=3D end), before the = current >> acknowledgement came back. >>=20 >> Thus the expectation is, that sackhint.sack_bytes_rexmit also has a = value of at >> least that number of bytes (4320). It is increased in tcp_output() = for each >> packet leaving while performing a retransmission. >>=20 >> But this is the peculiar part: >>=20 >> (kgdb) p tp@entry->sackhint.sack_bytes_rexmit >> $3 =3D -1440 >>=20 >> Indicating negative one packet had been retransmitted before (thus = subtracting >> the hole, which was previously retransmitted violates the invariant). = And the >> only piece of code decrementing it appears to be in tcp_output() = during >> non-permanent error handling=E2=80=A6 >>=20 >> All updates to sackhint should be protected by the INPLOCK, so even = if the rx >> and tx paths are running on different core, the sack_bytes_rexmit = should never >> become negative. >>=20 >> The sack blocks returned indicate that (with snd.una as zero = baseline, in >> segments) the client knows about segments 2..34 and 35..47. >>=20 >> The first hole has shrunk from the right (unusual; possible when two >> retransmissions were lost again, or the 3 segment originally sent, = delayed by >> ~50 segments (unlikely). >>=20 >> Sorry to not being able to spot something obvious right away=E2=80=A6 >=20 > Thank you very much for the response. > Unfortunately, I cannot help much in terms of re-creating the issue as = for me it > really "just happened" without me touching anything. There were just = some > HTTP(S) and SSH sessions, the usual stuff. >=20 > If you need anything else from the crash dump, please let me know. >=20 >> *Von:*tuexen@freebsd.org >> *Gesendet:* Dienstag, 23. Februar 2021 22:21 >> *An:* Richard Scheffenegger >> *Betreff:* Fwd: panic: sackhint bytes rtx >=3D 0 >>=20 >> =20 >>=20 >> *NetApp Security WARNING*: This is an external email. Do not click = links or open >> attachments unless you recognize the sender and know the content is = safe. >>=20 >>=20 >>=20 >> FYI >>=20 >>=20 >>=20 >> Begin forwarded message: >>=20 >> =20 >>=20 >> *From: *Andriy Gapon > >>=20 >> *Subject: panic: sackhint bytes rtx >=3D 0* >>=20 >> *Date: *23. February 2021 at 22:02:20 CET >>=20 >> *To: *FreeBSD Current >, >> net@FreeBSD.org >>=20 >> =20 >>=20 >>=20 >> Got this panic on 13.0-STABLE 4b2a20dfde9c using a custom kernel = with INVARIANTS >> enabled. >> Below is some information from the crash dump. >> If anyone has any clues, suggestions, etc, please help. >> I will try to help you to help me the best I can. >>=20 >> #0 doadump (textdump=3Dtextdump@entry=3D1) >> at /usr/devel/git/trant/sys/kern/kern_shutdown.c:399 >> #1 0xffffffff808396b2 in kern_reboot (howto=3D260) >> at /usr/devel/git/trant/sys/kern/kern_shutdown.c:486 >> #2 0xffffffff80839d07 in vpanic ( >> fmt=3D0xffffffff80cbd551 "sackhint bytes rtx >=3D 0", = ap=3D0xfffffe0120b9e6d0) >> at /usr/devel/git/trant/sys/kern/kern_shutdown.c:919 >> #3 0xffffffff808398b3 in panic (fmt=3D) >> at /usr/devel/git/trant/sys/kern/kern_shutdown.c:843 >> #4 0xffffffff8098a82c in tcp_sack_doack (tp=3D, >> tp@entry=3D0xfffff807548187f0, to=3D, >> to@entry=3D0xfffffe0120b9e780, th_ack=3D) >> at /usr/devel/git/trant/sys/netinet/tcp_sack.c:691 >> #5 0xffffffff80983699 in tcp_do_segment (m=3D0xfffff8029868ca00, >> m@entry=3D, >> th=3D, >> th@entry=3D, >> so=3D0xfffff804e7359b10, >> so@entry=3D, >> tp=3D0xfffff807548187f0, >> tp@entry=3D, >> drop_hdrlen=3D60, >> drop_hdrlen@entry=3D, >> tlen=3D, >> tlen@entry=3D, >> iptos=3D72 'H', >> iptos@entry=3D) >> at /usr/devel/git/trant/sys/netinet/tcp_input.c:2497 >> #6 0xffffffff80980d97 in tcp_input (mp=3D, >> mp@entry=3D, >> offp=3D, >> offp@entry=3D, >> proto=3D) >> at /usr/devel/git/trant/sys/netinet/tcp_input.c:1381 >> #7 0xffffffff80976eb7 in ip_input (m=3D0x0) >> at /usr/devel/git/trant/sys/netinet/ip_input.c:833 >> #8 0xffffffff8094c78f in netisr_dispatch_src (proto=3D1, >> source=3Dsource@entry=3D0, m=3D0xfffff8029868ca00) >> at /usr/devel/git/trant/sys/net/netisr.c:1143 >> #9 0xffffffff8094cb0e in netisr_dispatch (proto=3D, >> m=3D) at = /usr/devel/git/trant/sys/net/netisr.c:1234 >> #10 0xffffffff80943345 in ether_demux = (ifp=3Difp@entry=3D0xfffff80008c75000, >> m=3D) at = /usr/devel/git/trant/sys/net/if_ethersubr.c:923 >> #11 0xffffffff809446c1 in ether_input_internal = (ifp=3D0xfffff80008c75000, >> m=3D) at = /usr/devel/git/trant/sys/net/if_ethersubr.c:709 >> #12 0xffffffff809443d0 in ether_nh_input (m=3D) >> at /usr/devel/git/trant/sys/net/if_ethersubr.c:739 >> #13 0xffffffff8094c78f in netisr_dispatch_src = (proto=3Dproto@entry=3D5, >> source=3Dsource@entry=3D0, m=3Dm@entry=3D0xfffff8029868ca00) >> at /usr/devel/git/trant/sys/net/netisr.c:1143 >> #14 0xffffffff8094cb0e in netisr_dispatch (proto=3D, >> proto@entry=3D5, m=3D, m@entry=3D0xfffff8029868ca00)= >> at /usr/devel/git/trant/sys/net/netisr.c:1234 >> #15 0xffffffff8094383d in ether_input (ifp=3D0xfffff80008c75000, >> ifp@entry=3D, >> m=3D0xfffff8029868ca00, >> m@entry=3D) >> at /usr/devel/git/trant/sys/net/if_ethersubr.c:830 >> #16 0xffffffff8066da13 in re_rxeof = (sc=3Dsc@entry=3D0xfffffe00391a5000, >> rx_npktsp=3D0x0) at = /usr/devel/git/trant/sys/dev/re/if_re.c:2388 >> #17 0xffffffff8066b3ab in re_intr_msi (xsc=3D0xfffffe00391a5000) >> at /usr/devel/git/trant/sys/dev/re/if_re.c:2684 >> #18 0xffffffff80801bcf in intr_event_execute_handlers ( >> p=3Dp@entry=3D0xfffff80006a94a50, = ie=3Die@entry=3D0xfffff80008c57800) >> at /usr/devel/git/trant/sys/kern/kern_intr.c:1168 >> #19 0xffffffff80801942 in ithread_execute_handlers ( >> p=3Dp@entry=3D0xfffff80006a94a50, = ie=3Die@entry=3D0xfffff80008c57800) >> at /usr/devel/git/trant/sys/kern/kern_intr.c:1181 >> #20 0xffffffff80801758 in ithread_loop = (arg=3Darg@entry=3D0xfffff80008c20c40) >> at /usr/devel/git/trant/sys/kern/kern_intr.c:1269 >> #21 0xffffffff807fe0a9 in fork_exit ( >> callout=3D0xffffffff808016c0 , = arg=3D0xfffff80008c20c40, >> frame=3D0xfffffe0120b9ed40) >> at /usr/devel/git/trant/sys/kern/kern_fork.c:1069 >>=20 >>=20 >> (kgdb) fr 4 >> #4 0xffffffff8098a82c in tcp_sack_doack (tp=3D, >> tp@entry=3D0xfffff807548187f0, to=3D, = to@entry=3D0xfffffe0120b9e780, >> th_ack=3D) at = /usr/devel/git/trant/sys/netinet/tcp_sack.c:691 >> 691 KASSERT(tp->sackhint.sack_bytes_rexmit >=3D = 0, >> (kgdb) i loc >> sack_blocks =3D {{start =3D 3846350860, end =3D 3846396940}, = {start =3D 3846398380, end >> =3D 3846415660}, {start =3D 0, end =3D 0}, {start =3D 1417775088, = end =3D 4294965255}, >> {start =3D 549054304, end =3D 4294966785}} >> left_edge_delta =3D >> delivered_data =3D 0 >> sack_changed =3D >> num_sack_blks =3D >> i =3D >> j =3D >> sack =3D {start =3D , end =3D } >> sblkp =3D 0xfffffe0120b9e700 >> temp =3D >> cur =3D 0xfffff8013da5a320 >> (kgdb) p *cur >> $1 =3D {start =3D 3846347980, end =3D 3846352300, rxmit =3D = 3846352300, scblink =3D >> {tqe_next =3D 0xfffff8013da5a220, tqe_prev =3D = 0xfffff80754818930}} >> (kgdb) p 3846352300 - 3846347980 >> $2 =3D 4320 >> (kgdb) p tp->sackhint.sack_bytes_rexmit >> value has been optimized out >> (kgdb) p tp@entry->sackhint.sack_bytes_rexmit >> >> $3 =3D -1440 >> (kgdb) p 4320 - 1440 >> $4 =3D 2880 >> (kgdb) p *sblkp >> $5 =3D {start =3D 3846350860, end =3D 3846396940} >>=20 >> (kgdb) p *tp@entry >> $7 =3D {t_inpcb =3D 0xfffff80640ca65b8, t_fb =3D = 0xffffffff80ef4700 , >> t_fb_ptr =3D 0x0, t_maxseg =3D 1440, t_logstate =3D 0, t_port =3D = 0, t_state =3D 4, >> t_idle_reduce =3D 0, t_delayed_ack =3D 0, t_fin_is_rst =3D 0, >> t_log_state_set =3D 0, bits_spare =3D 0, t_flags =3D 1613759072, = snd_una =3D >> 3846347980, snd_max =3D 3846417100, snd_nxt =3D 3846417100, snd_up = =3D 3846347980, >> snd_wnd =3D 237568, snd_cwnd =3D 4320, t_peakrate_thr =3D 0, = ts_offset =3D 71449215, >> rfbuf_ts =3D 162235772, rcv_numsacks =3D 0, t_tsomax =3D 0, = t_tsomaxsegcount =3D 0, >> t_tsomaxsegsize =3D 0, rcv_nxt =3D 2281639092, rcv_adv =3D = 2281705332, rcv_wnd =3D >> 66240, t_flags2 =3D 1030, t_srtt =3D 876, t_rttvar =3D 33, = ts_recent =3D 0, >> snd_scale =3D 8 '\b', rcv_scale =3D 6 '\006', snd_limited =3D 2 = '\002', >> request_r_scale =3D 6 '\006', last_ack_sent =3D 2281639092, = t_rcvtime =3D 2309118641, >> rcv_up =3D 2281639092, t_segqlen =3D 0, t_segqmbuflen =3D 0, = t_segq =3D { >> tqh_first =3D 0x0, tqh_last =3D 0xfffff80754818880}, t_in_pkt =3D= 0x0, t_tail_pkt >> =3D 0x0, t_timers =3D 0xfffff80754818a78, t_vnet =3D 0x0, = snd_ssthresh =3D 31680, >> snd_wl1 =3D 2281639092, snd_wl2 =3D 3846347980, irs =3D = 2281631223, >> iss =3D 3840447913, t_acktime =3D 0, t_sndtime =3D 2309118613, = ts_recent_age =3D 0, >> snd_recover =3D 3846415660, cl4_spare =3D 0, t_oobflags =3D 0 = '\000', t_iobc =3D 0 >> '\000', t_rxtcur =3D 270, t_rxtshift =3D 1, t_rtttime =3D = 2309118613, >> t_rtseq =3D 3846415660, t_starttime =3D 2309086941, t_fbyte_in =3D = 2309087188, >> t_fbyte_out =3D 2309087159, t_pmtud_saved_maxseg =3D 0, = t_blackhole_enter =3D 0, >> t_blackhole_exit =3D 0, t_rttmin =3D 30, t_rttbest =3D 845, = t_softerror =3D 0, >> max_sndwnd =3D 237568, snd_cwnd_prev =3D 64800, snd_ssthresh_prev = =3D 8640, >> snd_recover_prev =3D 3846347980, t_sndzerowin =3D 0, t_rttupdated = =3D 368, >> snd_numholes =3D 2, t_badrxtwin =3D 0, snd_holes =3D {tqh_first =3D = 0xfffff8013da5a320, >> tqh_last =3D 0xfffff8013da5a230}, snd_fack =3D 3846415660, = sackblks =3D {{start =3D >> 2281632180, end =3D 2281632690}, {start =3D 0, end =3D 0}, {start = =3D 0, end =3D 0}, >> {start =3D 0, end =3D 0}, {start =3D 0, end =3D 0}, {start =3D 0, = end =3D 0}}, >> sackhint =3D {nexthole =3D 0xfffff8013da5a220, sack_bytes_rexmit = =3D -1440, >> last_sack_ack =3D 3846415660, delivered_data =3D 1440, = sacked_bytes =3D 61920, >> recover_fs =3D 67680, prr_delivered =3D 1440, _pad =3D {0}}, = t_rttlow =3D 25, >> rfbuf_cnt =3D 0, tod =3D 0x0, t_sndrexmitpack =3D 520, = t_rcvoopack =3D 0, t_toe =3D 0x0, >> cc_algo =3D 0xffffffff80ef2530 , ccv =3D = 0xfffff80754818bc0, osd =3D >> 0x0, t_bytes_acked =3D 11520, t_maxunacktime =3D 0, t_keepinit =3D = 0, >> t_keepidle =3D 0, t_keepintvl =3D 0, t_keepcnt =3D 0, t_dupacks =3D= 4, t_lognum =3D 0, >> t_loglimit =3D 0, t_pacing_rate =3D -1, t_logs =3D {stqh_first =3D = 0x0, stqh_last =3D >> 0x0}, t_lin =3D 0x0, t_lib =3D 0x0, t_output_caller =3D 0x0, = t_stats =3D 0x0, >> t_logsn =3D 0, gput_ts =3D 0, gput_seq =3D 0, gput_ack =3D 0, = t_stats_gput_prev =3D 0, >> t_tfo_client_cookie_len =3D 0 '\000', t_end_info_status =3D 0, = t_tfo_pending =3D 0x0, >> t_tfo_cookie =3D {client =3D '\000' , server =3D = 0}, { >> t_end_info_bytes =3D "\000\000\000\000\000\000\000", t_end_info = =3D 0}} >>=20 >> (kgdb) p *tp@entry->sackhint.nexthole = >> $8 =3D {start =3D 3846396940, end =3D 3846398380, rxmit =3D = 3846398380, scblink =3D >> {tqe_next =3D 0x0, tqe_prev =3D 0xfffff8013da5a330}} >>=20 >> --=20 >> Andriy Gapon >> _______________________________________________ >> freebsd-current@freebsd.org = mailing list >> https://lists.freebsd.org/mailman/listinfo/freebsd-current >> >> To unsubscribe, send any mail to = "freebsd-current-unsubscribe@freebsd.org >> " >>=20 >> =20 >>=20 >=20 >=20 > --=20 > Andriy Gapon