RFH, where did I go wrong?

RFH, where did I go wrong?

[Thorsten Glaser]

Hi,

under high load, my homegrown qdisc causes a system crash,
but I’m a bit baffled at the message and location. Perhaps
anyone has directly an idea where I could have messed up?


Transcription of the most relevant info from the screen photo:

virt_to_cache: Object is not a Slab page!
… at mm/slab.h:435 kmem_cache_free+…

Call Trace:
__rtnl_unlock+0x34/0x40
netdev_run_todo+…
rtnetlink_rcv_msg
? _copy_to_iter
? __free_one_page
? rtnl_calcit.isra.0
netlink_rcv_skb
netlink_unicast
netlink_sendmsg
sock_sendmsg
____sys_sendmsg
[…]

The trace is followed by two…

BUG: Bad rss-counter state mm:0000000001b817b09
first one is type:MM_FILEPAGES val:81
second one is type:MM_ANONPAGES val:30


I guess I either messed up with pointers or locking, but I don’t
have the Linux kernel coding experience to know where to even start
looking for causes.

Source in question is…
https://github.com/tarent/sch_jens/blob/iproute2_5.10.0-4jens14/janz/sch_janz.c
… though I don’t exactly ask for someone to solve this for me (though
that would, obviously, also be welcome ☺) but to get to know enough
for me to figure out the bug.

I probably would start by adding lots of debugging printks, but the
problem occurs when throwing iperf with 40 Mbit/s on this set to limit
to 20 Mbit/s, which’d cause a lot of information — plus I don’t even
know what kind of error “Object is not a Slab page” is (i.e. what wrong
thing is passed where or written to where).

Thanks in advance,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Sergey Ryazanov]

Hello Thorsten,

On Fri, Sep 9, 2022 at 12:19 AM Thorsten Glaser <t.glaser@tarent.de> wrote:
> under high load, my homegrown qdisc causes a system crash,
> but I’m a bit baffled at the message and location. Perhaps
> anyone has directly an idea where I could have messed up?
>
> Transcription of the most relevant info from the screen photo:
>
> virt_to_cache: Object is not a Slab page!
> … at mm/slab.h:435 kmem_cache_free+…
>
> Call Trace:
> __rtnl_unlock+0x34/0x40
> netdev_run_todo+…
> rtnetlink_rcv_msg
> ? _copy_to_iter
> ? __free_one_page
> ? rtnl_calcit.isra.0
> netlink_rcv_skb
> netlink_unicast
> netlink_sendmsg
> sock_sendmsg
> ____sys_sendmsg
> […]
>
> The trace is followed by two…
>
> BUG: Bad rss-counter state mm:0000000001b817b09
> first one is type:MM_FILEPAGES val:81
> second one is type:MM_ANONPAGES val:30
>
>
> I guess I either messed up with pointers or locking, but I don’t
> have the Linux kernel coding experience to know where to even start
> looking for causes.
>
> Source in question is…
> https://github.com/tarent/sch_jens/blob/iproute2_5.10.0-4jens14/janz/sch_janz.c
> … though I don’t exactly ask for someone to solve this for me (though
> that would, obviously, also be welcome ☺) but to get to know enough
> for me to figure out the bug.
>
> I probably would start by adding lots of debugging printks, but the
> problem occurs when throwing iperf with 40 Mbit/s on this set to limit
> to 20 Mbit/s, which’d cause a lot of information — plus I don’t even
> know what kind of error “Object is not a Slab page” is (i.e. what wrong
> thing is passed where or written to where).

At first glance, this looks like some memory access issue. Try to
enable KASAN. Maybe it will be able to provide some more details about
a source of issue.

BTW, the stack backtrace contains only RTNL related functions. Does
this warning appear when trying to reconfigure the qdisc? If so, then
the error is probably somewhere in the qdisc configuration code. Such
code is much easier to debug with printk than the packet processing
path.

If you still need some tracing support, take a look at the kernel
tracing capabilities. See Documentation/trace/tracepoints.rst for
documentation and, for example, net/mac80211/trace.h for reference.

-- 
Sergey

Re: RFH, where did I go wrong?

[Thorsten Glaser]

Hi Sergey,

> BTW, the stack backtrace contains only RTNL related functions. Does
> this warning appear when trying to reconfigure the qdisc? If so, then
> the error is probably somewhere in the qdisc configuration code. Such

good point. The qdisc is used in a mode where it’s reconfigured multiple
times per second, although I do not know if my colleague used it like
this or if the issue also happens when statically configuring.

@Haye: does it also crash for you if you don’t run the playlist but just
configure the qdisc with just the tc qdisc add … rate 20m command?

I did not have access to my test VM until today, so I’ll be able to look
into this more next week.

Thanks,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

AW: RFH, where did I go wrong?

[Haye.Haehne]

Hi,
I could retest the crash scenario of the qdisc, it occurs in the context of tc change /reconfiguration.
When I define a static qdisc setup, the iperf udp stream with 50M (qdisc rate 20M) is stable.
So you should indeed take a deeper look into the processing during reconfiguration.
Kind regards, Haye

-----Ursprüngliche Nachricht-----
Von: Thorsten Glaser <t.glaser@tarent.de> 
Gesendet: Sonntag, 11. September 2022 01:44
An: Hähne, Haye <Haye.Haehne@telekom.de>; Sergey Ryazanov <ryazanov.s.a@gmail.com>
Cc: netdev@vger.kernel.org
Betreff: Re: RFH, where did I go wrong?

Hi Sergey,

> BTW, the stack backtrace contains only RTNL related functions. Does 
> this warning appear when trying to reconfigure the qdisc? If so, then 
> the error is probably somewhere in the qdisc configuration code. Such

good point. The qdisc is used in a mode where it’s reconfigured multiple times per second, although I do not know if my colleague used it like this or if the issue also happens when statically configuring.

@Haye: does it also crash for you if you don’t run the playlist but just configure the qdisc with just the tc qdisc add … rate 20m command?

I did not have access to my test VM until today, so I’ll be able to look into this more next week.

Thanks,
//mirabilos
--
Infrastrukturexperte • tarent solutions GmbH Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/ Telephon +49 228 54881-393 • Fax: +49 228 54881-235 HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Thorsten Glaser]

Hi Haye,

> I could retest the crash scenario of the qdisc, it occurs in the
> context of tc change /reconfiguration. When I define a static qdisc
> setup, the iperf udp stream with 50M (qdisc rate 20M) is stable.

thanks. (By the way, gstscream/scripts/sysctl.sh from SCReAM indeed
allows me to fill the queue fully with locally originating traffic.)

> So you should indeed take a deeper look into the processing during
> reconfiguration.

I did have a look. I could not reproduce the crash just with changing
qdisc things, not even a lot of times (100 Hz).

I tried:

$ sudo mksh -c 'qq=0; while sleep 0.01; do
	if (( ++qq == 500 )); then lim=50; qq=0; else lim=10240; fi
	tc qdisc change dev eth1 handle 1: janz rate 20mbit limit $lim
    done'

(changing the qdisc 100 times a second; every five seconds the limit
goes WAY down, to show the dropping code isn’t the cause either)

3x $ iperf -u -c 10.82.222.129 -t 600 -b 40M -S 0x01

(for some reason, IPv6 did not work with iperf for me)

$ sudo mksh -c 'while sleep 0.25; do tc -s qdisc show dev eth1 | fgrep backlog; done'

(for monitoring)


Evidently, what I’m changing, or how often, isn’t sufficient to trigger
the issue. Let’s phone tomorrow to try to figure out a good reproducer,
I might need to use jenscli with the data rate pattern you use, which is
less self-contained than I would normally prefer in a reproducer…

bye,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Thorsten Glaser]

Hi all,

I finally managed to reproduce it, and this is the full trace, from virsh console
output from an emulated serial console. (Took multiple test runs of 10 minutes
each to crash it still…)

The beginning of the trace seems a little hard to read because it’s interspersed
with the list of loaded modules for some reason (crash code not MP-safe?), but
the basic points (rtnl and sendmsg) are similar; there’s a second trace below
though which I didn’t see in the screen photos from my colleagues.

I now have some ideas I could try (including those Dave Täht wrote to me in
private replies), but if this rings with someone or if someone has got a good
idea how to debug this (the new info here is “nonzero _refcount”) be my guest
and share.

Thanks in advance,
//mirabilos

[852650.833646] ------------[ cut here ]------------
[852650.835760] BUG: Bad page state in process swapper/0  pfn:10178
[852650.837103] kernel BUG at mm/slub.c:305!
[852650.841016] page:000000009e06fd59 refcount:-1 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x10178
[852650.841019] flags: 0xfffffc0000000()
[852650.841028] raw: 000fffffc0000000 dead000000000100 dead000000000122 0000000000000000
[852650.843530] invalid opcode: 0000 [#1] SMP PTI
[852650.843534] CPU: 2 PID: 4397 Comm: tc Tainted: G           OE     5.10.0-18-amd64 #1 Debian 5.10.140-1
[852650.843537] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[852650.849183] raw: 0000000000000000 0000000000000000 ffffffffffffffff 0000000000000000
[852650.851804] RIP: 0010:__slab_free+0x21b/0x430
[852650.856338] page dumped because: nonzero _refcount
[852650.859047] Code: 44 24 20 e8 07 fc ff ff 44 8b 44 24 20 85 c0 0f 85 37 fe ff ff eb ae 41 f7 46 08 00 0d 21 00 0f 85 17 ff ff ff e9 09 ff ff ff <0f> 0b 80 4c 24 5b 80 45 31 c9 e9 76 fe ff ff f3 90 49 8b 04 24 a8
[852650.864402] Modules linked in:
[852650.869306] RSP: 0018:ffffa0f545bcb990 EFLAGS: 00010246
[852650.873856]  sch_janz(OE)
[852650.876721]
[852650.879594]  xt_conntrack
[852650.895021] RAX: ffff9450c114ef00 RBX: 000000008010000f RCX: ffff9450c114ee00
[852650.897053]  nft_chain_nat
[852650.901578] RDX: ffff9450c114ee00 RSI: ffffe246c4045380 RDI: ffff9450c0042600
[852650.903352]  xt_MASQUERADE
[852650.905027] RBP: ffffa0f545bcba40 R08: 0000000000000001 R09: ffffffff8e2ec1b1
[852650.906794]  nf_nat
[852650.912292] R10: ffff9450c114ee00 R11: ffff944ff5f8c300 R12: ffffe246c4045380
[852650.914132]  nf_conntrack_netlink
[852650.920046] R13: ffff9450c114ee00 R14: ffff9450c0042600 R15: ffff9450c114ee00
[852650.921866]  nf_conntrack
[852650.926695] FS:  00007f084af58740(0000) GS:ffff94513ad00000(0000) knlGS:0000000000000000
[852650.928341]  nf_defrag_ipv6
[852650.933091] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[852650.935495]  nf_defrag_ipv4
[852650.940282] CR2: 0000555772316de0 CR3: 00000000101cc000 CR4: 0000000000000ee0
[852650.942128]  xfrm_user
[852650.948202] Call Trace:
[852650.950305]  xfrm_algo
[852650.954000]  ? __free_one_page+0x3a5/0x450
[852650.955985]  nft_counter
[852650.960821]  ? kfree_skb+0x41/0xb0
[852650.962539]  xt_addrtype
[852650.964695]  kfree+0x410/0x490
[852650.966410]  nft_compat
[852650.969219]  kfree_skb+0x41/0xb0
[852650.970966]  x_tables
[852650.973479]  __rtnl_unlock+0x34/0x50
[852650.975417]  nf_tables
[852650.977653]  netdev_run_todo+0x60/0x360
[852650.979345]  libcrc32c
[852650.981765]  rtnetlink_rcv_msg+0x134/0x380
[852650.983525]  br_netfilter
[852650.985953]  ? _copy_to_iter+0xb5/0x4c0
[852650.987597]  bridge
[852650.990183]  ? __free_one_page+0x3a5/0x450
[852650.991979]  stp
[852650.995073]  ? kernel_init_free_pages+0x46/0x60
[852650.997083]  llc
[852650.999666]  ? rtnl_calcit.isra.0+0x120/0x120
[852651.001219]  overlay
[852651.004233]  netlink_rcv_skb+0x50/0x100
[852651.005848]  nfnetlink
[852651.009049]  netlink_unicast+0x209/0x2d0
[852651.010449]  nfsd auth_rpcgss nfs_acl nfs lockd grace nfs_ssc fscache sunrpc loop kvm_intel kvm drm_kms_helper
[852651.013943]  netlink_sendmsg+0x250/0x4b0
[852651.015615]  irqbypass
[852651.018929]  sock_sendmsg+0x62/0x70
[852651.020735]  cec
[852651.023896]  ____sys_sendmsg+0x232/0x270
[852651.030369]  drm
[852651.033098]  ? import_iovec+0x2d/0x40
[852651.035110]  virtio_rng
[852651.037626]  ? sendmsg_copy_msghdr+0x80/0xa0
[852651.039206]  virtio_balloon
[852651.042319]  ___sys_sendmsg+0x75/0xc0
[852651.044113]  evdev
[852651.047167]  ? wp_page_copy+0x2fd/0x840
[852651.049031]  rng_core
[852651.052467]  ? handle_mm_fault+0x1143/0x1c10
[852651.054539]  joydev
[852651.057269]  __sys_sendmsg+0x59/0xa0
[852651.058931]  serio_raw
[852651.061516]  do_syscall_64+0x33/0x80
[852651.063385]  pcspkr
[852651.066605]  entry_SYSCALL_64_after_hwframe+0x61/0xc6
[852651.068996]  qemu_fw_cfg
[852651.071465] RIP: 0033:0x7f084b084fc3
[852651.073916]  button
[852651.076976] Code: 64 89 02 48 c7 c0 ff ff ff ff eb b7 66 2e 0f 1f 84 00 00 00 00 00 90 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 2e 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 89 54 24 1c 48
[852651.078698]  ext4
[852651.082814] RSP: 002b:00007ffd63fd6708 EFLAGS: 00000246
[852651.084859]  crc16
[852651.087757]  ORIG_RAX: 000000000000002e
[852651.089473]  mbcache
[852651.106133] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f084b084fc3
[852651.107962]  jbd2
[852651.112893] RDX: 0000000000000000 RSI: 00007ffd63fd6770 RDI: 0000000000000003
[852651.114442]  crc32c_generic
[852651.117215] RBP: 00000000633dcefa R08: 0000000000000001 R09: 00007f084b156be0
[852651.118924]  hid_generic usbhid hid virtio_net virtio_blk net_failover failover uhci_hcd ata_generic ehci_hcd ata_piix psmouse usbcore libata crc32c_intel virtio_pci
[852651.123723] R10: 0000555773f318f0 R11: 0000000000000246 R12: 0000000000000001
[852651.125316]  virtio_ring
[852651.130148] R13: 0000000000000004 R14: 00007ffd63fe6a48 R15: 0000555772315f80
[852651.132112]  i2c_piix4
[852651.137135] Modules linked in:
[852651.146865]  virtio
[852651.151664]  sch_janz(OE)
[852651.153468]  scsi_mod
[852651.158290]  xt_conntrack
[852651.160056]  usb_common
[852651.162176]  nft_chain_nat
[852651.163832]  floppy
[852651.165820]  xt_MASQUERADE
[852651.167494]  [last unloaded: sch_janz]
[852651.169464]  nf_nat
[852651.171178]
[852651.173168]  nf_conntrack_netlink
[852651.174807] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G           OE     5.10.0-18-amd64 #1 Debian 5.10.140-1
[852651.176719]  nf_conntrack
[852651.179456] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[852651.181137]  nf_defrag_ipv6
[852651.182504] Call Trace:
[852651.184737]  nf_defrag_ipv4
[852651.191593]  <IRQ>
[852651.193439]  xfrm_user
[852651.198995]  dump_stack+0x6b/0x83
[852651.201000]  xfrm_algo
[852651.203174]  bad_page.cold+0x63/0x94
[852651.205314]  nft_counter xt_addrtype nft_compat x_tables nf_tables libcrc32c br_netfilter bridge stp llc overlay nfnetlink nfsd auth_rpcgss nfs_acl nfs lockd grace nfs_ssc fscache sunrpc loop kvm_intel kvm
[852651.207205]  get_page_from_freelist+0xc0b/0x1330
[852651.209090]  drm_kms_helper
[852651.211501]  ? __napi_alloc_skb+0x3f/0xf0
[852651.213379]  irqbypass
[852651.215934]  __alloc_pages_nodemask+0x161/0x310
[852651.227502]  cec
[852651.230870]  skb_page_frag_refill+0x8d/0x130
[852651.232841]  drm
[852651.235627]  try_fill_recv+0x310/0x700 [virtio_net]
[852651.237401]  virtio_rng
[852651.240976]  virtnet_poll+0x34a/0x45a [virtio_net]
[852651.242446]  virtio_balloon
[852651.245349]  net_rx_action+0x145/0x3e0
[852651.246901]  evdev
[852651.250248]  __do_softirq+0xc5/0x279
[852651.252027]  rng_core
[852651.255413]  asm_call_irq_on_stack+0x12/0x20
[852651.257525]  joydev
[852651.260184]  </IRQ>
[852651.261747]  serio_raw
[852651.264346]  do_softirq_own_stack+0x37/0x50
[852651.266108]  pcspkr
[852651.268992]  irq_exit_rcu+0x92/0xc0
[852651.270695]  qemu_fw_cfg
[852651.272427]  sysvec_apic_timer_interrupt+0x36/0x80
[852651.274102]  button
[852651.277273]  asm_sysvec_apic_timer_interrupt+0x12/0x20
[852651.278928]  ext4
[852651.281830] RIP: 0010:native_safe_halt+0xe/0x20
[852651.283587]  crc16
[852651.286888] Code: 00 f0 80 48 02 20 48 8b 00 a8 08 75 c0 e9 77 ff ff ff cc cc cc cc cc cc cc cc cc cc e9 07 00 00 00 0f 00 2d a6 39 51 00 fb f4 <c3> cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 e9 07 00 00
[852651.288550]  mbcache
[852651.292157] RSP: 0018:ffffffff8f203eb8 EFLAGS: 00000212
[852651.293745]  jbd2
[852651.296934]
[852651.298648]  crc32c_generic
[852651.310456] RAX: ffffffff8e4f6390 RBX: 0000000000000000 RCX: ffff94513ac30a40
[852651.312430]  hid_generic
[852651.315540] RDX: 0000000010af973e RSI: ffffffff8f203e50 RDI: 0003077bfb649443
[852651.317392]  usbhid
[852651.318707] RBP: ffffffff8f213940 R08: 0000000000000001 R09: 0000000000000001
[852651.321202]  hid
[852651.325831] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[852651.327840]  virtio_net
[852651.332590] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[852651.332596]  ? __sched_text_end+0x6/0x6
[852651.332600]  default_idle+0xa/0x20
[852651.332603]  default_idle_call+0x3c/0xd0
[852651.332606]  do_idle+0x20c/0x2b0
[852651.332610]  cpu_startup_entry+0x19/0x20
[852651.332621]  start_kernel+0x574/0x599
[852651.332627]  secondary_startup_64_no_verify+0xb0/0xbb
[852651.372595]  virtio_blk net_failover failover uhci_hcd ata_generic ehci_hcd ata_piix psmouse usbcore libata crc32c_intel virtio_pci virtio_ring i2c_piix4 virtio scsi_mod usb_common floppy [last unloaded: sch_janz]
[852651.384220] general protection fault, probably for non-canonical address 0x61a18e4baaf4c70c: 0000 [#2] SMP PTI
[852651.384301] ---[ end trace 0c5eff17e57064a0 ]---
[852651.389902] CPU: 0 PID: 12 Comm: ksoftirqd/0 Tainted: G    B D    OE     5.10.0-18-amd64 #1 Debian 5.10.140-1
[852651.389903] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[852651.389909] RIP: 0010:__kmalloc_node_track_caller+0xd7/0x2a0
[852651.389911] Code: 41 39 ce 74 19 48 8b 0c 24 44 89 f2 44 89 fe 4c 89 e7 e8 5c e8 ff ff 48 89 44 24 08 eb 42 41 8b 4c 24 28 49 8b 3c 24 48 01 c1 <48> 8b 19 48 89 ce 49 33 9c 24 b8 00 00 00 48 8d 4a 01 48 0f ce 48
[852651.389913] RSP: 0018:ffffa0f54006bb70 EFLAGS: 00010206
[852651.389915] RAX: 61a18e4baaf4c60c RBX: 00000000ffffffff RCX: 61a18e4baaf4c70c
[852651.389919] RDX: 00000000011b11c1 RSI: 0000000000082a20 RDI: 0000000000033120
[852651.392771] RIP: 0010:__slab_free+0x21b/0x430
[852651.398467] RBP: ffff9450c0042600 R08: ffff94513ac33120 R09: ffff944ff5e31600
[852651.398469] R10: 0000000000005a00 R11: 0000000000000600 R12: ffff9450c0042600
[852651.398470] R13: 0000000000000200 R14: 00000000ffffffff R15: 0000000000082a20
[852651.398473] FS:  0000000000000000(0000) GS:ffff94513ac00000(0000) knlGS:0000000000000000
[852651.398474] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[852651.398476] CR2: 00007fb16cdc4030 CR3: 00000001043ee000 CR4: 0000000000000ef0
[852651.398481] Call Trace:
[852651.398487]  ? __napi_alloc_skb+0x3f/0xf0
[852651.398491]  __alloc_skb+0x79/0x200
[852651.403422] Code: 44 24 20 e8 07 fc ff ff 44 8b 44 24 20 85 c0 0f 85 37 fe ff ff eb ae 41 f7 46 08 00 0d 21 00 0f 85 17 ff ff ff e9 09 ff ff ff <0f> 0b 80 4c 24 5b 80 45 31 c9 e9 76 fe ff ff f3 90 49 8b 04 24 a8
[852651.406803]  __napi_alloc_skb+0x3f/0xf0
[852651.406810]  page_to_skb+0x61/0x370 [virtio_net]
[852651.406815]  receive_buf+0xdfe/0x1a20 [virtio_net]
[852651.406819]  ? inet_gro_receive+0x23a/0x300
[852651.406825]  ? gro_normal_one+0x31/0xa0
[852651.417319] RSP: 0018:ffffa0f545bcb990 EFLAGS: 00010246
[852651.420409]  virtnet_poll+0x14e/0x45a [virtio_net]
[852651.420414]  net_rx_action+0x145/0x3e0
[852651.420418]  __do_softirq+0xc5/0x279
[852651.420422]  run_ksoftirqd+0x2a/0x40
[852651.420425]  smpboot_thread_fn+0xc5/0x160
[852651.420428]  ? smpboot_register_percpu_thread+0xf0/0xf0
[852651.420433]  kthread+0x11b/0x140
[852651.424873]
[852651.429080]  ? __kthread_bind_mask+0x60/0x60
[852651.429084]  ret_from_fork+0x22/0x30
[852651.429086] Modules linked in: sch_janz(OE) xt_conntrack nft_chain_nat xt_MASQUERADE nf_nat nf_conntrack_netlink nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xfrm_user xfrm_algo nft_counter xt_addrtype nft_compat x_tables nf_tables libcrc32c
[852651.431825] RAX: ffff9450c114ef00 RBX: 000000008010000f RCX: ffff9450c114ee00
[852651.436085]  br_netfilter bridge stp llc overlay nfnetlink nfsd auth_rpcgss nfs_acl nfs lockd grace nfs_ssc fscache sunrpc loop kvm_intel kvm drm_kms_helper irqbypass cec drm virtio_rng virtio_balloon evdev rng_core joydev serio_raw
[852651.440362] RDX: ffff9450c114ee00 RSI: ffffe246c4045380 RDI: ffff9450c0042600
[852651.444563]  pcspkr qemu_fw_cfg button ext4 crc16 mbcache jbd2 crc32c_generic hid_generic usbhid hid virtio_net virtio_blk net_failover failover uhci_hcd ata_generic ehci_hcd ata_piix psmouse usbcore libata crc32c_intel virtio_pci virtio_ring i2c_piix4 virtio scsi_mod usb_common floppy [last unloaded: sch_janz]
[852651.444636] ---[ end trace 0c5eff17e57064a1 ]---
[852651.449355] RBP: ffffa0f545bcba40 R08: 0000000000000001 R09: ffffffff8e2ec1b1
[852651.449358] R10: ffff9450c114ee00 R11: ffff944ff5f8c300 R12: ffffe246c4045380
[852651.452820] RIP: 0010:__slab_free+0x21b/0x430
[852651.452824] Code: 44 24 20 e8 07 fc ff ff 44 8b 44 24 20 85 c0 0f 85 37 fe ff ff eb ae 41 f7 46 08 00 0d 21 00 0f 85 17 ff ff ff e9 09 ff ff ff <0f> 0b 80 4c 24 5b 80 45 31 c9 e9 76 fe ff ff f3 90 49 8b 04 24 a8
[852651.457211] R13: ffff9450c114ee00 R14: ffff9450c0042600 R15: ffff9450c114ee00
[852651.458887] RSP: 0018:ffffa0f545bcb990 EFLAGS: 00010246
[852651.461412] FS:  00007f084af58740(0000) GS:ffff94513ad00000(0000) knlGS:0000000000000000
[852651.463607]
[852651.474096] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[852651.476642] RAX: ffff9450c114ef00 RBX: 000000008010000f RCX: ffff9450c114ee00
[852651.476643] RDX: ffff9450c114ee00 RSI: ffffe246c4045380 RDI: ffff9450c0042600
[852651.476646] RBP: ffffa0f545bcba40 R08: 0000000000000001 R09: ffffffff8e2ec1b1
[852651.479436] CR2: 0000555772316de0 CR3: 00000000101cc000 CR4: 0000000000000ee0
[852651.482322] R10: ffff9450c114ee00 R11: ffff944ff5f8c300 R12: ffffe246c4045380
[852651.482325] R13: ffff9450c114ee00 R14: ffff9450c0042600 R15: ffff9450c114ee00
[852651.631634] FS:  0000000000000000(0000) GS:ffff94513ac00000(0000) knlGS:0000000000000000
[852651.636352] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[852651.639739] CR2: 00007fb16cdc4030 CR3: 00000001043ee000 CR4: 0000000000000ef0
[852651.643985] Kernel panic - not syncing: Fatal exception in interrupt
[852651.647874] Kernel Offset: 0xcc00000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[852651.653955] ---[ end Kernel panic - not syncing: Fatal exception in interrupt ]---

Re: RFH, where did I go wrong?

[Thorsten Glaser]

On Wed, 5 Oct 2022, Thorsten Glaser wrote:

> I finally managed to reproduce it, and this is the full trace, from virsh console
> output from an emulated serial console. (Took multiple test runs of 10 minutes
> each to crash it still…)

I reduced the queue size and it crashed faster and interestingly enough
with a slightly different message, involving a nōn-canonical address, if
that helps in figuring out the case…

[515605.047121] general protection fault, probably for non-canonical address 0x1e8aad2910e48f51: 0000 [#1] SMP PTI
[515605.052590] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G           OE     5.10.0-18-amd64 #1 Debian 5.10.140-1
[515605.057952] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[515605.062691] RIP: 0010:kmem_cache_alloc_node+0xa4/0x220
[515605.065694] Code: 00 48 85 c9 0f 84 63 01 00 00 83 fd ff 74 0f 48 8b 09 48 c1 e9 36 39 cd 0f 85 4f 01 00 00 41 8b 4c 24 28 49 8b 3c 24 48 01 c1 <48> 8b 19 48 89 ce 49 33 9c 24 b8 00 00 00 48 8d 4a 01 48 0f ce 48
[515605.075754] RSP: 0018:ffffab8f40003c88 EFLAGS: 00010202
[515605.078817] RAX: 1e8aad2910e48ee1 RBX: 00000000ffffffff RCX: 1e8aad2910e48f51
[515605.082977] RDX: 0000000000300995 RSI: 0000000000000a20 RDI: 0000000000035af0
[515605.087135] RBP: 00000000ffffffff R08: ffff901e3ac35af0 R09: 0000000000000600
[515605.091288] R10: 0000000000001800 R11: 0000000000000600 R12: ffff901e3ac43900
[515605.095423] R13: ffffffffa2cea3b6 R14: 0000000000000a20 R15: ffff901e3ac43900
[515605.099588] FS:  0000000000000000(0000) GS:ffff901e3ac00000(0000) knlGS:0000000000000000
[515605.104247] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[515605.107527] CR2: 00007fbae55d0030 CR3: 00000001039fe000 CR4: 0000000000000ef0
[515605.111697] Call Trace:
[515605.113383]  <IRQ>
[515605.114836]  __alloc_skb+0x46/0x200
[515605.117058]  __napi_alloc_skb+0x3f/0xf0
[515605.119439]  page_to_skb+0x61/0x370 [virtio_net]
[515605.122216]  receive_buf+0xdfe/0x1a20 [virtio_net]
[515605.125057]  ? inet_gro_receive+0x23a/0x300
[515605.127603]  ? gro_normal_one+0x31/0xa0
[515605.129980]  virtnet_poll+0x14e/0x45a [virtio_net]
[515605.132819]  net_rx_action+0x145/0x3e0
[515605.135076]  __do_softirq+0xc5/0x279
[515605.137342]  asm_call_irq_on_stack+0x12/0x20
[515605.139925]  </IRQ>
[515605.141423]  do_softirq_own_stack+0x37/0x50
[515605.143983]  irq_exit_rcu+0x92/0xc0
[515605.146190]  common_interrupt+0x74/0x130
[515605.148609]  asm_common_interrupt+0x1e/0x40
[515605.151137] RIP: 0010:native_safe_halt+0xe/0x20
[515605.153863] Code: 00 f0 80 48 02 20 48 8b 00 a8 08 75 c0 e9 77 ff ff ff cc cc cc cc cc cc cc cc cc cc e9 07 00 00 00 0f 00 2d a6 39 51 00 fb f4 <c3> cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 e9 07 00 00
[515605.164167] RSP: 0018:ffffffffa3c03eb8 EFLAGS: 00000202
[515605.167227] RAX: ffffffffa2ef6390 RBX: 0000000000000000 RCX: ffff901e3ac30a40
[515605.171395] RDX: 0000000007a1f1c6 RSI: ffffffffa3c03e50 RDI: 0001d4f111e9f981
[515605.175562] RBP: ffffffffa3c13940 R08: 0000000000000001 R09: 0000000000002000
[515605.179763] R10: 0000000000002000 R11: 0000000000000000 R12: 0000000000000000
[515605.183929] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[515605.188125]  ? __sched_text_end+0x6/0x6
[515605.190498]  default_idle+0xa/0x20
[515605.192665]  default_idle_call+0x3c/0xd0
[515605.195103]  do_idle+0x20c/0x2b0
[515605.197165]  cpu_startup_entry+0x19/0x20
[515605.199609]  start_kernel+0x574/0x599
[515605.201920]  secondary_startup_64_no_verify+0xb0/0xbb
[515605.204910] Modules linked in: sch_janz(OE) xt_conntrack nft_chain_nat xt_MASQUERADE nf_nat nf_conntrack_netlink nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xfrm_user xfrm_algo nft_counter xt_addrtype nft_compat x_tables nf_tables libcrc32c br_netfilter bridge stp llc nfnetlink overlay nfsd auth_rpcgss nfs_acl nfs lockd grace nfs_ssc fscache sunrpc loop kvm_intel kvm drm_kms_helper irqbypass cec drm virtio_balloon joydev virtio_rng rng_core evdev serio_raw pcspkr qemu_fw_cfg button ext4 crc16 mbcache jbd2 crc32c_generic hid_generic usbhid hid virtio_net net_failover virtio_blk failover uhci_hcd ehci_hcd ata_generic usbcore ata_piix libata psmouse crc32c_intel scsi_mod virtio_pci virtio_ring virtio floppy i2c_piix4 usb_common
[515605.239110] ---[ end trace 2913cde92d19dc0b ]---
[515605.241867] RIP: 0010:kmem_cache_alloc_node+0xa4/0x220
[515605.243441] BUG: Bad page state in process tc  pfn:147d98
[515605.244897] Code: 00 48 85 c9 0f 84 63 01 00 00 83 fd ff 74 0f 48 8b 09 48 c1 e9 36 39 cd 0f 85 4f 01 00 00 41 8b 4c 24 28 49 8b 3c 24 48 01 c1 <48> 8b 19 48 89 ce 49 33 9c 24 b8 00 00 00 48 8d 4a 01 48 0f ce 48
[515605.244898] RSP: 0018:ffffab8f40003c88 EFLAGS: 00010202
[515605.244901] RAX: 1e8aad2910e48ee1 RBX: 00000000ffffffff RCX: 1e8aad2910e48f51
[515605.244902] RDX: 0000000000300995 RSI: 0000000000000a20 RDI: 0000000000035af0
[515605.244911] RBP: 00000000ffffffff R08: ffff901e3ac35af0 R09: 0000000000000600
[515605.244913] R10: 0000000000001800 R11: 0000000000000600 R12: ffff901e3ac43900
[515605.244914] R13: ffffffffa2cea3b6 R14: 0000000000000a20 R15: ffff901e3ac43900
[515605.244916] FS:  0000000000000000(0000) GS:ffff901e3ac00000(0000) knlGS:0000000000000000
[515605.244918] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[515605.244919] CR2: 00007fbae55d0030 CR3: 00000001039fe000 CR4: 0000000000000ef0
[515605.244925] Kernel panic - not syncing: Fatal exception in interrupt
[515605.343549] page:00000000a7ad6eb8 refcount:-7 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x147d98
[515605.353713] flags: 0x17ffffc0000000()
[515605.356764] raw: 0017ffffc0000000 dead000000000100 dead000000000122 0000000000000000
[515605.361568] raw: 0000000000000000 0000000000000000 fffffff9ffffffff 0000000000000000
[515605.366046] page dumped because: nonzero _refcount
[515605.368910] Modules linked in: sch_janz(OE) xt_conntrack nft_chain_nat xt_MASQUERADE nf_nat nf_conntrack_netlink nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xfrm_user xfrm_algo nft_counter xt_addrtype nft_compat x_tables nf_tables libcrc32c br_netfilter bridge stp llc nfnetlink overlay nfsd auth_rpcgss nfs_acl nfs lockd grace nfs_ssc fscache sunrpc loop kvm_intel kvm drm_kms_helper irqbypass cec drm virtio_balloon joydev virtio_rng rng_core evdev serio_raw pcspkr qemu_fw_cfg button ext4 crc16 mbcache jbd2 crc32c_generic hid_generic usbhid hid virtio_net net_failover virtio_blk failover uhci_hcd ehci_hcd ata_generic usbcore ata_piix libata psmouse crc32c_intel scsi_mod virtio_pci virtio_ring virtio floppy i2c_piix4 usb_common
[515605.402912] CPU: 2 PID: 6951 Comm: tc Tainted: G      D    OE     5.10.0-18-amd64 #1 Debian 5.10.140-1
[515605.408258] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[515605.413046] Call Trace:
[515605.414753]  dump_stack+0x6b/0x83
[515605.416879]  bad_page.cold+0x63/0x94
[515605.419142]  get_page_from_freelist+0xc0b/0x1330
[515605.421924]  __alloc_pages_nodemask+0x161/0x310
[515605.424638]  kmalloc_large_node+0x3d/0x110
[515605.427157]  __kmalloc_node_track_caller+0x235/0x2a0
[515605.430130]  ? netlink_dump+0x9c/0x350
[515605.432503]  __alloc_skb+0x79/0x200
[515605.434686]  netlink_dump+0x9c/0x350
[515605.436948]  netlink_recvmsg+0x246/0x420
[515605.439424]  ____sys_recvmsg+0x87/0x180
[515605.441844]  ? flush_tlb_func_common.constprop.0+0x10f/0x1e0
[515605.445141]  ? __check_object_size+0x4a/0x160
[515605.447786]  ? _copy_from_user+0x28/0x60
[515605.450219]  ? iovec_from_user+0x5b/0x180
[515605.452693]  ___sys_recvmsg+0x82/0x110
[515605.455017]  ? handle_mm_fault+0x1143/0x1c10
[515605.457608]  __sys_recvmsg+0x56/0xa0
[515605.459853]  do_syscall_64+0x33/0x80
[515605.462087]  entry_SYSCALL_64_after_hwframe+0x61/0xc6
[515605.465079] RIP: 0033:0x7f24c51b6e63
[515605.467301] Code: 8b 15 31 10 0d 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b5 0f 1f 00 64 8b 04 25 18 00 00 00 85 c0 75 14 b8 2f 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 55 c3 0f 1f 40 00 48 83 ec 28 89 54 24 1c 48
[515605.477470] RSP: 002b:00007ffd49f7c7f8 EFLAGS: 00000246 ORIG_RAX: 000000000000002f
[515605.481870] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007f24c51b6e63
[515605.486040] RDX: 0000000000000022 RSI: 00007ffd49f7c8e0 RDI: 0000000000000003
[515605.490174] RBP: 0000000000000022 R08: 000000007c9654be R09: 00007f24c5288be0
[515605.494362] R10: 0000000000000076 R11: 0000000000000246 R12: 00007ffd49f7c8e0
[515605.498537] R13: 0000000000000003 R14: 00007ffd49f7c8d0 R15: 0000000000000000
[515605.502778] Kernel Offset: 0x21600000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[515605.508847] ---[ end Kernel panic - not syncing: Fatal exception in interrupt ]---

TIA,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Thorsten Glaser]

On Thu, 8 Sep 2022, Dave Taht wrote:

> I would just keep time in ns throughout as its hard to think through.

I’ve converted the code to do just that now. The only conversions
left are from/to ms (for tc qdisc add/change/show) and one place
where the 1024ns-based units are used in debugfs reporting.

> I'll take a harder look, but does it crash if you rip out debugfs?

I’ve added enough ifdeffery to disable all of debugfs except for
the basic initialisation of it, so the file is present, and even
disabling the code to read the iptos byte and sort into different
FIFOs based on priority. Relayfs’ spinlock isn’t present then either.

And yes, it (commit dbb99579808dcf106264f28f3c8cf5ef2f2c05bf) still
crashes even if this time I get yet another message… all of those I
got seem to imply some kind of memory corruption though?

[ 8361.191173] list_del corruption. next->prev should be ffff979fc2046800, but was ffffb5bc00003c80
[ 8361.197092] ------------[ cut here ]------------
[ 8361.200466] kernel BUG at lib/list_debug.c:62!
[ 8361.203175] invalid opcode: 0000 [#1] SMP PTI
[ 8361.205751] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G           OE     5.10.0-18-amd64 #1 Debian 5.10.140-1
[ 8361.211219] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
[ 8361.216048] RIP: 0010:__list_del_entry_valid.cold+0x1d/0x69
[ 8361.219379] Code: c7 c7 48 26 32 a6 e8 77 12 ff ff 0f 0b 48 89 fe 48 c7 c7 58 27 32 a6 e8 66 12 ff ff 0f 0b 48 c7 c7 68 28 32 a6 e8 58 12 ff ff <0f> 0b 48 89 f2 48 89 fe 48 c7 c7 28 28 32 a6 e8 44 12 ff ff 0f 0b
[ 8361.229618] RSP: 0018:ffffb5bc00003c48 EFLAGS: 00010246
[ 8361.232652] RAX: 0000000000000054 RBX: ffff979fc2046300 RCX: 0000000000000000
[ 8361.237195] RDX: 0000000000000000 RSI: ffff97a03ac1ca00 RDI: ffff97a03ac1ca00
[ 8361.241320] RBP: ffff979fc2046800 R08: 0000000000000000 R09: ffffb5bc00003a70
[ 8361.245429] R10: ffffb5bc00003a68 R11: ffffffffa68cb448 R12: ffffb5bc00003c80
[ 8361.249535] R13: ffffb5bc00003d00 R14: ffffffffa6a14ec0 R15: ffff979fc2046300
[ 8361.253763] FS:  0000000000000000(0000) GS:ffff97a03ac00000(0000) knlGS:0000000000000000
[ 8361.258400] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 8361.261696] CR2: 000000c000589000 CR3: 0000000103ec4000 CR4: 0000000000000ef0
[ 8361.265693] Call Trace:
[ 8361.267488]  <IRQ>
[ 8361.268909]  ip_sublist_rcv_finish+0x25/0x70
[ 8361.271501]  ip_sublist_rcv+0x193/0x220
[ 8361.273857]  ? ip_rcv_finish_core.constprop.0+0x410/0x410
[ 8361.276990]  ip_list_rcv+0x135/0x160
[ 8361.279199]  __netif_receive_skb_list_core+0x2b0/0x2e0
[ 8361.282203]  netif_receive_skb_list_internal+0x1b7/0x2f0
[ 8361.285479]  ? inet_gro_receive+0x23a/0x300
[ 8361.288000]  gro_normal_one+0x77/0xa0
[ 8361.290249]  napi_gro_receive+0x152/0x190
[ 8361.292721]  virtnet_poll+0x14e/0x45a [virtio_net]
[ 8361.295570]  net_rx_action+0x145/0x3e0
[ 8361.297863]  __do_softirq+0xc5/0x279
[ 8361.300081]  asm_call_irq_on_stack+0x12/0x20
[ 8361.302651]  </IRQ>
[ 8361.304139]  do_softirq_own_stack+0x37/0x50
[ 8361.306649]  irq_exit_rcu+0x92/0xc0
[ 8361.308836]  common_interrupt+0x74/0x130
[ 8361.311219]  asm_common_interrupt+0x1e/0x40
[ 8361.313725] RIP: 0010:native_safe_halt+0xe/0x20
[ 8361.316416] Code: 00 f0 80 48 02 20 48 8b 00 a8 08 75 c0 e9 77 ff ff ff cc cc cc cc cc cc cc cc cc cc e9 07 00 00 00 0f 00 2d a6 39 51 00 fb f4 <c3> cc cc cc cc 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 e9 07 00 00
[ 8361.326934] RSP: 0018:ffffffffa6803eb8 EFLAGS: 00000202
[ 8361.329994] RAX: ffffffffa5af6390 RBX: 0000000000000000 RCX: ffff97a03ac30a40
[ 8361.334016] RDX: 0000000000a72606 RSI: ffffffffa6803e50 RDI: 0000079aa3bb2dc6
[ 8361.337990] RBP: ffffffffa6813940 R08: 0000000000000001 R09: 0000000000002c00
[ 8361.342018] R10: 0000000000002c00 R11: 0000000000000000 R12: 0000000000000000
[ 8361.346211] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 8361.350204]  ? __sched_text_end+0x6/0x6
[ 8361.352536]  default_idle+0xa/0x20
[ 8361.354654]  default_idle_call+0x3c/0xd0
[ 8361.357021]  do_idle+0x20c/0x2b0
[ 8361.359216]  cpu_startup_entry+0x19/0x20
[ 8361.361607]  start_kernel+0x574/0x599
[ 8361.363867]  secondary_startup_64_no_verify+0xb0/0xbb
[ 8361.366821] Modules linked in: sch_janz(OE) xt_conntrack nft_chain_nat xt_MASQUERADE nf_nat nf_conntrack_netlink nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xfrm_user xfrm_algo nft_counter xt_addrtype nft_compat x_tables nf_tables libcrc32c br_netfilter bridge stp llc overlay nfnetlink nfsd auth_rpcgss nfs_acl nfs lockd grace nfs_ssc fscache sunrpc loop kvm_intel drm_kms_helper kvm cec irqbypass drm joydev evdev virtio_rng virtio_balloon serio_raw rng_core pcspkr qemu_fw_cfg button ext4 crc16 mbcache jbd2 crc32c_generic hid_generic usbhid hid virtio_net net_failover virtio_blk failover ata_generic uhci_hcd ata_piix ehci_hcd libata psmouse usbcore usb_common crc32c_intel scsi_mod virtio_pci virtio_ring virtio i2c_piix4 floppy [last unloaded: sch_janz]
[ 8361.406894] ---[ end trace a306e6bc977bf075 ]---
[ 8361.409635] RIP: 0010:__list_del_entry_valid.cold+0x1d/0x69
[ 8361.412841] Code: c7 c7 48 26 32 a6 e8 77 12 ff ff 0f 0b 48 89 fe 48 c7 c7 58 27 32 a6 e8 66 12 ff ff 0f 0b 48 c7 c7 68 28 32 a6 e8 58 12 ff ff <0f> 0b 48 89 f2 48 89 fe 48 c7 c7 28 28 32 a6 e8 44 12 ff ff 0f 0b
[ 8361.422997] RSP: 0018:ffffb5bc00003c48 EFLAGS: 00010246
[ 8361.426023] RAX: 0000000000000054 RBX: ffff979fc2046300 RCX: 0000000000000000
[ 8361.430242] RDX: 0000000000000000 RSI: ffff97a03ac1ca00 RDI: ffff97a03ac1ca00
[ 8361.434253] RBP: ffff979fc2046800 R08: 0000000000000000 R09: ffffb5bc00003a70
[ 8361.438312] R10: ffffb5bc00003a68 R11: ffffffffa68cb448 R12: ffffb5bc00003c80
[ 8361.442172] R13: ffffb5bc00003d00 R14: ffffffffa6a14ec0 R15: ffff979fc2046300
[ 8361.446497] FS:  0000000000000000(0000) GS:ffff97a03ac00000(0000) knlGS:0000000000000000
[ 8361.451201] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 8361.454526] CR2: 000000c000589000 CR3: 0000000103ec4000 CR4: 0000000000000ef0
[ 8361.458549] Kernel panic - not syncing: Fatal exception in interrupt
[ 8361.462556] Kernel Offset: 0x24200000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[ 8361.468698] ---[ end Kernel panic - not syncing: Fatal exception in interrupt ]---

TIA,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Thorsten Glaser]

On Tue, 11 Oct 2022, Thorsten Glaser wrote:

> And yes, it (commit dbb99579808dcf106264f28f3c8cf5ef2f2c05bf) still

Probably best run it through…

unifdef -DJANZ_REPORTING=0 janz/sch_janz.c >janz-reduced.c

… and read that instead.

bye,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Thorsten Glaser]

Dixi quod…

> > I'll take a harder look, but does it crash if you rip out debugfs?
[…]
> And yes, it (commit dbb99579808dcf106264f28f3c8cf5ef2f2c05bf) still
> crashes even if this time I get yet another message… all of those I

I may have found the case by reducing further. Disabling the periodic
dropping of too-old packets wasn’t it, but apparently, the code now
guarded by JANZ_HEADDROP is it. Replacing it (dropping the oldest
packet returning NET_XMIT_CN) with trivial code that rejects the new
packet-to-be-enqueued with qdisc_drop() instead… seems to not crash.

So, the code in question that seems to introduce the crash is:


u32 prev_backlog = sch->qstats.backlog;
//… normal code to add the passed skb (timestamp, etc.)
// q->memusage += cb->truesz;
if (unlikely(overlimit = (++sch->q.qlen > sch->limit))) {
	struct sk_buff *skbtodrop;
	/* skbtodrop = head of FIFO and remove it from the FIFO */
	skbtodrop = q->q[1].first;
	if (!(q->q[1].first = skbtodrop->next))
		q->q[1].last = NULL;
	--sch->q.qlen;
	/* accounting */
	q->memusage -= get_janz_skb(skbtodrop)->truesz;
	qdisc_qstats_backlog_dec(sch, skbtodrop);
	/* free the skb */
	rtnl_kfree_skbs(skbtodrop, skbtodrop)
}
//… normal code to add:
// line 879-885 enqueue into the FIFO
// qdisc_qstats_backlog_inc(sch, skb);
//… now code protected by the flag again:
if (unlikely(overlimit)) {
	qdisc_qstats_overlimit(sch);
	qdisc_tree_reduce_backlog(sch, 0,
	    prev_backlog - sch->qstats.backlog);
	return (NET_XMIT_CN);
}
// normal code remaining: return (NET_XMIT_SUCCESS);


This *seems* pretty straightforward to me, given similar code
in other qdiscs, and what I could learn from their header and
implementation.

TIA,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Eric Dumazet]

On 10/12/22 13:17, Thorsten Glaser wrote:
> Dixi quod…
>
>>> I'll take a harder look, but does it crash if you rip out debugfs?
> […]
>> And yes, it (commit dbb99579808dcf106264f28f3c8cf5ef2f2c05bf) still
>> crashes even if this time I get yet another message… all of those I
> I may have found the case by reducing further. Disabling the periodic
> dropping of too-old packets wasn’t it, but apparently, the code now
> guarded by JANZ_HEADDROP is it. Replacing it (dropping the oldest
> packet returning NET_XMIT_CN) with trivial code that rejects the new
> packet-to-be-enqueued with qdisc_drop() instead… seems to not crash.
>
> So, the code in question that seems to introduce the crash is:
>
>
> u32 prev_backlog = sch->qstats.backlog;
> //… normal code to add the passed skb (timestamp, etc.)
> // q->memusage += cb->truesz;
> if (unlikely(overlimit = (++sch->q.qlen > sch->limit))) {
> 	struct sk_buff *skbtodrop;
> 	/* skbtodrop = head of FIFO and remove it from the FIFO */
> 	skbtodrop = q->q[1].first;
> 	if (!(q->q[1].first = skbtodrop->next))
> 		q->q[1].last = NULL;
> 	--sch->q.qlen;
> 	/* accounting */
> 	q->memusage -= get_janz_skb(skbtodrop)->truesz;
> 	qdisc_qstats_backlog_dec(sch, skbtodrop);
> 	/* free the skb */
> 	rtnl_kfree_skbs(skbtodrop, skbtodrop)

This looks wrong (although I have not read your code)

I guess RTNL is not held at this point.

Use kfree_skb(skb) or __qdisc_drop(skb, to_free)


> }
> //… normal code to add:
> // line 879-885 enqueue into the FIFO
> // qdisc_qstats_backlog_inc(sch, skb);
> //… now code protected by the flag again:
> if (unlikely(overlimit)) {
> 	qdisc_qstats_overlimit(sch);
> 	qdisc_tree_reduce_backlog(sch, 0,
> 	    prev_backlog - sch->qstats.backlog);
> 	return (NET_XMIT_CN);
> }
> // normal code remaining: return (NET_XMIT_SUCCESS);
>
>
> This *seems* pretty straightforward to me, given similar code
> in other qdiscs, and what I could learn from their header and
> implementation.
>
> TIA,
> //mirabilos

Re: RFH, where did I go wrong?

[Thorsten Glaser]

On Wed, 12 Oct 2022, Eric Dumazet wrote:

> This looks wrong (although I have not read your code)
> 
> I guess RTNL is not held at this point.
> 
> Use kfree_skb(skb) or __qdisc_drop(skb, to_free)

Ooh! Will try! That’s what I get for getting, ahem, inspiration
from other qdiscs.

Thanks,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Andrew Lunn]

On Wed, Oct 12, 2022 at 10:48:53PM +0200, Thorsten Glaser wrote:
> On Wed, 12 Oct 2022, Eric Dumazet wrote:
> 
> > This looks wrong (although I have not read your code)
> > 
> > I guess RTNL is not held at this point.
> > 
> > Use kfree_skb(skb) or __qdisc_drop(skb, to_free)
> 
> Ooh! Will try! That’s what I get for getting, ahem, inspiration
> from other qdiscs.

Are other qdiscs also missing RTNL, or are you just using the
inspiration in a different context?

	    Andrew

Re: RFH, where did I go wrong?

[Thorsten Glaser]

On Wed, 12 Oct 2022, Andrew Lunn wrote:

> > Ooh! Will try! That’s what I get for getting, ahem, inspiration
> > from other qdiscs.
> 
> Are other qdiscs also missing RTNL, or are you just using the
> inspiration in a different context?

I think I was probably confused between which of the functions can
be used when. Eric explained the why. What I was missing was… well,
basically what I asked for weeks ago — what functions I need to
provide when writing a qdisc, and which guarantees and expectations
these have. That rtnl is held for… apparently all but enqueue/dequeue…
was one of these. I doubt other qdiscs miss it, or their users would
also run into this crash or so :/

The thing I did first was to add ASSERT_RTNL(); directly before the
rtnl_* call, just like it was in the other place. That, of course,
crashed immediately. Now *this* could be done systematically.

In OpenBSD, things like that are often hidden behind #if DIAGNOSTIC
which is a global option, disabled in “prod” or space-constrained
(installer) kernels but enabled for the “generic” one for wide testing.
Something to think about?

I’m sure there’s lots of things like flow analysis around in the
Linux world, however that wouldn’t help out-of-tree code being
developed, whereas extra checks like that would. Just some thoughts,
as said earlier this is basically¹ my start in Linux kernel dev.

bye,
//mirabilos
① some small patching of existing code over the years excepted
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Vladimir Oltean]

On Wed, Oct 12, 2022 at 11:56:11PM +0200, Thorsten Glaser wrote:
> The thing I did first was to add ASSERT_RTNL(); directly before the
> rtnl_* call, just like it was in the other place. That, of course,
> crashed immediately. Now *this* could be done systematically.
> 
> In OpenBSD, things like that are often hidden behind #if DIAGNOSTIC
> which is a global option, disabled in “prod” or space-constrained
> (installer) kernels but enabled for the “generic” one for wide testing.
> Something to think about?
> 
> I’m sure there’s lots of things like flow analysis around in the
> Linux world, however that wouldn’t help out-of-tree code being
> developed, whereas extra checks like that would. Just some thoughts,
> as said earlier this is basically¹ my start in Linux kernel dev.

Not trying to defend the Qdisc framework which has poor to non-existing
documentation, but with some minimal level of experience you'd kind of
expect that a function named rtnl_kfree_skbs() expects a calling context
where the rtnl_mutex is held. It is even more clear that this is the
case when you notice that in its implementation, there is a single
defer_kfree_skb_list global to the kernel, which is processed in
__rtnl_unlock().

I think as a takeaway from your debugging journey, you can add an
ASSERT_RTNL() to rtnl_kfree_skbs() and add a comment documenting the
function. You can use the commit message of 1b5c5493e3e6 ("net_sched:
add the ability to defer skb freeing") as inspiration for the function
description.

Re: RFH, where did I go wrong?

[Andrew Lunn]

On Wed, Oct 12, 2022 at 11:56:11PM +0200, Thorsten Glaser wrote:
> On Wed, 12 Oct 2022, Andrew Lunn wrote:
> 
> > > Ooh! Will try! That’s what I get for getting, ahem, inspiration
> > > from other qdiscs.
> > 
> > Are other qdiscs also missing RTNL, or are you just using the
> > inspiration in a different context?
> 
> I think I was probably confused between which of the functions can
> be used when. Eric explained the why. What I was missing was… well,
> basically what I asked for weeks ago — what functions I need to
> provide when writing a qdisc, and which guarantees and expectations
> these have. That rtnl is held for… apparently all but enqueue/dequeue…
> was one of these. I doubt other qdiscs miss it, or their users would
> also run into this crash or so :/

Not all broken code, specially with locks, causes a simple to
reproduce crash. So i was hoping that now you have gained an
understanding of what you did wrong, maybe you can see other places
which make the same error, possibly from where you cut/pasted, which
might not yet of crashed. Thats another way of say, if you have found
a bug, look around and see if the same bug exists somewhere else
nearby.

> The thing I did first was to add ASSERT_RTNL(); directly before the
> rtnl_* call, just like it was in the other place. That, of course,
> crashed immediately. Now *this* could be done systematically.
> 
> In OpenBSD, things like that are often hidden behind #if DIAGNOSTIC
> which is a global option, disabled in “prod” or space-constrained
> (installer) kernels but enabled for the “generic” one for wide testing.
> Something to think about?

The network stack generally falls into two parts. The fast path tries
its best to avoid anything expensive, like mutexes. It uses spinlocks
if it needs any sort of locking. And there is the rest, which is
mostly the control plain, which is the slow path. It is protected by
RTNL. As you said above, "That rtnl is held for… apparently all but
enqueue/dequeue…" enqueue/dequeue are the fast path, so RTNL is not
required, the rest is mostly control plan, so RTNL is probably
required. Also, since it is the slow path, adding ASSERT_RTNL() is
fine, and it does not need to be hidden behind #if DIAGNOSTIC. Linux
does have some debug code hidden behind ifdefs, see the kernel hacking
section of make menuconfig. The sleep in atomic context test is a good
example of this. While doing development work, you want to turn on
most of the checks in this section. That sleep in atomic check will
probably help you find cases where you hold RTNL but should not. The
lock checking will help you find potential deadlocks with RTNL and any
other locks you might use, etc.

	Andrew

Re: RFH, where did I go wrong?

[Thorsten Glaser]

On Wed, 12 Oct 2022, Eric Dumazet wrote:

> I guess RTNL is not held at this point.

OIC, so it’s held for .init and .reset but not the other methods.
I wish this were documented…

Looking good so far. Thank you very much!

bye,
//mirabilos
-- 
Infrastrukturexperte • tarent solutions GmbH
Am Dickobskreuz 10, D-53121 Bonn • http://www.tarent.de/
Telephon +49 228 54881-393 • Fax: +49 228 54881-235
HRB AG Bonn 5168 • USt-ID (VAT): DE122264941
Geschäftsführer: Dr. Stefan Barth, Kai Ebenrett, Boris Esser, Alexander Steeg

                        ****************************************************
/⁀\ The UTF-8 Ribbon
╲ ╱ Campaign against      Mit dem tarent-Newsletter nichts mehr verpassen:
 ╳  HTML eMail! Also,     https://www.tarent.de/newsletter
╱ ╲ header encryption!
                        ****************************************************

Re: RFH, where did I go wrong?

[Eric Dumazet]

On 10/12/22 14:05, Thorsten Glaser wrote:
> On Wed, 12 Oct 2022, Eric Dumazet wrote:
>
>> I guess RTNL is not held at this point.
> OIC, so it’s held for .init and .reset but not the other methods.
> I wish this were documented…


RTNL being a mutex it only can be acquired in process context.

qdisc fast path (queue/dequeue) can be called from (soft)irq context, so 
RTNL is out of reach.


>
> Looking good so far. Thank you very much!
>
> bye,
> //mirabilos