[4.14rc6] suspicious nfs rcu dereference

From: Dave Jones
Date: Tue Oct 24 2017 - 22:23:13 EST


WARNING: suspicious RCU usage
4.14.0-rc6-think+ #2 Not tainted
-----------------------------
net/sunrpc/clnt.c:1206 suspicious rcu_dereference_check() usage!

other info that might help us debug this:


rcu_scheduler_active = 2, debug_locks = 1
2 locks held by kworker/2:0/9104:
#0:
(
"rpciod"
){+.+.}
, at: [<ffffffff8110102e>] process_one_work+0x66e/0xea0
#1:
(
(&task->u.tk_work)
){+.+.}
, at: [<ffffffff8110102e>] process_one_work+0x66e/0xea0

stack backtrace:
CPU: 2 PID: 9104 Comm: kworker/2:0 Not tainted 4.14.0-rc6-think+ #2
Workqueue: rpciod rpc_async_schedule [sunrpc]
Call Trace:
dump_stack+0xbc/0x145
? dma_virt_map_sg+0xfb/0xfb
? lockdep_rcu_suspicious+0xda/0x100
rpc_peeraddr2str+0x11a/0x130 [sunrpc]
? call_start+0x1e0/0x1e0 [sunrpc]
perf_trace_nfs4_clientid_event+0xde/0x420 [nfsv4]
? do_raw_spin_unlock+0x147/0x220
? save_trace+0x1c0/0x1c0
? perf_trace_nfs4_open_event+0x5f0/0x5f0 [nfsv4]
? nfs41_sequence_process+0xba/0x5a0 [nfsv4]
? _raw_spin_unlock+0x24/0x30
? nfs41_sequence_free_slot.isra.47+0x143/0x230 [nfsv4]
? __lock_is_held+0x51/0xd0
nfs41_sequence_call_done+0x29a/0x430 [nfsv4]
? perf_trace_nfs4_open_event+0x5f0/0x5f0 [nfsv4]
? nfs4_proc_unlink_done+0xb0/0xb0 [nfsv4]
? __internal_add_timer+0x11b/0x170
? call_connect_status+0x490/0x490 [sunrpc]
? __lock_is_held+0x51/0xd0
? call_decode+0x33f/0xdd0 [sunrpc]
? nfs4_proc_unlink_done+0xb0/0xb0 [nfsv4]
? rpc_make_runnable+0x180/0x180 [sunrpc]
rpc_exit_task+0x61/0x100 [sunrpc]
? rpc_make_runnable+0x180/0x180 [sunrpc]
__rpc_execute+0x1c8/0x9e0 [sunrpc]
? rpc_wake_up_queued_task+0x40/0x40 [sunrpc]
? lock_downgrade+0x310/0x310
? match_held_lock+0xa6/0x410
? sched_clock_cpu+0x14/0xf0
? sched_clock_cpu+0x14/0xf0
? save_trace+0x1c0/0x1c0
? lock_acquire+0x12e/0x350
? lock_acquire+0x12e/0x350
? process_one_work+0x66e/0xea0
? lock_release+0x890/0x890
? do_raw_spin_trylock+0x100/0x100
? __lock_is_held+0x51/0xd0
process_one_work+0x766/0xea0
? pwq_dec_nr_in_flight+0x1e0/0x1e0
? preempt_notifier_dec+0x20/0x20
? __schedule+0x5cc/0x1310
? __sched_text_start+0x8/0x8
? match_held_lock+0x93/0x410
? save_trace+0x1c0/0x1c0
? native_sched_clock+0xf9/0x1a0
? cyc2ns_read_end+0x10/0x10
? cyc2ns_read_end+0x10/0x10
? find_held_lock+0x74/0xd0
? lock_contended+0x790/0x790
? lock_release+0x890/0x890
? do_raw_spin_unlock+0x147/0x220
? do_raw_spin_trylock+0x100/0x100
? retint_kernel+0x10/0x10
? do_raw_spin_trylock+0xb3/0x100
? do_raw_spin_lock+0x110/0x110
? mark_held_locks+0x1b/0xa0
worker_thread+0x1cf/0xcf0
? do_raw_spin_unlock+0x147/0x220
? do_raw_spin_trylock+0x100/0x100
? process_one_work+0xea0/0xea0
? get_vtime_delta+0x13/0x80
? mark_held_locks+0x1b/0xa0
? trace_hardirqs_on_caller+0x17a/0x250
? _raw_spin_unlock_irq+0x29/0x40
? finish_task_switch+0x183/0x470
? finish_task_switch+0x101/0x470
? preempt_notifier_dec+0x20/0x20
? __schedule+0x5cc/0x1310
? try_to_wake_up+0xe7/0xbb0
? save_stack+0x32/0xb0
? kasan_kmalloc+0xa0/0xd0
? native_sched_clock+0xf9/0x1a0
? ret_from_fork+0x27/0x40
? sched_clock_cpu+0x14/0xf0
? sched_clock_cpu+0x14/0xf0
? lock_downgrade+0x310/0x310
? __schedule+0x1310/0x1310
? do_raw_spin_unlock+0x147/0x220
? do_raw_spin_trylock+0x100/0x100
? do_raw_spin_lock+0x110/0x110
? __init_waitqueue_head+0xbe/0xf0
? mark_held_locks+0x1b/0xa0
? _raw_spin_unlock_irqrestore+0x32/0x50
? process_one_work+0xea0/0xea0
kthread+0x1c9/0x1f0
? kthread_create_on_node+0xc0/0xc0
ret_from_fork+0x27/0x40