Re: "cat /proc/lockdep" after "rmmod <some module>" when !debug_locks will crash the system

Re: "cat /proc/lockdep" after "rmmod <some module>" when !debug_locks will crash the system

[Bart Van Assche]

On Mon, 2019-03-25 at 17:45 +0800, shenghui wrote:
> Sorry to trouble you.
> 
> I installed virtualbox-5.2.24 on my system (x86 32) and on bootup I got some warning:
> ---------------------
> 1251 [   42.640869] DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled)
> 1252 [   42.640880] WARNING: CPU: 0 PID: 841 at kernel/locking/lockdep.c:4132 check_flags.part.45+0x9e/0x190
> ...
> 
> As no crash afterwards, I just ignore the warning and continue using my system.
> 
> Later I rmmod some module and run "cat /proc/lockdep", the system crashed. 
> (Sorry I cannot capture the crash log as kdump didn't work on my system, but I can 
> see some words "...normal kernel read fault...")
> 
> 
> Then I walked through the code and found:
> 1) DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled) will turn debug_locks to 0
> 2) if !debug_locks, graph_lock() will return 0
> 3) On module unloading, lockdep_free_key_range_reg() will run.
>    But when !debug_locks, lockdep_free_key_range_reg() will do nothing.
> 
> 4743 static void lockdep_free_key_range_reg(void *start, unsigned long size)
> 4744 {
> ...
> 4751     raw_local_irq_save(flags);
> 4752     locked = graph_lock();
> 4753     if (!locked)
> 4754         goto out_irq;
> ...
> 4759 
> 4760     graph_unlock();
> 4761 out_irq:
> 4762     raw_local_irq_restore(flags);
> 
> 4) The result is: module is unloaded, but some lock_class related with the module
>    still exist in all_lock_classes.
> 5) 'cat /proc/lockdep' will access elements of all_lock_classes, and will trigger the crash.
> 
> 
> Seems the usage of "!graph_lock()" can prevent any new changes to all_lock_classes and other hashtables
> if !debug_locks.

Hi Shenghui,

None of the rmmod / cat /proc/lockdep tests I ran triggered the above warning.
It would help if you could share the steps you followed to trigger that warning.

Thanks,

Bart.

Re: "cat /proc/lockdep" after "rmmod <some module>" when !debug_locks will crash the system

[Bart Van Assche]

On Mon, 2019-03-25 at 17:45 +0800, shenghui wrote:
> I installed virtualbox-5.2.24 on my system (x86 32) and on bootup I got some warning:
> ---------------------
> 1251 [   42.640869] DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled)
> 1252 [   42.640880] WARNING: CPU: 0 PID: 841 at kernel/locking/lockdep.c:4132 check_flags.part.45+0x9e/0x190
> ...

Hi Shenghui,

That warning should have been followed by a call trace. Please share that
call trace.

Thanks,

Bart.

Re: "cat /proc/lockdep" after "rmmod <some module>" when !debug_locks will crash the system

[Bart Van Assche]

On 3/25/19 5:27 PM, shenghui wrote:
> On 3/26/19 1:06 AM, Bart Van Assche wrote:
>> On Mon, 2019-03-25 at 17:45 +0800, shenghui wrote:
> [   47.103637] vboxdrv: loading out-of-tree module taints kernel.
> [   47.111919] vboxdrv: Found 2 processor cores
> [   47.119013] vboxdrv: fAsync=0 offMin=0x2ee offMax=0x13f7
 > [ ...........] ...
 > [   47.219043] DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled)
 > [   47.219055] WARNING: CPU: 0 PID: 844 at 
kernel/locking/lockdep.c:4142 check_flags.part.45+0x9e/0x190
> [   47.219142] Call Trace:
> [   47.219148]  lock_acquire+0x3a/0x150
> [   47.219153]  fs_reclaim_acquire.part.106+0x21/0x30
> [   47.219156]  ? fs_reclaim_acquire.part.106+0x5/0x30
> [   47.219159]  fs_reclaim_acquire+0x1d/0x20
> [   47.219163]  __kmalloc+0x4d/0x280
> [   47.219192]  ? rtR0MemAllocEx+0xaf/0x110 [vboxdrv]
> [   47.219210]  ? supdrvGipInitMeasureTscFreq+0x15c/0x460 [vboxdrv]
> [   47.219229]  rtR0MemAllocEx+0xaf/0x110 [vboxdrv]
> [   47.219247]  ? supdrvTscDeltaThreadStartMeasurement.part.5+0x80/0x80 [vboxdrv]
> [   47.219265]  VBoxHost_RTMemAllocTag+0x23/0x50 [vboxdrv]
> [   47.219284]  VBoxHost_RTMpNotificationRegister+0x97/0x170 [vboxdrv]

Hi Shenghui,

I have not found the VBoxHost_RTMpNotificationRegister function name 
anywhere in the kernel tree. I think that means that this warning is 
generated by an out-of-tree driver. Please report this issue to the 
virtualbox maintainers as a kernel v5.1 interoperability bug.

Thanks,

Bart.

Re: "cat /proc/lockdep" after "rmmod <some module>" when !debug_locks will crash the system

[Bart Van Assche]

On Tue, 2019-03-26 at 08:35 +0800, shenghui wrote:
> My test steps:
> --------------
> 1) bootup the system, and check the calltrace in dmesg. Just warning and ignore it.
> 2) cat /proc/lockdep   # everything is well
> 3) rmmod some module which provides lock_class in lockdep
>    In my system, module bcache is used:  ('grep bcache /proc/lockdep' prints something)
>         * stop bcache set
>         * rmmod bcache
>    I have tried other module, e.g: rmmod iwldvm
> 4) cat /proc/lockdep   # system crash

Hi shenghui,

Thank you for having shared your test steps. I ran a slightly different test
myself:

while true; do cat /proc/lockdep >/dev/null; done &
(cd blktests && while ./check -q; do :; done)

This test reads /proc/lockdep in a loop while running a test that stresses
lockdep and also that loads and unloads kernel modules. Since this test
passed on my setup I suggest that you have a close look at your setup. The
vboxdrv kernel driver or an out-of-tree patch may be what is making your
system unstable.

Bart.

Re: "cat /proc/lockdep" after "rmmod <some module>" when !debug_locks will crash the system

[Bart Van Assche]

On Tue, 2019-03-26 at 10:44 -0700, Bart Van Assche wrote:
> On Tue, 2019-03-26 at 08:35 +0800, shenghui wrote:
> > My test steps:
> > --------------
> > 1) bootup the system, and check the calltrace in dmesg. Just warning and ignore it.
> > 2) cat /proc/lockdep   # everything is well
> > 3) rmmod some module which provides lock_class in lockdep
> >    In my system, module bcache is used:  ('grep bcache /proc/lockdep' prints something)
> >         * stop bcache set
> >         * rmmod bcache
> >    I have tried other module, e.g: rmmod iwldvm
> > 4) cat /proc/lockdep   # system crash
> 
> Hi shenghui,
> 
> Thank you for having shared your test steps. I ran a slightly different test
> myself:
> 
> while true; do cat /proc/lockdep >/dev/null; done &
> (cd blktests && while ./check -q; do :; done)

It seems like I hit "send" too quickly. That test just triggered the following:

BUG: unable to handle kernel paging request at fffffbfff40ca448
#PF error: [normal kernel read fault]
PGD 13bfde067 P4D 13bfde067 PUD 13bf7a067 PMD 1167d3067 PTE 0
Oops: 0000 [#1] PREEMPT SMP KASAN
CPU: 4 PID: 4529 Comm: cat Tainted: G    B   W  O      5.1.0-rc1-dbg+ #4
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
RIP: 0010:__asan_load1+0x28/0x50
Call Trace:
 string+0xac/0x180
 vsnprintf+0x23e/0x820
 seq_vprintf+0x82/0xc0
 seq_printf+0x92/0xb0
 print_name+0x34/0xb0
 l_show+0x184/0x200
 seq_read+0x59e/0x6c0
 proc_reg_read+0x11f/0x170
 __vfs_read+0x4d/0x90
 vfs_read+0xc5/0x1f0
 ksys_read+0xab/0x130
 __x64_sys_read+0x43/0x50
 do_syscall_64+0x71/0x210
 entry_SYSCALL_64_after_hwframe+0x49/0xbe

I will have a closer look at this.

Bart.