From owner-freebsd-net@freebsd.org Thu Feb 25 18:08:28 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 DDB4956B172 for ; Thu, 25 Feb 2021 18:08:28 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from mailman.nyi.freebsd.org (unknown [127.0.1.3]) by mx1.freebsd.org (Postfix) with ESMTP id 4Dmgl05Hmbz56pk for ; Thu, 25 Feb 2021 18:08:28 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: by mailman.nyi.freebsd.org (Postfix) id B202F56B171; Thu, 25 Feb 2021 18:08:28 +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 B0F4A56B2D5 for ; Thu, 25 Feb 2021 18:08:28 +0000 (UTC) (envelope-from avg@FreeBSD.org) Received: from relay9-d.mail.gandi.net (relay9-d.mail.gandi.net [217.70.183.199]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 4Dmgl00jwlz56pd; Thu, 25 Feb 2021 18:08:27 +0000 (UTC) (envelope-from avg@FreeBSD.org) X-Originating-IP: 195.64.148.76 Received: from [192.168.0.88] (unknown [195.64.148.76]) (Authenticated sender: andriy.gapon@uabsd.com) by relay9-d.mail.gandi.net (Postfix) with ESMTPSA id 2B1F1FF809; Thu, 25 Feb 2021 18:08:24 +0000 (UTC) Subject: Re: AW: panic: sackhint bytes rtx >= 0 To: "Scheffenegger, Richard" Cc: "tuexen@freebsd.org" , "net@FreeBSD.org" References: <960081ac-2839-a226-3142-5a4666eb54ad@FreeBSD.org> <8BB910F9-B828-49A2-8941-4F6C6419D8EA@freebsd.org> From: Andriy Gapon Message-ID: Date: Thu, 25 Feb 2021 20:08:24 +0200 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:78.0) Gecko/20100101 Firefox/78.0 Thunderbird/78.8.0 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=windows-1252 Content-Language: en-US Content-Transfer-Encoding: 8bit X-Rspamd-Queue-Id: 4Dmgl00jwlz56pd X-Spamd-Bar: / Authentication-Results: mx1.freebsd.org; none X-Spamd-Result: default: False [0.00 / 15.00]; ASN(0.00)[asn:29169, ipnet:217.70.176.0/20, country:FR]; local_wl_from(0.00)[FreeBSD.org] 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:08:29 -0000 On 24/02/2021 00:40, Scheffenegger, Richard wrote: > Hi Andriy, > > I guess I am currently the person who has the most recent knowledge about that > part of the base stack… > > Do you happen to have more (preceding) information about this, or a way to > reproduce this? Unfortunately, no. It "just happened". There was no unusual activity at the time of the crash. At least, from a user / administrator perspective. > 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)? I do not have any customizations to the network stack, everything at defaults. > Or was something done with the ipfw that may have temporarily impacted a tcp > session? I use pf as a firewall. I did not touch it at the time of the crash. > 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). > > (kgdb) p *cur > $1 = {start = 3846347980, end = 3846352300, rxmit = 3846352300, scblink = > {tqe_next = 0xfffff8013da5a220, tqe_prev = 0xfffff80754818930}} > > This indicates, that the current hole in the SACK scoreboard (3 segments of size > 1440 bytes) were retransmitted  (rxmit == end), before the current > acknowledgement came back. > > 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. > > But this is the peculiar part: > > (kgdb) p tp@entry->sackhint.sack_bytes_rexmit > $3 = -1440 > > 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… > > 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. > > The sack blocks returned indicate that (with snd.una as zero baseline, in > segments) the client knows about segments 2..34 and 35..47. > > 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). > > Sorry to not being able to spot something obvious right away… 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. If you need anything else from the crash dump, please let me know. > *Von:*tuexen@freebsd.org > *Gesendet:* Dienstag, 23. Februar 2021 22:21 > *An:* Richard Scheffenegger > *Betreff:* Fwd: panic: sackhint bytes rtx >= 0 > >   > > *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. > > > > FYI > > > > Begin forwarded message: > >   > > *From: *Andriy Gapon > > > *Subject: panic: sackhint bytes rtx >= 0* > > *Date: *23. February 2021 at 22:02:20 CET > > *To: *FreeBSD Current >, > net@FreeBSD.org > >   > > > 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. > > #0  doadump (textdump=textdump@entry=1) >    at /usr/devel/git/trant/sys/kern/kern_shutdown.c:399 > #1  0xffffffff808396b2 in kern_reboot (howto=260) >    at /usr/devel/git/trant/sys/kern/kern_shutdown.c:486 > #2  0xffffffff80839d07 in vpanic ( >    fmt=0xffffffff80cbd551 "sackhint bytes rtx >= 0", ap=0xfffffe0120b9e6d0) >    at /usr/devel/git/trant/sys/kern/kern_shutdown.c:919 > #3  0xffffffff808398b3 in panic (fmt=) >    at /usr/devel/git/trant/sys/kern/kern_shutdown.c:843 > #4  0xffffffff8098a82c in tcp_sack_doack (tp=, >    tp@entry=0xfffff807548187f0, to=, >    to@entry=0xfffffe0120b9e780, th_ack=) >    at /usr/devel/git/trant/sys/netinet/tcp_sack.c:691 > #5  0xffffffff80983699 in tcp_do_segment (m=0xfffff8029868ca00, >    m@entry=, >    th=, >    th@entry=, >    so=0xfffff804e7359b10, >    so@entry=, >    tp=0xfffff807548187f0, >    tp@entry=, >    drop_hdrlen=60, >    drop_hdrlen@entry=, >    tlen=, >    tlen@entry=, >    iptos=72 'H', >    iptos@entry=) >    at /usr/devel/git/trant/sys/netinet/tcp_input.c:2497 > #6  0xffffffff80980d97 in tcp_input (mp=, >    mp@entry=, >    offp=, >    offp@entry=, >    proto=) >    at /usr/devel/git/trant/sys/netinet/tcp_input.c:1381 > #7  0xffffffff80976eb7 in ip_input (m=0x0) >    at /usr/devel/git/trant/sys/netinet/ip_input.c:833 > #8  0xffffffff8094c78f in netisr_dispatch_src (proto=1, >    source=source@entry=0, m=0xfffff8029868ca00) >    at /usr/devel/git/trant/sys/net/netisr.c:1143 > #9  0xffffffff8094cb0e in netisr_dispatch (proto=, >    m=) at /usr/devel/git/trant/sys/net/netisr.c:1234 > #10 0xffffffff80943345 in ether_demux (ifp=ifp@entry=0xfffff80008c75000, >    m=) at /usr/devel/git/trant/sys/net/if_ethersubr.c:923 > #11 0xffffffff809446c1 in ether_input_internal (ifp=0xfffff80008c75000, >    m=) at /usr/devel/git/trant/sys/net/if_ethersubr.c:709 > #12 0xffffffff809443d0 in ether_nh_input (m=) >    at /usr/devel/git/trant/sys/net/if_ethersubr.c:739 > #13 0xffffffff8094c78f in netisr_dispatch_src (proto=proto@entry=5, >    source=source@entry=0, m=m@entry=0xfffff8029868ca00) >    at /usr/devel/git/trant/sys/net/netisr.c:1143 > #14 0xffffffff8094cb0e in netisr_dispatch (proto=, >    proto@entry=5, m=, m@entry=0xfffff8029868ca00) >    at /usr/devel/git/trant/sys/net/netisr.c:1234 > #15 0xffffffff8094383d in ether_input (ifp=0xfffff80008c75000, >    ifp@entry=, >    m=0xfffff8029868ca00, >    m@entry=) >    at /usr/devel/git/trant/sys/net/if_ethersubr.c:830 > #16 0xffffffff8066da13 in re_rxeof (sc=sc@entry=0xfffffe00391a5000, >    rx_npktsp=0x0) at /usr/devel/git/trant/sys/dev/re/if_re.c:2388 > #17 0xffffffff8066b3ab in re_intr_msi (xsc=0xfffffe00391a5000) >    at /usr/devel/git/trant/sys/dev/re/if_re.c:2684 > #18 0xffffffff80801bcf in intr_event_execute_handlers ( >    p=p@entry=0xfffff80006a94a50, ie=ie@entry=0xfffff80008c57800) >    at /usr/devel/git/trant/sys/kern/kern_intr.c:1168 > #19 0xffffffff80801942 in ithread_execute_handlers ( >    p=p@entry=0xfffff80006a94a50, ie=ie@entry=0xfffff80008c57800) >    at /usr/devel/git/trant/sys/kern/kern_intr.c:1181 > #20 0xffffffff80801758 in ithread_loop (arg=arg@entry=0xfffff80008c20c40) >    at /usr/devel/git/trant/sys/kern/kern_intr.c:1269 > #21 0xffffffff807fe0a9 in fork_exit ( >    callout=0xffffffff808016c0 , arg=0xfffff80008c20c40, >    frame=0xfffffe0120b9ed40) >    at /usr/devel/git/trant/sys/kern/kern_fork.c:1069 > > > (kgdb) fr 4 > #4  0xffffffff8098a82c in tcp_sack_doack (tp=, > tp@entry=0xfffff807548187f0, to=, to@entry=0xfffffe0120b9e780, > th_ack=) at /usr/devel/git/trant/sys/netinet/tcp_sack.c:691 > 691                     KASSERT(tp->sackhint.sack_bytes_rexmit >= 0, > (kgdb) i loc > sack_blocks = {{start = 3846350860, end = 3846396940}, {start = 3846398380, end > = 3846415660}, {start = 0, end = 0}, {start = 1417775088, end = 4294965255}, > {start = 549054304, end = 4294966785}} > left_edge_delta = > delivered_data = 0 > sack_changed = > num_sack_blks = > i = > j = > sack = {start = , end = } > sblkp = 0xfffffe0120b9e700 > temp = > cur = 0xfffff8013da5a320 > (kgdb) p *cur > $1 = {start = 3846347980, end = 3846352300, rxmit = 3846352300, scblink = > {tqe_next = 0xfffff8013da5a220, tqe_prev = 0xfffff80754818930}} > (kgdb) p 3846352300 - 3846347980 > $2 = 4320 > (kgdb) p tp->sackhint.sack_bytes_rexmit > value has been optimized out > (kgdb) p tp@entry->sackhint.sack_bytes_rexmit > > $3 = -1440 > (kgdb) p 4320 - 1440 > $4 = 2880 > (kgdb) p *sblkp > $5 = {start = 3846350860, end = 3846396940} > > (kgdb) p *tp@entry > $7 = {t_inpcb = 0xfffff80640ca65b8, t_fb = 0xffffffff80ef4700 , > t_fb_ptr = 0x0, t_maxseg = 1440, t_logstate = 0, t_port = 0, t_state = 4, > t_idle_reduce = 0, t_delayed_ack = 0, t_fin_is_rst = 0, >  t_log_state_set = 0, bits_spare = 0, t_flags = 1613759072, snd_una = > 3846347980, snd_max = 3846417100, snd_nxt = 3846417100, snd_up = 3846347980, > snd_wnd = 237568, snd_cwnd = 4320, t_peakrate_thr = 0, ts_offset = 71449215, >  rfbuf_ts = 162235772, rcv_numsacks = 0, t_tsomax = 0, t_tsomaxsegcount = 0, > t_tsomaxsegsize = 0, rcv_nxt = 2281639092, rcv_adv = 2281705332, rcv_wnd = > 66240, t_flags2 = 1030, t_srtt = 876, t_rttvar = 33, ts_recent = 0, >  snd_scale = 8 '\b', rcv_scale = 6 '\006', snd_limited = 2 '\002', > request_r_scale = 6 '\006', last_ack_sent = 2281639092, t_rcvtime = 2309118641, > rcv_up = 2281639092, t_segqlen = 0, t_segqmbuflen = 0, t_segq = { >    tqh_first = 0x0, tqh_last = 0xfffff80754818880}, t_in_pkt = 0x0, t_tail_pkt > = 0x0, t_timers = 0xfffff80754818a78, t_vnet = 0x0, snd_ssthresh = 31680, > snd_wl1 = 2281639092, snd_wl2 = 3846347980, irs = 2281631223, >  iss = 3840447913, t_acktime = 0, t_sndtime = 2309118613, ts_recent_age = 0, > snd_recover = 3846415660, cl4_spare = 0, t_oobflags = 0 '\000', t_iobc = 0 > '\000', t_rxtcur = 270, t_rxtshift = 1, t_rtttime = 2309118613, >  t_rtseq = 3846415660, t_starttime = 2309086941, t_fbyte_in = 2309087188, > t_fbyte_out = 2309087159, t_pmtud_saved_maxseg = 0, t_blackhole_enter = 0, > t_blackhole_exit = 0, t_rttmin = 30, t_rttbest = 845, t_softerror = 0, >  max_sndwnd = 237568, snd_cwnd_prev = 64800, snd_ssthresh_prev = 8640, > snd_recover_prev = 3846347980, t_sndzerowin = 0, t_rttupdated = 368, > snd_numholes = 2, t_badrxtwin = 0, snd_holes = {tqh_first = 0xfffff8013da5a320, >    tqh_last = 0xfffff8013da5a230}, snd_fack = 3846415660, sackblks = {{start = > 2281632180, end = 2281632690}, {start = 0, end = 0}, {start = 0, end = 0}, > {start = 0, end = 0}, {start = 0, end = 0}, {start = 0, end = 0}}, >  sackhint = {nexthole = 0xfffff8013da5a220, sack_bytes_rexmit = -1440, > last_sack_ack = 3846415660, delivered_data = 1440, sacked_bytes = 61920, > recover_fs = 67680, prr_delivered = 1440, _pad = {0}}, t_rttlow = 25, >  rfbuf_cnt = 0, tod = 0x0, t_sndrexmitpack = 520, t_rcvoopack = 0, t_toe = 0x0, > cc_algo = 0xffffffff80ef2530 , ccv = 0xfffff80754818bc0, osd = > 0x0, t_bytes_acked = 11520, t_maxunacktime = 0, t_keepinit = 0, >  t_keepidle = 0, t_keepintvl = 0, t_keepcnt = 0, t_dupacks = 4, t_lognum = 0, > t_loglimit = 0, t_pacing_rate = -1, t_logs = {stqh_first = 0x0, stqh_last = > 0x0}, t_lin = 0x0, t_lib = 0x0, t_output_caller = 0x0, t_stats = 0x0, >  t_logsn = 0, gput_ts = 0, gput_seq = 0, gput_ack = 0, t_stats_gput_prev = 0, > t_tfo_client_cookie_len = 0 '\000', t_end_info_status = 0, t_tfo_pending = 0x0, > t_tfo_cookie = {client = '\000' , server = 0}, { >    t_end_info_bytes = "\000\000\000\000\000\000\000", t_end_info = 0}} > > (kgdb) p *tp@entry->sackhint.nexthole > $8 = {start = 3846396940, end = 3846398380, rxmit = 3846398380, scblink = > {tqe_next = 0x0, tqe_prev = 0xfffff8013da5a330}} > > -- > 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 > " > >   > -- Andriy Gapon