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-next>] [day] [month] [year] [list]
Date:   Mon, 17 Dec 2018 12:16:15 +0800
From:   kernel test robot <lkp@...el.com>
To:     Bart Van Assche <bvanassche@....org>
Cc:     LKP <lkp@...org>, linux-kernel@...r.kernel.org
Subject: cdbeb78c7a ("kernel/workqueue: Use dynamic lockdep keys for .."):  WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:1002 lockdep_register_key

Greetings,

0day kernel testing robot got the below dmesg and the first bad commit is

https://github.com/bvanassche/linux for-next

commit cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9
Author:     Bart Van Assche <bvanassche@....org>
AuthorDate: Fri Nov 9 09:53:31 2018 -0800
Commit:     Bart Van Assche <bvanassche@....org>
CommitDate: Fri Dec 14 11:24:37 2018 -0800

    kernel/workqueue: Use dynamic lockdep keys for workqueues
    
    Commit 87915adc3f0a ("workqueue: re-add lockdep dependencies for flushing")
    improved deadlock checking in the workqueue implementation. Unfortunately
    that patch also introduced a few false positive lockdep complaints. This
    patch suppresses these false positives by allocating the workqueue mutex
    lockdep key dynamically. An example of a false positive lockdep complaint
    suppressed by this report can be found below. The root cause of the
    lockdep complaint shown below is that the direct I/O code can call
    alloc_workqueue() from inside a work item created by another
    alloc_workqueue() call and that both workqueues share the same lockdep
    key. This patch avoids that that lockdep complaint is triggered by
    allocating the work queue lockdep keys dynamically. In other words, this
    patch guarantees that a unique lockdep key is associated with each work
    queue mutex.
    
    ======================================================
    WARNING: possible circular locking dependency detected
    4.19.0-dbg+ #1 Not tainted
    ------------------------------------------------------
    fio/4129 is trying to acquire lock:
    00000000a01cfe1a ((wq_completion)"dio/%s"sb->s_id){+.+.}, at: flush_workqueue+0xd0/0x970
    
    but task is already holding lock:
    00000000a0acecf9 (&sb->s_type->i_mutex_key#14){+.+.}, at: ext4_file_write_iter+0x154/0x710
    
    which lock already depends on the new lock.
    
    the existing dependency chain (in reverse order) is:
    
    -> #2 (&sb->s_type->i_mutex_key#14){+.+.}:
           down_write+0x3d/0x80
           __generic_file_fsync+0x77/0xf0
           ext4_sync_file+0x3c9/0x780
           vfs_fsync_range+0x66/0x100
           dio_complete+0x2f5/0x360
           dio_aio_complete_work+0x1c/0x20
           process_one_work+0x481/0x9f0
           worker_thread+0x63/0x5a0
           kthread+0x1cf/0x1f0
           ret_from_fork+0x24/0x30
    
    -> #1 ((work_completion)(&dio->complete_work)){+.+.}:
           process_one_work+0x447/0x9f0
           worker_thread+0x63/0x5a0
           kthread+0x1cf/0x1f0
           ret_from_fork+0x24/0x30
    
    -> #0 ((wq_completion)"dio/%s"sb->s_id){+.+.}:
           lock_acquire+0xc5/0x200
           flush_workqueue+0xf3/0x970
           drain_workqueue+0xec/0x220
           destroy_workqueue+0x23/0x350
           sb_init_dio_done_wq+0x6a/0x80
           do_blockdev_direct_IO+0x1f33/0x4be0
           __blockdev_direct_IO+0x79/0x86
           ext4_direct_IO+0x5df/0xbb0
           generic_file_direct_write+0x119/0x220
           __generic_file_write_iter+0x131/0x2d0
           ext4_file_write_iter+0x3fa/0x710
           aio_write+0x235/0x330
           io_submit_one+0x510/0xeb0
           __x64_sys_io_submit+0x122/0x340
           do_syscall_64+0x71/0x220
           entry_SYSCALL_64_after_hwframe+0x49/0xbe
    
    other info that might help us debug this:
    
    Chain exists of:
      (wq_completion)"dio/%s"sb->s_id --> (work_completion)(&dio->complete_work) --> &sb->s_type->i_mutex_key#14
    
     Possible unsafe locking scenario:
    
           CPU0                    CPU1
           ----                    ----
      lock(&sb->s_type->i_mutex_key#14);
                                   lock((work_completion)(&dio->complete_work));
                                   lock(&sb->s_type->i_mutex_key#14);
      lock((wq_completion)"dio/%s"sb->s_id);
    
     *** DEADLOCK ***
    
    1 lock held by fio/4129:
     #0: 00000000a0acecf9 (&sb->s_type->i_mutex_key#14){+.+.}, at: ext4_file_write_iter+0x154/0x710
    
    stack backtrace:
    CPU: 3 PID: 4129 Comm: fio Not tainted 4.19.0-dbg+ #1
    Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
    Call Trace:
     dump_stack+0x86/0xc5
     print_circular_bug.isra.32+0x20a/0x218
     __lock_acquire+0x1c68/0x1cf0
     lock_acquire+0xc5/0x200
     flush_workqueue+0xf3/0x970
     drain_workqueue+0xec/0x220
     destroy_workqueue+0x23/0x350
     sb_init_dio_done_wq+0x6a/0x80
     do_blockdev_direct_IO+0x1f33/0x4be0
     __blockdev_direct_IO+0x79/0x86
     ext4_direct_IO+0x5df/0xbb0
     generic_file_direct_write+0x119/0x220
     __generic_file_write_iter+0x131/0x2d0
     ext4_file_write_iter+0x3fa/0x710
     aio_write+0x235/0x330
     io_submit_one+0x510/0xeb0
     __x64_sys_io_submit+0x122/0x340
     do_syscall_64+0x71/0x220
     entry_SYSCALL_64_after_hwframe+0x49/0xbe
    
    Cc: Ingo Molnar <mingo@...hat.com>
    Cc: Peter Zijlstra <peterz@...radead.org>
    Cc: Will Deacon <will.deacon@....com>
    Cc: Tejun Heo <tj@...nel.org>
    Cc: Waiman Long <longman@...hat.com>
    Cc: Johannes Berg <johannes.berg@...el.com>
    Signed-off-by: Bart Van Assche <bvanassche@....org>

60e521015c  locking/lockdep: Add support for dynamic keys
cdbeb78c7a  kernel/workqueue: Use dynamic lockdep keys for workqueues
9294000d6d  IB/srp: Drain the send queue before destroying a QP
+-----------------------------------------------------------+------------+------------+---------------------+
|                                                           | 60e521015c | cdbeb78c7a | bvanassche/for-next |
+-----------------------------------------------------------+------------+------------+---------------------+
| boot_successes                                            | 915        | 305        | 0                   |
| boot_failures                                             | 1          | 7          | 310                 |
| INFO:rcu_preempt_self-detected_stall_on_CPU               | 1          |            |                     |
| EIP:smp_call_function_single                              | 1          |            |                     |
| BUG:kernel_hang_in_boot-around-mounting-root_stage        | 1          |            |                     |
| WARNING:at_kernel/locking/lockdep.c:#lockdep_register_key | 0          | 7          |                     |
| EIP:lockdep_register_key                                  | 0          | 7          |                     |
| WARNING:kernel_stack                                      | 0          | 0          | 310                 |
+-----------------------------------------------------------+------------+------------+---------------------+

[    0.255225]       .init : 0x5cafd000 - 0x5cc21000   (1168 kB)
[    0.255225]       .data : 0x5bcd26bd - 0x5cae3a40   (14404 kB)
[    0.255225]       .text : 0x5a600000 - 0x5bcd26bd   (23369 kB)
[    0.255616] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[    0.263302] SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[    0.267586] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:1002 lockdep_register_key+0x3b/0x161
[    0.267680] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.20.0-rc6-00030-gcdbeb78 #1
[    0.267748] EIP: lockdep_register_key+0x3b/0x161
[    0.267837] Code: 57 56 53 89 c3 e8 9a e2 ff ff 83 05 28 fd e3 5c 01 83 15 2c fd e3 5c 00 85 c0 74 23 83 05 30 fd e3 5c 01 83 15 34 fd e3 5c 00 <0f> 0b 83 05 38 fd e3 5c 01 83 15 3c fd e3 5c 00 e9 0c 01 00 00 83
[    0.267901] EAX: 00000001 EBX: 5dc08098 ECX: 5cc9001c EDX: 00000000
[    0.267944] ESI: 5dc08000 EDI: 5dc080b8 EBP: 5c661f28 ESP: 5c661f1c
[    0.268007] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00210046
[    0.268069] CR0: 80050033 CR2: ffc6f000 CR3: 1cc2b000 CR4: 00000690
[    0.268137] Call Trace:
[    0.268229]  ? alloc_workqueue+0x1dd/0x63e
[    0.268356]  ? workqueue_init_early+0x302/0x522
[    0.268487]  ? start_kernel+0x60c/0xb08
[    0.268554]  ? i386_start_kernel+0x1b7/0x1c9
[    0.268620]  ? startup_32_smp+0x15f/0x164
[    0.268745] random: get_random_bytes called from init_oops_id+0x31/0x65 with crng_init=0
[    0.268815] ---[ end trace 358134c881f779eb ]---
[    0.270375] rcu: Preemptible hierarchical RCU implementation.

                                                          # HH:MM RESULT GOOD BAD GOOD_BUT_DIRTY DIRTY_NOT_BAD
git bisect start 76aaa5f181905fb71f79065478e486d3422338db 40e020c129cfc991e8ab4736d2665351ffd1468d --
git bisect  bad 4fafdd784cbe99b4b0f5e2c87f0849ea09a1e4dd  # 09:18  B     60     1    0   0  Merge 'dm/for-next' into devel-hourly-2018121509
git bisect good 66b85b30a8df43a5f3fe2871e2ee3c0d89f41fd1  # 11:03  G    236     0    0   0  Merge 'tty/tty-next' into devel-hourly-2018121509
git bisect good fe5dae5296a75d4f4f835b214da08f72e068a196  # 12:33  G    230     0    0   0  Merge 'tyhicks/apparmor/keyring' into devel-hourly-2018121509
git bisect good 0ed6b133563af0f842b98b811b6da1ede7cb18e9  # 13:29  G    237     0    0   0  Merge 'linux-review/Corentin-Labbe/sparc-Set-ARCH-sunxx-information-on-the-same-line/20181212-023207' into devel-hourly-2018121509
git bisect good 56bd71423bc2445a4fd3398e89611cad8bb54136  # 15:01  G    237     0    0   0  Merge 'rockchip/v4.21-armsoc/dts64' into devel-hourly-2018121509
git bisect good 10a3445ab315460e1cf2de1b14cf90619240f94e  # 15:29  G    237     0    0   0  Merge 'renesas/arm-dt-for-v4.22' into devel-hourly-2018121509
git bisect  bad a9419ab759baadf463d3ca44fc11ee4be433ac23  # 16:32  B     85     1    0   0  Merge 'arm-soc/amlogic/dt-2' into devel-hourly-2018121509
git bisect  bad afed425871d7a58095c1a7839ac088174fa57e13  # 19:06  B    129     1    0   0  Merge 'bvanassche/for-next' into devel-hourly-2018121509
git bisect good d39bbfc24d2040a2b1a9566fcf791fb00975c970  # 21:21  G    309     0    0   0  locking/lockdep: Make zap_class() remove all matching lock order entries
git bisect good ceefdaeedc43d36722fa200e998157985dc7e844  # 23:04  G    308     0    0   0  locking/lockdep: Check data structure consistency
git bisect  bad 826fc6028e1f5cc294fb39e26c96a4d88aeec379  # 00:06  B     26     1    0   0  tools-kernel
git bisect good 60e521015cc2a5532604c325d7a86f905706738e  # 00:38  G    303     0    0   0  locking/lockdep: Add support for dynamic keys
git bisect  bad 302d55b825c68479e0221425056bf753fe9d19c4  # 01:15  B     81     1    0   0  lockdep tests: Test dynamic key registration
git bisect  bad cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9  # 02:19  B     90     1    0   0  kernel/workqueue: Use dynamic lockdep keys for workqueues
# first bad commit: [cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9] kernel/workqueue: Use dynamic lockdep keys for workqueues
git bisect good 60e521015cc2a5532604c325d7a86f905706738e  # 02:44  G    908     0    0   0  locking/lockdep: Add support for dynamic keys
# extra tests with debug options
git bisect  bad cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9  # 04:01  B     22     1    0   0  kernel/workqueue: Use dynamic lockdep keys for workqueues
# extra tests on HEAD of linux-devel/devel-hourly-2018121509
git bisect  bad 76aaa5f181905fb71f79065478e486d3422338db  # 04:01  B     88     2    0   0  0day head guard for 'devel-hourly-2018121509'
# extra tests on tree/branch bvanassche/for-next
git bisect good 9294000d6d895ad609f3cc4aff98c9c6175b466f  # 10:51  G    308     0  308 308  IB/srp: Drain the send queue before destroying a QP
# extra tests with first bad commit reverted
git bisect good 322ac97e8b243ba9a707575087b7f97878e97db2  # 12:14  G    310     0    0   0  Revert "kernel/workqueue: Use dynamic lockdep keys for workqueues"

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/lkp                          Intel Corporation

Download attachment "dmesg-quantal-vm-quantal-239:20181217022531:i386-randconfig-x0-12151238:4.20.0-rc6-00030-gcdbeb78:1.gz" of type "application/gzip" (23968 bytes)

Download attachment "dmesg-quantal-vm-quantal-238:20181217024430:i386-randconfig-x0-12151238:4.20.0-rc6-00029-g60e5210:1.gz" of type "application/gzip" (10157 bytes)

View attachment "reproduce-quantal-vm-quantal-239:20181217022531:i386-randconfig-x0-12151238:4.20.0-rc6-00030-gcdbeb78:1" of type "text/plain" (910 bytes)

View attachment "config-4.20.0-rc6-00030-gcdbeb78" of type "text/plain" (115615 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ