WARNING: inconsistent lock state

Status: fixed on 2018/05/08 18:30
Subsystems: kernel
[Documentation on labels]
Reported-by: syzbot+9de458f6a5e713ee8c1a@syzkaller.appspotmail.com
Fix commit: 6c1e851c4edc random: fix possible sleeping allocation from irq context
First crash: 3019d, last: 3015d
▶ ▼ Discussions (6)
Title Replies (including bot) Last reply
[PATCH 4.9 000/264] 4.9.320-rc1 review 270 (270) 2022/06/25 13:53
[PATCH 4.16 000/113] 4.16.7-stable review 120 (120) 2018/05/01 19:26
[PATCH 4.9 00/61] 4.9.98-stable review 66 (66) 2018/05/01 19:07
[PATCH 4.14 00/91] 4.14.39-stable review 97 (97) 2018/05/01 19:06
[PATCH] random: fix possible sleeping allocation from irq context 4 (4) 2018/04/25 10:47
WARNING: inconsistent lock state 2 (3) 2018/04/23 11:01

Sample crash report:
random: sshd: uninitialized urandom read (32 bytes read)
random: sshd: uninitialized urandom read (32 bytes read)
random: sshd: uninitialized urandom read (32 bytes read)

================================
WARNING: inconsistent lock state
4.17.0-rc2+ #18 Not tainted
--------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
swapper/0/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
        (ptrval) (fs_reclaim){?.+.}, at: fs_reclaim_acquire.part.82+0x0/0x30 mm/page_alloc.c:463
{HARDIRQ-ON-W} state was registered at:
  lock_acquire+0x1dc/0x520 kernel/locking/lockdep.c:3920
  fs_reclaim_acquire.part.82+0x24/0x30 mm/page_alloc.c:3739
  fs_reclaim_acquire+0x14/0x20 mm/page_alloc.c:3740
  slab_pre_alloc_hook mm/slab.h:418 [inline]
  slab_alloc_node mm/slab.c:3299 [inline]
  kmem_cache_alloc_node_trace+0x39/0x770 mm/slab.c:3661
  kmalloc_node include/linux/slab.h:550 [inline]
  kzalloc_node include/linux/slab.h:712 [inline]
  alloc_worker+0xbd/0x2e0 kernel/workqueue.c:1704
  init_rescuer.part.25+0x1f/0x190 kernel/workqueue.c:4000
  init_rescuer kernel/workqueue.c:3997 [inline]
  workqueue_init+0x51f/0x7d0 kernel/workqueue.c:5732
  kernel_init_freeable+0x2ad/0x58e init/main.c:1115
  kernel_init+0x11/0x1b3 init/main.c:1053
  ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
irq event stamp: 351752
hardirqs last  enabled at (351749): [<ffffffff876ecf67>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last  enabled at (351749): [<ffffffff876ecf67>] _raw_spin_unlock_irq+0x27/0x70 kernel/locking/spinlock.c:192
hardirqs last disabled at (351750): [<ffffffff87800905>] interrupt_entry+0xb5/0xf0 arch/x86/entry/entry_64.S:625
softirqs last  enabled at (351752): [<ffffffff81471abc>] _local_bh_enable+0x1c/0x30 kernel/softirq.c:155
softirqs last disabled at (351751): [<ffffffff81474e40>] irq_enter+0xa0/0xd0 kernel/softirq.c:351

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(fs_reclaim);
  <Interrupt>
    lock(fs_reclaim);

 *** DEADLOCK ***

no locks held by swapper/0/0.

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.17.0-rc2+ #18
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x1b9/0x294 lib/dump_stack.c:113
 print_usage_bug.cold.59+0x320/0x41a kernel/locking/lockdep.c:2542
 valid_state kernel/locking/lockdep.c:2555 [inline]
 mark_lock_irq kernel/locking/lockdep.c:2749 [inline]
 mark_lock+0x1034/0x19e0 kernel/locking/lockdep.c:3147
 mark_irqflags kernel/locking/lockdep.c:3022 [inline]
 __lock_acquire+0x1595/0x5140 kernel/locking/lockdep.c:3388
 lock_acquire+0x1dc/0x520 kernel/locking/lockdep.c:3920
 fs_reclaim_acquire.part.82+0x24/0x30 mm/page_alloc.c:3739
 fs_reclaim_acquire+0x14/0x20 mm/page_alloc.c:3740
 slab_pre_alloc_hook mm/slab.h:418 [inline]
 slab_alloc mm/slab.c:3378 [inline]
 __do_kmalloc mm/slab.c:3716 [inline]
 __kmalloc+0x45/0x760 mm/slab.c:3727
 kmalloc_array include/linux/slab.h:631 [inline]
 kcalloc include/linux/slab.h:642 [inline]
 numa_crng_init drivers/char/random.c:798 [inline]
 crng_reseed+0x427/0x920 drivers/char/random.c:923
 credit_entropy_bits+0x98d/0xa30 drivers/char/random.c:708
 add_interrupt_randomness+0x494/0x860 drivers/char/random.c:1254
 handle_irq_event_percpu+0xf9/0x1c0 kernel/irq/handle.c:191
 handle_irq_event+0xa7/0x135 kernel/irq/handle.c:206
 handle_edge_irq+0x20f/0x870 kernel/irq/chip.c:791
 generic_handle_irq_desc include/linux/irqdesc.h:159 [inline]
 handle_irq+0x18c/0x2e7 arch/x86/kernel/irq_64.c:77
 do_IRQ+0x78/0x190 arch/x86/kernel/irq.c:245
 common_interrupt+0xf/0xf arch/x86/entry/entry_64.S:642
 </IRQ>
RIP: 0010:arch_local_irq_enable arch/x86/include/asm/paravirt.h:793 [inline]
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x56/0x70 kernel/locking/spinlock.c:192
RSP: 0018:ffffffff88c079c0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffffda
RAX: dffffc0000000000 RBX: ffff8801dae2c580 RCX: 0000000000000000
RDX: 1ffffffff11a315f RSI: 0000000000000001 RDI: ffffffff88d18af8
RBP: ffffffff88c079c8 R08: ffffed003b5c58b1 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff88c75dc0
R13: ffff8801ac422140 R14: 0000000000000000 R15: ffffffff88c75dc0
 finish_lock_switch kernel/sched/core.c:2603 [inline]
 finish_task_switch+0x1ca/0x810 kernel/sched/core.c:2701
 context_switch kernel/sched/core.c:2851 [inline]
 __schedule+0x809/0x1e30 kernel/sched/core.c:3490
 schedule_idle+0x45/0x80 kernel/sched/core.c:3576
 do_idle+0x177/0x560 kernel/sched/idle.c:286
 cpu_startup_entry+0x104/0x120 kernel/sched/idle.c:368
 rest_init+0xe1/0xe4 init/main.c:441
 start_kernel+0x906/0x92d init/main.c:737
 x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:445
 x86_64_start_kernel+0x76/0x79 arch/x86/kernel/head64.c:426
 secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:242
BUG: sleeping function called from invalid context at mm/slab.h:421
in_atomic(): 1, irqs_disabled(): 1, pid: 0, name: swapper/0
INFO: lockdep is turned off.
irq event stamp: 351752
hardirqs last  enabled at (351749): [<ffffffff876ecf67>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last  enabled at (351749): [<ffffffff876ecf67>] _raw_spin_unlock_irq+0x27/0x70 kernel/locking/spinlock.c:192
hardirqs last disabled at (351750): [<ffffffff87800905>] interrupt_entry+0xb5/0xf0 arch/x86/entry/entry_64.S:625
softirqs last  enabled at (351752): [<ffffffff81471abc>] _local_bh_enable+0x1c/0x30 kernel/softirq.c:155
softirqs last disabled at (351751): [<ffffffff81474e40>] irq_enter+0xa0/0xd0 kernel/softirq.c:351
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.17.0-rc2+ #18
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x1b9/0x294 lib/dump_stack.c:113
 ___might_sleep.cold.87+0x11f/0x13a kernel/sched/core.c:6188
 __might_sleep+0x95/0x190 kernel/sched/core.c:6141
 slab_pre_alloc_hook mm/slab.h:421 [inline]
 slab_alloc mm/slab.c:3378 [inline]
 __do_kmalloc mm/slab.c:3716 [inline]
 __kmalloc+0x2b9/0x760 mm/slab.c:3727
 kmalloc_array include/linux/slab.h:631 [inline]
 kcalloc include/linux/slab.h:642 [inline]
 numa_crng_init drivers/char/random.c:798 [inline]
 crng_reseed+0x427/0x920 drivers/char/random.c:923
 credit_entropy_bits+0x98d/0xa30 drivers/char/random.c:708
 add_interrupt_randomness+0x494/0x860 drivers/char/random.c:1254
 handle_irq_event_percpu+0xf9/0x1c0 kernel/irq/handle.c:191
 handle_irq_event+0xa7/0x135 kernel/irq/handle.c:206
 handle_edge_irq+0x20f/0x870 kernel/irq/chip.c:791
 generic_handle_irq_desc include/linux/irqdesc.h:159 [inline]
 handle_irq+0x18c/0x2e7 arch/x86/kernel/irq_64.c:77
 do_IRQ+0x78/0x190 arch/x86/kernel/irq.c:245
 common_interrupt+0xf/0xf arch/x86/entry/entry_64.S:642
 </IRQ>
RIP: 0010:arch_local_irq_enable arch/x86/include/asm/paravirt.h:793 [inline]
RIP: 0010:__raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
RIP: 0010:_raw_spin_unlock_irq+0x56/0x70 kernel/locking/spinlock.c:192
RSP: 0018:ffffffff88c079c0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffffda
RAX: dffffc0000000000 RBX: ffff8801dae2c580 RCX: 0000000000000000
RDX: 1ffffffff11a315f RSI: 0000000000000001 RDI: ffffffff88d18af8
RBP: ffffffff88c079c8 R08: ffffed003b5c58b1 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff88c75dc0
R13: ffff8801ac422140 R14: 0000000000000000 R15: ffffffff88c75dc0
 finish_lock_switch kernel/sched/core.c:2603 [inline]
 finish_task_switch+0x1ca/0x810 kernel/sched/core.c:2701
 context_switch kernel/sched/core.c:2851 [inline]
 __schedule+0x809/0x1e30 kernel/sched/core.c:3490
 schedule_idle+0x45/0x80 kernel/sched/core.c:3576
 do_idle+0x177/0x560 kernel/sched/idle.c:286
 cpu_startup_entry+0x104/0x120 kernel/sched/idle.c:368
 rest_init+0xe1/0xe4 init/main.c:441
 start_kernel+0x906/0x92d init/main.c:737
 x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:445
 x86_64_start_kernel+0x76/0x79 arch/x86/kernel/head64.c:426
 secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:242
random: crng init done

Crashes (22):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2018/04/26 23:16 upstream 69bfd470f462 73417389 .config console log report syz C ci-upstream-kasan-gce
2018/04/26 22:46 upstream 69bfd470f462 73417389 .config console log report syz C ci-upstream-kasan-gce
2018/04/26 15:07 upstream 69bfd470f462 73417389 .config console log report syz C ci-upstream-kasan-gce
2018/04/26 08:43 upstream 26ed24e429d8 73417389 .config console log report syz C ci-upstream-kasan-gce-root
2018/04/24 19:52 upstream 6d08b06e67cd 37e76fe2 .config console log report syz C ci-upstream-kasan-gce-root
2018/04/24 16:50 upstream 6d08b06e67cd 2bf86f40 .config console log report syz C ci-upstream-kasan-gce
2018/04/24 15:08 upstream 6d08b06e67cd 2bf86f40 .config console log report syz C ci-upstream-kasan-gce-root
2018/04/24 04:41 upstream 6d08b06e67cd e7e85d36 .config console log report syz C ci-upstream-kasan-gce
2018/04/23 23:49 upstream 6d08b06e67cd 0d8e591c .config console log report syz C ci-upstream-kasan-gce
2018/04/23 21:18 upstream 6d08b06e67cd 0d8e591c .config console log report syz C ci-upstream-kasan-gce
2018/04/23 18:09 upstream 6d08b06e67cd 0d8e591c .config console log report syz C ci-upstream-kasan-gce-root
2018/04/23 05:07 upstream 5ec83b22a2dd d23fcf6c .config console log report syz C ci-upstream-kasan-gce-root
2018/04/22 11:56 upstream 285848b0f407 d23fcf6c .config console log report syz C ci-upstream-kasan-gce
2018/04/22 11:25 upstream 285848b0f407 d23fcf6c .config console log report syz C ci-upstream-kasan-gce-root
2018/04/22 10:03 upstream 285848b0f407 d23fcf6c .config console log report syz C ci-upstream-kasan-gce-root
2018/04/22 09:47 upstream 285848b0f407 d23fcf6c .config console log report syz C ci-upstream-kasan-gce-root
2018/04/22 09:33 upstream 285848b0f407 d23fcf6c .config console log report syz C ci-upstream-kasan-gce
2018/04/26 08:54 upstream 26ed24e429d8 73417389 .config console log report syz C ci-upstream-kasan-gce-386
2018/04/26 03:44 upstream 26ed24e429d8 73417389 .config console log report syz C ci-upstream-kasan-gce-386
2018/04/25 21:18 upstream 3be4aaf4e2d3 73417389 .config console log report syz C ci-upstream-kasan-gce-386
2018/04/26 00:38 net-next-old c8ad08929d1b 73417389 .config console log report syz C ci-upstream-net-kasan-gce
2018/04/25 12:20 upstream 3be4aaf4e2d3 73417389 .config console log report syz ci-upstream-kasan-gce-386
* Struck through repros no longer work on HEAD.