NICMx
Null pointer dereference in kernel module
I'm running Jool on a pair of Debian Buster VM's, which are acting as border routers for a test network I'm operating. Both of these machines are running Debian's 4.19.160 kernel, and Jool version 4.1.4 with the issue #340 patches cherry-picked from master (so NAT64 session replication works correctly).
One of these two routers (which I suspect handles more traffic than the other) has spontaneously crashed twice within 24 hours, with the same kernel panic trace in both cases, which seems to indicate a null pointer dereference within the jool_common kernel module.
Both machines are performing SIIT and NAT64 functions simultaneously, using iptables to inject traffic to the appropriate kernel module based on source and destination address:
- IPv4 packets entering the test network whose destination address is in the NAT64
pool4are sent tojool. - IPv4 packets entering the network whose destination address is within a prefix configured in the SIIT EAMT are sent to
jool_siit. - IPv6 packets leaving the test network whose destination is within the
pool6prefix and whose source address is within a prefix configured in the SIIT EAMT are sent tojool_siit. - All other egress IPv6 packets whose destination is within the
pool6prefix are sent tojool.
iptables on Debian Buster is a synonym for iptables-nft, so the packet matching logic is actually attached to netfilter instead of the old kernel iptables implementation.
Panic trace:
[41296.788688] BUG: unable to handle kernel NULL pointer dereference at 0000000000000008
[41296.791050] PGD 0 P4D 0
[41296.791770] Oops: 0000 [#1] SMP PTI
[41296.792699] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G OE 4.19.0-13-amd64 #1 Debian 4.19.160-2
[41296.795322] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[41296.797575] RIP: 0010:skb_release_data+0x76/0x170
[41296.799032] Code: 00 31 db 41 80 7c 24 02 00 48 89 fd 75 10 eb 46 41 0f b6 44 24 02 48 83 c3 01 39 d8 7e 38 48 89 d8 48 c1 e0 04 49 8b 7c 04 30 <48> 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa 66 66 66 66 90 f0 ff 4f
[41296.804273] RSP: 0018:ffff9ddb3ba03960 EFLAGS: 00010246
[41296.806451] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000004
[41296.808209] RDX: 0000000000000000 RSI: 0000000000000043 RDI: 0000000000000000
[41296.809723] RBP: ffff9ddb35c18200 R08: 0000000034e3ffff R09: 0000000000000000
[41296.811240] R10: 0000000000000000 R11: 0000000000000003 R12: ffff9dda970c6cc0
[41296.812690] R13: ffff9ddb35c18d00 R14: ffff9ddb0fd0e500 R15: ffff9ddb0fd0e5c8
[41296.814198] FS: 0000000000000000(0000) GS:ffff9ddb3ba00000(0000) knlGS:0000000000000000
[41296.815823] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[41296.817072] CR2: 0000000000000008 CR3: 0000000135a66000 CR4: 00000000000406f0
[41296.819049] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[41296.820942] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[41296.822950] Call Trace:
[41296.823572]
[41296.824031] ? kfree_skb_list+0x13/0x20
[41296.824866] kfree_skb+0x32/0xa0
[41296.825648] kfree_skb_list+0x13/0x20
[41296.826448] translating_the_packet+0x197/0x200 [jool_common]
[41296.827645] core_common+0x44/0x110 [jool_common]
[41296.828604] core_4to6+0x7c/0xd0 [jool_common]
[41296.829489] target_ipv4+0x65/0x80 [jool_common]
[41296.830615] nft_target_eval_xt+0x35/0x50 [nft_compat]
[41296.831676] nft_do_chain+0xea/0x420 [nf_tables]
[41296.832621] ? nf_ct_get_tuple+0x1da/0x1f0 [nf_conntrack]
[41296.833861] ? ip_route_input_slow+0x33f/0xae0
[41296.834770] ? __skb_checksum+0x6c/0x2c0
[41296.835746] ? nf_ct_get_tuplepr+0x70/0xa0 [nf_conntrack]
[41296.837343] ? icmp_packet+0x50/0x50 [nf_conntrack]
[41296.838808] ? icmp_error+0x1ca/0x2c0 [nf_conntrack]
[41296.840510] ? nf_conntrack_in+0xd0/0x4c0 [nf_conntrack]
[41296.842112] nft_do_chain_ipv4+0x66/0x80 [nf_tables]
[41296.843208] nf_hook_slow+0x44/0xc0
[41296.843938] ip_rcv+0x91/0xd0
[41296.844577] ? ip_rcv_finish_core.isra.18+0x360/0x360
[41296.845836] __netif_receive_skb_one_core+0x5a/0x80
[41296.847004] netif_receive_skb_internal+0x2f/0xa0
[41296.848035] napi_gro_receive+0xba/0xe0
[41296.849027] receive_buf+0x175/0x1510 [virtio_net]
[41296.851930] ? try_to_wake_up+0x54/0x470
[41296.854334] ? vring_unmap_one+0x16/0x70 [virtio_ring]
[41296.856923] ? detach_buf+0x69/0x110 [virtio_ring]
[41296.859383] virtnet_poll+0x143/0x328 [virtio_net]
[41296.862004] net_rx_action+0x149/0x3b0
[41296.864069] __do_softirq+0xde/0x2d8
[41296.866086] irq_exit+0xba/0xc0
[41296.868398] do_IRQ+0x7f/0xe0
[41296.871163] common_interrupt+0xf/0xf
[41296.873226]
[41296.874842] RIP: 0010:native_safe_halt+0xe/0x10
[41296.876902] Code: ff ff 7f c3 65 48 8b 04 25 40 5c 01 00 f0 80 48 02 20 48 8b 00 a8 08 75 c4 eb 80 90 e9 07 00 00 00 0f 00 2d d6 4d 4d 00 fb f4 90 e9 07 00 00 00 0f 00 2d c6 4d 4d 00 f4 c3 90 90 66 66 66 66
[41296.883374] RSP: 0018:ffffffff8c603e88 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffd7
[41296.886095] RAX: ffffffff8bd32cc0 RBX: 0000000000000000 RCX: ffffffff8c64f210
[41296.889116] RDX: 000000000a7a7fc6 RSI: ffffffff8c64ae78 RDI: 0000000000000086
[41296.891816] RBP: 0000000000000000 R08: 00002771dc7ffa1d R09: 0000258f0798cb79
[41296.894458] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[41296.897380] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[41296.900296] ? __sched_text_end+0x7/0x7
[41296.903448] default_idle+0x1c/0x140
[41296.905487] do_idle+0x1e3/0x270
[41296.907426] cpu_startup_entry+0x6f/0x80
[41296.909477] start_kernel+0x507/0x52a
[41296.911695] secondary_startup_64+0xa4/0xb0
[41296.914003] Modules linked in: sctp nft_chain_route_ipv6 ipt_REJECT nf_reject_ipv4 xt_multiport nft_counter nft_chain_route_ipv4 xt_conntrack nf_conntrack libcrc32c nft_compat nf_tables nfnetlink crct10dif_pclmul crc32_pclmul cirrus ghash_clmulni_intel ttm drm_kms_helper sg joydev evdev virtio_balloon drm serio_raw pcspkr qemu_fw_cfg button jool_siit(OE) jool(OE) jool_common(OE) nf_defrag_ipv6 nf_defrag_ipv4 tun dummy wireguard(E) ip6_udp_tunnel udp_tunnel ip_tables x_tables autofs4 ext4 hid_generic usbhid hid crc16 mbcache jbd2 crc32c_generic fscrypto ecb virtio_net net_failover virtio_blk failover sr_mod cdrom ata_generic crc32c_intel ata_piix libata aesni_intel uhci_hcd aes_x86_64 ehci_pci crypto_simd cryptd ehci_hcd glue_helper usbcore scsi_mod psmouse usb_common virtio_pci virtio_ring virtio
[41296.941006] i2c_piix4 floppy
[41296.944211] CR2: 0000000000000008
[41296.946906] ---[ end trace a83411d47bce2273 ]---
[41296.949420] RIP: 0010:skb_release_data+0x76/0x170
[41296.952295] Code: 00 31 db 41 80 7c 24 02 00 48 89 fd 75 10 eb 46 41 0f b6 44 24 02 48 83 c3 01 39 d8 7e 38 48 89 d8 48 c1 e0 04 49 8b 7c 04 30 <48> 8b 47 08 48 8d 50 ff a8 01 48 0f 45 fa 66 66 66 66 90 f0 ff 4f
[41296.959247] RSP: 0018:ffff9ddb3ba03960 EFLAGS: 00010246
[41296.961815] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000004
[41296.965986] RDX: 0000000000000000 RSI: 0000000000000043 RDI: 0000000000000000
[41296.969640] RBP: ffff9ddb35c18200 R08: 0000000034e3ffff R09: 0000000000000000
[41296.972795] R10: 0000000000000000 R11: 0000000000000003 R12: ffff9dda970c6cc0
[41296.975884] R13: ffff9ddb35c18d00 R14: ffff9ddb0fd0e500 R15: ffff9ddb0fd0e5c8
[41296.979414] FS: 0000000000000000(0000) GS:ffff9ddb3ba00000(0000) knlGS:0000000000000000
[41296.982955] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[41296.986260] CR2: 0000000000000008 CR3: 0000000135a66000 CR4: 00000000000406f0
[41296.989694] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[41296.992820] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[41296.996134] Kernel panic - not syncing: Fatal exception in interrupt
[41297.000474] Kernel Offset: 0xa600000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[41297.004614] ---[ end Kernel panic - not syncing: Fatal exception in interrupt ]---
According to the vmlinux, it's crashing here.
(One possible call stack is skb_release_data() -> __skb_frag_unref() > put_page() > compound_head() > READ_ONCE() > __READ_ONCE() -> __read_once_size().)
So apparently, some packet page is NULL. It's annoying, because page management is buried deep within the confines of the kernel API. Jool has nothing to do with them.
But what's more baffling is that you got two kernel crashes in so little time. The bug doesn't seem to have anything to do with joold, which means it's likely to not have been introduced in the #340 patches. But if it was still present in Jool 4.1.4, I'm surprised nobody seems to have run into it before. 4.1.4 is almost three months old.
Would you be able to attempt to reproduce the bug with Jool 4.1.4, and without joold?
Unfortunately, I don't have any reliable means to trigger this particular crash. Both of the times when it's crashed so far have been overnight when I've been asleep, and I've woken up in the morning to find the machine unresponsive.
If I find that the crashes continue, I'll revert the #340 patches, reinstall, and see what happens without running joold.
Here's a likely better option: I just uploaded a patch to the issue352 branch.
If my suspicions are correct, the patch should catch the bug, print a bunch of debugging information and leak the packet. (Instead of crashing the kernel.) It is not a long-term solution, but should give us valuable insight.
Sample output:
[ 362.444325] Bug #352 found!
[ 362.444326] =================
[ 362.444327] Incoming packet
[ 362.444328] skb fields:
[ 362.444330] prev: (null)
[ 362.444332] next: (null)
[ 362.444334] dev:00000000ef69ff80
[ 362.444336] len:32
[ 362.444338] data_len:0
[ 362.444340] mac_len:14
[ 362.444341] hdr_len:0
[ 362.444343] truesize:768
[ 362.444345] pkt_type:0
[ 362.444346] ignore_df:0
[ 362.444348] ip_summed:0 (CHECKSUM_NONE)
[ 362.444350] csum_valid:0
[ 362.444351] csum_start:0
[ 362.444353] csum_offset:0
[ 362.444355] mark:0
[ 362.444356] inner_transport_header:0
[ 362.444358] inner_network_header:0
[ 362.444359] inner_mac_header:0
[ 362.444361] protocol:2048 (IPv4)
[ 362.444363] transport_header:148
[ 362.444364] network_header:128
[ 362.444366] mac_header:114
[ 362.444368] head:00000000c7151709
[ 362.444369] data:128
[ 362.444371] tail:160
[ 362.444373] end:192
[ 362.444374] Content:
[ 362.444376] IPv4 header:
[ 362.444378] Version: 4
[ 362.444379] IHL: 5
[ 362.444381] TOS: 0
[ 362.444383] Total Length: 32
[ 362.444385] Fragment ID: 0
[ 362.444387] Reserved:0 DF:1 MF:1 FragmentOffset: 0
[ 362.444389] TTL: 64
[ 362.444391] Protocol: 17
[ 362.444393] Checksum: 0x2e76
[ 362.444395] Source Address: 198.51.100.2
[ 362.444397] Destination Address: 192.0.2.33
[ 362.444399] UDP header:
[ 362.444401] Src Port: 2000
[ 362.444403] Dst Port: 4000
[ 362.444405] Length: 12
[ 362.444407] Checksum: 0x0
[ 362.444409] Payload:
[ 362.444410] 00 01 02 03
[ 362.444414] shared info:
[ 362.444415] nr_frags:0
[ 362.444417] tx_flags:0
[ 362.444418] gso_size:0
[ 362.444420] gso_segs:0
[ 362.444421] gso_type:0
[ 362.444423] frags:
[ 362.444424] =================
[ 362.444426] Outgoing packet
[ 362.444426] skb fields:
[ 362.444428] prev: (null)
[ 362.444429] next: (null)
[ 362.444431] dev:00000000ef69ff80
[ 362.444433] len:60
[ 362.444434] data_len:0
[ 362.444436] mac_len:0
[ 362.444437] hdr_len:0
[ 362.444439] truesize:768
[ 362.444440] pkt_type:0
[ 362.444442] ignore_df:0
[ 362.444443] ip_summed:0 (CHECKSUM_NONE)
[ 362.444445] csum_valid:0
[ 362.444446] csum_start:0
[ 362.444448] csum_offset:0
[ 362.444450] mark:0
[ 362.444451] inner_transport_header:0
[ 362.444453] inner_network_header:0
[ 362.444454] inner_mac_header:0
[ 362.444456] protocol:34525 (IPv6)
[ 362.444458] transport_header:176
[ 362.444459] network_header:128
[ 362.444461] mac_header:128
[ 362.444462] head:00000000ba5af142
[ 362.444464] data:128
[ 362.444465] tail:188
[ 362.444467] end:192
[ 362.444468] Content:
[ 362.444470] IPv6 header:
[ 362.444471] Version: 6
[ 362.444473] Priority: 0
[ 362.444475] Flow Label: 0x000000
[ 362.444477] Payload Length: 20
[ 362.444479] Next Header: 44
[ 362.444480] Hop Limit: 63
[ 362.444482] Source Address: 2001:db8:1c6:3364:2::
[ 362.444485] Destination Address: 2001:db8:1c0:2:21::
[ 362.444487] Fragment Header:
[ 362.444489] Next Header: 17
[ 362.444491] Reserved: 0
[ 362.444493] FragmentOffset:0 Res:0 M:1
[ 362.444495] Identification: 0
[ 362.444497] UDP header:
[ 362.444498] Src Port: 2000
[ 362.444500] Dst Port: 4000
[ 362.444502] Length: 12
[ 362.444503] Checksum: 0x0
[ 362.444505] Payload:
[ 362.444506] 00 01 02 03
[ 362.444510] shared info:
[ 362.444511] nr_frags:0
[ 362.444512] tx_flags:0
[ 362.444514] gso_size:0
[ 362.444515] gso_segs:0
[ 362.444517] gso_type:0
[ 362.444518] frags:
You can get the output from dmesg, after the bug has happened.
Okay, I'll patch and rebuild the kernel module on the affected router, and see if that logs anything.
Unfortunately I haven't seen any further cases of this error happening since I installed a version of Jool with the logging patch applied.
Ok.
- This bug is unlikely to have been introduced in the latest patches.
- We might have to wait a while before the bug happens again.
- I don't want this wait to stall the release of 4.1.5.
Therefore, I'm going to commit the temporary patch to master. A memory leak is a bug, but it's better than a kernel crash at least.
I'm expecting to release 4.1.5 roughly at the end of the month.
Still nothing, unfortunately. My test machines were moved to kernel 4.9 a few weeks after I opened this issue, in order to work around an unrelated IPv6 forwarding bug which was causing problems (I did briefly try 5.9 instead of moving backwards, but session state replication didn't immediately work and I didn't have time to work out why).
I think this issue should probably be closed, as I haven't been able to reproduce this since my original report, and it can be reopened in the future if the bug reappears.
You're free to close it if you want, but I'd personally rather keep it in the radar for at least a year.
(It has the "Status: Stuck" tag, so it's easy to filter out of the TODO list.)
Okay, I'll leave it open for now; if i have time to look at the 5.9 issues again, then I'll open a separate issue.