2020-09-06 09:05:53

by Chen, Rong A

[permalink] [raw]
Subject: [smsc95xx] 05b35e7eb9: WARNING:possible_circular_locking_dependency_detected

Greeting,

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

commit: 05b35e7eb9a11bbe8102836965e634c04e712c88 ("smsc95xx: add phylib support")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master


in testcase: trinity
version:
with following parameters:

runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

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


+-------------------------------------------------------+------------+------------+
| | ad90a73f02 | 05b35e7eb9 |
+-------------------------------------------------------+------------+------------+
| boot_successes | 323 | 248 |
| boot_failures | 6 | 80 |
| INFO:rcu_preempt_self-detected_stall_on_CPU | 5 | 3 |
| RIP:iov_iter_copy_from_user_atomic | 4 | 3 |
| BUG:soft_lockup-CPU##stuck_for#s![trinity-c4:#] | 2 | 2 |
| Kernel_panic-not_syncing:softlockup:hung_tasks | 3 | 2 |
| BUG:soft_lockup-CPU##stuck_for#s![trinity-c6:#] | 1 | |
| RIP:__task_pid_nr_ns | 1 | |
| RIP:syscall_enter_from_user_mode | 1 | |
| WARNING:at_net/sched/sch_generic.c:#dev_watchdog | 1 | |
| RIP:dev_watchdog | 1 | |
| BUG:kernel_hang_in_test_stage | 1 | 3 |
| WARNING:possible_circular_locking_dependency_detected | 0 | 69 |
| WARNING:possible_recursive_locking_detected | 0 | 6 |
| invoked_oom-killer:gfp_mask=0x | 0 | 1 |
| Mem-Info | 0 | 1 |
+-------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>


[ 276.006545] WARNING: possible circular locking dependency detected
[ 276.010112] 5.9.0-rc1-00605-g05b35e7eb9a11 #1 Not tainted
[ 276.013664] ------------------------------------------------------
[ 276.016801] trinity-c1/4424 is trying to acquire lock:
[ 276.020005] ffffffffa23705c8 (kexec_mutex){+.+.}-{3:3}, at: crash_get_memory_size+0x15/0x60
[ 276.023659]
[ 276.023659] but task is already holding lock:
[ 276.029215] ffff9a3cf9960c88 (&of->mutex){+.+.}-{3:3}, at: kernfs_seq_start+0x25/0xa0
[ 276.031572]
[ 276.031572] which lock already depends on the new lock.
[ 276.031572]
[ 276.039983]
[ 276.039983] the existing dependency chain (in reverse order) is:
[ 276.045899]
[ 276.045899] -> #2 (&of->mutex){+.+.}-{3:3}:
[ 276.051336] __lock_acquire+0x51c/0xb20
[ 276.054352] lock_acquire+0xab/0x3a0
[ 276.057203] __mutex_lock+0xac/0x9e0
[ 276.059937] kernfs_seq_start+0x25/0xa0
[ 276.062741] seq_read+0x93/0x420
[ 276.065388] vfs_read+0xb1/0x1c0
[ 276.067961] ksys_read+0x68/0xe0
[ 276.070463] do_syscall_64+0x33/0x40
[ 276.073039] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 276.075646]
[ 276.075646] -> #1 (&p->lock){+.+.}-{3:3}:
[ 276.080124] __lock_acquire+0x51c/0xb20
[ 276.082648] lock_acquire+0xab/0x3a0
[ 276.084973] __mutex_lock+0xac/0x9e0
[ 276.087252] seq_read+0x34/0x420
[ 276.089450] __kernel_read+0x71/0x180
[ 276.091647] kernel_read_file+0xd8/0x1a0
[ 276.093892] kernel_read_file_from_fd+0x44/0x80
[ 276.096103] kimage_file_alloc_init+0x86/0x240
[ 276.098313] __x64_sys_kexec_file_load+0x140/0x2a0
[ 276.100466] do_syscall_64+0x33/0x40
[ 276.102319] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 276.104485]
[ 276.104485] -> #0 (kexec_mutex){+.+.}-{3:3}:
[ 276.107942] check_prev_add+0x8e/0xa00
[ 276.109822] validate_chain+0x79b/0x1080
[ 276.111656] __lock_acquire+0x51c/0xb20
[ 276.113370] lock_acquire+0xab/0x3a0
[ 276.115071] __mutex_lock+0xac/0x9e0
[ 276.116726] crash_get_memory_size+0x15/0x60
[ 276.118445] kexec_crash_size_show+0xe/0x40
[ 276.120138] sysfs_kf_seq_show+0xb7/0x100
[ 276.121756] seq_read+0xba/0x420
[ 276.123289] do_iter_read+0x14e/0x1e0
[ 276.124831] compat_readv+0x9d/0xe0
[ 276.128646] do_compat_readv+0x58/0xc0
[ 276.130196] do_int80_syscall_32+0x41/0x60
[ 276.131494] entry_INT80_compat+0x88/0x8d
[ 276.132927]
[ 276.132927] other info that might help us debug this:
[ 276.132927]
[ 276.136642] Chain exists of:
[ 276.136642] kexec_mutex --> &p->lock --> &of->mutex
[ 276.136642]
[ 276.140393] Possible unsafe locking scenario:
[ 276.140393]
[ 276.142973] CPU0 CPU1
[ 276.144424] ---- ----
[ 276.145923] lock(&of->mutex);
[ 276.147223] lock(&p->lock);
[ 276.148759] lock(&of->mutex);
[ 276.150394] lock(kexec_mutex);
[ 276.151678]
[ 276.151678] *** DEADLOCK ***
[ 276.151678]
[ 276.154961] 4 locks held by trinity-c1/4424:
[ 276.156343] #0: ffff9a3ca6a0b0f0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x4a/0x60
[ 276.158210] #1: ffff9a3cfa3f86f8 (&p->lock){+.+.}-{3:3}, at: seq_read+0x34/0x420
[ 276.159807] #2: ffff9a3cf9960c88 (&of->mutex){+.+.}-{3:3}, at: kernfs_seq_start+0x25/0xa0
[ 276.161779] #3: ffff9a3d37d85740 (kn->active#99){.+.+}-{0:0}, at: kernfs_seq_start+0x2d/0xa0
[ 276.163899]
[ 276.163899] stack backtrace:
[ 276.166312] CPU: 1 PID: 4424 Comm: trinity-c1 Not tainted 5.9.0-rc1-00605-g05b35e7eb9a11 #1
[ 276.168453] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 276.170587] Call Trace:
[ 276.171886] dump_stack+0x96/0xe0
[ 276.173365] check_noncircular+0x162/0x180
[ 276.174963] ? stack_trace_save+0x4b/0x80
[ 276.176490] check_prev_add+0x8e/0xa00
[ 276.178029] validate_chain+0x79b/0x1080
[ 276.179573] __lock_acquire+0x51c/0xb20
[ 276.181059] lock_acquire+0xab/0x3a0
[ 276.182555] ? crash_get_memory_size+0x15/0x60
[ 276.184090] __mutex_lock+0xac/0x9e0
[ 276.185587] ? crash_get_memory_size+0x15/0x60
[ 276.187217] ? crash_get_memory_size+0x15/0x60
[ 276.188797] ? kernfs_seq_start+0x2d/0xa0
[ 276.190362] ? crash_get_memory_size+0x15/0x60
[ 276.191946] crash_get_memory_size+0x15/0x60
[ 276.193595] kexec_crash_size_show+0xe/0x40
[ 276.195155] sysfs_kf_seq_show+0xb7/0x100
[ 276.196666] seq_read+0xba/0x420
[ 276.198166] do_iter_read+0x14e/0x1e0
[ 276.199639] compat_readv+0x9d/0xe0
[ 276.201064] ? __fdget_pos+0x4a/0x60
[ 276.202634] ? lock_acquire+0xab/0x3a0


To reproduce:

# build kernel
cd linux
cp config-5.9.0-rc1-00605-g05b35e7eb9a11 .config
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage

git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Rong Chen


Attachments:
(No filename) (7.49 kB)
config-5.9.0-rc1-00605-g05b35e7eb9a11 (213.35 kB)
job-script (4.41 kB)
dmesg.xz (17.96 kB)
trinity (4.08 kB)
Download all attachments

2020-09-30 05:04:07

by Parthiban Veerasooran

[permalink] [raw]
Subject: Re: [smsc95xx] 05b35e7eb9: WARNING:possible_circular_locking_dependency_detected

Hi,

Greetings.

When I try to reproduce the issue reported in the below email using the below procedure, I am getting the below two issues (full dmesg is attached in this email).

I followed the procedure which is described in the below email. Please let me know whether am I doing anything wrong here. The procedure which I followed is below,

git clone git://git.kernel.org/pub/scm/linux/kernel/git/next/linux-next.git
git clone https://github.com/intel/lkp-tests.git
cd linux-next
git checkout 05b35e7eb9a11bbe8102836965e634c04e712c88
cp config-5.9.0-rc1-00605-g05b35e7eb9a11 .config # config-5.9.0-rc1-00605-g05b35e7eb9a11 is attached in this email
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
cp arch/x86/boot/bzImage ../lkp-tests

cd lkp-tests
bin/lkp qemu -k bzImage job-script # job-script is attached in this email

I executed the above procedure in my Ubuntu 18.04.1 desktop pc which is having 16GB RAM.

---------------------------------------------------------------------------------
[ 5.429388] random: fast init done
depmod: ERROR: could not open directory /lib/modules/5.9.0-rc1-00605-g05b35e7eb9a1: No such file or directory
depmod: WARNING: -e needs -E or -F
depmod: ERROR: could not open directory /lib/modules/5.9.0-rc1-00605-g05b35e7eb9a1: No such file or directory
depmod: FATAL: could not search modules: No such file or directory
[ 6.669157] urandom_read: 4 callbacks suppressed
[ 6.669160] random: dd: uninitialized urandom read (512 bytes read)
INIT: Entering runlevel: 5
Configuring network interfaces... ip: RTNETLINK answers: File exists
Starting syslogd/klogd: done
------------------------------------------------------------------------------------
[ 298.987156] futex_wake_op: trinity-c2 tries to shift op by -1157; fix this program
[ 301.205739] trinity-c7 invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=500
[ 301.208458] CPU: 1 PID: 5184 Comm: trinity-c7 Not tainted 5.9.0-rc1-00605-g05b35e7eb9a1 #19
[ 301.210476] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1ubuntu1 04/01/2014
[ 301.212578] Call Trace:
[ 301.213319] dump_stack+0x96/0xdb
[ 301.214204] dump_header+0x4f/0x3f0
[ 301.215127] oom_kill_process+0xfa/0x210
[ 301.216133] out_of_memory+0x11a/0x620
[ 301.217109] __alloc_pages_slowpath.constprop.107+0xbaa/0xf70
[ 301.218483] __alloc_pages_nodemask+0x3b4/0x450
[ 301.219610] alloc_pages_vma+0x7c/0x200
[ 301.220601] shmem_alloc_page+0x47/0x90
[ 301.221607] shmem_alloc_and_acct_page+0x78/0x1c0
[ 301.222767] shmem_getpage_gfp+0x17a/0x8d0
[ 301.223813] shmem_fallocate+0x439/0x5c0
[ 301.224821] ? lock_acquire+0xac/0x3b0
[ 301.225795] ? vfs_fallocate+0x1f4/0x270
[ 301.226803] ? __sb_start_write+0x190/0x280
[ 301.227858] ? preempt_count_sub+0xa1/0xe0
[ 301.228898] vfs_fallocate+0x142/0x270
[ 301.229876] ksys_fallocate+0x3c/0x70
[ 301.230834] __ia32_sys_ia32_fallocate+0x2e/0x40
[ 301.231971] do_int80_syscall_32+0x41/0x50
[ 301.233008] entry_INT80_compat+0x88/0x8d
[ 301.234034] RIP: 0033:0x407ebc
[ 301.234871] Code: 83 c0 01 41 89 80 40 30 00 00 8b 44 24 04 4c 89 d1 48 8b 54 24 08 4c 89 de 4c 89 e7 55 41 50 41 51 41 52 41 53 4c 89 cd cd 80 <41> 5b 41 5a 41 59 41 58 5d 48 3d 7a ff ff ff 49 89 c4 0f 87 5c 01
[ 301.238992] RSP: 002b:00007ffc345ba048 EFLAGS: 00000202 ORIG_RAX: 0000000000000144
[ 301.240825] RAX: ffffffffffffffda RBX: 0000000000000129 RCX: 0000000000000000
[ 301.242446] RDX: 00000000000000de RSI: 0000000000000004 RDI: 0000000000000100
[ 301.244063] RBP: 0000000002000000 R08: 00007f69e6087000 R09: 0000000002000000
[ 301.245684] R10: 0000000000000000 R11: 0000000000000004 R12: 0000000000000100
[ 301.247302] R13: 00007f69e5d5f058 R14: 0000000002cc3850 R15: 00007f69e5d5f000
[ 301.249120] Mem-Info:
[ 301.249896] active_anon:6522 inactive_anon:1701031 isolated_anon:0
[ 301.249896] active_file:0 inactive_file:10 isolated_file:0
[ 301.249896] unevictable:12230 dirty:2 writeback:0
[ 301.249896] slab_reclaimable:12215 slab_unreclaimable:11838
[ 301.249896] mapped:11302 shmem:1703813 pagetables:445 bounce:0
[ 301.249896] free:25493 free_pcp:267 free_cma:0
---------------------------------------------------------------------------------------------------------------

Thanks & Regards,
Parthiban V

From: kernel test robot <[email protected]>
Sent: Sunday, September 6, 2020 10:55
To: Andre Edich - M21181 <[email protected]>
Cc: David S. Miller <[email protected]>; LKML <[email protected]>; [email protected] <[email protected]>; [email protected] <[email protected]>
Subject: [smsc95xx] 05b35e7eb9: WARNING:possible_circular_locking_dependency_detected

EXTERNAL EMAIL: Do not click links or open attachments unless you know the content is safe

Greeting,

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

commit: 05b35e7eb9a11bbe8102836965e634c04e712c88 ("smsc95xx: add phylib support")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master


in testcase: trinity
version:
with following parameters:

runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 8G

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


+-------------------------------------------------------+------------+------------+
| | ad90a73f02 | 05b35e7eb9 |
+-------------------------------------------------------+------------+------------+
| boot_successes | 323 | 248 |
| boot_failures | 6 | 80 |
| INFO:rcu_preempt_self-detected_stall_on_CPU | 5 | 3 |
| RIP:iov_iter_copy_from_user_atomic | 4 | 3 |
| BUG:soft_lockup-CPU##stuck_for#s![trinity-c4:#] | 2 | 2 |
| Kernel_panic-not_syncing:softlockup:hung_tasks | 3 | 2 |
| BUG:soft_lockup-CPU##stuck_for#s![trinity-c6:#] | 1 | |
| RIP:__task_pid_nr_ns | 1 | |
| RIP:syscall_enter_from_user_mode | 1 | |
| WARNING:at_net/sched/sch_generic.c:#dev_watchdog | 1 | |
| RIP:dev_watchdog | 1 | |
| BUG:kernel_hang_in_test_stage | 1 | 3 |
| WARNING:possible_circular_locking_dependency_detected | 0 | 69 |
| WARNING:possible_recursive_locking_detected | 0 | 6 |
| invoked_oom-killer:gfp_mask=0x | 0 | 1 |
| Mem-Info | 0 | 1 |
+-------------------------------------------------------+------------+------------+


If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>


[ 276.006545] WARNING: possible circular locking dependency detected
[ 276.010112] 5.9.0-rc1-00605-g05b35e7eb9a11 #1 Not tainted
[ 276.013664] ------------------------------------------------------
[ 276.016801] trinity-c1/4424 is trying to acquire lock:
[ 276.020005] ffffffffa23705c8 (kexec_mutex){+.+.}-{3:3}, at: crash_get_memory_size+0x15/0x60
[ 276.023659]
[ 276.023659] but task is already holding lock:
[ 276.029215] ffff9a3cf9960c88 (&of->mutex){+.+.}-{3:3}, at: kernfs_seq_start+0x25/0xa0
[ 276.031572]
[ 276.031572] which lock already depends on the new lock.
[ 276.031572]
[ 276.039983]
[ 276.039983] the existing dependency chain (in reverse order) is:
[ 276.045899]
[ 276.045899] -> #2 (&of->mutex){+.+.}-{3:3}:
[ 276.051336] __lock_acquire+0x51c/0xb20
[ 276.054352] lock_acquire+0xab/0x3a0
[ 276.057203] __mutex_lock+0xac/0x9e0
[ 276.059937] kernfs_seq_start+0x25/0xa0
[ 276.062741] seq_read+0x93/0x420
[ 276.065388] vfs_read+0xb1/0x1c0
[ 276.067961] ksys_read+0x68/0xe0
[ 276.070463] do_syscall_64+0x33/0x40
[ 276.073039] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 276.075646]
[ 276.075646] -> #1 (&p->lock){+.+.}-{3:3}:
[ 276.080124] __lock_acquire+0x51c/0xb20
[ 276.082648] lock_acquire+0xab/0x3a0
[ 276.084973] __mutex_lock+0xac/0x9e0
[ 276.087252] seq_read+0x34/0x420
[ 276.089450] __kernel_read+0x71/0x180
[ 276.091647] kernel_read_file+0xd8/0x1a0
[ 276.093892] kernel_read_file_from_fd+0x44/0x80
[ 276.096103] kimage_file_alloc_init+0x86/0x240
[ 276.098313] __x64_sys_kexec_file_load+0x140/0x2a0
[ 276.100466] do_syscall_64+0x33/0x40
[ 276.102319] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 276.104485]
[ 276.104485] -> #0 (kexec_mutex){+.+.}-{3:3}:
[ 276.107942] check_prev_add+0x8e/0xa00
[ 276.109822] validate_chain+0x79b/0x1080
[ 276.111656] __lock_acquire+0x51c/0xb20
[ 276.113370] lock_acquire+0xab/0x3a0
[ 276.115071] __mutex_lock+0xac/0x9e0
[ 276.116726] crash_get_memory_size+0x15/0x60
[ 276.118445] kexec_crash_size_show+0xe/0x40
[ 276.120138] sysfs_kf_seq_show+0xb7/0x100
[ 276.121756] seq_read+0xba/0x420
[ 276.123289] do_iter_read+0x14e/0x1e0
[ 276.124831] compat_readv+0x9d/0xe0
[ 276.128646] do_compat_readv+0x58/0xc0
[ 276.130196] do_int80_syscall_32+0x41/0x60
[ 276.131494] entry_INT80_compat+0x88/0x8d
[ 276.132927]
[ 276.132927] other info that might help us debug this:
[ 276.132927]
[ 276.136642] Chain exists of:
[ 276.136642] kexec_mutex --> &p->lock --> &of->mutex
[ 276.136642]
[ 276.140393] Possible unsafe locking scenario:
[ 276.140393]
[ 276.142973] CPU0 CPU1
[ 276.144424] ---- ----
[ 276.145923] lock(&of->mutex);
[ 276.147223] lock(&p->lock);
[ 276.148759] lock(&of->mutex);
[ 276.150394] lock(kexec_mutex);
[ 276.151678]
[ 276.151678] *** DEADLOCK ***
[ 276.151678]
[ 276.154961] 4 locks held by trinity-c1/4424:
[ 276.156343] #0: ffff9a3ca6a0b0f0 (&f->f_pos_lock){+.+.}-{3:3}, at: __fdget_pos+0x4a/0x60
[ 276.158210] #1: ffff9a3cfa3f86f8 (&p->lock){+.+.}-{3:3}, at: seq_read+0x34/0x420
[ 276.159807] #2: ffff9a3cf9960c88 (&of->mutex){+.+.}-{3:3}, at: kernfs_seq_start+0x25/0xa0
[ 276.161779] #3: ffff9a3d37d85740 (kn->active#99){.+.+}-{0:0}, at: kernfs_seq_start+0x2d/0xa0
[ 276.163899]
[ 276.163899] stack backtrace:
[ 276.166312] CPU: 1 PID: 4424 Comm: trinity-c1 Not tainted 5.9.0-rc1-00605-g05b35e7eb9a11 #1
[ 276.168453] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 276.170587] Call Trace:
[ 276.171886] dump_stack+0x96/0xe0
[ 276.173365] check_noncircular+0x162/0x180
[ 276.174963] ? stack_trace_save+0x4b/0x80
[ 276.176490] check_prev_add+0x8e/0xa00
[ 276.178029] validate_chain+0x79b/0x1080
[ 276.179573] __lock_acquire+0x51c/0xb20
[ 276.181059] lock_acquire+0xab/0x3a0
[ 276.182555] ? crash_get_memory_size+0x15/0x60
[ 276.184090] __mutex_lock+0xac/0x9e0
[ 276.185587] ? crash_get_memory_size+0x15/0x60
[ 276.187217] ? crash_get_memory_size+0x15/0x60
[ 276.188797] ? kernfs_seq_start+0x2d/0xa0
[ 276.190362] ? crash_get_memory_size+0x15/0x60
[ 276.191946] crash_get_memory_size+0x15/0x60
[ 276.193595] kexec_crash_size_show+0xe/0x40
[ 276.195155] sysfs_kf_seq_show+0xb7/0x100
[ 276.196666] seq_read+0xba/0x420
[ 276.198166] do_iter_read+0x14e/0x1e0
[ 276.199639] compat_readv+0x9d/0xe0
[ 276.201064] ? __fdget_pos+0x4a/0x60
[ 276.202634] ? lock_acquire+0xab/0x3a0


To reproduce:

# build kernel
cd linux
cp config-5.9.0-rc1-00605-g05b35e7eb9a11 .config
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage

git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email



Thanks,
Rong Chen


Attachments:
dmesg_commit_05b35e7eb9a11bbe8102836965e634c04e712c88.txt (108.19 kB)
dmesg_commit_05b35e7eb9a11bbe8102836965e634c04e712c88.txt
config-5.9.0-rc1-00605-g05b35e7eb9a11 (213.35 kB)
config-5.9.0-rc1-00605-g05b35e7eb9a11
job-script (4.41 kB)
job-script
Download all attachments