audit: rcu_read_lock() used illegally while idle

Dave Jones
2014-12-03T18:19:36Z

I'm not sure why this only just started complaining, because this code
hasn't changed in years, but I don't recall seeing this before.
This gets spewed during bootup since I put 3.18-rc7 on my firewall.
Previously it was running rc4 where I didn't see this.

Did something in RCU change recently ?

===============================
[ INFO: suspicious RCU usage. ]
3.18.0-rc7+ #93 Not tainted
-------------------------------
include/linux/rcupdate.h:883 rcu_read_lock() used illegally while idle!

other info that might help us debug this:

RCU used illegally from idle CPU!
rcu_scheduler_active = 1, debug_locks = 0
RCU used illegally from extended quiescent state!
1 lock held by systemd-sysctl/557:
#0: (rcu_read_lock){......}, at: [<ffffffff890f1320>] audit_filter_type+0x0/0x240

stack backtrace:
CPU: 0 PID: 557 Comm: systemd-sysctl Not tainted 3.18.0-rc7+ #93
0000000000000000 0000000063c50efc ffff88021f51fd28 ffffffff895abec3
0000000000000000 ffff880234758000 ffff88021f51fd58 ffffffff890a5280
ffff880221d9c548 00007fd651f320d0 0000000000000514 00000000ffff9012
Call Trace:
[<ffffffff895abec3>] dump_stack+0x4e/0x68
[<ffffffff890a5280>] lockdep_rcu_suspicious+0xf0/0x110
[<ffffffff890f150e>] audit_filter_type+0x1ee/0x240
[<ffffffff890f1320>] ? audit_filter_user+0x340/0x340
[<ffffffff890ecd39>] audit_log_start+0x49/0x4a0
[<ffffffff8908f4f5>] ? local_clock+0x25/0x30
[<ffffffff890a397f>] ? lock_release_holdtime.part.30+0xf/0x190
[<ffffffff890f1973>] audit_log_exit+0x53/0xcf0
[<ffffffff8908f4f5>] ? local_clock+0x25/0x30
[<ffffffff890a397f>] ? lock_release_holdtime.part.30+0xf/0x190