WARNING: suspicious RCU usage in netem

WARNING: suspicious RCU usage in netem_enqueue
Status: upstream: reported C repro on 2019/09/27 08:42
Reported-by: syzbot+9ea180ba12a5c1098b92@syzkaller.appspotmail.com
First crash: 48d, last: 25d

similar bugs (2):
Kernel	Title	Repro	Bisected	Count	Last	Reported	Patched	Status
upstream	WARNING: suspicious RCU usage in netem_enqueue	C	cause	16	48d	62d	14/14	fixed on 2019/10/15 23:40
linux-4.19	WARNING: suspicious RCU usage in netem_enqueue	C		2	46d	51d	0/1	upstream: reported C repro on 2019/09/24 09:38

Sample crash report:

netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
=============================
WARNING: suspicious RCU usage
4.14.146 #0 Not tainted
-----------------------------
./include/net/sch_generic.h:303 suspicious rcu_dereference_check() usage!

other info that might help us debug this:


rcu_scheduler_active = 2, debug_locks = 1
3 locks held by syz-executor107/6888:
 #0:  (rcu_read_lock_bh){....}, at: [<ffffffff8520d2b6>] lwtunnel_xmit_redirect include/net/lwtunnel.h:92 [inline]
 #0:  (rcu_read_lock_bh){....}, at: [<ffffffff8520d2b6>] ip_finish_output2+0x256/0x14a0 net/ipv4/ip_output.c:213
 #1:  (rcu_read_lock_bh){....}, at: [<ffffffff84d51762>] __dev_queue_xmit+0x1e2/0x25e0 net/core/dev.c:3459
 #2:  (&qdisc_tx_lock){+...}, at: [<ffffffff84d52740>] spin_lock include/linux/spinlock.h:317 [inline]
 #2:  (&qdisc_tx_lock){+...}, at: [<ffffffff84d52740>] __dev_xmit_skb net/core/dev.c:3204 [inline]
 #2:  (&qdisc_tx_lock){+...}, at: [<ffffffff84d52740>] __dev_queue_xmit+0x11c0/0x25e0 net/core/dev.c:3493

stack backtrace:
CPU: 1 PID: 6888 Comm: syz-executor107 Not tainted 4.14.146 #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0x138/0x197 lib/dump_stack.c:53
 lockdep_rcu_suspicious+0x153/0x15d kernel/locking/lockdep.c:4662
 qdisc_root include/net/sch_generic.h:303 [inline]
 netem_enqueue+0x79c/0x2780 net/sched/sch_netem.c:472
 __dev_xmit_skb net/core/dev.c:3229 [inline]
 __dev_queue_xmit+0x12da/0x25e0 net/core/dev.c:3493
 dev_queue_xmit+0x18/0x20 net/core/dev.c:3558
 neigh_hh_output include/net/neighbour.h:490 [inline]
 neigh_output include/net/neighbour.h:498 [inline]
 ip_finish_output2+0xddc/0x14a0 net/ipv4/ip_output.c:229
 ip_finish_output+0x56d/0xc60 net/ipv4/ip_output.c:317
 NF_HOOK_COND include/linux/netfilter.h:239 [inline]
 ip_mc_output+0x24a/0xd40 net/ipv4/ip_output.c:390
 dst_output include/net/dst.h:462 [inline]
 ip_local_out+0x97/0x170 net/ipv4/ip_output.c:124
 ip_send_skb+0x3e/0xc0 net/ipv4/ip_output.c:1418
 udp_send_skb+0x616/0xb90 net/ipv4/udp.c:833
 udp_sendmsg+0x16df/0x1da0 net/ipv4/udp.c:1057
 inet_sendmsg+0x122/0x500 net/ipv4/af_inet.c:762
 sock_sendmsg_nosec net/socket.c:646 [inline]
 sock_sendmsg+0xce/0x110 net/socket.c:656
 ___sys_sendmsg+0x349/0x840 net/socket.c:2062
 __sys_sendmmsg+0x152/0x3a0 net/socket.c:2152
 SYSC_sendmmsg net/socket.c:2183 [inline]
 SyS_sendmmsg+0x35/0x60 net/socket.c:2178
 do_syscall_64+0x1e8/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x4423e9
RSP: 002b:00007ffc6e5516f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000133
RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00000000004423e9
RDX: 04000000000001a8 RSI: 0000000020007fc0 RDI: 0000000000000005
RBP: 735f656764697262 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000403340 R14: 0000000000000000 R15: 0000000000000000
IPv6: ADDRCONF(NETDEV_CHANGE): bond0: link becomes ready
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
nla_parse: 398 callbacks suppressed
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.
nla_parse: 436 callbacks suppressed
netlink: 80 bytes leftover after parsing attributes in process `syz-executor107'.
netlink: 48 bytes leftover after parsing attributes in process `syz-executor107'.

Crashes (3):
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report	Syz repro	C repro	Maintainers
ci2-linux-4-14	2019/09/27 07:41	linux-4.14.y	f6e27dbb	2f1548bc	.config	log	report	syz	C	davem@davemloft.net, kuznet@ms2.inr.ac.ru, linux-kernel@vger.kernel.org, netdev@vger.kernel.org, yoshfuji@linux-ipv6.org
ci2-linux-4-14	2019/10/01 21:32	linux-4.14.y	f6e27dbb	b7a87a83	.config	log	report	syz	C	davem@davemloft.net, kuznet@ms2.inr.ac.ru, linux-kernel@vger.kernel.org, netdev@vger.kernel.org, yoshfuji@linux-ipv6.org
ci2-linux-4-14	2019/10/20 13:38	linux-4.14.y	b98aebd2	8c88c9c1	.config	log	report			linux-fsdevel@vger.kernel.org, linux-kernel@vger.kernel.org, viro@zeniv.linux.org.uk