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] [day] [month] [year] [list]
Message-ID: <20211110063928.GB30217@xsang-OptiPlex-9020>
Date:   Wed, 10 Nov 2021 14:39:28 +0800
From:   kernel test robot <oliver.sang@...el.com>
To:     Kuniyuki Iwashima <kuniyu@...zon.co.jp>
Cc:     lkp@...ts.01.org, lkp@...el.com,
        "David S. Miller" <davem@...emloft.net>,
        Jakub Kicinski <kuba@...nel.org>,
        Kuniyuki Iwashima <kuniyu@...zon.co.jp>,
        Kuniyuki Iwashima <kuni1840@...il.com>,
        Benjamin Herrenschmidt <benh@...zon.com>,
        netdev@...r.kernel.org
Subject: [af_unix]  95e381b609: WARNING:possible_recursive_locking_detected



Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: 95e381b6095d0808a64ecbe36515cca2ea2df477 ("[PATCH net-next 12/13] af_unix: Replace the big lock with small locks.")
url: https://github.com/0day-ci/linux/commits/Kuniyuki-Iwashima/af_unix-Replace-unix_table_lock-with-per-hash-locks/20211106-172208
base: https://git.kernel.org/cgit/linux/kernel/git/davem/net-next.git 84882cf72cd774cf16fd338bdbf00f69ac9f9194
patch link: https://lore.kernel.org/netdev/20211106091712.15206-13-kuniyu@amazon.co.jp

in testcase: kernel-selftests
version: kernel-selftests-x86_64-c8c9111a-1_20210929
with following parameters:

	group: x86
	ucode: 0xde

test-description: The kernel contains a set of "self tests" under the tools/testing/selftests/ directory. These are intended to be small unit tests to exercise individual code paths in the kernel.
test-url: https://www.kernel.org/doc/Documentation/kselftest.txt


on test machine: 4 threads 1 sockets Intel(R) Core(TM) i7-7567U CPU @ 3.50GHz with 32G memory

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):


+---------------------------------------------+------------+------------+
|                                             | 5c1456529e | 95e381b609 |
+---------------------------------------------+------------+------------+
| boot_successes                              | 4          | 0          |
| boot_failures                               | 0          | 4          |
| WARNING:possible_recursive_locking_detected | 0          | 4          |
+---------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <oliver.sang@...el.com>


kern  :warn  : [   39.215794] WARNING: possible recursive locking detected
kern  :warn  : [   39.216286] 5.15.0-rc7-02477-g95e381b6095d #1 Not tainted
kern  :warn  : [   39.216816] --------------------------------------------
kern  :warn  : [   39.217306] systemd/1 is trying to acquire lock:
kern :warn : [   39.217783] ffffffff87c53fb8 (&unix_table_locks[i]){+.+.}-{2:2}, at: unix_bind (net/unix/af_unix.c:1176 net/unix/af_unix.c:1253) 
kern  :warn  : [   39.218514]
but task is already holding lock:
kern :warn : [   39.219142] ffffffff87c4de38 (&unix_table_locks[i]){+.+.}-{2:2}, at: unix_table_double_lock (net/unix/af_unix.c:170) 
kern  :warn  : [   39.219969]
other info that might help us debug this:
kern  :warn  : [   39.220611]  Possible unsafe locking scenario:

kern  :warn  : [   39.221209]        CPU0
kern  :warn  : [   39.221499]        ----
kern  :warn  : [   39.221789]   lock(&unix_table_locks[i]);
kern  :warn  : [   39.222191]   lock(&unix_table_locks[i]);
kern  :warn  : [   39.222592]
*** DEADLOCK ***

kern  :warn  : [   39.223256]  May be due to missing lock nesting notation

kern  :warn  : [   39.223919] 4 locks held by systemd/1:
kern :warn : [   39.224301] #0: ffff8888765ca448 (sb_writers#6){.+.+}-{0:0}, at: filename_create (fs/namei.c:3656) 
kern :warn : [   39.225037] #1: ffff888100275280 (&type->i_mutex_dir_key#4/1){+.+.}-{3:3}, at: filename_create (fs/namei.c:3657) 
kern :warn : [   39.225863] #2: ffff888874f82e18 (&u->bindlock){+.+.}-{3:3}, at: unix_bind (net/unix/af_unix.c:1168 net/unix/af_unix.c:1253) 
kern :warn : [   39.226571] #3: ffffffff87c4de38 (&unix_table_locks[i]){+.+.}-{2:2}, at: unix_table_double_lock (net/unix/af_unix.c:170) 
kern  :warn  : [   39.227394]
stack backtrace:
kern  :warn  : [   39.227885] CPU: 2 PID: 1 Comm: systemd Not tainted 5.15.0-rc7-02477-g95e381b6095d #1
kern  :warn  : [   39.228571] Hardware name: Intel Corporation NUC7i7BNH/NUC7i7BNB, BIOS BNKBL357.86A.0067.2018.0814.1500 08/14/2018
kern  :warn  : [   39.229434] Call Trace:
kern :warn : [   39.229727] dump_stack_lvl (lib/dump_stack.c:107) 
kern :warn : [   39.230107] __lock_acquire.cold (kernel/locking/lockdep.c:2944 kernel/locking/lockdep.c:2987 kernel/locking/lockdep.c:3776 kernel/locking/lockdep.c:5015) 
kern :warn : [   39.230530] ? lockdep_hardirqs_on_prepare (kernel/locking/lockdep.c:4873) 
kern :warn : [   39.231012] ? lock_is_held_type (kernel/locking/lockdep.c:438 kernel/locking/lockdep.c:5669) 
kern :warn : [   39.231426] ? lockdep_hardirqs_on_prepare (kernel/locking/lockdep.c:4873) 
kern :warn : [   39.231907] ? lock_is_held_type (kernel/locking/lockdep.c:438 kernel/locking/lockdep.c:5669) 
kern :warn : [   39.232321] ? rcu_read_lock_sched_held (include/linux/lockdep.h:283 kernel/rcu/update.c:125) 
kern :warn : [   39.232779] lock_acquire (kernel/locking/lockdep.c:438 kernel/locking/lockdep.c:5627 kernel/locking/lockdep.c:5590) 
kern :warn : [   39.233155] ? unix_bind (net/unix/af_unix.c:1176 net/unix/af_unix.c:1253) 
kern :warn : [   39.233533] ? rcu_read_unlock (include/linux/rcupdate.h:716 (discriminator 5)) 
kern :warn : [   39.233932] ? do_raw_spin_lock (arch/x86/include/asm/atomic.h:202 include/linux/atomic/atomic-instrumented.h:513 include/asm-generic/qspinlock.h:82 kernel/locking/spinlock_debug.c:115) 
kern :warn : [   39.234346] ? rwlock_bug+0xc0/0xc0 
kern :warn : [   39.234757] _raw_spin_lock (include/linux/spinlock_api_smp.h:143 kernel/locking/spinlock.c:154) 
kern :warn : [   39.235135] ? unix_bind (net/unix/af_unix.c:1176 net/unix/af_unix.c:1253) 
kern :warn : [   39.235513] unix_bind (net/unix/af_unix.c:1176 net/unix/af_unix.c:1253) 
kern :warn : [   39.235880] ? unix_socketpair (net/unix/af_unix.c:1239) 
kern :warn : [   39.236289] ? _copy_from_user (arch/x86/include/asm/uaccess_64.h:46 arch/x86/include/asm/uaccess_64.h:52 lib/usercopy.c:16) 
kern :warn : [   39.236694] __sys_bind (net/socket.c:1693) 
kern :warn : [   39.237061] ? __ia32_sys_socketpair (net/socket.c:1680) 
kern :warn : [   39.237504] ? lock_is_held_type (kernel/locking/lockdep.c:438 kernel/locking/lockdep.c:5669) 
kern :warn : [   39.237919] ? lock_is_held_type (kernel/locking/lockdep.c:438 kernel/locking/lockdep.c:5669) 
kern :warn : [   39.238332] ? syscall_enter_from_user_mode (kernel/entry/common.c:107) 
kern :warn : [   39.241493] ? rcu_read_lock_sched_held (include/linux/lockdep.h:283 kernel/rcu/update.c:125) 
kern :warn : [   39.241951] ? rcu_read_lock_bh_held (kernel/rcu/update.c:120) 
kern :warn : [   39.242382] ? do_syscall_64 (arch/x86/entry/common.c:87) 
kern :warn : [   39.242768] __x64_sys_bind (net/socket.c:1702) 
kern :warn : [   39.243145] ? syscall_enter_from_user_mode (arch/x86/include/asm/irqflags.h:45 arch/x86/include/asm/irqflags.h:80 kernel/entry/common.c:107) 
kern :warn : [   39.243620] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80) 
kern :warn : [   39.243994] ? do_syscall_64 (arch/x86/entry/common.c:87) 
kern :warn : [   39.244378] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:4344) 
kern :warn : [   39.244803] ? do_syscall_64 (arch/x86/entry/common.c:87) 
kern :warn : [   39.245188] ? do_syscall_64 (arch/x86/entry/common.c:87) 
kern :warn : [   39.245571] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:4344) 
kern :warn : [   39.245997] ? do_syscall_64 (arch/x86/entry/common.c:87) 
kern :warn : [   39.246380] ? asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:638) 
kern :warn : [   39.246873] ? asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:638) 
kern :warn : [   39.247359] ? lockdep_hardirqs_on (kernel/locking/lockdep.c:4344) 
kern :warn : [   39.247786] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:113) 
kern  :warn  : [   39.248260] RIP: 0033:0x7f84b7e22497
kern :warn : [ 39.248632] Code: ff ff ff ff c3 48 8b 15 f7 09 0c 00 f7 d8 64 89 02 b8 ff ff ff ff eb ba 66 2e 0f 1f 84 00 00 00 00 00 90 b8 31 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c9 09 0c 00 f7 d8 64 89 01 48
All code
========
   0:	ff                   	(bad)  
   1:	ff                   	(bad)  
   2:	ff                   	(bad)  
   3:	ff c3                	inc    %ebx
   5:	48 8b 15 f7 09 0c 00 	mov    0xc09f7(%rip),%rdx        # 0xc0a03
   c:	f7 d8                	neg    %eax
   e:	64 89 02             	mov    %eax,%fs:(%rdx)
  11:	b8 ff ff ff ff       	mov    $0xffffffff,%eax
  16:	eb ba                	jmp    0xffffffffffffffd2
  18:	66 2e 0f 1f 84 00 00 	nopw   %cs:0x0(%rax,%rax,1)
  1f:	00 00 00 
  22:	90                   	nop
  23:	b8 31 00 00 00       	mov    $0x31,%eax
  28:	0f 05                	syscall 
  2a:*	48 3d 01 f0 ff ff    	cmp    $0xfffffffffffff001,%rax		<-- trapping instruction
  30:	73 01                	jae    0x33
  32:	c3                   	retq   
  33:	48 8b 0d c9 09 0c 00 	mov    0xc09c9(%rip),%rcx        # 0xc0a03
  3a:	f7 d8                	neg    %eax
  3c:	64 89 01             	mov    %eax,%fs:(%rcx)
  3f:	48                   	rex.W

Code starting with the faulting instruction
===========================================
   0:	48 3d 01 f0 ff ff    	cmp    $0xfffffffffffff001,%rax
   6:	73 01                	jae    0x9
   8:	c3                   	retq   
   9:	48 8b 0d c9 09 0c 00 	mov    0xc09c9(%rip),%rcx        # 0xc09d9
  10:	f7 d8                	neg    %eax
  12:	64 89 01             	mov    %eax,%fs:(%rcx)
  15:	48                   	rex.W
kern  :warn  : [   39.250101] RSP: 002b:00007ffd7751fa58 EFLAGS: 00000246 ORIG_RAX: 0000000000000031
kern  :warn  : [   39.250770] RAX: ffffffffffffffda RBX: 0000559d4fc70bb0 RCX: 00007f84b7e22497
kern  :warn  : [   39.251406] RDX: 0000000000000016 RSI: 00007ffd7751fa70 RDI: 000000000000000f
kern  :warn  : [   39.252042] RBP: 00007ffd7751fa70 R08: 000000000000000c R09: 0000559d4fcd6670
kern  :warn  : [   39.252679] R10: 00007ffd7751fa24 R11: 0000000000000246 R12: 000000000000000f
kern  :warn  : [   39.253314] R13: 0000000000000016 R14: 00007ffd7751fb50 R15: 00007ffd7751fb48
kern  :notice: [   39.425532] random: systemd-random-: uninitialized urandom read (512 bytes read)
kern  :info  : [   39.905355] intel_pmc_core INT33A1:00:  initialized
kern  :debug : [   40.139879] IOAPIC[2]: Set IRTE entry (P:1 FPD:0 Dst_Mode:1 Redir_hint:1 Trig_Mode:0 Dlvry_Mode:0 Avail:0 Vector:EF Dest:00000001 SID:F0F8 SQ:0 SVT:1)
kern  :debug : [   40.141118] IOAPIC[0]: Preconfigured routing entry (2-18 -> IRQ 18 Level:1 ActiveLow:1)
kern  :info  : [   40.186707] mei_me 0000:00:16.0: enabling device (0004 -> 0006)
kern  :debug : [   40.196333] libata version 3.00 loaded.
kern  :notice: [   40.361505] random: dbus-daemon: uninitialized urandom read (12 bytes read)
kern  :notice: [   40.365282] random: dbus-daemon: uninitialized urandom read (12 bytes read)
kern  :info  : [   40.969470] microcode: updated to revision 0xde, date = 2020-05-27
kern  :warn  : [   40.970115] x86/CPU: CPU features have changed after loading microcode, but might not take effect.
kern  :warn  : [   40.971061] x86/CPU: Please consider either early loading through initrd/built-in or a potential BIOS update.
kern  :info  : [   40.971992] microcode: Reload completed, microcode revision: 0xde
kern  :info  : [   41.013694] i801_smbus 0000:00:1f.4: SPD Write Disable is set
kern  :info  : [   41.014375] i801_smbus 0000:00:1f.4: SMBus using PCI interrupt
kern  :info  : [   41.015800] IPMI message handler: version 39.2
kern  :info  : [   41.022407] iTCO_wdt iTCO_wdt: Found a Intel PCH TCO device (Version=4, TCOBASE=0x0400)
kern  :info  : [   41.023587] ipmi device interface
kern  :info  : [   41.033277] iTCO_wdt iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
kern  :notice: [   41.048766] random: ln: uninitialized urandom read (6 bytes read)
kern  :debug : [   41.068893] ahci 0000:00:17.0: version 3.0
kern  :info  : [   41.115078] ipmi_si: IPMI System Interface driver
kern  :warn  : [   41.117158] ipmi_si: Unable to find any System Interface(s)
kern  :info  : [   41.117819] ahci 0000:00:17.0: AHCI 0001.0301 32 slots 2 ports 6 Gbps 0x5 impl SATA mode
kern  :info  : [   41.118556] ahci 0000:00:17.0: flags: 64bit ncq pm led clo only pio slum part deso sadm sds apst
kern  :notice: [   41.138009] random: ln: uninitialized urandom read (6 bytes read)
kern  :info  : [   41.170985] RAPL PMU: API unit is 2^-32 Joules, 5 fixed counters, 655360 ms ovfl timer
kern  :info  : [   41.171706] RAPL PMU: hw unit of domain pp0-core 2^-14 Joules
kern  :info  : [   41.172240] RAPL PMU: hw unit of domain package 2^-14 Joules
kern  :info  : [   41.172781] RAPL PMU: hw unit of domain dram 2^-14 Joules
kern  :info  : [   41.173296] RAPL PMU: hw unit of domain pp1-gpu 2^-14 Joules
kern  :info  : [   41.174495] RAPL PMU: hw unit of domain psys 2^-14 Joules
kern  :info  : [   41.220484] scsi host0: ahci
kern  :info  : [   41.235600] i2c i2c-0: 2/2 memory slots populated (from DMI)
kern  :info  : [   41.236463] scsi host1: ahci
kern  :info  : [   41.243332] i2c i2c-0: Successfully instantiated SPD at 0x50
kern  :info  : [   41.251989] scsi host2: ahci
kern  :info  : [   41.254369] ata1: SATA max UDMA/133 abar m2048@...c24b000 port 0xdc24b100 irq 129
kern  :info  : [   41.255076] ata2: DUMMY
kern  :info  : [   41.255403] ata3: SATA max UDMA/133 abar m2048@...c24b000 port 0xdc24b200 irq 129
kern  :info  : [   41.428685] i915 0000:00:02.0: [drm] Found 64MB of eDRAM
kern  :info  : [   41.429635] i915 0000:00:02.0: vgaarb: deactivate vga console


To reproduce:

        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        sudo bin/lkp install job.yaml           # job file is attached in this email
        bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
        sudo bin/lkp run generated-yaml-file

        # if come across any failure that blocks the test,
        # please remove ~/.lkp and /lkp dir to run from a clean state.



---
0DAY/LKP+ Test Infrastructure                   Open Source Technology Center
https://lists.01.org/hyperkitty/list/lkp@lists.01.org       Intel Corporation

Thanks,
Oliver Sang


View attachment "config-5.15.0-rc7-02477-g95e381b6095d" of type "text/plain" (176779 bytes)

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

Download attachment "kmsg.xz" of type "application/x-xz" (40396 bytes)

View attachment "kernel-selftests" of type "text/plain" (141325 bytes)

View attachment "job.yaml" of type "text/plain" (4888 bytes)

View attachment "reproduce" of type "text/plain" (147 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ