Date: Thu, 25 Feb 2021 20:08:24 +0200 From: Andriy Gapon <avg@FreeBSD.org> To: "Scheffenegger, Richard" <Richard.Scheffenegger@netapp.com> Cc: "tuexen@freebsd.org" <tuexen@freebsd.org>, "net@FreeBSD.org" <net@freebsd.org> Subject: Re: AW: panic: sackhint bytes rtx >= 0 Message-ID: <c03e903f-5386-4c7b-ee95-b558791d6e35@FreeBSD.org> In-Reply-To: <SN4PR0601MB37288873BB2967AC78B26C8986809@SN4PR0601MB3728.namprd06.prod.outlook.com> References: <960081ac-2839-a226-3142-5a4666eb54ad@FreeBSD.org> <8BB910F9-B828-49A2-8941-4F6C6419D8EA@freebsd.org> <SN4PR0601MB37288873BB2967AC78B26C8986809@SN4PR0601MB3728.namprd06.prod.outlook.com>
next in thread | previous in thread | raw e-mail | index | archive | help
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 <tuexen@freebsd.org>
> *Gesendet:* Dienstag, 23. Februar 2021 22:21
> *An:* Richard Scheffenegger <rscheff@freebsd.org>
> *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 <avg@FreeBSD.org <mailto:avg@FreeBSD.org>>
>
> *Subject: panic: sackhint bytes rtx >= 0*
>
> *Date: *23. February 2021 at 22:02:20 CET
>
> *To: *FreeBSD Current <current@FreeBSD.org <mailto:current@FreeBSD.org>>,
> net@FreeBSD.org <mailto: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=<unavailable>)
> at /usr/devel/git/trant/sys/kern/kern_shutdown.c:843
> #4 0xffffffff8098a82c in tcp_sack_doack (tp=<optimized out>,
> tp@entry=0xfffff807548187f0, to=<optimized out>,
> to@entry=0xfffffe0120b9e780, th_ack=<optimized out>)
> at /usr/devel/git/trant/sys/netinet/tcp_sack.c:691
> #5 0xffffffff80983699 in tcp_do_segment (m=0xfffff8029868ca00,
> m@entry=<error reading variable: value is not available>,
> th=<optimized out>,
> th@entry=<error reading variable: value is not available>,
> so=0xfffff804e7359b10,
> so@entry=<error reading variable: value is not available>,
> tp=0xfffff807548187f0,
> tp@entry=<error reading variable: value is not available>,
> drop_hdrlen=60,
> drop_hdrlen@entry=<error reading variable: value is not available>,
> tlen=<optimized out>,
> tlen@entry=<error reading variable: value is not available>,
> iptos=72 'H',
> iptos@entry=<error reading variable: value is not available>)
> at /usr/devel/git/trant/sys/netinet/tcp_input.c:2497
> #6 0xffffffff80980d97 in tcp_input (mp=<optimized out>,
> mp@entry=<error reading variable: value is not available>,
> offp=<optimized out>,
> offp@entry=<error reading variable: value is not available>,
> proto=<optimized out>)
> 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=<unavailable>,
> m=<unavailable>) at /usr/devel/git/trant/sys/net/netisr.c:1234
> #10 0xffffffff80943345 in ether_demux (ifp=ifp@entry=0xfffff80008c75000,
> m=<unavailable>) at /usr/devel/git/trant/sys/net/if_ethersubr.c:923
> #11 0xffffffff809446c1 in ether_input_internal (ifp=0xfffff80008c75000,
> m=<unavailable>) at /usr/devel/git/trant/sys/net/if_ethersubr.c:709
> #12 0xffffffff809443d0 in ether_nh_input (m=<unavailable>)
> 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=<unavailable>,
> proto@entry=5, m=<unavailable>, m@entry=0xfffff8029868ca00)
> at /usr/devel/git/trant/sys/net/netisr.c:1234
> #15 0xffffffff8094383d in ether_input (ifp=0xfffff80008c75000,
> ifp@entry=<error reading variable: value is not available>,
> m=0xfffff8029868ca00,
> m@entry=<error reading variable: value is not available>)
> 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 <ithread_loop>, 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=<optimized out>,
> tp@entry=0xfffff807548187f0, to=<optimized out>, to@entry=0xfffffe0120b9e780,
> th_ack=<optimized out>) 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 = <optimized out>
> delivered_data = 0
> sack_changed = <optimized out>
> num_sack_blks = <optimized out>
> i = <optimized out>
> j = <optimized out>
> sack = {start = <optimized out>, end = <optimized out>}
> sblkp = 0xfffffe0120b9e700
> temp = <optimized out>
> 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
> <mailto:tp@entry-%3esackhint.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 <tcp_def_funcblk>,
> 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 <newreno_cc_algo>, 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' <repeats 15 times>, server = 0}, {
> t_end_info_bytes = "\000\000\000\000\000\000\000", t_end_info = 0}}
>
> (kgdb) p *tp@entry->sackhint.nexthole <mailto:*tp@entry-%3esackhint.nexthole>
> $8 = {start = 3846396940, end = 3846398380, rxmit = 3846398380, scblink =
> {tqe_next = 0x0, tqe_prev = 0xfffff8013da5a330}}
>
> --
> Andriy Gapon
> _______________________________________________
> freebsd-current@freebsd.org <mailto:freebsd-current@freebsd.org> mailing list
> https://lists.freebsd.org/mailman/listinfo/freebsd-current
> <https://lists.freebsd.org/mailman/listinfo/freebsd-current>;
> To unsubscribe, send any mail to "freebsd-current-unsubscribe@freebsd.org
> <mailto:freebsd-current-unsubscribe@freebsd.org>"
>
>
>
--
Andriy Gapon
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?c03e903f-5386-4c7b-ee95-b558791d6e35>