WARNING: locking bug in lock_downgrade

WARNING: locking bug in lock_downgrade

[syzbot]

Hello,

syzbot found the following crash on:

HEAD commit:    e195ca6cb6f2 Merge branch 'for-linus' of git://git.kernel...
git tree:       upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=12336ed5400000
kernel config:  https://syzkaller.appspot.com/x/.config?x=73e2bc0cb6463446
dashboard link: https://syzkaller.appspot.com/bug?extid=53383ae265fb161ef488
compiler:       gcc (GCC) 8.0.1 20180413 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+53383ae265fb161ef488@syzkaller.appspotmail.com


------------[ cut here ]------------
downgrading a read lock
WARNING: CPU: 0 PID: 26202 at kernel/locking/lockdep.c:3556  
__lock_downgrade kernel/locking/lockdep.c:3556 [inline]
WARNING: CPU: 0 PID: 26202 at kernel/locking/lockdep.c:3556  
lock_downgrade+0x4d7/0x900 kernel/locking/lockdep.c:3819
Kernel panic - not syncing: panic_on_warn set ...
CPU: 0 PID: 26202 Comm: blkid Not tainted 4.20.0-rc3+ #127
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS  
Google 01/01/2011
Call Trace:
  __dump_stack lib/dump_stack.c:77 [inline]
  dump_stack+0x244/0x39d lib/dump_stack.c:113
  panic+0x2ad/0x55c kernel/panic.c:188
  __warn.cold.8+0x20/0x45 kernel/panic.c:540
  report_bug+0x254/0x2d0 lib/bug.c:186
  fixup_bug arch/x86/kernel/traps.c:178 [inline]
  do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
  do_invalid_op+0x36/0x40 arch/x86/kernel/traps.c:290
  invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
RIP: 0010:__lock_downgrade kernel/locking/lockdep.c:3556 [inline]
RIP: 0010:lock_downgrade+0x4d7/0x900 kernel/locking/lockdep.c:3819
Code: 00 00 fc ff df 41 c6 44 05 00 f8 e9 1b ff ff ff 48 c7 c7 60 68 2b 88  
4c 89 9d 58 ff ff ff 48 89 85 60 ff ff ff e8 d9 1f e7 ff <0f> 0b 48 8b 85  
60 ff ff ff 4c 8d 4d d8 4c 89 e9 48 ba 00 00 00 00
RSP: 0018:ffff8881ba547b70 EFLAGS: 00010086
RAX: 0000000000000000 RBX: 1ffff110374a8f74 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff8165eaf5 RDI: 0000000000000006
RBP: ffff8881ba547c28 R08: ffff88817c0b2400 R09: fffffbfff12b2254
R10: fffffbfff12b2254 R11: ffffffff895912a3 R12: ffffffff8b0f67a0
R13: ffff8881ba547bc0 R14: 0000000000000001 R15: ffff88817c0b2400
  downgrade_write+0x76/0x270 kernel/locking/rwsem.c:147
  __do_munmap+0xcd8/0xf80 mm/mmap.c:2812
  __vm_munmap+0x138/0x1f0 mm/mmap.c:2837
  __do_sys_munmap mm/mmap.c:2862 [inline]
  __se_sys_munmap mm/mmap.c:2859 [inline]
  __x64_sys_munmap+0x65/0x80 mm/mmap.c:2859
  do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
  entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f237e5ce417
Code: f0 ff ff 73 01 c3 48 8d 0d 8a ad 20 00 31 d2 48 29 c2 89 11 48 83 c8  
ff eb eb 90 90 90 90 90 90 90 90 90 b8 0b 00 00 00 0f 05 <48> 3d 01 f0 ff  
ff 73 01 c3 48 8d 0d 5d ad 20 00 31 d2 48 29 c2 89
RSP: 002b:00007ffe61bed9d8 EFLAGS: 00000203 ORIG_RAX: 000000000000000b
RAX: ffffffffffffffda RBX: 00007f237e7d91c8 RCX: 00007f237e5ce417
RDX: 000000000224ff00 RSI: 00000000000033ef RDI: 00007f237e7d1000
RBP: 00007ffe61bedb40 R08: 0000000000000001 R09: 0000000000000007
R10: 00007f237e5c8a0b R11: 0000000000000203 R12: 00000000b1f97d00
R13: 000004b2b1f97d00 R14: 000004b2afd5fdeb R15: 00007f237e7ce740
Kernel Offset: disabled
Rebooting in 86400 seconds..


---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@googlegroups.com.

syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#bug-status-tracking for how to communicate with  
syzbot.

Re: WARNING: locking bug in lock_downgrade

[Yang Shi]

Cc'ed Peter, Ingo and Waiman.


It took me a few days to look into this warning, but I got lost in 
lockdep code.


The problem is the commit dd2283f2605e ("mm: mmap: zap pages with read 
mmap_sem in munmap") does an optimization for munmap by downgrading 
write mmap_sem to read before zapping pages. But, lockdep reports 
downgrading a read lock.


I'm pretty sure mmap_sem is held as write before downgrade_write() is 
called in the patch. And, there are 4 places which may downgrade a mmap_sem:

     - munmap

     - mremap

     - brk

     - clear_refs_write (fs/proc/task_mmu.c)


The first three come from my patches, and they just do: 
down_write_killable() -> .. -> downgrade_write().

But the last one is a little bit more complicated, it does down_read() 
->.. -> up_read() ->.. -> down_write_killable() ->.. -> downgrade_write().

And, the last one may be called from any process to touch the other 
processes' mmap_sem.


By looking into lockdep code, I'm not sure if lockdep may get confused 
by such sequence or not?


Any hint is appreciated.


Regards,

Yang



On 11/26/18 12:38 PM, syzbot wrote:
> Hello,
>
> syzbot found the following crash on:
>
> HEAD commit:    e195ca6cb6f2 Merge branch 'for-linus' of 
> git://git.kernel...
> git tree:       upstream
> console output: https://syzkaller.appspot.com/x/log.txt?x=12336ed5400000
> kernel config: https://syzkaller.appspot.com/x/.config?x=73e2bc0cb6463446
> dashboard link: 
> https://syzkaller.appspot.com/bug?extid=53383ae265fb161ef488
> compiler:       gcc (GCC) 8.0.1 20180413 (experimental)
>
> Unfortunately, I don't have any reproducer for this crash yet.
>
> IMPORTANT: if you fix the bug, please add the following tag to the 
> commit:
> Reported-by: syzbot+53383ae265fb161ef488@syzkaller.appspotmail.com
>
>
> ------------[ cut here ]------------
> downgrading a read lock
> WARNING: CPU: 0 PID: 26202 at kernel/locking/lockdep.c:3556 
> __lock_downgrade kernel/locking/lockdep.c:3556 [inline]
> WARNING: CPU: 0 PID: 26202 at kernel/locking/lockdep.c:3556 
> lock_downgrade+0x4d7/0x900 kernel/locking/lockdep.c:3819
> Kernel panic - not syncing: panic_on_warn set ...
> CPU: 0 PID: 26202 Comm: blkid Not tainted 4.20.0-rc3+ #127
> Hardware name: Google Google Compute Engine/Google Compute Engine, 
> BIOS Google 01/01/2011
> Call Trace:
>  __dump_stack lib/dump_stack.c:77 [inline]
>  dump_stack+0x244/0x39d lib/dump_stack.c:113
>  panic+0x2ad/0x55c kernel/panic.c:188
>  __warn.cold.8+0x20/0x45 kernel/panic.c:540
>  report_bug+0x254/0x2d0 lib/bug.c:186
>  fixup_bug arch/x86/kernel/traps.c:178 [inline]
>  do_error_trap+0x11b/0x200 arch/x86/kernel/traps.c:271
>  do_invalid_op+0x36/0x40 arch/x86/kernel/traps.c:290
>  invalid_op+0x14/0x20 arch/x86/entry/entry_64.S:969
> RIP: 0010:__lock_downgrade kernel/locking/lockdep.c:3556 [inline]
> RIP: 0010:lock_downgrade+0x4d7/0x900 kernel/locking/lockdep.c:3819
> Code: 00 00 fc ff df 41 c6 44 05 00 f8 e9 1b ff ff ff 48 c7 c7 60 68 
> 2b 88 4c 89 9d 58 ff ff ff 48 89 85 60 ff ff ff e8 d9 1f e7 ff <0f> 0b 
> 48 8b 85 60 ff ff ff 4c 8d 4d d8 4c 89 e9 48 ba 00 00 00 00
> RSP: 0018:ffff8881ba547b70 EFLAGS: 00010086
> RAX: 0000000000000000 RBX: 1ffff110374a8f74 RCX: 0000000000000000
> RDX: 0000000000000000 RSI: ffffffff8165eaf5 RDI: 0000000000000006
> RBP: ffff8881ba547c28 R08: ffff88817c0b2400 R09: fffffbfff12b2254
> R10: fffffbfff12b2254 R11: ffffffff895912a3 R12: ffffffff8b0f67a0
> R13: ffff8881ba547bc0 R14: 0000000000000001 R15: ffff88817c0b2400
>  downgrade_write+0x76/0x270 kernel/locking/rwsem.c:147
>  __do_munmap+0xcd8/0xf80 mm/mmap.c:2812
>  __vm_munmap+0x138/0x1f0 mm/mmap.c:2837
>  __do_sys_munmap mm/mmap.c:2862 [inline]
>  __se_sys_munmap mm/mmap.c:2859 [inline]
>  __x64_sys_munmap+0x65/0x80 mm/mmap.c:2859
>  do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
>  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> RIP: 0033:0x7f237e5ce417
> Code: f0 ff ff 73 01 c3 48 8d 0d 8a ad 20 00 31 d2 48 29 c2 89 11 48 
> 83 c8 ff eb eb 90 90 90 90 90 90 90 90 90 b8 0b 00 00 00 0f 05 <48> 3d 
> 01 f0 ff ff 73 01 c3 48 8d 0d 5d ad 20 00 31 d2 48 29 c2 89
> RSP: 002b:00007ffe61bed9d8 EFLAGS: 00000203 ORIG_RAX: 000000000000000b
> RAX: ffffffffffffffda RBX: 00007f237e7d91c8 RCX: 00007f237e5ce417
> RDX: 000000000224ff00 RSI: 00000000000033ef RDI: 00007f237e7d1000
> RBP: 00007ffe61bedb40 R08: 0000000000000001 R09: 0000000000000007
> R10: 00007f237e5c8a0b R11: 0000000000000203 R12: 00000000b1f97d00
> R13: 000004b2b1f97d00 R14: 000004b2afd5fdeb R15: 00007f237e7ce740
> Kernel Offset: disabled
> Rebooting in 86400 seconds..
>
>
> ---
> This bug is generated by a bot. It may contain errors.
> See https://goo.gl/tpsmEJ for more information about syzbot.
> syzbot engineers can be reached at syzkaller@googlegroups.com.
>
> syzbot will keep track of this bug report. See:
> https://goo.gl/tpsmEJ#bug-status-tracking for how to communicate with 
> syzbot.

Re: WARNING: locking bug in lock_downgrade

[Waiman Long]

On 12/12/2018 08:14 PM, Yang Shi wrote:
> Cc'ed Peter, Ingo and Waiman.
>
>
> It took me a few days to look into this warning, but I got lost in
> lockdep code.
>
>
> The problem is the commit dd2283f2605e ("mm: mmap: zap pages with read
> mmap_sem in munmap") does an optimization for munmap by downgrading
> write mmap_sem to read before zapping pages. But, lockdep reports
> downgrading a read lock.
>
>
> I'm pretty sure mmap_sem is held as write before downgrade_write() is
> called in the patch. And, there are 4 places which may downgrade a
> mmap_sem:
>
>     - munmap
>
>     - mremap
>
>     - brk
>
>     - clear_refs_write (fs/proc/task_mmu.c)
>
>
> The first three come from my patches, and they just do:
> down_write_killable() -> .. -> downgrade_write().
>
> But the last one is a little bit more complicated, it does down_read()
> ->.. -> up_read() ->.. -> down_write_killable() ->.. ->
> downgrade_write().
>
> And, the last one may be called from any process to touch the other
> processes' mmap_sem.
>
>
> By looking into lockdep code, I'm not sure if lockdep may get confused
> by such sequence or not?
>
>
> Any hint is appreciated.
>
>
> Regards,
>
> Yang 

The warning was printed because hlock->read was set when doing the
downgrade_write(). So it is either downgrade_write() was called a second
time or a read lock was held originally. It is hard to tell what is the
root cause without a reproducer.

Cheers,
Longman

Re: WARNING: locking bug in lock_downgrade

[Tetsuo Handa]

On 2018/12/14 4:46, Waiman Long wrote:
> On 12/12/2018 08:14 PM, Yang Shi wrote:
>> By looking into lockdep code, I'm not sure if lockdep may get confused
>> by such sequence or not?
>>
>>
>> Any hint is appreciated.
>>
>>
>> Regards,
>>
>> Yang 
> 
> The warning was printed because hlock->read was set when doing the
> downgrade_write(). So it is either downgrade_write() was called a second
> time or a read lock was held originally. It is hard to tell what is the
> root cause without a reproducer.
> 
> Cheers,
> Longman
> 

Comparing with output from

        struct rw_semaphore *sem = &current->mm->mmap_sem;

        down_write(sem);
        pr_warn("mmap_sem: count=%ld current=%px, owner=%px\n", atomic_long_read(&sem->count), current, READ_ONCE(sem->owner));
        /* mmap_sem: count=-4294967295 current=ffff88813095ca80, owner=ffff88813095ca80 */
        downgrade_write(sem);
        pr_warn("mmap_sem: count=%ld current=%px, owner=%px\n", atomic_long_read(&sem->count), current, READ_ONCE(sem->owner));
        /* mmap_sem: count=1 current=ffff88813095ca80, owner=ffff88813095ca83 */
        up_read(sem);
        pr_warn("mmap_sem: count=%ld current=%px, owner=%px\n", atomic_long_read(&sem->count), current, READ_ONCE(sem->owner));
        /* mmap_sem: count=0 current=ffff88813095ca80, owner=0000000000000003 */

what we got with debug printk() patch

  https://syzkaller.appspot.com/text?tag=CrashLog&x=169dbb9b400000

  [ 2580.337550][ T3645] mmap_sem: hlock->read=1 count=-4294967295 current=ffff888050e04140, owner=ffff888050e04140
  [ 2580.353526][ T3645] ------------[ cut here ]------------
  [ 2580.367859][ T3645] downgrading a read lock
  [ 2580.367935][ T3645] WARNING: CPU: 1 PID: 3645 at kernel/locking/lockdep.c:3572 lock_downgrade+0x35d/0xbe0
  [ 2580.382206][ T3645] Kernel panic - not syncing: panic_on_warn set ...

  https://syzkaller.appspot.com/text?tag=CrashLog&x=1542da4f400000

  [  386.342585][T16698] mmap_sem: hlock->read=1 count=-4294967295 current=ffff8880512ae180, owner=ffff8880512ae180
  [  386.348586][T16698] ------------[ cut here ]------------
  [  386.357203][T16698] downgrading a read lock
  [  386.357294][T16698] WARNING: CPU: 1 PID: 16698 at kernel/locking/lockdep.c:3572 lock_downgrade+0x35d/0xbe0
  [  386.372148][T16698] Kernel panic - not syncing: panic_on_warn set ...

indicates that lockdep is saying that "current->mm->mmap_sem is held for read"
while "struct rw_semaphore" is saying that "current->mm->mmap_sem is held for write".
Something made lockdep confused. Possibly a lockdep bug.

Re: WARNING: locking bug in lock_downgrade

[Waiman Long]

On 01/09/2019 09:18 AM, Tetsuo Handa wrote:
> On 2018/12/14 4:46, Waiman Long wrote:
>> On 12/12/2018 08:14 PM, Yang Shi wrote:
>>> By looking into lockdep code, I'm not sure if lockdep may get confused
>>> by such sequence or not?
>>>
>>>
>>> Any hint is appreciated.
>>>
>>>
>>> Regards,
>>>
>>> Yang 
>> The warning was printed because hlock->read was set when doing the
>> downgrade_write(). So it is either downgrade_write() was called a second
>> time or a read lock was held originally. It is hard to tell what is the
>> root cause without a reproducer.
>>
>> Cheers,
>> Longman
>>
> Comparing with output from
>
>         struct rw_semaphore *sem = &current->mm->mmap_sem;
>
>         down_write(sem);
>         pr_warn("mmap_sem: count=%ld current=%px, owner=%px\n", atomic_long_read(&sem->count), current, READ_ONCE(sem->owner));
>         /* mmap_sem: count=-4294967295 current=ffff88813095ca80, owner=ffff88813095ca80 */
>         downgrade_write(sem);
>         pr_warn("mmap_sem: count=%ld current=%px, owner=%px\n", atomic_long_read(&sem->count), current, READ_ONCE(sem->owner));
>         /* mmap_sem: count=1 current=ffff88813095ca80, owner=ffff88813095ca83 */
>         up_read(sem);
>         pr_warn("mmap_sem: count=%ld current=%px, owner=%px\n", atomic_long_read(&sem->count), current, READ_ONCE(sem->owner));
>         /* mmap_sem: count=0 current=ffff88813095ca80, owner=0000000000000003 */

The behavior is correct. The current code will leave the reader task
structure pointer in owner even if it is a read lock. You have to look
at bit 0 to know if the owner is a reader or writer.

> what we got with debug printk() patch
>
>   https://syzkaller.appspot.com/text?tag=CrashLog&x=169dbb9b400000
>
>   [ 2580.337550][ T3645] mmap_sem: hlock->read=1 count=-4294967295 current=ffff888050e04140, owner=ffff888050e04140
>   [ 2580.353526][ T3645] ------------[ cut here ]------------
>   [ 2580.367859][ T3645] downgrading a read lock
>   [ 2580.367935][ T3645] WARNING: CPU: 1 PID: 3645 at kernel/locking/lockdep.c:3572 lock_downgrade+0x35d/0xbe0
>   [ 2580.382206][ T3645] Kernel panic - not syncing: panic_on_warn set ...
>
>   https://syzkaller.appspot.com/text?tag=CrashLog&x=1542da4f400000
>
>   [  386.342585][T16698] mmap_sem: hlock->read=1 count=-4294967295 current=ffff8880512ae180, owner=ffff8880512ae180
>   [  386.348586][T16698] ------------[ cut here ]------------
>   [  386.357203][T16698] downgrading a read lock
>   [  386.357294][T16698] WARNING: CPU: 1 PID: 16698 at kernel/locking/lockdep.c:3572 lock_downgrade+0x35d/0xbe0
>   [  386.372148][T16698] Kernel panic - not syncing: panic_on_warn set ...
>
> indicates that lockdep is saying that "current->mm->mmap_sem is held for read"
> while "struct rw_semaphore" is saying that "current->mm->mmap_sem is held for write".
> Something made lockdep confused. Possibly a lockdep bug.
>
It could be a bug in lockdep regarding downgrade. Someone else has
reported similar problem before.

-Longman

Re: WARNING: locking bug in lock_downgrade

[Tetsuo Handa]

OK. I noticed that when downgrade_write() warning is printed, there is always
another lockdep warning in progress at the same moment. And I confirmed that
downgrade_write() is confused by __debug_locks_off() called by concurrently
triggered lockdep warning. In other words, since another lockdep warning calls
__debug_locks_off(), downgrade_write() is making decisions based on "no longer
maintained dependency".

----------------------------------------
#include <linux/module.h>
#include <linux/sched.h>
#include <linux/rwsem.h>

static int __init test_init(void)
{
        struct rw_semaphore *sem = &current->mm->mmap_sem;
        static DECLARE_RWSEM(test_lock);

        down_read(sem);
        down_read(&test_lock);
        down_read(&test_lock);
        up_read(&test_lock);
        up_read(&test_lock);
        up_read(sem);
        return -EINVAL;
}

module_init(test_init);
MODULE_LICENSE("GPL");
----------------------------------------

----------------------------------------
[   40.822909][ T9174] test: loading out-of-tree module taints kernel.
[   40.827870][ T9174] 
[   40.828504][ T9174] ============================================
[   40.830253][ T9174] WARNING: possible recursive locking detected
[   40.831922][ T9174] 5.0.0-rc1-next-20190109 #269 Tainted: G           O     
[   40.833832][ T9174] --------------------------------------------
[   40.835461][ T9174] insmod/9174 is trying to acquire lock:
[   40.836871][ T9174] 000000007dbea5ef (test_lock){.+.+}, at: test_init+0x3c/0x1000 [test]
[   40.838936][ T9174] 
[   40.838936][ T9174] but task is already holding lock:
[   40.840827][ T9174] 000000007dbea5ef (test_lock){.+.+}, at: test_init+0x30/0x1000 [test]
[   40.842962][ T9174] 
[   40.842962][ T9174] other info that might help us debug this:
[   40.844979][ T9174]  Possible unsafe locking scenario:
[   40.844979][ T9174] 
[   40.847031][ T9174]        CPU0
[   40.847923][ T9174]        ----
[   40.848741][ T9174]   lock(test_lock);
[   40.849786][ T9174]   lock(test_lock);
[   40.850860][ T9174] 
[   40.850860][ T9174]  *** DEADLOCK ***
[   40.850860][ T9174] 
[   40.852892][ T9174]  May be due to missing lock nesting notation
[   40.852892][ T9174] 
[   40.855000][ T9174] 2 locks held by insmod/9174:
[   40.856187][ T9174]  #0: 000000008f7a8ad1 (&mm->mmap_sem){++++}, at: test_init+0x24/0x1000 [test]
[   40.858441][ T9174]  #1: 000000007dbea5ef (test_lock){.+.+}, at: test_init+0x30/0x1000 [test]
[   40.860784][ T9174] 
[   40.860784][ T9174] stack backtrace:
[   40.862253][ T9174] CPU: 1 PID: 9174 Comm: insmod Kdump: loaded Tainted: G           O      5.0.0-rc1-next-20190109 #269
[   40.865225][ T9174] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   40.868304][ T9174] Call Trace:
[   40.869127][ T9174]  dump_stack+0x67/0x95
[   40.870274][ T9174]  __lock_acquire+0x1073/0x1260
[   40.871555][ T9174]  lock_acquire+0xd3/0x210
[   40.872657][ T9174]  ? test_init+0x3c/0x1000 [test]
[   40.873912][ T9174]  down_read+0x47/0xa0
[   40.874927][ T9174]  ? test_init+0x3c/0x1000 [test]
[   40.876222][ T9174]  test_init+0x3c/0x1000 [test]
[   40.877432][ T9174]  ? 0xffffffffc03ff000
[   40.878854][ T9174]  do_one_initcall+0x72/0x395
[   40.880625][ T9174]  ? rcu_read_lock_sched_held+0x8c/0xa0
[   40.882965][ T9174]  ? kmem_cache_alloc_trace+0x2b5/0x360
[   40.884734][ T9174]  do_init_module+0x5b/0x1ef
[   40.886265][ T9174]  load_module+0x17ed/0x1d10
[   40.887800][ T9174]  ? __symbol_put+0x90/0x90
[   40.889315][ T9174]  ? kernel_read+0x2c/0x40
[   40.890976][ T9174]  __do_sys_finit_module+0xa9/0x100
[   40.892648][ T9174]  __x64_sys_finit_module+0x15/0x20
[   40.894315][ T9174]  do_syscall_64+0x4a/0x180
[   40.895848][ T9174]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   40.897756][ T9174] RIP: 0033:0x7f2ccd0c11c9
[   40.899229][ T9174] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 dc 2c 00 f7 d8 64 89 01 48
[   40.906285][ T9174] RSP: 002b:00007fff3f992348 EFLAGS: 00000206 ORIG_RAX: 0000000000000139
[   40.909468][ T9174] RAX: ffffffffffffffda RBX: 0000000000bcb1f0 RCX: 00007f2ccd0c11c9
[   40.912444][ T9174] RDX: 0000000000000000 RSI: 000000000041a94e RDI: 0000000000000003
[   40.915459][ T9174] RBP: 000000000041a94e R08: 0000000000000000 R09: 00007fff3f9924e8
[   40.917978][ T9174] R10: 0000000000000003 R11: 0000000000000206 R12: 0000000000000000
[   40.920434][ T9174] R13: 0000000000bca130 R14: 0000000000000000 R15: 0000000000000000
[   41.305025][ T9174] mmap_sem: hlock->read=1 count=-4294967295 current=ffffa3f06d423840, owner=ffffa3f06d423840
[   41.308093][ T9174] ------------[ cut here ]------------
[   41.309878][ T9174] downgrading a read lock
[   41.309884][ T9174] WARNING: CPU: 1 PID: 9174 at kernel/locking/lockdep.c:3572 lock_downgrade+0xe5/0x240
[   41.314382][ T9174] Modules linked in: vmw_balloon pcspkr sg vmw_vmci i2c_piix4 ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_nat_ipv6 ip6table_mangle ip6table_raw iptable_nat nf_nat_ipv4 nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_tables xfs libcrc32c sd_mod sr_mod cdrom serio_raw ata_generic pata_acpi vmwgfx drm_kms_helper ahci syscopyarea libahci sysfillrect sysimgblt e1000 fb_sys_fops mptspi ttm scsi_transport_spi mptscsih drm mptbase i2c_core ata_piix libata
[   41.332426][ T9174] CPU: 1 PID: 9174 Comm: insmod Kdump: loaded Tainted: G           O      5.0.0-rc1-next-20190109 #269
[   41.335600][ T9174] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   41.338867][ T9174] RIP: 0010:lock_downgrade+0xe5/0x240
[   41.340989][ T9174] Code: 48 85 c0 74 13 49 8d 56 90 48 05 b8 00 00 00 48 39 c2 0f 84 35 01 00 00 48 c7 c7 36 70 df 9e 31 c0 4c 89 4d c0 e8 cb c7 f9 ff <0f> 0b 8b 55 cc 4c 8b 4d c0 41 0f b6 41 32 4d 89 79 08 44 89 e6 48
[   41.346977][ T9174] RSP: 0018:ffffbbbf007d7e00 EFLAGS: 00010086
[   41.349340][ T9174] RAX: 0000000000000000 RBX: ffffa3f06d423840 RCX: ffffffffa0049040
[   41.351999][ T9174] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffffff9e0ddd22
[   41.354449][ T9174] RBP: ffffbbbf007d7e40 R08: 0000000000000000 R09: 6572206120676e69
[   41.357085][ T9174] R10: 72206120676e6964 R11: 0000000000000001 R12: 0000000000000002
[   41.359517][ T9174] R13: 0000000000000246 R14: ffffa3f0737f0968 R15: ffffffff9e1e9008
[   41.362154][ T9174] FS:  00007f2ccdbee740(0000) GS:ffffa3f07a600000(0000) knlGS:0000000000000000
[   41.365009][ T9174] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   41.367247][ T9174] CR2: 00007f2ccd122250 CR3: 0000000131f6e004 CR4: 00000000003606e0
[   41.369726][ T9174] Call Trace:
[   41.371284][ T9174]  downgrade_write+0x15/0x90
[   41.372939][ T9174]  __do_munmap+0x378/0x3c0
[   41.374557][ T9174]  __vm_munmap+0x76/0xd0
[   41.376401][ T9174]  __x64_sys_munmap+0x27/0x30
[   41.378079][ T9174]  do_syscall_64+0x4a/0x180
[   41.379711][ T9174]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   41.381940][ T9174] RIP: 0033:0x7f2ccd0c13f7
[   41.383564][ T9174] Code: 64 89 02 48 83 c8 ff eb 9c 48 8b 15 93 da 2c 00 f7 d8 64 89 02 e9 6a ff ff ff 66 0f 1f 84 00 00 00 00 00 b8 0b 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 69 da 2c 00 f7 d8 64 89 01 48
[   41.389435][ T9174] RSP: 002b:00007fff3f992378 EFLAGS: 00000206 ORIG_RAX: 000000000000000b
[   41.392384][ T9174] RAX: ffffffffffffffda RBX: 0000000000bcb300 RCX: 00007f2ccd0c13f7
[   41.394929][ T9174] RDX: 0000000000000000 RSI: 00000000000011c8 RDI: 00007f2ccdc06000
[   41.397432][ T9174] RBP: 0000000000000000 R08: 000000000040acd0 R09: 0000000000000000
[   41.400105][ T9174] R10: 00007fff3f991da0 R11: 0000000000000206 R12: 0000000000bca010
[   41.402693][ T9174] R13: 00007fff3f9924e0 R14: 0000000000000000 R15: 0000000000000000
[   41.405218][ T9174] irq event stamp: 4607
[   41.409414][ T9174] hardirqs last  enabled at (4607): [<ffffffff9e20ec47>] __slab_alloc.isra.84.constprop.90+0x5e/0x77
[   41.412696][ T9174] hardirqs last disabled at (4606): [<ffffffff9e20ec08>] __slab_alloc.isra.84.constprop.90+0x1f/0x77
[   41.416069][ T9174] softirqs last  enabled at (4528): [<ffffffff9e5fee8f>] peernet2id+0x4f/0x80
[   41.418737][ T9174] softirqs last disabled at (4526): [<ffffffff9e5fee71>] peernet2id+0x31/0x80
[   41.421542][ T9174] ---[ end trace 6db2652247cd6a11 ]---
----------------------------------------

If I do

 static inline int __debug_locks_off(void)
 {
-	return xchg(&debug_locks, 0);
+	return 1;
 }

then downgrade_write() warning is no longer printed by the reproducer (though
other lockdep warnings are printed because dependency is no longer correct).

----------------------------------------
[   34.554580][ T9173] test: loading out-of-tree module taints kernel.
[   34.559029][ T9173] 
[   34.559656][ T9173] ============================================
[   34.561416][ T9173] WARNING: possible recursive locking detected
[   34.563008][ T9173] 5.0.0-rc1-next-20190109+ #270 Tainted: G           O     
[   34.565045][ T9173] --------------------------------------------
[   34.566619][ T9173] insmod/9173 is trying to acquire lock:
[   34.568127][ T9173] 00000000cf012899 (test_lock){.+.+}, at: test_init+0x3c/0x1000 [test]
[   34.570594][ T9173] 
[   34.570594][ T9173] but task is already holding lock:
[   34.573474][ T9173] 00000000cf012899 (test_lock){.+.+}, at: test_init+0x30/0x1000 [test]
[   34.575650][ T9173] 
[   34.575650][ T9173] other info that might help us debug this:
[   34.577843][ T9173]  Possible unsafe locking scenario:
[   34.577843][ T9173] 
[   34.579813][ T9173]        CPU0
[   34.580707][ T9173]        ----
[   34.581576][ T9173]   lock(test_lock);
[   34.582604][ T9173]   lock(test_lock);
[   34.583630][ T9173] 
[   34.583630][ T9173]  *** DEADLOCK ***
[   34.583630][ T9173] 
[   34.585840][ T9173]  May be due to missing lock nesting notation
[   34.585840][ T9173] 
[   34.588127][ T9173] 2 locks held by insmod/9173:
[   34.589406][ T9173]  #0: 00000000d68054a9 (&mm->mmap_sem){++++}, at: test_init+0x24/0x1000 [test]
[   34.591822][ T9173]  #1: 00000000cf012899 (test_lock){.+.+}, at: test_init+0x30/0x1000 [test]
[   34.594205][ T9173] 
[   34.594205][ T9173] stack backtrace:
[   34.595789][ T9173] CPU: 1 PID: 9173 Comm: insmod Kdump: loaded Tainted: G           O      5.0.0-rc1-next-20190109+ #270
[   34.598773][ T9173] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   34.602109][ T9173] Call Trace:
[   34.603046][ T9173]  dump_stack+0x67/0x95
[   34.604783][ T9173]  __lock_acquire+0x1073/0x1260
[   34.606529][ T9173]  lock_acquire+0xd3/0x210
[   34.608203][ T9173]  ? test_init+0x3c/0x1000 [test]
[   34.609972][ T9173]  down_read+0x47/0xa0
[   34.611451][ T9173]  ? test_init+0x3c/0x1000 [test]
[   34.613228][ T9173]  test_init+0x3c/0x1000 [test]
[   34.614849][ T9173]  ? 0xffffffffc01d0000
[   34.616458][ T9173]  do_one_initcall+0x72/0x395
[   34.618000][ T9173]  ? rcu_read_lock_sched_held+0x8c/0xa0
[   34.619922][ T9173]  ? kmem_cache_alloc_trace+0x2b5/0x360
[   34.621843][ T9173]  do_init_module+0x5b/0x1ef
[   34.623527][ T9173]  load_module+0x17ed/0x1d10
[   34.625295][ T9173]  ? __symbol_put+0x90/0x90
[   34.627035][ T9173]  ? kernel_read+0x2c/0x40
[   34.628717][ T9173]  __do_sys_finit_module+0xa9/0x100
[   34.630384][ T9173]  __x64_sys_finit_module+0x15/0x20
[   34.632125][ T9173]  do_syscall_64+0x4a/0x180
[   34.633612][ T9173]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   34.635548][ T9173] RIP: 0033:0x7f5b50e1f1c9
[   34.637082][ T9173] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 dc 2c 00 f7 d8 64 89 01 48
[   34.643337][ T9173] RSP: 002b:00007ffcee219f68 EFLAGS: 00000202 ORIG_RAX: 0000000000000139
[   34.645825][ T9173] RAX: ffffffffffffffda RBX: 00000000011631f0 RCX: 00007f5b50e1f1c9
[   34.648340][ T9173] RDX: 0000000000000000 RSI: 000000000041a94e RDI: 0000000000000003
[   34.650841][ T9173] RBP: 000000000041a94e R08: 0000000000000000 R09: 00007ffcee21a108
[   34.653287][ T9173] R10: 0000000000000003 R11: 0000000000000202 R12: 0000000000000000
[   34.655978][ T9173] R13: 0000000001162130 R14: 0000000000000000 R15: 0000000000000000
[   34.659756][ T9173] 
[   34.661520][ T9173] =====================================
[   34.663790][ T9173] WARNING: bad unlock balance detected!
[   34.665636][ T9173] 5.0.0-rc1-next-20190109+ #270 Tainted: G           O     
[   34.667902][ T9173] -------------------------------------
[   34.669595][ T9173] insmod/9173 is trying to release lock (test_lock) at:
[   34.672164][ T9173] [<ffffffffc01d0054>] test_init+0x54/0x1000 [test]
[   34.674384][ T9173] but there are no more locks to release!
[   34.676195][ T9173] 
[   34.676195][ T9173] other info that might help us debug this:
[   34.679053][ T9173] 1 lock held by insmod/9173:
[   34.680569][ T9173]  #0: 00000000d68054a9 (&mm->mmap_sem){++++}, at: test_init+0x24/0x1000 [test]
[   34.683362][ T9173] 
[   34.683362][ T9173] stack backtrace:
[   34.685567][ T9173] CPU: 1 PID: 9173 Comm: insmod Kdump: loaded Tainted: G           O      5.0.0-rc1-next-20190109+ #270
[   34.689164][ T9173] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 04/13/2018
[   34.692636][ T9173] Call Trace:
[   34.694044][ T9173]  dump_stack+0x67/0x95
[   34.695444][ T9173]  ? test_init+0x54/0x1000 [test]
[   34.697031][ T9173]  print_unlock_imbalance_bug+0xec/0x100
[   34.698899][ T9173]  ? test_init+0x54/0x1000 [test]
[   34.700489][ T9173]  lock_release+0x230/0x4c0
[   34.702119][ T9173]  up_read+0x1a/0xa0
[   34.703521][ T9173]  test_init+0x54/0x1000 [test]
[   34.705069][ T9173]  ? 0xffffffffc01d0000
[   34.706727][ T9173]  do_one_initcall+0x72/0x395
[   34.708233][ T9173]  ? rcu_read_lock_sched_held+0x8c/0xa0
[   34.710167][ T9173]  ? kmem_cache_alloc_trace+0x2b5/0x360
[   34.711885][ T9173]  do_init_module+0x5b/0x1ef
[   34.713538][ T9173]  load_module+0x17ed/0x1d10
[   34.715027][ T9173]  ? __symbol_put+0x90/0x90
[   34.716494][ T9173]  ? kernel_read+0x2c/0x40
[   34.718226][ T9173]  __do_sys_finit_module+0xa9/0x100
[   34.719924][ T9173]  __x64_sys_finit_module+0x15/0x20
[   34.721734][ T9173]  do_syscall_64+0x4a/0x180
[   34.723199][ T9173]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   34.725136][ T9173] RIP: 0033:0x7f5b50e1f1c9
[   34.726770][ T9173] Code: 01 00 48 81 c4 80 00 00 00 e9 f1 fe ff ff 0f 1f 00 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 97 dc 2c 00 f7 d8 64 89 01 48
[   34.732837][ T9173] RSP: 002b:00007ffcee219f68 EFLAGS: 00000202 ORIG_RAX: 0000000000000139
[   34.738479][ T9173] RAX: ffffffffffffffda RBX: 00000000011631f0 RCX: 00007f5b50e1f1c9
[   34.741078][ T9173] RDX: 0000000000000000 RSI: 000000000041a94e RDI: 0000000000000003
[   34.743495][ T9173] RBP: 000000000041a94e R08: 0000000000000000 R09: 00007ffcee21a108
[   34.746043][ T9173] R10: 0000000000000003 R11: 0000000000000202 R12: 0000000000000000
[   34.748450][ T9173] R13: 0000000001162130 R14: 0000000000000000 R15: 0000000000000000
----------------------------------------