WARNING in debug_print_object (3)

[syzbot]

Hello,

syzbot hit the following crash on upstream commit
0b412605ef5f5c64b31f19e2910b1d5eba9929c3 (Thu Mar 29 01:07:23 2018 +0000)
Merge tag 'drm-fixes-for-v4.16-rc8' of
git://people.freedesktop.org/~airlied/linux
syzbot dashboard link:
https://syzkaller.appspot.com/bug?extid=ba74230605f61f04058d

Unfortunately, I don't have any reproducer for this crash yet.
Raw console output:
https://syzkaller.appspot.com/x/log.txt?id=6736208109502464
Kernel config:
https://syzkaller.appspot.com/x/.config?id=-8440362230543204781
compiler: gcc (GCC) 7.1.1 20170620
CC: [linux-...@vger.kernel.org linu...@vger.kernel.org
net...@vger.kernel.org pau...@samba.org]

IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+ba7423...@syzkaller.appspotmail.com
It will help syzbot understand when the bug is fixed. See footer for
details.
If you forward the report, please keep this part and the footer.

device bridge0 entered promiscuous mode
------------[ cut here ]------------
ODEBUG: free active (active state 0) object type: work_struct hint:
process_one_req+0x0/0x6c0 include/net/dst.h:165
WARNING: CPU: 1 PID: 248 at lib/debugobjects.c:291
debug_print_object+0x166/0x220 lib/debugobjects.c:288
FAULT_INJECTION: forcing a failure.
name fail_page_alloc, interval 1, probability 0, space 0, times 1
Kernel panic - not syncing: panic_on_warn set ...

CPU: 0 PID: 7189 Comm: syz-executor1 Not tainted 4.16.0-rc7+ #370
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x194/0x24d lib/dump_stack.c:53
fail_dump lib/fault-inject.c:51 [inline]
should_fail+0x8c0/0xa40 lib/fault-inject.c:149
should_fail_alloc_page mm/page_alloc.c:2961 [inline]
prepare_alloc_pages mm/page_alloc.c:4200 [inline]
__alloc_pages_nodemask+0x327/0xdd0 mm/page_alloc.c:4239
__alloc_pages include/linux/gfp.h:456 [inline]
__alloc_pages_node include/linux/gfp.h:469 [inline]
kmem_getpages mm/slab.c:1411 [inline]
cache_grow_begin+0x72/0x640 mm/slab.c:2666
cache_alloc_refill mm/slab.c:3033 [inline]
____cache_alloc mm/slab.c:3115 [inline]
slab_alloc_node mm/slab.c:3310 [inline]
kmem_cache_alloc_node_trace+0x434/0x760 mm/slab.c:3649
__do_kmalloc_node mm/slab.c:3669 [inline]
__kmalloc_node+0x33/0x70 mm/slab.c:3677
kmalloc_node include/linux/slab.h:554 [inline]
kvmalloc_node+0x99/0xd0 mm/util.c:419
kvmalloc include/linux/mm.h:541 [inline]
kvzalloc include/linux/mm.h:549 [inline]
alloc_netdev_mqs+0x16d/0xfb0 net/core/dev.c:8311
ppp_create_interface drivers/net/ppp/ppp_generic.c:3020 [inline]
ppp_unattached_ioctl drivers/net/ppp/ppp_generic.c:865 [inline]
ppp_ioctl+0x1777/0x2be0 drivers/net/ppp/ppp_generic.c:601
vfs_ioctl fs/ioctl.c:46 [inline]
do_vfs_ioctl+0x1b1/0x1520 fs/ioctl.c:686
SYSC_ioctl fs/ioctl.c:701 [inline]
SyS_ioctl+0x8f/0xc0 fs/ioctl.c:692
do_syscall_64+0x281/0x940 arch/x86/entry/common.c:287
entry_SYSCALL_64_after_hwframe+0x42/0xb7
RIP: 0033:0x4548b9
RSP: 002b:00007f6d54fc0c68 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007f6d54fc16d4 RCX: 00000000004548b9
RDX: 0000000020000f0a RSI: 00000000c004743e RDI: 0000000000000013
RBP: 000000000072bea0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000014
R13: 00000000000001e4 R14: 00000000006f4e00 R15: 0000000000000001
CPU: 1 PID: 248 Comm: kworker/u4:4 Not tainted 4.16.0-rc7+ #370
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: ib_addr process_one_req
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x194/0x24d lib/dump_stack.c:53
panic+0x1e4/0x41c kernel/panic.c:183
__warn+0x1dc/0x200 kernel/panic.c:547
report_bug+0x1f4/0x2b0 lib/bug.c:186
fixup_bug.part.11+0x37/0x80 arch/x86/kernel/traps.c:178
fixup_bug arch/x86/kernel/traps.c:247 [inline]
do_error_trap+0x2d7/0x3e0 arch/x86/kernel/traps.c:296
do_invalid_op+0x1b/0x20 arch/x86/kernel/traps.c:315
invalid_op+0x1b/0x40 arch/x86/entry/entry_64.S:986
RIP: 0010:debug_print_object+0x166/0x220 lib/debugobjects.c:288
RSP: 0018:ffff8801d8cbf210 EFLAGS: 00010086
RAX: dffffc0000000008 RBX: 0000000000000003 RCX: ffffffff815b7bde
RDX: 0000000000000000 RSI: 1ffff1003b197df2 RDI: 1ffff1003b197dc7
RBP: ffff8801d8cbf250 R08: 0000000000000000 R09: 1ffff1003b197d99
R10: ffffed003b197e71 R11: ffffffff87b3b658 R12: 0000000000000001
R13: ffffffff87b16640 R14: ffffffff86e59240 R15: ffffffff8147fea0
__debug_check_no_obj_freed lib/debugobjects.c:745 [inline]
debug_check_no_obj_freed+0x662/0xf1f lib/debugobjects.c:774
kfree+0xc7/0x260 mm/slab.c:3800
process_one_req+0x2e7/0x6c0 drivers/infiniband/core/addr.c:592
process_one_work+0xc47/0x1bb0 kernel/workqueue.c:2113
worker_thread+0x223/0x1990 kernel/workqueue.c:2247
kthread+0x33c/0x400 kernel/kthread.c:238
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:406

======================================================
WARNING: possible circular locking dependency detected
4.16.0-rc7+ #370 Not tainted
------------------------------------------------------
kworker/u4:4/248 is trying to acquire lock:
((console_sem).lock){-.-.}, at: [<00000000adc77084>]
down_trylock+0x13/0x70 kernel/locking/semaphore.c:136

but task is already holding lock:
(&obj_hash[i].lock){-.-.}, at: [<0000000051c2f570>]
__debug_check_no_obj_freed lib/debugobjects.c:736 [inline]
(&obj_hash[i].lock){-.-.}, at: [<0000000051c2f570>]
debug_check_no_obj_freed+0x1e9/0xf1f lib/debugobjects.c:774

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #3 (&obj_hash[i].lock){-.-.}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
__debug_object_init+0x109/0x1040 lib/debugobjects.c:343
debug_object_init+0x17/0x20 lib/debugobjects.c:391
debug_hrtimer_init kernel/time/hrtimer.c:410 [inline]
debug_init kernel/time/hrtimer.c:458 [inline]
hrtimer_init+0x8c/0x410 kernel/time/hrtimer.c:1259
init_dl_task_timer+0x1b/0x50 kernel/sched/deadline.c:1060
__sched_fork+0x2bb/0xb60 kernel/sched/core.c:2189
init_idle+0x75/0x820 kernel/sched/core.c:5352
sched_init+0xb19/0xc43 kernel/sched/core.c:6049
start_kernel+0x452/0x819 init/main.c:586
x86_64_start_reservations+0x2a/0x2c arch/x86/kernel/head64.c:378
x86_64_start_kernel+0x77/0x7a arch/x86/kernel/head64.c:359
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:239

-> #2 (&rq->lock){-.-.}:
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
rq_lock kernel/sched/sched.h:1760 [inline]
task_fork_fair+0x7a/0x690 kernel/sched/fair.c:9471
sched_fork+0x450/0xc10 kernel/sched/core.c:2405
copy_process.part.38+0x17c9/0x4bd0 kernel/fork.c:1763
copy_process kernel/fork.c:1606 [inline]
_do_fork+0x1f7/0xf70 kernel/fork.c:2087
kernel_thread+0x34/0x40 kernel/fork.c:2146
rest_init+0x22/0xf0 init/main.c:403
start_kernel+0x7f1/0x819 init/main.c:717
x86_64_start_reservations+0x2a/0x2c arch/x86/kernel/head64.c:378
x86_64_start_kernel+0x77/0x7a arch/x86/kernel/head64.c:359
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:239

-> #1 (&p->pi_lock){-.-.}:
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
try_to_wake_up+0xbc/0x15f0 kernel/sched/core.c:1989
wake_up_process+0x10/0x20 kernel/sched/core.c:2152
__up.isra.0+0x1cc/0x2c0 kernel/locking/semaphore.c:262
up+0x13b/0x1d0 kernel/locking/semaphore.c:187
__up_console_sem+0xb2/0x1a0 kernel/printk/printk.c:242
console_unlock+0x5af/0xfb0 kernel/printk/printk.c:2417
do_con_write+0x106e/0x1f70 drivers/tty/vt/vt.c:2433
con_write+0x25/0xb0 drivers/tty/vt/vt.c:2782
process_output_block drivers/tty/n_tty.c:579 [inline]
n_tty_write+0x5ef/0xec0 drivers/tty/n_tty.c:2308
do_tty_write drivers/tty/tty_io.c:958 [inline]
tty_write+0x3fa/0x840 drivers/tty/tty_io.c:1042
__vfs_write+0xef/0x970 fs/read_write.c:480
vfs_write+0x189/0x510 fs/read_write.c:544
SYSC_write fs/read_write.c:589 [inline]
SyS_write+0xef/0x220 fs/read_write.c:581
do_syscall_64+0x281/0x940 arch/x86/entry/common.c:287
entry_SYSCALL_64_after_hwframe+0x42/0xb7

-> #0 ((console_sem).lock){-.-.}:
lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:3920
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
down_trylock+0x13/0x70 kernel/locking/semaphore.c:136
__down_trylock_console_sem+0xa2/0x1e0 kernel/printk/printk.c:225
console_trylock+0x15/0x70 kernel/printk/printk.c:2229
console_trylock_spinning kernel/printk/printk.c:1643 [inline]
vprintk_emit+0x5b5/0xb90 kernel/printk/printk.c:1906
vprintk_default+0x28/0x30 kernel/printk/printk.c:1947
vprintk_func+0x57/0xc0 kernel/printk/printk_safe.c:379
printk+0xaa/0xca kernel/printk/printk.c:1980
__warn_printk+0x90/0xf0 kernel/panic.c:599
debug_print_object+0x166/0x220 lib/debugobjects.c:288
__debug_check_no_obj_freed lib/debugobjects.c:745 [inline]
debug_check_no_obj_freed+0x662/0xf1f lib/debugobjects.c:774
kfree+0xc7/0x260 mm/slab.c:3800
process_one_req+0x2e7/0x6c0 drivers/infiniband/core/addr.c:592
process_one_work+0xc47/0x1bb0 kernel/workqueue.c:2113
worker_thread+0x223/0x1990 kernel/workqueue.c:2247
kthread+0x33c/0x400 kernel/kthread.c:238
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:406

other info that might help us debug this:

Chain exists of:
(console_sem).lock --> &rq->lock --> &obj_hash[i].lock

Possible unsafe locking scenario:

CPU0 CPU1
---- ----
lock(&obj_hash[i].lock);
lock(&rq->lock);
lock(&obj_hash[i].lock);
lock((console_sem).lock);

*** DEADLOCK ***

3 locks held by kworker/u4:4/248:
#0: ((wq_completion)"ib_addr"){+.+.}, at: [<000000000bf55d97>]
work_static include/linux/workqueue.h:198 [inline]
#0: ((wq_completion)"ib_addr"){+.+.}, at: [<000000000bf55d97>]
set_work_data kernel/workqueue.c:619 [inline]
#0: ((wq_completion)"ib_addr"){+.+.}, at: [<000000000bf55d97>]
set_work_pool_and_clear_pending kernel/workqueue.c:646 [inline]
#0: ((wq_completion)"ib_addr"){+.+.}, at: [<000000000bf55d97>]
process_one_work+0xb12/0x1bb0 kernel/workqueue.c:2084
#1: ((work_completion)(&(&req->work)->work)){+.+.}, at:
[<000000007b587db8>] process_one_work+0xb89/0x1bb0 kernel/workqueue.c:2088
#2: (&obj_hash[i].lock){-.-.}, at: [<0000000051c2f570>]
__debug_check_no_obj_freed lib/debugobjects.c:736 [inline]
#2: (&obj_hash[i].lock){-.-.}, at: [<0000000051c2f570>]
debug_check_no_obj_freed+0x1e9/0xf1f lib/debugobjects.c:774

stack backtrace:
CPU: 1 PID: 248 Comm: kworker/u4:4 Not tainted 4.16.0-rc7+ #370
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Workqueue: ib_addr process_one_req
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x194/0x24d lib/dump_stack.c:53
print_circular_bug.isra.38+0x2cd/0x2dc kernel/locking/lockdep.c:1223
check_prev_add kernel/locking/lockdep.c:1863 [inline]
check_prevs_add kernel/locking/lockdep.c:1976 [inline]
validate_chain kernel/locking/lockdep.c:2417 [inline]
__lock_acquire+0x30a8/0x3e00 kernel/locking/lockdep.c:3431
lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:3920
__raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:110 [inline]
_raw_spin_lock_irqsave+0x96/0xc0 kernel/locking/spinlock.c:152
down_trylock+0x13/0x70 kernel/locking/semaphore.c:136
__down_trylock_console_sem+0xa2/0x1e0 kernel/printk/printk.c:225
console_trylock+0x15/0x70 kernel/printk/printk.c:2229
console_trylock_spinning kernel/printk/printk.c:1643 [inline]
vprintk_emit+0x5b5/0xb90 kernel/printk/printk.c:1906
vprintk_default+0x28/0x30 kernel/printk/printk.c:1947
vprintk_func+0x57/0xc0 kernel/printk/printk_safe.c:379
printk+0xaa/0xca kernel/printk/printk.c:1980
__warn_printk+0x90/0xf0 kernel/panic.c:599
debug_print_object+0x166/0x220 lib/debugobjects.c:288
__debug_check_no_obj_freed lib/debugobjects.c:745 [inline]
debug_check_no_obj_freed+0x662/0xf1f lib/debugobjects.c:774
kfree+0xc7/0x260 mm/slab.c:3800
process_one_req+0x2e7/0x6c0 drivers/infiniband/core/addr.c:592
process_one_work+0xc47/0x1bb0 kernel/workqueue.c:2113
worker_thread+0x223/0x1990 kernel/workqueue.c:2247
kthread+0x33c/0x400 kernel/kthread.c:238
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:406
Shutting down cpus with NMI
Dumping ftrace buffer:
(ftrace buffer empty)
Kernel Offset: disabled
Rebooting in 86400 seconds..


---
This bug is generated by a dumb bot. It may contain errors.
See https://goo.gl/tpsmEJ for details.
Direct all questions to syzk...@googlegroups.com.

syzbot will keep track of this bug report.
If you forgot to add the Reported-by tag, once the fix for this bug is
merged
into any tree, please reply to this email with:
#syz fix: exact-commit-title
To mark this as a duplicate of another syzbot report, please reply with:
#syz dup: exact-subject-of-another-report
If it's a one-off invalid bug report, please reply with:
#syz invalid
Note: if the crash happens again, it will cause creation of a new bug
report.
Note: all commands must start from beginning of the line in the email body.
To upstream this report, please reply with:
#syz upstream

[syzbot]

Auto-closing this bug as obsolete.
Crashes did not happen for a while, no reproducer and no activity.