2022-03-11 21:04:45

by kernel test robot

[permalink] [raw]
Subject: [cifs] 187af6e98b: BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c



Greeting,

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

commit: 187af6e98b44e5d8f25e1d41a92db138eb54416f ("cifs: fix handlecache and multiuser")
git://github.com/smfrench/smb3-kernel.git for-next

in testcase: xfstests
version: xfstests-x86_64-1de1db8-1_20220217
with following parameters:

disk: 4HDD
fs: ext4
fs2: smbv3
test: generic-group-17
ucode: 0xec

test-description: xfstests is a regression test suite for xfs and other files ystems.
test-url: git://git.kernel.org/pub/scm/fs/xfs/xfstests-dev.git


on test machine: 8 threads Intel(R) Core(TM) i7-6700 CPU @ 3.40GHz with 16G memory

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



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


[ 74.561542][ T1668] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:280
[ 74.570943][ T1668] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 1668, name: umount
[ 74.579453][ T1668] preempt_count: 1, expected: 0
[ 74.584151][ T1668] CPU: 1 PID: 1668 Comm: umount Not tainted 5.17.0-rc7-00001-g187af6e98b44 #1
[ 74.592828][ T1668] Hardware name: HP HP Z240 SFF Workstation/802E, BIOS N51 Ver. 01.63 10/05/2017
[ 74.601756][ T1668] Call Trace:
[ 74.604892][ T1668] <TASK>
[ 74.607681][ T1668] dump_stack_lvl (lib/dump_stack.c:107)
[ 74.612028][ T1668] __might_resched.cold (kernel/sched/core.c:9586 kernel/sched/core.c:9539)
[ 74.617065][ T1668] mutex_lock (kernel/locking/mutex.c:280)
[ 74.621155][ T1668] ? __mutex_lock_slowpath (kernel/locking/mutex.c:279)
[ 74.626279][ T1668] ? _raw_spin_lock_bh (kernel/locking/spinlock.c:153)
[ 74.631231][ T1668] ? dput (fs/dcache.c:788 fs/dcache.c:900)
[ 74.634973][ T1668] cifs_kill_sb (fs/cifs/cifsfs.c:276) cifs
[ 74.639898][ T1668] deactivate_locked_super (fs/super.c:339)
[ 74.645110][ T1668] cleanup_mnt (fs/namespace.c:1174)
[ 74.649369][ T1668] task_work_run (kernel/task_work.c:166 (discriminator 1))
[ 74.653715][ T1668] exit_to_user_mode_prepare (include/linux/tracehook.h:188 kernel/entry/common.c:175 kernel/entry/common.c:207)
[ 74.659185][ T1668] syscall_exit_to_user_mode (arch/x86/include/asm/jump_label.h:27 include/linux/context_tracking_state.h:31 include/linux/context_tracking.h:40 kernel/entry/common.c:130 kernel/entry/common.c:302)
[ 74.664483][ T1668] do_syscall_64 (arch/x86/entry/common.c:87)
[ 74.668746][ T1668] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:113)
[ 74.674474][ T1668] RIP: 0033:0x7f3a611a1507
[ 74.678734][ T1668] Code: 19 0c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 31 f6 e9 09 00 00 00 66 0f 1f 84 00 00 00 00 00 b8 a6 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 59 19 0c 00 f7 d8 64 89 01 48
All code
========
0: 19 0c 00 sbb %ecx,(%rax,%rax,1)
3: f7 d8 neg %eax
5: 64 89 01 mov %eax,%fs:(%rcx)
8: 48 83 c8 ff or $0xffffffffffffffff,%rax
c: c3 retq
d: 66 0f 1f 44 00 00 nopw 0x0(%rax,%rax,1)
13: 31 f6 xor %esi,%esi
15: e9 09 00 00 00 jmpq 0x23
1a: 66 0f 1f 84 00 00 00 nopw 0x0(%rax,%rax,1)
21: 00 00
23: b8 a6 00 00 00 mov $0xa6,%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 59 19 0c 00 mov 0xc1959(%rip),%rcx # 0xc1993
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 59 19 0c 00 mov 0xc1959(%rip),%rcx # 0xc1969
10: f7 d8 neg %eax
12: 64 89 01 mov %eax,%fs:(%rcx)
15: 48 rex.W
[ 74.698120][ T1668] RSP: 002b:00007ffca5c1bd18 EFLAGS: 00000246 ORIG_RAX: 00000000000000a6
[ 74.706354][ T1668] RAX: 0000000000000000 RBX: 00005558d280c970 RCX: 00007f3a611a1507
[ 74.714158][ T1668] RDX: 0000000000000001 RSI: 0000000000000000 RDI: 00005558d2819880
[ 74.721960][ T1668] RBP: 0000000000000000 R08: 0000000000000003 R09: 0000000000000000
[ 74.729766][ T1668] R10: 00005558d280c010 R11: 0000000000000246 R12: 00005558d2819880
[ 74.737571][ T1668] R13: 00007f3a612c71c4 R14: 00005558d280ca68 R15: 00005558d280cb80
[ 74.745375][ T1668] </TASK>
[ 75.031130][ T374] 2022-03-09 08:21:14 mount /dev/sda1 /fs/sda1
[ 75.031140][ T374]
[ 75.239400][ T1675] EXT4-fs (sda1): mounted filesystem with ordered data mode. Quota mode: none.
[ 75.252398][ T374] 2022-03-09 08:21:14 mkdir -p /smbv3//cifs/sda1
[ 75.252410][ T374]
[ 75.261526][ T374] 2022-03-09 08:21:14 export FSTYP=cifs
[ 75.261532][ T374]
[ 75.270233][ T374] 2022-03-09 08:21:14 export TEST_DEV=//localhost/fs/sda1
[ 75.270240][ T374]
[ 75.280459][ T374] 2022-03-09 08:21:14 export TEST_DIR=/smbv3//cifs/sda1
[ 75.280466][ T374]
[ 75.291769][ T374] 2022-03-09 08:21:14 export CIFS_MOUNT_OPTIONS=-ousername=root,password=pass,noperm,vers=3.0,mfsymlinks,actimeo=0
[ 75.291776][ T374]
[ 75.307646][ T374] 2022-03-09 08:21:14 sed "s:^:generic/:" //lkp/benchmarks/xfstests/tests/generic-group-17
[ 75.307653][ T374]
[ 75.327839][ T374] 2022-03-09 08:21:14 ./check -E tests/cifs/exclude.incompatible-smb3.txt -E tests/cifs/exclude.very-slow.txt generic/340 generic/341 generic/342 generic/343 generic/344 generic/345 generic/346 generic/347 generic/348 generic/349 generic/350 generic/351 generic/352 generic/353 generic/354 generic/355 generic/356 generic/357 generic/358 generic/359
[ 75.327849][ T374]
[ 75.483648][ T1827] CIFS: Attempting to mount \localhostfs
[ 75.699964][ T376] 512+0 records in
[ 75.699974][ T376]
[ 75.760407][ T376] 512+0 records out
[ 75.760416][ T376]
[ 75.879469][ T374] FSTYP -- cifs
[ 75.879478][ T374]
[ 75.892612][ T374] PLATFORM -- Linux/x86_64 lkp-skl-d07 5.17.0-rc7-00001-g187af6e98b44 #1 SMP Wed Mar 9 07:29:53 CST 2022
[ 75.892621][ T374]
[ 75.906288][ T374]
[ 75.906294][ T374]
[ 75.939060][ T1691] run fstests generic/340 at 2022-03-09 08:21:14
[ 76.259980][ T374] generic/340 [not run] this test requires a valid $SCRATCH_DEV
[ 76.259990][ T374]
[ 76.319584][ T1691] run fstests generic/341 at 2022-03-09 08:21:15
[ 76.679861][ T374] generic/341 [not run] this test requires a valid $SCRATCH_DEV
[ 76.679871][ T374]
[ 76.740767][ T1691] run fstests generic/342 at 2022-03-09 08:21:15
[ 77.106763][ T374] generic/342 [not run] this test requires a valid $SCRATCH_DEV
[ 77.106773][ T374]
[ 77.168094][ T1691] run fstests generic/343 at 2022-03-09 08:21:16
[ 77.559600][ T374] generic/343 [not run] this test requires a valid $SCRATCH_DEV
[ 77.559610][ T374]
[ 77.621918][ T1691] run fstests generic/344 at 2022-03-09 08:21:16
[ 77.900535][ T376] 262144 bytes (262 kB, 256 KiB) copied, 0.0136526 s, 19.2 MB/s
[ 77.900545][ T376]
[ 77.910559][ T376] 512+0 records in
[ 77.910565][ T376]
[ 77.916687][ T376] 512+0 records out
[ 77.916693][ T376]
[ 77.923774][ T376] 262144 bytes (262 kB, 256 KiB) copied, 0.124869 s, 2.1 MB/s
[ 77.923784][ T376]
[ 77.933597][ T376] 512+0 records in
[ 77.933604][ T376]
[ 77.939717][ T376] 512+0 records out
[ 77.939723][ T376]
[ 77.946815][ T376] 262144 bytes (262 kB, 256 KiB) copied, 0.0339024 s, 7.7 MB/s
[ 77.946822][ T376]
[ 77.955841][ T374] generic/344 [not run] this test requires a valid $SCRATCH_DEV
[ 77.956391][ T374]
[ 78.009695][ T1691] run fstests generic/345 at 2022-03-09 08:21:17
[ 78.306499][ T374] generic/345 [not run] this test requires a valid $SCRATCH_DEV
[ 78.306508][ T374]
[ 78.359294][ T1691] run fstests generic/346 at 2022-03-09 08:21:17
[ 78.657899][ T374] generic/346 [not run] this test requires a valid $SCRATCH_DEV
[ 78.657909][ T374]
[ 78.710496][ T1691] run fstests generic/347 at 2022-03-09 08:21:17
[ 79.092262][ T374] generic/347 [not run] this test requires a valid $SCRATCH_DEV
[ 79.092271][ T374]
[ 79.143820][ T1691] run fstests generic/348 at 2022-03-09 08:21:18
[ 79.476259][ T374] generic/348 [not run] this test requires a valid $SCRATCH_DEV
[ 79.476268][ T374]
[ 79.528611][ T1691] run fstests generic/349 at 2022-03-09 08:21:18
[ 79.890188][ T1830] Attempt to set a LOCK_MAND lock via flock(2). This support has been removed and the request ignored.
[ 79.949726][ T3759] scsi_debug:sdebug_add_store: 8192 provisioning blocks
[ 79.957335][ T3759] scsi_debug:sdebug_driver_probe: scsi_debug: trim poll_queues to 0. poll_q/nr_hw = (0/1)
[ 79.967058][ T3759] scsi host4: scsi_debug: version 0190 [20200710]
[ 79.967058][ T3759] dev_size_mb=4, opts=0x0, submit_queues=1, statistics=0
[ 79.981743][ T57] scsi 4:0:0:0: Direct-Access Linux scsi_debug 0190 PQ: 0 ANSI: 7
[ 79.991267][ C1] sd 4:0:0:0: Power-on or device reset occurred
[ 79.991273][ T57] sd 4:0:0:0: Attached scsi generic sg2 type 0
[ 79.999665][ T58] sd 4:0:0:0: [sdc] 8192 512-byte logical blocks: (4.19 MB/4.00 MiB)
[ 80.012384][ T58] sd 4:0:0:0: [sdc] Write Protect is off
[ 80.017885][ T58] sd 4:0:0:0: [sdc] Mode Sense: 73 00 10 08
[ 80.025694][ T58] sd 4:0:0:0: [sdc] Write cache: enabled, read cache: enabled, supports DPO and FUA
[ 80.037986][ T58] sd 4:0:0:0: [sdc] Optimal transfer size 524288 bytes
[ 80.087055][ T58] sd 4:0:0:0: [sdc] Attached SCSI disk
[ 80.280021][ T3793] sd 4:0:0:0: [sdc] Synchronizing SCSI cache


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.



---
0-DAY CI Kernel Test Service
https://lists.01.org/hyperkitty/list/[email protected]

Thanks,
Oliver Sang


Attachments:
(No filename) (10.37 kB)
config-5.17.0-rc7-00001-g187af6e98b44 (168.17 kB)
job-script (5.73 kB)
dmesg.xz (28.17 kB)
xfstests (3.38 kB)
job.yaml (4.85 kB)
reproduce (1.54 kB)
Download all attachments