lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20171121100430.pv2hn4caddrrirqs@wfg-t540p.sh.intel.com>
Date:   Tue, 21 Nov 2017 18:04:30 +0800
From:   Fengguang Wu <fengguang.wu@...el.com>
To:     Peter Zijlstra <peterz@...radead.org>
Cc:     Ingo Molnar <mingo@...hat.com>,
        Chris Wilson <chris@...is-wilson.co.uk>,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        linux-kernel@...r.kernel.org, lkp@...org
Subject: [test_abba] WARNING: possible circular locking dependency detected

Hello,

FYI this happens in mainline kernel 4.14.0-12891-gc8a0739.
It looks like a new regression after 4.14.

It occurs in 2 out of 2 boots.

[    1.588989] spin_lock-torture: Creating lock_torture_stats task
[    1.589710] spin_lock-torture: lock_torture_writer task started
[    1.590645] spin_lock-torture: lock_torture_stats task started
[    2.100149]
[    2.100363] ======================================================
[    2.101009] WARNING: possible circular locking dependency detected
[    2.101645] 4.14.0-12891-gc8a0739 #1 Not tainted
[    2.102150] ------------------------------------------------------
[    2.102783] kworker/0:1/14 is trying to acquire lock:
[    2.103312]  (ww_class_mutex){+.+.}, at: [<ffffffff8115fd09>] test_abba_work+0xd9/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:179
[    2.104009]
[    2.104009] but now in release context of a crosslock acquired at the following:
[    2.104009]  ((completion)&abba.b_ready){+.+.}, at: [<ffffffff81160132>] test_abba+0x1a4/0x3c0:
test_abba at kernel/locking/test-ww_mutex.c:218
[    2.104009]
[    2.104009] which lock already depends on the new lock.
[    2.104009]
[    2.104009] the existing dependency chain (in reverse order) is:
[    2.104009]
[    2.104009] -> #1 ((completion)&abba.b_ready){+.+.}:
[    2.104009]        wait_for_completion+0x5e/0x220:
spin_lock_irq at include/linux/spinlock.h:340
  (inlined by) __wait_for_common at kernel/sched/completion.c:111
  (inlined by) wait_for_common at kernel/sched/completion.c:123
  (inlined by) wait_for_completion at kernel/sched/completion.c:144
[    2.104009]        test_abba+0x1a4/0x3c0:
test_abba at kernel/locking/test-ww_mutex.c:218
[    2.104009]        test_ww_mutex_init+0xcc/0x3e1:
test_ww_mutex_init at kernel/locking/test-ww_mutex.c:610
[    2.104009]        do_one_initcall+0xac/0x1c7:
do_one_initcall at init/main.c:826
[    2.104009]        kernel_init_freeable+0x116/0x1db:
do_initcall_level at init/main.c:891
  (inlined by) do_initcalls at init/main.c:900
  (inlined by) do_basic_setup at init/main.c:918
  (inlined by) kernel_init_freeable at init/main.c:1066
[    2.104009]        kernel_init+0xa/0x160:
kernel_init at init/main.c:995
[    2.104009]        ret_from_fork+0x24/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:443
[    2.104009]
[    2.104009] -> #0 (ww_class_mutex){+.+.}:
[    2.104009]        test_abba_work+0xd9/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:179
[    2.104009]
[    2.104009] other info that might help us debug this:
[    2.104009]
[    2.104009]  Possible unsafe locking scenario by crosslock:
[    2.104009]
[    2.104009]        CPU0                    CPU1
[    2.104009]        ----                    ----
[    2.104009]   lock(ww_class_mutex);
[    2.104009]   lock((completion)&abba.b_ready);
[    2.104009]                                lock(ww_class_mutex);
[    2.104009]                                unlock((completion)&abba.b_ready);
[    2.104009]
[    2.104009]  *** DEADLOCK ***
[    2.104009]
[    2.104009] 5 locks held by kworker/0:1/14:
[    2.104009]  #0:  ((wq_completion)"events"){+.+.}, at: [<ffffffff8111a46b>] process_one_work+0x32b/0xae0:
set_work_data at kernel/workqueue.c:617
  (inlined by) set_work_pool_and_clear_pending at kernel/workqueue.c:645
  (inlined by) process_one_work at kernel/workqueue.c:2083
[    2.104009]  #1:  ((work_completion)(&abba.work)){+.+.}, at: [<ffffffff8111a46b>] process_one_work+0x32b/0xae0:
set_work_data at kernel/workqueue.c:617
  (inlined by) set_work_pool_and_clear_pending at kernel/workqueue.c:645
  (inlined by) process_one_work at kernel/workqueue.c:2083
[    2.104009]  #2:  (ww_class_acquire){+.+.}, at: [<ffffffff8111a62c>] process_one_work+0x4ec/0xae0:
__read_once_size at include/linux/compiler.h:178
  (inlined by) atomic_read at arch/x86/include/asm/atomic.h:27
  (inlined by) static_key_count at include/linux/jump_label.h:191
  (inlined by) static_key_false at include/linux/jump_label.h:201
  (inlined by) trace_workqueue_execute_end at include/trace/events/workqueue.h:112
  (inlined by) process_one_work at kernel/workqueue.c:2117
[    2.104009]  #3:  (ww_class_mutex){+.+.}, at: [<ffffffff8115fd09>] test_abba_work+0xd9/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:179
[    2.104009]  #4:  (&x->wait#5){....}, at: [<ffffffff8114a538>] complete+0x18/0x70:
complete_release_commit at include/linux/completion.h:50
  (inlined by) complete at kernel/sched/completion.c:40
[    2.104009]
[    2.104009] stack backtrace:
[    2.104009] CPU: 0 PID: 14 Comm: kworker/0:1 Not tainted 4.14.0-12891-gc8a0739 #1
[    2.104009] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[    2.104009] Workqueue: events test_abba_work
[    2.104009] Call Trace:
[    2.104009]  print_circular_bug+0x2d8/0x2f0:
print_circular_bug at kernel/locking/lockdep.c:1274
[    2.104009]  check_prev_add+0x150/0x700:
check_prev_add at kernel/locking/lockdep.c:1914
[    2.104009]  ? zap_class+0xe0/0xe0:
copy_trace at kernel/locking/lockdep.c:4984
[    2.104009]  ? lock_commit_crosslock+0x4df/0x600:
commit_xhlock at kernel/locking/lockdep.c:5023
  (inlined by) commit_xhlocks at kernel/locking/lockdep.c:5067
  (inlined by) lock_commit_crosslock at kernel/locking/lockdep.c:5106
[    2.104009]  lock_commit_crosslock+0x4df/0x600:
commit_xhlock at kernel/locking/lockdep.c:5023
  (inlined by) commit_xhlocks at kernel/locking/lockdep.c:5067
  (inlined by) lock_commit_crosslock at kernel/locking/lockdep.c:5106
[    2.104009]  ? do_raw_spin_lock+0xbe/0x100:
debug_spin_lock_before at kernel/locking/spinlock_debug.c:85
  (inlined by) do_raw_spin_lock at kernel/locking/spinlock_debug.c:112
[    2.104009]  complete+0x25/0x70:
complete at kernel/sched/completion.c:42
[    2.104009]  test_abba_work+0xe5/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:180
[    2.104009]  ? process_one_work+0x4ec/0xae0:
__read_once_size at include/linux/compiler.h:178
  (inlined by) atomic_read at arch/x86/include/asm/atomic.h:27
  (inlined by) static_key_count at include/linux/jump_label.h:191
  (inlined by) static_key_false at include/linux/jump_label.h:201
  (inlined by) trace_workqueue_execute_end at include/trace/events/workqueue.h:112
  (inlined by) process_one_work at kernel/workqueue.c:2117
[    2.104009]  process_one_work+0x4ec/0xae0:
__read_once_size at include/linux/compiler.h:178
  (inlined by) atomic_read at arch/x86/include/asm/atomic.h:27
  (inlined by) static_key_count at include/linux/jump_label.h:191
  (inlined by) static_key_false at include/linux/jump_label.h:201
  (inlined by) trace_workqueue_execute_end at include/trace/events/workqueue.h:112
  (inlined by) process_one_work at kernel/workqueue.c:2117
[    2.104009]  worker_thread+0x3d8/0x6c0:
__read_once_size at include/linux/compiler.h:178
  (inlined by) list_empty at include/linux/list.h:203
  (inlined by) worker_thread at kernel/workqueue.c:2247
[    2.104009]  ? process_one_work+0xae0/0xae0:
worker_thread at kernel/workqueue.c:2189
[    2.104009]  kthread+0x1a1/0x1b0:
kthread at kernel/kthread.c:240
[    2.104009]  ? __kthread_bind_mask+0x40/0x40
[    2.104009]  ret_from_fork+0x24/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:443
[    2.592101] tsc: Refined TSC clocksource calibration: 2693.508 MHz
[    2.592788] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x26d349e8249, max_idle_ns: 440795288087 ns
[    8.156610] torture_init_begin: Refusing rcu init: spin_lock running.
[    8.157659] torture_init_begin: One torture test at a time!
[    8.161633] Initialise system trusted keyrings

Attached the full dmesg, kconfig and reproduce scripts.

Thanks,
Fengguang

View attachment "dmesg-vm-ivb41-yocto-ia32-10:20171120163240:x86_64-randconfig-h0-11121445:4.14.0-12891-gc8a0739:1" of type "text/plain" (59902 bytes)

View attachment ".config" of type "text/plain" (104643 bytes)

View attachment "job-script" of type "text/plain" (3786 bytes)

View attachment "reproduce-vm-ivb41-yocto-ia32-10:20171120163240:x86_64-randconfig-h0-11121445:4.14.0-12891-gc8a0739:1" of type "text/plain" (2135 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ