We enable RCU and lock debugging options of the Linux kernel.
And run TestPaging with this debug kernel.
We see some RCU and lock warnings.
[ 275.088296] [gtp5g] gtp5g_encap_enable_socket: enable gtp5g for the fd(11) type(5)
[ 275.095202] upfgtp:[gtp5g] gtp5g_newlink: Registered a new 5G GTP interface
[ 320.641030] =============================
[ 320.641032] WARNING: suspicious RCU usage
[ 320.641037] 5.4.157 #1 Tainted: G OE
[ 320.641040] -----------------------------
[ 320.641043] include/linux/rcupdate.h:274 Illegal context switch in RCU read-side critical section!
[ 320.641046]
other info that might help us debug this:
[ 320.641049]
rcu_scheduler_active = 2, debug_locks = 1
[ 320.641053] 4 locks held by free5gc-upfd/7884:
[ 320.641055] #0: ffffffff9a6e8af8 (cb_lock){++++}, at: genl_rcv+0x1a/0x40
[ 320.641070] #1: ffffffff9a6e8bb0 (genl_mutex){+.+.}, at: genl_rcv_msg+0x6d/0xa0
[ 320.641077] #2: ffffffff9a6cca50 (rtnl_mutex){+.+.}, at: rtnl_lock+0x17/0x20
[ 320.641087] #3: ffffffff9a4a13a0 (rcu_read_lock){....}, at: gtp5g_genl_add_far+0x26/0x1b0 [gtp5g]
[ 320.641102]
stack backtrace:
[ 320.641107] CPU: 0 PID: 7884 Comm: free5gc-upfd Kdump: loaded Tainted: G OE 5.4.157 #1
[ 320.641110] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
[ 320.641113] Call Trace:
[ 320.641124] dump_stack+0x98/0xd2
[ 320.641133] lockdep_rcu_suspicious+0xeb/0xf5
[ 320.641143] ___might_sleep+0x113/0x1a0
[ 320.641148] __might_sleep+0x4b/0x80
[ 320.641158] apparmor_socket_create+0x58/0x2d0
[ 320.641167] security_socket_create+0x3d/0x60
[ 320.641175] __sock_create+0x69/0x350
[ 320.641184] sock_create+0x34/0x40
[ 320.641190] unix_sock_client_update+0x74/0x170 [gtp5g]
[ 320.641199] far_fill.isra.0+0x39f/0x700 [gtp5g]
[ 320.641205] ? seid_and_u32id_to_hex_str+0xc1/0x170 [gtp5g]
[ 320.641220] gtp5g_gnl_add_far+0xd5/0x770 [gtp5g]
[ 320.641233] ? gtp5g_genl_add_far+0x26/0x1b0 [gtp5g]
[ 320.641246] gtp5g_genl_add_far+0x8c/0x1b0 [gtp5g]
[ 320.641252] genl_family_rcv_msg+0x1b9/0x480
[ 320.641257] ? genl_rcv_msg+0x6d/0xa0
[ 320.641273] genl_rcv_msg+0x4c/0xa0
[ 320.641277] ? genl_family_rcv_msg+0x480/0x480
[ 320.641282] netlink_rcv_skb+0x50/0x120
[ 320.641291] genl_rcv+0x29/0x40
[ 320.641296] netlink_unicast+0x187/0x220
[ 320.641304] netlink_sendmsg+0x238/0x3f0
[ 320.641315] sock_sendmsg+0x65/0x70
[ 320.641320] __sys_sendto+0x116/0x1a0
[ 320.641336] ? _raw_spin_unlock_irq+0x2d/0x40
[ 320.641344] ? lockdep_hardirqs_on+0xfb/0x190
[ 320.641353] ? trace_hardirqs_off_caller+0x17/0xe0
[ 320.641357] ? lockdep_hardirqs_on+0xfb/0x190
[ 320.641365] __x64_sys_sendto+0x29/0x30
[ 320.641373] do_syscall_64+0x5f/0x230
[ 320.641378] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 320.641382] RIP: 0033:0x7f36c84c2844
[ 320.641386] Code: c2 f7 ff ff 44 8b 4c 24 2c 4c 8b 44 24 20 89 c5 44 8b 54 24 28 48 8b 54 24 18 b8 2c 00 00 00 48 8b 74 24 10 8b 7c 24 08 0f 05 <48> 3d 00 f0 ff ff 77 30 89 ef 48 89 44 24 08 e8 e8 f7 ff ff 48 8b
[ 320.641389] RSP: 002b:00007ffd61f4acc0 EFLAGS: 00000293 ORIG_RAX: 000000000000002c
[ 320.641392] RAX: ffffffffffffffda RBX: 0000000000001000 RCX: 00007f36c84c2844
[ 320.641395] RDX: 0000000000000054 RSI: 00007ffd61f4bd90 RDI: 000000000000000e
[ 320.641397] RBP: 0000000000000000 R08: 00007f36c82ab9e0 R09: 000000000000000c
[ 320.641399] R10: 0000000000000000 R11: 0000000000000293 R12: 00007ffd61f4bd00
[ 320.641401] R13: 0000000000000000 R14: 0000000000001000 R15: 0000000000000000
[ 320.641418] BUG: sleeping function called from invalid context at security/apparmor/include/cred.h:164
[ 320.641562] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 7884, name: free5gc-upfd
[ 320.641626] 4 locks held by free5gc-upfd/7884:
[ 320.641629] #0: ffffffff9a6e8af8 (cb_lock){++++}, at: genl_rcv+0x1a/0x40
[ 320.641636] #1: ffffffff9a6e8bb0 (genl_mutex){+.+.}, at: genl_rcv_msg+0x6d/0xa0
[ 320.641643] #2: ffffffff9a6cca50 (rtnl_mutex){+.+.}, at: rtnl_lock+0x17/0x20
[ 320.641650] #3: ffffffff9a4a13a0 (rcu_read_lock){....}, at: gtp5g_genl_add_far+0x26/0x1b0 [gtp5g]
[ 320.641660] CPU: 0 PID: 7884 Comm: free5gc-upfd Kdump: loaded Tainted: G OE 5.4.157 #1
[ 320.641663] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
[ 320.641665] Call Trace:
[ 320.641670] dump_stack+0x98/0xd2
[ 320.641675] ___might_sleep.cold+0xb3/0xc4
[ 320.641681] __might_sleep+0x4b/0x80
[ 320.641687] apparmor_socket_create+0x58/0x2d0
[ 320.641695] security_socket_create+0x3d/0x60
[ 320.641702] __sock_create+0x69/0x350
[ 320.641710] sock_create+0x34/0x40
[ 320.641717] unix_sock_client_update+0x74/0x170 [gtp5g]
[ 320.641725] far_fill.isra.0+0x39f/0x700 [gtp5g]
[ 320.641732] ? seid_and_u32id_to_hex_str+0xc1/0x170 [gtp5g]
[ 320.641746] gtp5g_gnl_add_far+0xd5/0x770 [gtp5g]
[ 320.641759] ? gtp5g_genl_add_far+0x26/0x1b0 [gtp5g]
[ 320.641772] gtp5g_genl_add_far+0x8c/0x1b0 [gtp5g]
[ 320.641778] genl_family_rcv_msg+0x1b9/0x480
[ 320.641784] ? genl_rcv_msg+0x6d/0xa0
[ 320.641799] genl_rcv_msg+0x4c/0xa0
[ 320.641803] ? genl_family_rcv_msg+0x480/0x480
[ 320.641808] netlink_rcv_skb+0x50/0x120
[ 320.641818] genl_rcv+0x29/0x40
[ 320.641822] netlink_unicast+0x187/0x220
[ 320.641830] netlink_sendmsg+0x238/0x3f0
[ 320.641841] sock_sendmsg+0x65/0x70
[ 320.641846] __sys_sendto+0x116/0x1a0
[ 320.641862] ? _raw_spin_unlock_irq+0x2d/0x40
[ 320.641866] ? lockdep_hardirqs_on+0xfb/0x190
[ 320.641871] ? trace_hardirqs_off_caller+0x17/0xe0
[ 320.641876] ? lockdep_hardirqs_on+0xfb/0x190
[ 320.641883] __x64_sys_sendto+0x29/0x30
[ 320.641887] do_syscall_64+0x5f/0x230
[ 320.641892] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 320.641895] RIP: 0033:0x7f36c84c2844
[ 320.641898] Code: c2 f7 ff ff 44 8b 4c 24 2c 4c 8b 44 24 20 89 c5 44 8b 54 24 28 48 8b 54 24 18 b8 2c 00 00 00 48 8b 74 24 10 8b 7c 24 08 0f 05 <48> 3d 00 f0 ff ff 77 30 89 ef 48 89 44 24 08 e8 e8 f7 ff ff 48 8b
[ 320.641900] RSP: 002b:00007ffd61f4acc0 EFLAGS: 00000293 ORIG_RAX: 000000000000002c
[ 320.641903] RAX: ffffffffffffffda RBX: 0000000000001000 RCX: 00007f36c84c2844
[ 320.641906] RDX: 0000000000000054 RSI: 00007ffd61f4bd90 RDI: 000000000000000e
[ 320.641908] RBP: 0000000000000000 R08: 00007f36c82ab9e0 R09: 000000000000000c
[ 320.641910] R10: 0000000000000000 R11: 0000000000000293 R12: 00007ffd61f4bd00
[ 320.641912] R13: 0000000000000000 R14: 0000000000001000 R15: 0000000000000000
[ 321.739723] =============================
[ 321.739725] WARNING: suspicious RCU usage
[ 321.739730] 5.4.157 #1 Tainted: G W OE
[ 321.739732] -----------------------------
[ 321.739736] kernel/sched/core.c:6854 Illegal context switch in RCU-bh read-side critical section!
[ 321.739738]
other info that might help us debug this:
[ 321.739740]
rcu_scheduler_active = 2, debug_locks = 1
[ 321.739744] 3 locks held by nc/7977:
[ 321.739746] #0: ffffffff9a4a1360 (rcu_read_lock_bh){....}, at: ip_finish_output2+0xa5/0xa20
[ 321.739761] #1: ffffffff9a4a1360 (rcu_read_lock_bh){....}, at: __dev_queue_xmit+0x72/0xde0
[ 321.739771] #2: ffffffff9a4a13a0 (rcu_read_lock){....}, at: gtp5g_dev_xmit+0x8a/0x4b0 [gtp5g]
[ 321.739786]
stack backtrace:
[ 321.739790] CPU: 3 PID: 7977 Comm: nc Kdump: loaded Tainted: G W OE 5.4.157 #1
[ 321.739793] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
[ 321.739796] Call Trace:
[ 321.739808] dump_stack+0x98/0xd2
[ 321.739816] lockdep_rcu_suspicious+0xeb/0xf5
[ 321.739826] ___might_sleep+0x150/0x1a0
[ 321.739831] __might_sleep+0x4b/0x80
[ 321.739841] kmem_cache_alloc_trace+0x292/0x360
[ 321.739847] ? unix_sock_send+0x92/0x1e0 [gtp5g]
[ 321.739858] unix_sock_send+0x92/0x1e0 [gtp5g]
[ 321.739875] gtp5g_dev_xmit+0x38f/0x4b0 [gtp5g]
[ 321.739882] ? __lock_acquire+0x258/0x1990
[ 321.739898] dev_hard_start_xmit+0xa8/0x2e0
[ 321.739908] __dev_queue_xmit+0xac3/0xde0
[ 321.739914] ? ___neigh_create+0x76d/0xb50
[ 321.739925] dev_queue_xmit+0x10/0x20
[ 321.739929] ? dev_queue_xmit+0x10/0x20
[ 321.739933] neigh_direct_output+0x11/0x20
[ 321.739937] ip_finish_output2+0x21e/0xa20
[ 321.739943] ? __cgroup_bpf_run_filter_skb+0x489/0x640
[ 321.739952] __ip_finish_output+0x136/0x3e0
[ 321.739955] ? __ip_finish_output+0x136/0x3e0
[ 321.739962] ip_finish_output+0x2d/0xb0
[ 321.739968] ip_output+0x7c/0x250
[ 321.739975] ? __ip_finish_output+0x3e0/0x3e0
[ 321.739982] ip_local_out+0x41/0x70
[ 321.739988] ip_send_skb+0x19/0x40
[ 321.739994] udp_send_skb.isra.0+0x258/0x3c0
[ 321.740003] udp_sendmsg+0xbd4/0x1040
[ 321.740009] ? ip_reply_glue_bits+0x50/0x50
[ 321.740020] ? __lock_acquire+0x258/0x1990
[ 321.740031] ? __might_sleep+0x4b/0x80
[ 321.740039] ? debug_lockdep_rcu_enabled+0x1d/0x20
[ 321.740048] ? aa_sk_perm+0x7b/0x2b0
[ 321.740056] inet_sendmsg+0x65/0x70
[ 321.740060] ? inet_sendmsg+0x65/0x70
[ 321.740067] sock_sendmsg+0x5e/0x70
[ 321.740072] sock_write_iter+0x96/0xf0
[ 321.740085] new_sync_write+0x128/0x1c0
[ 321.740099] __vfs_write+0x29/0x40
[ 321.740103] vfs_write+0xe1/0x1d0
[ 321.740110] ksys_write+0x70/0xf0
[ 321.740117] __x64_sys_write+0x1a/0x20
[ 321.740126] do_syscall_64+0x5f/0x230
[ 321.740132] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 321.740137] RIP: 0033:0x7f5afeea61e7
[ 321.740140] Code: 64 89 02 48 c7 c0 ff ff ff ff eb bb 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 321.740143] RSP: 002b:00007ffd3025ded8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 321.740147] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f5afeea61e7
[ 321.740149] RDX: 0000000000000005 RSI: 00007ffd30261f40 RDI: 0000000000000003
[ 321.740151] RBP: 00007ffd3025df18 R08: 0000000000000000 R09: 0000000000000000
[ 321.740153] R10: 0000000000000001 R11: 0000000000000246 R12: 0000000000000005
[ 321.740156] R13: 00007ffd30261f40 R14: 0000000000000003 R15: 0000000000000005
[ 321.740172] BUG: sleeping function called from invalid context at mm/slab.h:565
[ 321.740273] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 7977, name: nc
[ 321.740331] 3 locks held by nc/7977:
[ 321.740333] #0: ffffffff9a4a1360 (rcu_read_lock_bh){....}, at: ip_finish_output2+0xa5/0xa20
[ 321.740340] #1: ffffffff9a4a1360 (rcu_read_lock_bh){....}, at: __dev_queue_xmit+0x72/0xde0
[ 321.740346] #2: ffffffff9a4a13a0 (rcu_read_lock){....}, at: gtp5g_dev_xmit+0x8a/0x4b0 [gtp5g]
[ 321.740356] CPU: 3 PID: 7977 Comm: nc Kdump: loaded Tainted: G W OE 5.4.157 #1
[ 321.740358] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 09/21/2015
[ 321.740360] Call Trace:
[ 321.740365] dump_stack+0x98/0xd2
[ 321.740371] ___might_sleep.cold+0xb3/0xc4
[ 321.740377] __might_sleep+0x4b/0x80
[ 321.740383] kmem_cache_alloc_trace+0x292/0x360
[ 321.740389] ? unix_sock_send+0x92/0x1e0 [gtp5g]
[ 321.740400] unix_sock_send+0x92/0x1e0 [gtp5g]
[ 321.740417] gtp5g_dev_xmit+0x38f/0x4b0 [gtp5g]
[ 321.740421] ? __lock_acquire+0x258/0x1990
[ 321.740437] dev_hard_start_xmit+0xa8/0x2e0
[ 321.740447] __dev_queue_xmit+0xac3/0xde0
[ 321.740451] ? ___neigh_create+0x76d/0xb50
[ 321.740462] dev_queue_xmit+0x10/0x20
[ 321.740466] ? dev_queue_xmit+0x10/0x20
[ 321.740470] neigh_direct_output+0x11/0x20
[ 321.740474] ip_finish_output2+0x21e/0xa20
[ 321.740477] ? __cgroup_bpf_run_filter_skb+0x489/0x640
[ 321.740486] __ip_finish_output+0x136/0x3e0
[ 321.740490] ? __ip_finish_output+0x136/0x3e0
[ 321.740497] ip_finish_output+0x2d/0xb0
[ 321.740503] ip_output+0x7c/0x250
[ 321.740510] ? __ip_finish_output+0x3e0/0x3e0
[ 321.740517] ip_local_out+0x41/0x70
[ 321.740523] ip_send_skb+0x19/0x40
[ 321.740528] udp_send_skb.isra.0+0x258/0x3c0
[ 321.740536] udp_sendmsg+0xbd4/0x1040
[ 321.740542] ? ip_reply_glue_bits+0x50/0x50
[ 321.740553] ? __lock_acquire+0x258/0x1990
[ 321.740564] ? __might_sleep+0x4b/0x80
[ 321.740569] ? debug_lockdep_rcu_enabled+0x1d/0x20
[ 321.740573] ? aa_sk_perm+0x7b/0x2b0
[ 321.740581] inet_sendmsg+0x65/0x70
[ 321.740585] ? inet_sendmsg+0x65/0x70
[ 321.740590] sock_sendmsg+0x5e/0x70
[ 321.740595] sock_write_iter+0x96/0xf0
[ 321.740607] new_sync_write+0x128/0x1c0
[ 321.740620] __vfs_write+0x29/0x40
[ 321.740624] vfs_write+0xe1/0x1d0
[ 321.740631] ksys_write+0x70/0xf0
[ 321.740638] __x64_sys_write+0x1a/0x20
[ 321.740643] do_syscall_64+0x5f/0x230
[ 321.740648] entry_SYSCALL_64_after_hwframe+0x49/0xbe
[ 321.740651] RIP: 0033:0x7f5afeea61e7
[ 321.740654] Code: 64 89 02 48 c7 c0 ff ff ff ff eb bb 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[ 321.740656] RSP: 002b:00007ffd3025ded8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 321.740660] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f5afeea61e7
[ 321.740662] RDX: 0000000000000005 RSI: 00007ffd30261f40 RDI: 0000000000000003
[ 321.740664] RBP: 00007ffd3025df18 R08: 0000000000000000 R09: 0000000000000000
[ 321.740666] R10: 0000000000000001 R11: 0000000000000246 R12: 0000000000000005
[ 321.740668] R13: 00007ffd30261f40 R14: 0000000000000003 R15: 0000000000000005
[ 334.951468] upfgtp:[gtp5g] gtp5g_dellink: De-registered 5G GTP interface