Page 1 of 1

RCU lockdep warning from gr_log_mount() in 4.4.18-grsec

PostPosted: Thu Aug 18, 2016 2:16 pm
by eswierk
Running the latest stable kernel 4.4.18 with CONFIG_GRKERNSEC_AUDIT_MOUNT=y, I'm getting an RCU lockdep warning on every mount() syscall:

Code: Select all
[   16.171642] [ INFO: suspicious RCU usage. ]
[   16.171756] 4.4.18-grsec #1 Not tainted
[   16.171869] -------------------------------
[   16.171981] kernel/include/linux/rcupdate.h:560 Illegal context switch in RCU read-side critical section!
[   16.172228]
[   16.172228] other info that might help us debug this:
[   16.172228]
[   16.172413]
[   16.172413] rcu_scheduler_active = 1, debug_locks = 0
[   16.172563] 4 locks held by mount/214:
[   16.172674]  #0:  (rcu_read_lock){......}, at: [<gr_log_varargs at grsec_log.c:142>] ffffffff813e3920
[   16.173214]  #1:  (tasklist_lock){.+.+..}, at: [<gr_log_varargs at grsec_log.c:157 (discriminator 4)>] ffffffff813e39c2
[   16.173700]  #2:  (grsec_exec_file_lock){++++..}, at: [<gr_log_varargs at grsec_log.c:157 (discriminator 4)>] ffffffff813e39ce
[   16.174189]  #3:  (grsec_audit_lock){+.+...}, at: [<gr_log_varargs at grsec_log.c:52>] ffffffff813e39e3
[   16.174723]
[   16.174723] stack backtrace:
[   16.174867] CPU: 0 PID: 214 Comm: mount Not tainted 4.4.18-grsec #1
[   16.174991] Hardware name: Intel Corporation S2600GZ/S2600GZ, BIOS SE5C600.86B.02.03.0003.041920141333 04/19/2014
[   16.175158]  0000000000000000 ffffc90006923b08 ffffffff813ecbd8 0000000000000011
[   16.175579]  ffff88048b940000 0000000000000001 ffffc90006923b38 ffffffff810d53d7
[   16.175998]  0000000000000000 ffffffff81af21e0 00000000000002f5 0000000000001000
[   16.176483] Call Trace:
[   16.176599]  [<dump_stack at dump_stack.c:53>] dump_stack+0x9a/0xe2
[   16.176720]  [<lockdep_rcu_suspicious at lockdep.c:4303>] lockdep_rcu_suspicious+0xd7/0x110
[   16.176846]  [<___might_sleep at rcupdate.h:559>] ___might_sleep+0xa2/0x220
[   16.176966]  [<__might_sleep at core.c:7578 (discriminator 14)>] __might_sleep+0x44/0x80
[   16.177088]  [<dput at dcache.c:757>] dput+0x37/0x3e0
[   16.177206]  [<path_put at namei.c:498>] path_put+0x11/0x20
[   16.177324]  [<d_real_path at gracl.c:315>] d_real_path+0xfe/0x110
[   16.177443]  [<gr_to_filename at gracl.c:363>] ? gr_to_filename+0x26/0x30
[   16.177562]  [<gr_to_filename at gracl.c:363>] gr_to_filename+0x26/0x30
[   16.177681]  [<gr_log_varargs at grsec_log.c:214 (discriminator 4)>] gr_log_varargs+0x148c/0x2b80
[   16.177846]  [<gr_log_varargs at grsec_log.c:142>] ? gr_log_middle_varargs+0x80/0x80
[   16.177968]  [<mark_held_locks at lockdep.c:2541>] ? mark_held_locks+0x79/0xa0
[   16.178094]  [<_raw_spin_unlock_irqrestore at paravirt.h:839>] ? _raw_spin_unlock_irqrestore+0x31/0x70
[   16.178223]  [<attach_recursive_mnt at namespace.c:1956>] ? attach_recursive_mnt+0x145/0x280
[   16.178347]  [<xen_clocksource_read at preempt.h:74>] ? xen_clocksource_read+0x1c/0x30
[   16.178472]  [<mutex_unlock at mutex.c:438>] ? mutex_unlock+0x9/0x10
[   16.178589]  [<xen_clocksource_read at preempt.h:74>] ? xen_clocksource_read+0x1c/0x30
[   16.178714]  [<sched_clock at paravirt.h:189>] ? sched_clock+0x13/0x20
[   16.178834]  [<local_clock at clock.c:392>] ? local_clock+0x1c/0x20
[   16.178953]  [<lock_release at lockdep.c:3613>] ? lock_release+0x314/0x680
[   16.179072]  [<lock_release at lockdep.c:3613>] ? lock_release+0x314/0x680
[   16.179192]  [<__raw_callee_save___pv_queued_spin_unlock at ??:?>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[   16.179392]  [<trace_hardirqs_on_caller at lockdep.c:2570>] ? trace_hardirqs_on_caller+0x13d/0x1d0
[   16.179516]  [<mutex_unlock at mutex.c:438>] ? mutex_unlock+0x9/0x10
[   16.179635]  [<gr_log_mount at grsec_mount.c:36>] gr_log_mount+0x3a/0x40
[   16.179753]  [<do_mount at namespace.c:2749>] do_mount+0x9c/0xdb0
[   16.179875]  [<__check_object_size.part.38 at exec.c:2203>] ? __check_object_size.part.38+0x2f/0x1d0
[   16.179999]  [<__check_object_size at exec.c:2217>] ? __check_object_size+0x15/0x20
[   16.180137]  [<sys_mount at namespace.c:2941>] SyS_mount+0x86/0xd0
[   16.180258]  [<entry_SYSCALL_64_fastpath at entry_64.S:596>] entry_SYSCALL_64_fastpath+0x16/0x7e
[   16.180407] BUG: sleeping function called from invalid context at kernel/fs/dcache.c:757
[   16.180581] in_atomic(): 1, irqs_disabled(): 0, pid: 214, name: mount
[   16.180701] INFO: lockdep is turned off.


Any clues?

Re: RCU lockdep warning from gr_log_mount() in 4.4.18-grsec

PostPosted: Thu Aug 18, 2016 5:17 pm
by spender
For now, just remove the might_sleep() that was added to dput() in fs/dcache.c We would never have triggered the branch of the code that would sleep (dput sleeps in the case where the reference count drops to 0 and it needs to hold a contentious lock in order to free the dentry safely) in that function due to only calling dput() on the filesystem root under a lock. Working around this warning that's erroneous in our case will require reworking several of our APIs, so simply removing the might_sleep() is the best option for now, and I'll have a more comprehensive fix in a few days.

-Brad