Kernel panic NULL pointer dereference

[rbtcollins]

Not sure how I triggered this yet ....

[505155.116452] 062.459168 [2013] netmap_do_regif           lut ffffc90000fe8000 bufs 163840 size 2048
[505155.129809] 062.472526 [ 390] generic_netmap_register   Generic adapter ffff88003f923000 goes on
[505155.130567] 062.473282 [ 455] generic_qdisc_init        Qdisc #0 initialized with max_len = 1024
[505155.131723] 062.474431 [ 441] generic_netmap_register   RX ring 0 of generic adapter ffff88003f923000 goes
on
[505155.132891] 062.475607 [ 451] generic_netmap_register   TX ring 0 of generic adapter ffff88003f923000 goes on
[505159.113590] 066.456305 [ 305] generic_netmap_unregister RX ring 0 of generic adapter ffff88003f923000 goes off
[505159.114745] 066.457456 [ 323] generic_netmap_unregister TX ring 0 of generic adapter ffff88003f923000 goes off
[505159.116993] 066.459693 [1118] generic_netmap_dtor       Restored native NA           (null)
[505160.092132] BUG: unable to handle kernel NULL pointer dereference at 0000000000000798
[505160.093243] IP: [<ffffffffc01aac69>] generic_ndo_start_xmit+0x29/0x40 [netmap]
[505160.094420] PGD 3f9e8067 PUD 6eb09067 PMD 0
[505160.095299] Oops: 0000 [#1] SMP
[505160.096054] Modules linked in: netmap(OE) binfmt_misc xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack xt_tcpudp bridge stp llc iptable_filter ip_tables x_tables nls_iso8859_1 crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd serio_raw hyperv_fb joydev hv_balloon mac_hid autofs4 hid_generic hid_hyperv hv_storvsc hv_netvsc hv_utils hyperv_keyboard hid hv_vmbus
[505160.096054] CPU: 0 PID: 24257 Comm: ping Tainted: G           OE   4.4.0-23-generic #23
[505160.096054] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS Hyper-V UEFI Release v1.0 11/26/2012
[505160.096054] task: ffff8801f974ee00 ti: ffff88000136c000 task.ti: ffff88000136c000
[505160.096054] RIP: 0010:[<ffffffffc01aac69>]  [<ffffffffc01aac69>] generic_ndo_start_xmit+0x29/0x40 [netmap]
[505160.096054] RSP: 0018:ffff88000136f890  EFLAGS: 00010246
[505160.096054] RAX: ffff8801f5599000 RBX: ffff8801f2e22100 RCX: 0000000000b5e747
[505160.096054] RDX: 0000000000000000 RSI: ffff8801f5599000 RDI: ffff8801f2e22100
[505160.096054] RBP: ffff88000136f890 R08: 000000000001a000 R09: ffffffff81705e19
[505160.096054] R10: ffffea0007cb8880 R11: ffff88000136f9d0 R12: 0000000000000062
[505160.096054] R13: ffff8801f5599068 R14: 0000000000000001 R15: ffff880003fd4540
[505160.096054] FS:  00007fa9b1e97700(0000) GS:ffff8801fb400000(0000) knlGS:0000000000000000
[505160.096054] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[505160.096054] CR2: 0000000000000798 CR3: 00000000013e3000 CR4: 00000000003406f0
[505160.096054] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[505160.096054] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[505160.096054] Stack:
[505160.096054]  ffff88000136f900 ffffffff8171d5e9 ffff88000136f91c ffffffff81f35140
[505160.096054]  ffff8801f560b400 00ff8801f560b400 0000000000000000 ffff8801f5599000
[505160.096054]  ffff8801f5599000 ffff88007a8a5200 ffff8801f560b400 ffff8801f2e22100
[505160.096054] Call Trace:
[505160.096054]  [<ffffffff8171d5e9>] dev_hard_start_xmit+0x249/0x3d0
[505160.096054]  [<ffffffff817420ff>] sch_direct_xmit+0x12f/0x210
[505160.096054]  [<ffffffff817422e3>] __qdisc_run+0x103/0x1a0
[505160.096054]  [<ffffffff8171db8d>] __dev_queue_xmit+0x2dd/0x590
[505160.096054]  [<ffffffff8171de50>] dev_queue_xmit+0x10/0x20
[505160.096054]  [<ffffffff8175de45>] ip_finish_output2+0x285/0x340
[505160.096054]  [<ffffffff8175ec66>] ip_finish_output+0x136/0x1f0
[505160.096054]  [<ffffffff817524e3>] ? nf_hook_slow+0x73/0xd0
[505160.096054]  [<ffffffff8175f65e>] ip_output+0x6e/0xe0
[505160.096054]  [<ffffffff8175eb30>] ? __ip_flush_pending_frames.isra.39+0x90/0x90
[505160.096054]  [<ffffffff8175ee25>] ip_local_out+0x35/0x40
[505160.096054]  [<ffffffff81760029>] ip_send_skb+0x19/0x40
[505160.096054]  [<ffffffff81760083>] ip_push_pending_frames+0x33/0x40
[505160.096054]  [<ffffffff81786089>] raw_sendmsg+0x7e9/0xb20
[505160.096054]  [<ffffffff81391521>] ? aa_sock_msg_perm+0x61/0x150
[505160.096054]  [<ffffffff817959f5>] inet_sendmsg+0x65/0xa0
[505160.096054]  [<ffffffff816fec08>] sock_sendmsg+0x38/0x50
[505160.096054]  [<ffffffff816ff6b1>] ___sys_sendmsg+0x281/0x290
[505160.096054]  [<ffffffff8120031b>] ? mem_cgroup_try_charge+0x6b/0x1b0
[505160.096054]  [<ffffffff8119e0a7>] ? lru_cache_add_active_or_unevictable+0x27/0xa0
[505160.096054]  [<ffffffff811bf94a>] ? handle_mm_fault+0xcaa/0x1820
[505160.096054]  [<ffffffff81700001>] __sys_sendmsg+0x51/0x90
[505160.096054]  [<ffffffff81700052>] SyS_sendmsg+0x12/0x20
[505160.096054]  [<ffffffff818252f2>] entry_SYSCALL_64_fastpath+0x16/0x71
[505160.096054] Code: 00 00 0f 1f 44 00 00 55 81 bf 9c 00 00 00 10 d3 86 ad 48 89 f0 48 8b 96 f8 02 00 00 48 89 e5 75 12 c7 87 9c 00 00 00 00 00 00 00 <ff> 92 98 07 00 00 5d c3 48 89 fe 48 89 c7 e8 64 f0 ff ff 31 c0
[505160.096054] RIP  [<ffffffffc01aac69>] generic_ndo_start_xmit+0x29/0x40 [netmap]
[505160.096054]  RSP <ffff88000136f890>
[505160.096054] CR2: 0000000000000798

[rbtcollins]

This appears to have happened just as my test program using netmap finished, so I'm speculating that this is a result of incorrect cleanup in unregister or something..

[rbtcollins]

That said, I can trigger this reliably; its not a super small reproducer, but I'll put it up as an attachment tomorrow; sleep time now.

[vmaffione]

Hi thanks for reporting! I think you are right, weird that I've never bumped into that in three years. It seems to be some race condition in the generic_netmap_unregister. generic_ndo_start_xmit should never be called after unregif.

Could you please try with the following patch? It contains both a possible fix and a debug print to see if the crash is due to NULL netmap adapter.

x.patch.txt

[rbtcollins]

Its probably because I'm unregistering two separate fd's in a row in rust finalisers.

This is the code.

main.rs.txt

You'll need a Cargo.toml like so:

[package]
name = "foo"
version = "0.1.0"
authors = ["<example@example.org>"]

[dependencies]
libc="*"

[dependencies.netmap]
git = "https://github.com/rbtcollins/netmap-rs"

#[dependencies.netmap_sys]
#version = "0.1.0"
# Uncomment this line where you wish to use features guarded by the
# NETMAP_WITH_LIBS macro in C.
#features = ["netmap_with_libs"]

[dependencies.pnet]
version = "0.10.0"
#features = ["netmap"]

Drop main.rs in src/main.rs install rust and cargo, make sure you have netmap headers installed globally (/usr/include/net/netmap{,_user}.h) and then `sudo cargo run`` should trigger this.

[rbtcollins]

Good news, your patch triggers a different failure :).

[37133.475540] netmap: module verification failed: signature and/or required key missing - tainting kernel
[37133.477822] 236.185239 [3255] netmap_init               run mknod /dev/netmap c 10 53 # error 0
[37133.477895] netmap: loaded module
[37458.164705] 560.872179 [2013] netmap_do_regif           lut ffffc90000fee000 bufs 163840 size 2048
[37458.164752] 560.872226 [ 390] generic_netmap_register   Generic adapter ffff8801f60a8000 goes on
[37458.164805] 560.872277 [ 459] generic_qdisc_init        Qdisc #0 initialized with max_len = 1024
[37458.164952] 560.872415 [ 441] generic_netmap_register   RX ring 0 of generic adapter ffff8801f60a8000 goes on
[37458.164991] 560.872453 [ 451] generic_netmap_register   TX ring 0 of generic adapter ffff8801f60a8000 goes on
[37462.770376] 565.477874 [ 305] generic_netmap_unregister RX ring 0 of generic adapter ffff8801f60a8000 goes off
[37462.770412] 565.477910 [ 323] generic_netmap_unregister TX ring 0 of generic adapter ffff8801f60a8000 goes off
[37462.770955] 565.478424 [1118] generic_netmap_dtor       Restored native NA           (null)
[37462.772878] BUG: unable to handle kernel NULL pointer dereference at 000000000000000c
[37462.772928] IP: [<ffffffffc01ab063>] generic_rx_handler+0x43/0x210 [netmap]
[37462.772973] PGD 0
[37462.772986] Oops: 0000 [#1] SMP
[37462.773782] Modules linked in: netmap(OE) xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack xt_tcpudp bridge stp llc iptable_filter ip_tables x_tables binfmt_misc nls_iso8859_1 crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd serio_raw joydev mac_hid hyperv_fb hv_balloon autofs4 hid_generic hv_netvsc hv_storvsc hv_utils hid_hyperv hid hyperv_keyboard hv_vmbus
[37462.776009] CPU: 0 PID: 6456 Comm: cargo Tainted: G           OE   4.4.0-23-generic #23
[37462.776009] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS Hyper-V UEFI Release v1.0 11/26/2012
[37462.776009] task: ffff8801f6c20dc0 ti: ffff8801f6d80000 task.ti: ffff8801f6d80000
[37462.776009] RIP: 0010:[<ffffffffc01ab063>]  [<ffffffffc01ab063>] generic_rx_handler+0x43/0x210 [netmap]
[37462.776009] RSP: 0000:ffff8801fb403d50  EFLAGS: 00010202
[37462.776009] RAX: 0000000000000001 RBX: 0000000000000000 RCX: 0000000000000002
[37462.776009] RDX: ffff8800042193c0 RSI: ffff8801f56f9a00 RDI: ffff8801f55cb000
[37462.776009] RBP: ffff8801fb403d90 R08: 0000000000000068 R09: ffffffffc01b0540
[37462.776009] R10: ffff8801f55cc000 R11: 000055fbc25832c0 R12: 0000000000000000
[37462.776009] R13: ffff8801fb403dc8 R14: ffff8801f56f9a00 R15: 0000000000000000
[37462.776009] FS:  00007fa485ed38c0(0000) GS:ffff8801fb400000(0000) knlGS:0000000000000000
[37462.776009] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[37462.776009] CR2: 000000000000000c CR3: 00000001f7284000 CR4: 00000000003406f0
[37462.776009] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[37462.776009] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[37462.776009] Stack:
[37462.776009]  ffff8801f60aa800 ffff8801fb403da8 000000001a5f034a ffff8801f56f9a00
[37462.776009]  ffff8801f60aad40 ffff8801fb403dc8 ffff8801f55cb000 0000000000000000
[37462.776009]  ffff8801fb403da8 ffffffffc01b0572 ffff8801f56f9a00 ffff8801fb403e40
[37462.776009] Call Trace:
[37462.776009]  <IRQ>
[37462.776009]  [<ffffffffc01b0572>] linux_generic_rx_handler+0x32/0x60 [netmap]
[37462.776009]  [<ffffffff8171af84>] __netif_receive_skb_core+0x364/0xa60
[37462.776009]  [<ffffffffc01b0540>] ? linux_netmap_notifier_cb+0x50/0x50 [netmap]
[37462.776009]  [<ffffffffc000370b>] ? vmbus_recvpacket_raw+0x3b/0x70 [hv_vmbus]
[37462.776009]  [<ffffffff8171b698>] __netif_receive_skb+0x18/0x60
[37462.776009]  [<ffffffff8171c498>] process_backlog+0xa8/0x150
[37462.776009]  [<ffffffff8171bbde>] net_rx_action+0x21e/0x360
[37462.776009]  [<ffffffffc000273d>] ? vmbus_on_event+0x15d/0x190 [hv_vmbus]
[37462.776009]  [<ffffffff810859f1>] __do_softirq+0x101/0x290
[37462.776009]  [<ffffffff81085cf3>] irq_exit+0xa3/0xb0
[37462.776009]  [<ffffffff8104f4be>] hyperv_vector_handler+0x3e/0x50
[37462.776009]  [<ffffffff81827242>] hyperv_callback_vector+0x82/0x90
[37462.776009]  <EOI>
[37462.776009] Code:
[37462.776009] 83 ec 18 4c 8b a7 f8 02 00 00 65 48 8b 04 25 28 00 00 00 48 89 45 d0 31 c0 0f b7 86 8c 00 00 00 66 85 c0 74 06 8d 58 ff 0f b7 db <41> 8b 4c 24 0c 39 cb 72 08 89 d8 31 d2 f7 f1 89 d3 41 89 dd 31
[37462.776009] RIP  [<ffffffffc01ab063>] generic_rx_handler+0x43/0x210 [netmap]
[37462.776009]  RSP <ffff8801fb403d50>
[37462.776009] CR2: 000000000000000c

[rbtcollins]

I've also triggered the first trace again, this time with RACE CONDITION output - so your debug is triggering.

[rbtcollins]

I can reproduce this with sudo ./bridge netmap:eth0 - it runs ok, panics when I hit ctrl-C, after printing 'exiting'.

[rbtcollins]

running pkt-gen as I was before doesn't trigger it - its either related to the host interface, or to having two separate descriptors open.

[rbtcollins]

And bingo - pkt-gen -i eth0^ -f ping -n 2 triggers it reliably :/.

[rbtcollins]

(Which looks like:)

[  205.331885] netmap: loaded module
[  252.174584] 575.184600 [2013] netmap_do_regif           lut ffffc9000102c000 bufs 163840 size 2048
[  252.174618] 575.184635 [ 390] generic_netmap_register   Generic adapter ffff8801f6355800 goes on
[  252.174645] 575.184662 [ 441] generic_netmap_register   RX ring 0 of generic adapter ffff8801f6355800 goes o
n
[  252.174673] 575.184690 [ 451] generic_netmap_register   TX ring 0 of generic adapter ffff8801f6355800 goes on
[  252.174708] 575.184723 [ 459] generic_qdisc_init        Qdisc #0 initialized with max_len = 1024
[  299.608404] 622.618486 [ 286] generic_netmap_unregister Generic adapter ffff8801f6355800 goes off
[  299.609151] 622.619216 [ 305] generic_netmap_unregister RX ring 0 of generic adapter ffff8801f6355800 goes off
[  299.609884] 622.619933 [ 323] generic_netmap_unregister TX ring 0 of generic adapter ffff8801f6355800 goes off
[  299.611177] 622.621196 [1118] generic_netmap_dtor       Restored native NA           (null)
[  394.043939] 717.053938 [2013] netmap_do_regif           lut ffffc9000102c000 bufs 163840 size 2048
[  394.044009] 717.054649 [ 390] generic_netmap_register   Generic adapter ffff880079ce4000 goes on
[  394.044009] 717.055372 [ 459] generic_qdisc_init        Qdisc #0 initialized with max_len = 1024
[  400.051741] 723.061803 [1118] generic_netmap_dtor       Restored native NA           (null)
[  400.053315] 723.063390 [ 417] generic_ndo_start_xmit    RACE CONDITION
[  400.054184] BUG: unable to handle kernel NULL pointer dereference at 0000000000000798
[  400.055418] IP: [<ffffffffc01a2c93>] generic_ndo_start_xmit+0x53/0xe0 [netmap]
[  400.056565] PGD 0
[  400.056565] Oops: 0000 [#1] SMP
[  400.056565] Modules linked in: netmap(OE) xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack xt_tcpudp bridge stp llc iptable_filter ip_tables x_tables binfmt_misc nls_iso8859_1 crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd serio_raw hyperv_fb hv_balloon joydev mac_hid autofs4 hid_generic hid_hyperv hid hv_netvsc hv_storvsc hv_utils hyperv_keyboard hv_vmbus
[  400.056565] CPU: 0 PID: 2217 Comm: sshd Tainted: G           OE   4.4.0-22-generic #40-Ubuntu
[  400.056565] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS Hyper-V UEFI Release v1.0 11/26/2012
[  400.056565] task: ffff8801f9740000 ti: ffff88006fc50000 task.ti: ffff88006fc50000
[  400.056565] RIP: 0010:[<ffffffffc01a2c93>]  [<ffffffffc01a2c93>] generic_ndo_start_xmit+0x53/0xe0 [netmap]
[  400.056565] RSP: 0018:ffff88006fc538b0  EFLAGS: 00010246
[  400.056565] RAX: 000000000000003a RBX: ffff8801da51c8e8 RCX: 0000000000000006
[  400.056565] RDX: 0000000000000000 RSI: ffff8801f5583000 RDI: ffff8801da51c8e8
[  400.056565] RBP: ffff88006fc538e0 R08: 0000000000000000 R09: 0000000000000203
[  400.056565] R10: ffffea0007dcbe80 R11: 0000000000000203 R12: ffff8801f5583000
[  400.056565] R13: 0000000000000000 R14: 0000000000000009 R15: ffff8801f619d540
[  400.056565] FS:  00007f260440e8c0(0000) GS:ffff8801fb400000(0000) knlGS:0000000000000000
[  400.056565] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  400.056565] CR2: 0000000000000798 CR3: 000000006fc6b000 CR4: 00000000003406f0
[  400.056565] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  400.056565] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  400.056565] Stack:
[  400.056565]  00000000574f67db 000000000000f79e 0000000065f90750 ffff8801da51c8e8
[  400.056565]  0000000000000136 ffff8801f5583068 ffff88006fc53950 ffffffff8171d5e9
[  400.056565]  ffff88006fc5396c ffffffff81f35140 ffff8801f55c7e00 00ff8801f55c7e00
[  400.056565] Call Trace:
[  400.056565]  [<ffffffff8171d5e9>] dev_hard_start_xmit+0x249/0x3d0
[  400.056565]  [<ffffffff817420ff>] sch_direct_xmit+0x12f/0x210
[  400.056565]  [<ffffffff817422e3>] __qdisc_run+0x103/0x1a0
[  400.056565]  [<ffffffff8171db8d>] __dev_queue_xmit+0x2dd/0x590
[  400.056565]  [<ffffffff8171de50>] dev_queue_xmit+0x10/0x20
[  400.056565]  [<ffffffff8175de45>] ip_finish_output2+0x285/0x340
[  400.056565]  [<ffffffffc016c23d>] ? ipv4_confirm+0x7d/0x100 [nf_conntrack_ipv4]
[  400.056565]  [<ffffffff8175ec66>] ip_finish_output+0x136/0x1f0
[  400.056565]  [<ffffffff817524e3>] ? nf_hook_slow+0x73/0xd0
[  400.056565]  [<ffffffff8175f65e>] ip_output+0x6e/0xe0
[  400.056565]  [<ffffffff8175eb30>] ? __ip_flush_pending_frames.isra.39+0x90/0x90
[  400.056565]  [<ffffffff8175ee25>] ip_local_out+0x35/0x40
[  400.056565]  [<ffffffff8175f144>] ip_queue_xmit+0x154/0x380
[  400.056565]  [<ffffffff81776ec8>] tcp_transmit_skb+0x4e8/0x930
[  400.056565]  [<ffffffff817774e6>] tcp_write_xmit+0x1d6/0xed0
[  400.056565]  [<ffffffff81778471>] __tcp_push_pending_frames+0x31/0xd0
[  400.056565]  [<ffffffff8176691c>] tcp_push+0xec/0x110
[  400.056565]  [<ffffffff8176a90b>] tcp_sendmsg+0x70b/0xb20
[  400.056565]  [<ffffffff81390c60>] ? aa_sk_perm+0x70/0x210
[  400.056565]  [<ffffffff817959f5>] inet_sendmsg+0x65/0xa0
[  400.056565]  [<ffffffff816fec08>] sock_sendmsg+0x38/0x50
[  400.056565]  [<ffffffff816feca5>] sock_write_iter+0x85/0xf0
[  400.056565]  [<ffffffff8120c04b>] new_sync_write+0x9b/0xe0
[  400.056565]  [<ffffffff8120c0b6>] __vfs_write+0x26/0x40
[  400.056565]  [<ffffffff8120ca39>] vfs_write+0xa9/0x1a0
[  400.056565]  [<ffffffff810f58d1>] ? ktime_get_with_offset+0x51/0xc0
[  400.056565]  [<ffffffff8120d6f5>] SyS_write+0x55/0xc0
[  400.056565]  [<ffffffff818252f2>] entry_SYSCALL_64_fastpath+0x16/0x71
[  400.056565] Code: 48 89 45 e0 31 c0 4d 85 ed 74 41 81 bb 9c 00 00 00 10 d3 86 ad 0f 85 80 00 00 00 c7 83 9c 00 00 00 00 00 00 00 4c 89 e6 48 89 df <41> ff 95 98 07 00 00 48 8b 4d e0 65 48 33 0c 25 28 00 00 00 75
[  400.056565] RIP  [<ffffffffc01a2c93>] generic_ndo_start_xmit+0x53/0xe0 [netmap]
[  400.056565]  RSP <ffff88006fc538b0>
[  400.056565] CR2: 0000000000000798

[rbtcollins]

The triggering process is sshd - this may provide input into how I'm triggering it: I'm typically running these commands via an ssh session, so when bridge etc finishes the shell (or command) will generate output - such as a shell prompt - and that could be arriving on the netmap stack very rapidly.

Also, this is a single cpu VM I'm testing within.

[rbtcollins]

A related thing - I tried running the pkt-gen command in a console rather than over ssh; it didn't panic immediately on completion - but it did about 5-10 seconds later. In the interim period I tried to run pkt-gen again and it said the device was busy - which is suspicious to me, since the pkt-gen process had exited.

This one caused by nmbd, and appears to be failing in rx instead?.

Dmesg:

[  129.874441] 560.716847 [ 390] generic_netmap_register   Generic adapter ffff88007aa24000 goes on
[  129.876817] 560.719269 [ 460] generic_qdisc_init        Qdisc #0 initialized with max_len = 1024
[  147.244788] 578.090731 [1118] generic_netmap_dtor       Restored native NA           (null)
[  155.191412] 586.036966 [2013] netmap_do_regif           lut ffffc90001016000 bufs 163840 size 2048
[  155.192143] 586.037742 [ 390] generic_netmap_register   Generic adapter ffff88007aa27000 goes on
[  155.193010] 586.038591 [ 467] generic_netmap_register   nm_os_catch_rx(1) failed (16)
[  155.194355] 586.039906 [1118] generic_netmap_dtor       Restored native NA           (null)
[  177.728008] 608.573917 [2013] netmap_do_regif           lut ffffc90001016000 bufs 163840 size 2048
[  177.728008] 608.574514 [ 390] generic_netmap_register   Generic adapter ffff88007aa26800 goes on
[  177.728008] 608.575100 [ 467] generic_netmap_register   nm_os_catch_rx(1) failed (16)
[  177.728008] 608.576109 [1118] generic_netmap_dtor       Restored native NA           (null)
[  208.344411] BUG: unable to handle kernel NULL pointer dereference at 000000000000000c
[  208.345822] IP: [<ffffffffc01a4063>] generic_rx_handler+0x43/0x210 [netmap]
[  208.346555] PGD 0
[  208.347272] Oops: 0000 [#1] SMP
[  208.348126] Modules linked in: netmap(OE) xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack xt_tcpudp bridge stp llc iptable_filter ip_tables x_tables binfmt_misc nls_iso8859_1 crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd serio_raw hyperv_fb joydev hv_balloon mac_hid autofs4 hid_generic hv_netvsc hv_storvsc hv_utils hyperv_keyboard hid_hyperv hid hv_vmbus
[  208.348283] CPU: 0 PID: 1259 Comm: nmbd Tainted: G           OE   4.4.0-22-generic #40-Ubuntu
[  208.348283] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS Hyper-V UEFI Release v1.0 11/26/2012
[  208.348283] task: ffff8801f5a8b700 ti: ffff88000405c000 task.ti: ffff88000405c000
[  208.348283] RIP: 0010:[<ffffffffc01a4063>]  [<ffffffffc01a4063>] generic_rx_handler+0x43/0x210 [netmap]
[  208.348283] RSP: 0018:ffff8801fb403d78  EFLAGS: 00010246
[  208.348283] RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff8801f55e4000
[  208.348283] RDX: ffff880003e7ece2 RSI: ffff8801f5802e00 RDI: ffff8801f55e4000
[  208.348283] RBP: ffff8801fb403db8 R08: ffffffff81ef3ec0 R09: ffffffffc01a9540
[  208.348283] R10: 0000000008ebed07 R11: ffff88007ab00000 R12: 0000000000000000
[  208.348283] R13: ffff8801fb403df0 R14: ffff8801f5802e00 R15: 0000000000000000
[  208.348283] FS:  00007f122db80740(0000) GS:ffff8801fb400000(0000) knlGS:0000000000000000
[  208.348283] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  208.348283] CR2: 000000000000000c CR3: 0000000003fec000 CR4: 00000000003406f0
[  208.348283] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[  208.348283] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[  208.348283] Stack:
[  208.348283]  ffff88007aa32d40 ffff8801fb403dd0 00000000fc84db49 ffff8801f5802e00
[  208.348283]  ffff88007aa32d40 ffff8801fb403df0 ffff8801f55e4000 0000000000000000
[  208.348283]  ffff8801fb403dd0 ffffffffc01a9572 ffff8801f5802e00 ffff8801fb403e68
[  208.348283] Call Trace:
[  208.348283]  <IRQ>
[  208.348283]  [<ffffffffc01a9572>] linux_generic_rx_handler+0x32/0x60 [netmap]
[  208.348283]  [<ffffffff8171af84>] __netif_receive_skb_core+0x364/0xa60
[  208.348283]  [<ffffffffc01a9540>] ? linux_netmap_notifier_cb+0x50/0x50 [netmap]
[  208.348283]  [<ffffffff810aae74>] ? check_preempt_curr+0x54/0x90
[  208.348283]  [<ffffffff810aaec9>] ? ttwu_do_wakeup+0x19/0xe0
[  208.348283]  [<ffffffff8171b698>] __netif_receive_skb+0x18/0x60
[  208.348283]  [<ffffffff8171c498>] process_backlog+0xa8/0x150
[  208.348283]  [<ffffffff8171bbde>] net_rx_action+0x21e/0x360
[  208.348283]  [<ffffffff810859f1>] __do_softirq+0x101/0x290
[  208.348283]  [<ffffffff8182700c>] do_softirq_own_stack+0x1c/0x30
[  208.348283]  <EOI>
[  208.348283]  [<ffffffff81085438>] do_softirq.part.19+0x38/0x40
[  208.348283]  [<ffffffff81085bed>] do_softirq+0x1d/0x20
[  208.348283]  [<ffffffff8171a293>] netif_rx_ni+0x33/0x80
[  208.348283]  [<ffffffff8171a37a>] dev_loopback_xmit+0x9a/0xe0
[  208.348283]  [<ffffffff8175f51b>] ip_mc_output+0x1ab/0x280
[  208.348283]  [<ffffffff8175ed02>] ? ip_finish_output+0x1d2/0x1f0
[  208.348283]  [<ffffffff8171a2e0>] ? netif_rx_ni+0x80/0x80
[  208.348283]  [<ffffffff8175ee25>] ip_local_out+0x35/0x40
[  208.348283]  [<ffffffff81760029>] ip_send_skb+0x19/0x40
[  208.348283]  [<ffffffff8178759d>] udp_send_skb+0x9d/0x270
[  208.348283]  [<ffffffff817884d7>] udp_sendmsg+0x307/0xac0
[  208.348283]  [<ffffffff81391521>] ? aa_sock_msg_perm+0x61/0x150
[  208.348283]  [<ffffffff817959f5>] inet_sendmsg+0x65/0xa0
[  208.348283]  [<ffffffff816fec08>] sock_sendmsg+0x38/0x50
[  208.348283]  [<ffffffff816ff1f1>] SYSC_sendto+0x101/0x190
[  208.348283]  [<ffffffff810f597c>] ? __getnstimeofday64+0x3c/0xd0
[  208.348283]  [<ffffffff810f5a69>] ? do_gettimeofday+0x29/0x90
[  208.348283]  [<ffffffff816ffd0e>] SyS_sendto+0xe/0x10
[  208.348283]  [<ffffffff818252f2>] entry_SYSCALL_64_fastpath+0x16/0x71
[  208.348283] Code: 83 ec 18 4c 8b a7 f8 02 00 00 65 48 8b 04 25 28 00 00 00 48 89 45 d0 31 c0 0f b7 86 8c 00 00 00 66 85 c0 74 06 8d 58 ff 0f b7 db <41> 8b 4c 24 0c 39 cb 72 08 89 d8 31 d2 f7 f1 89 d3 41 89 dd 31
[  208.348283] RIP  [<ffffffffc01a4063>] generic_rx_handler+0x43/0x210 [netmap]
[  208.348283]  RSP <ffff8801fb403d78>
[  208.348283] CR2: 000000000000000c

and bt

      KERNEL: /usr/lib/debug/boot/vmlinux-4.4.0-22-generic
    DUMPFILE: dump.201606021840  [PARTIAL DUMP]
        CPUS: 1
        DATE: Thu Jun  2 18:40:39 2016
      UPTIME: 00:03:28
LOAD AVERAGE: 0.02, 0.04, 0.02
       TASKS: 118
    NODENAME: lifelesstab
     RELEASE: 4.4.0-22-generic
     VERSION: #40-Ubuntu SMP Thu May 12 22:03:46 UTC 2016
     MACHINE: x86_64  (2161 Mhz)
      MEMORY: 6 GB
       PANIC: "BUG: unable to handle kernel NULL pointer dereference at 000000000000000c"
         PID: 1259
     COMMAND: "nmbd"
        TASK: ffff8801f5a8b700  [THREAD_INFO: ffff88000405c000]
         CPU: 0
       STATE: TASK_RUNNING (PANIC)

crash> bt
PID: 1259   TASK: ffff8801f5a8b700  CPU: 0   COMMAND: "nmbd"
 #0 [ffff8801fb403a38] machine_kexec at ffffffff8105befb
 #1 [ffff8801fb403a98] crash_kexec at ffffffff8110da12
 #2 [ffff8801fb403b68] oops_end at ffffffff81031c29
 #3 [ffff8801fb403b90] no_context at ffffffff8106ad45
 #4 [ffff8801fb403bf0] __bad_area_nosemaphore at ffffffff8106b010
 #5 [ffff8801fb403c38] bad_area_nosemaphore at ffffffff8106b193
 #6 [ffff8801fb403c48] __do_page_fault at ffffffff8106b457
 #7 [ffff8801fb403ca0] do_page_fault at ffffffff8106b7c2
 #8 [ffff8801fb403cc0] page_fault at ffffffff81827478
    [exception RIP: generic_rx_handler+67]
    RIP: ffffffffc01a4063  RSP: ffff8801fb403d78  RFLAGS: 00010246
    RAX: 0000000000000000  RBX: 0000000000000000  RCX: ffff8801f55e4000
    RDX: ffff880003e7ece2  RSI: ffff8801f5802e00  RDI: ffff8801f55e4000
    RBP: ffff8801fb403db8   R8: ffffffff81ef3ec0   R9: ffffffffc01a9540
    R10: 0000000008ebed07  R11: ffff88007ab00000  R12: 0000000000000000
    R13: ffff8801fb403df0  R14: ffff8801f5802e00  R15: 0000000000000000
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #9 [ffff8801fb403dc0] linux_generic_rx_handler at ffffffffc01a9572 [netmap]
#10 [ffff8801fb403dd8] __netif_receive_skb_core at ffffffff8171af84
#11 [ffff8801fb403e70] __netif_receive_skb at ffffffff8171b698
#12 [ffff8801fb403e90] process_backlog at ffffffff8171c498
#13 [ffff8801fb403ed0] net_rx_action at ffffffff8171bbde
#14 [ffff8801fb403f48] __do_softirq at ffffffff810859f1
#15 [ffff8801fb403fb0] do_softirq_own_stack at ffffffff8182700c
--- <IRQ stack> ---
#16 [ffff88000405fb00] do_softirq_own_stack at ffffffff8182700c
    [exception RIP: dev_loopback_xmit+154]
    RIP: ffffffff8171a37a  RSP: ffffffff8175f51b  RFLAGS: ffff88000405fc10
    RAX: ffff88000405fb78  RBX: ffff88000405fb40  RCX: ffffffff8171a293
    RDX: 00000000817524e3  RSI: ffff8801f5802e00  RDI: ffff8801f5802e00
    RBP: ffffffff8171a0f4   R8: ffffffff81085bed   R9: ffff88000405fb50
    R10: ffff8801f5802e00  R11: ffffffff81085438  R12: ffff88000405fb50
    R13: ffff88000405fd18  R14: ffff8801f9e9a580  R15: ffffffff81ef3ec0
    ORIG_RAX: ffff88000405fb90  CS: ffff8801f5803b00  SS: 8000000000000004
bt: WARNING: possibly bogus exception frame
#17 [ffff88000405fc18] ip_local_out at ffffffff8175ee25
#18 [ffff88000405fc40] ip_send_skb at ffffffff81760029
#19 [ffff88000405fc58] udp_send_skb at ffffffff8178759d
#20 [ffff88000405fc98] udp_sendmsg at ffffffff817884d7
#21 [ffff88000405fdc8] inet_sendmsg at ffffffff817959f5
#22 [ffff88000405fdf0] sock_sendmsg at ffffffff816fec08
#23 [ffff88000405fe10] SYSC_sendto at ffffffff816ff1f1
#24 [ffff88000405ff40] sys_sendto at ffffffff816ffd0e
#25 [ffff88000405ff50] entry_SYSCALL_64_fastpath at ffffffff818252f2
    RIP: 00007f122d790af3  RSP: 00007ffcc5f033b8  RFLAGS: 00000246
    RAX: ffffffffffffffda  RBX: 00007ffcc5f04080  RCX: 00007f122d790af3
    RDX: 00000000000000eb  RSI: 00007ffcc5f033e0  RDI: 0000000000000014
    RBP: 00007ffcc5f040d0   R8: 00007ffcc5f033d0   R9: 0000000000000010
    R10: 0000000000000000  R11: 0000000000000246  R12: 000055578e135c1c
    R13: 0000000000000003  R14: 000055578e135ad0  R15: 0000000000000000
    ORIG_RAX: 000000000000002c  CS: 0033  SS: 002b

[rbtcollins]

On the receive side.. rx_handler = rcu_dereference(skb->dev->rx_handler); in skb_receive_core pointing at linux_generic_rx_handler means the dev handler is wrong, or the dev is wrong. I'm going to see about figuring that out.

[rbtcollins]

diff --git a/LINUX/netmap_linux.c b/LINUX/netmap_linux.c
index a2f17b1..7cd0186 100644
--- a/LINUX/netmap_linux.c
+++ b/LINUX/netmap_linux.c
@@ -316,6 +316,17 @@ linux_generic_rx_handler_common(struct mbuf *m)
 {
        int stolen;

+        if (unlikely(m == NULL)) {
+           BUG();
+        }
+       if (unlikely(m->dev == NULL)) {
+           BUG();
+       }
+       if (unlikely(NA(m->dev) == NULL)) {
+            D("netmap NULL %s", m->dev->name);
+           return NM_RX_HANDLER_PASS;
+       }
+
        /* If we were called by NM_SEND_UP(), we want to pass the mbuf
           to network stack. We detect this situation looking at the
           priority field. */
@@ -413,6 +424,12 @@ generic_ndo_start_xmit(struct mbuf *m, struct ifnet *ifp)
        struct netmap_generic_adapter *gna =
                (struct netmap_generic_adapter *)NA(ifp);

+        if (unlikely(gna == NULL)) {
+           D("netmap NULL xmit %s", ifp->name);
+           // Discard the frame - we can't do anything sane with it.
+           return NETDEV_TX_OK;
+        }
+

[vmaffione]

Yes, but this is a workaround, we first have to understand if the bug can be fixed in the proper way.

2016-06-03 5:58 GMT+02:00 rbtcollins notifications@github.com:

diff --git a/LINUX/netmap_linux.c b/LINUX/netmap_linux.c index a2f17b1..7cd0186 100644 --- a/LINUX/netmap_linux.c +++ b/LINUX/netmap_linux.c @@ -316,6 +316,17 @@ linux_generic_rx_handler_common(struct mbuf *m) { int stolen;

• if (unlikely(m == NULL)) {
• BUG();
• }
• if (unlikely(m->dev == NULL)) {
• BUG();
• }
• if (unlikely(NA(m->dev) == NULL)) {
• D("netmap NULL %s", m->dev->name);
• return NM_RX_HANDLER_PASS;

• }

  + /* If we were called by NM_SEND_UP(), we want to pass the mbuf to network stack. We detect this situation looking at the priority field. / @@ -413,6 +424,12 @@ generic_ndo_start_xmit(struct mbuf m, struct ifnet ifp) struct netmap_generic_adapter gna = (struct netmap_generic_adapter *)NA(ifp);

•  if (unlikely(gna == NULL)) {

• D("netmap NULL xmit %s", ifp->name);
• // Discard the frame - we can't do anything sane with it.
• return NETDEV_TX_OK;
• } +

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/luigirizzo/netmap/issues/189#issuecomment-223485266, or mute the thread https://github.com/notifications/unsubscribe/AEsSwbL8-v9sBKknpML0uQy8I2cMpmZ_ks5qH6ZigaJpZM4IramH .

Vincenzo Maffione

[rbtcollins]

Totally - I am merely trying to not have to reboot between diagnostic runs :) - faster iterations that way :).

[rbtcollins]

Have you been able to reproduce?

[rbtcollins]

I think I have the cause.

[ 3626.267071] 358.915810 [1190] generic_netmap_attach     Created generic NA ffff8801f6ffa000 (prev
(null))
[ 3626.323267] 358.971985 [2013] netmap_do_regif           lut ffffc90000ff8000 bufs 163840 size 2048
[ 3626.323319] 358.972037 [ 390] generic_netmap_register   Generic adapter ffff8801f6ffa000 goes on
[ 3626.323371] 358.972087 [ 475] generic_qdisc_init        Qdisc #0 initialized with max_len = 1024
[ 3634.334195] 366.983047 [1118] generic_netmap_dtor       Restored native NA           (null)
[ 3634.335560] BUG: unable to handle kernel NULL pointer dereference at           (null)

Note that the create has gna->prev null.

generic_netmap_dtor has a != NULL check, which will never fire in this case. AFAICT that needs to be == NULL instead, testing now.

[rbtcollins]

I'm keeping notes in https://gist.github.com/rbtcollins/8de642a5a5a0d87a6e904acc7437775e so I don't noisy-up the issue with my explorations.

[rbtcollins]

Still crashes with the check inverted, though it does actually release the adapter - I don't follow all the associated bits but I'm fairly sure its an improvement - #191

[rbtcollins]

So, this isn't a bad skbuff floating around:

[   41.929826] 085.603474 [3255] netmap_init               run mknod /dev/netmap c 10 53 # error 0
[   41.929871] netmap: loaded module
[   48.634575] 092.308191 [1190] generic_netmap_attach     Created generic NA ffff8801f93ca800 (prev
(null))
[   48.665975] 092.339622 [2013] netmap_do_regif           lut ffffc90000ffe000 bufs 163840 size 2048
[   48.666022] 092.339668 [ 390] generic_netmap_register   Generic adapter ffff8801f93ca800 goes on
[   48.666069] 092.339713 [ 476] generic_qdisc_init        Qdisc #0 initialized with max_len = 1024
[   48.666107] 092.339749 [ 679] nm_os_catch_tx            Saving netdev_ops ffffffffc00820a0
[   50.369105] hv_balloon: Received INFO_TYPE_MAX_PAGE_CNT
[   50.369143] hv_balloon: Data Size is 8
[   57.676850] 101.350542 [1102] generic_netmap_dtor       Released generic NA ffff8801f93ca800
[   57.677541] 101.351198 [1118] generic_netmap_dtor       Restored native NA           (null)
[   58.534568] 102.208305 [ 326] linux_generic_rx_handler_common XXX: netmap NULL eth0
[   58.535427] 102.209120 [ 327] linux_generic_rx_handler_common Current netdev_ops ffff8801f93cad50
[   58.536342] BUG: unable to handle kernel NULL pointer dereference at           (null)

note the current netdev_ops pointer is not pointing at the original device netdev_ops anymore when the crash occurs, so we're not uninstalling the things - and there's nearly a second between the Restore and the crash, so its clearly not a sub-RCU race (at least, AFAICT).

[vmaffione]

Hi, I've reproduced the bug with

 #pkt-gen -i eth0^ -f ping -n 2

I've pushed a fix that works on my side. The missing resource release was due to incorrect processing of kring flags in the generic adapter. Can you give a try?

[rbtcollins]

Seems great. Thank you!.