FYI, we noticed the following commit (built with gcc-7):
commit: 11b771ffff8fc0bfc176b829d986896a7d97a44c ("IMA: Defined timer to free queued keys")
https://git.kernel.org/cgit/linux/kernel/git/zohar/linux-integrity.git next-integrity-testing
in testcase: kernel_selftests
with following parameters:
group: kselftests-03
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: 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):
+-----------------------------------------------------------------------------+------------+------------+
| | 8f3d06587d | 11b771ffff |
+-----------------------------------------------------------------------------+------------+------------+
| boot_successes | 23 | 11 |
| boot_failures | 0 | 18 |
| BUG:sleeping_function_called_from_invalid_context_at_kernel/locking/mutex.c | 0 | 18 |
| RIP:native_safe_halt | 0 | 11 |
| Mem-Info | 0 | 11 |
| RIP:console_unlock | 0 | 1 |
| RIP:__handle_mm_fault | 0 | 1 |
| RIP:clear_page_rep | 0 | 2 |
+-----------------------------------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <[email protected]>
[ 333.455345] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:281
[ 333.457243] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 12395, name: userfaultfd
[ 333.458888] CPU: 1 PID: 12395 Comm: userfaultfd Not tainted 5.5.0-rc1-00011-g11b771ffff8fc #1
[ 333.461096] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 333.463893] Call Trace:
[ 333.465287] <IRQ>
[ 333.466351] dump_stack+0x66/0x8b
[ 333.467346] ___might_sleep+0x102/0x120
[ 333.468385] mutex_lock+0x1c/0x40
[ 333.469421] ima_process_queued_keys+0x24/0x110
[ 333.470529] ? ima_process_queued_keys+0x110/0x110
[ 333.471656] call_timer_fn+0x2d/0x140
[ 333.472707] run_timer_softirq+0x46f/0x4b0
[ 333.473752] ? enqueue_hrtimer+0x39/0xa0
[ 333.474780] __do_softirq+0xe3/0x2f8
[ 333.475768] irq_exit+0xd5/0xe0
[ 333.476738] smp_apic_timer_interrupt+0x74/0x140
[ 333.477834] apic_timer_interrupt+0xf/0x20
[ 333.478858] </IRQ>
[ 333.479659] RIP: 0010:clear_page_rep+0x7/0x10
[ 333.480736] Code: fe ff ff 31 c0 eb 9f 0f 0b 48 c7 c0 aa ff ff ff eb 94 e8 fc b2 5f ff cc cc cc cc cc cc cc cc cc cc cc cc b9 00 02 00 00 31 c0 <f3> 48 ab c3 0f 1f 44 00 00 31 c0 b9 40 00 00 00 66 0f 1f 84 00 00
[ 333.483937] RSP: 0000:ffff9d1c02837c30 EFLAGS: 00010246 ORIG_RAX: ffffffffffffff13
[ 333.485439] RAX: 0000000000000000 RBX: ffff8977a8ca7770 RCX: 00000000000001a4
[ 333.486827] RDX: fffff15b069d40c0 RSI: ffff8977cafe8000 RDI: ffff8977a75032e0
[ 333.488241] RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000001
[ 333.489975] R10: 00000ea4f962bf3f R11: 0000000000000000 R12: ffff897786409640
[ 333.491485] R13: ffff8977a8ca78e0 R14: 0000000000001fdb R15: 0000000000000000
[ 333.493205] shmem_getpage_gfp+0x6de/0x930
[ 333.494614] shmem_fault+0x99/0x220
[ 333.495940] ? file_update_time+0x60/0x130
[ 333.497431] __do_fault+0x30/0xe0
[ 333.498678] handle_pte_fault+0x749/0xb70
[ 333.500038] __handle_mm_fault+0x53b/0x660
[ 333.501391] handle_mm_fault+0xdd/0x210
[ 333.502422] __do_page_fault+0x2f1/0x520
[ 333.503460] ? ksys_mmap_pgoff+0xfb/0x220
[ 333.504566] do_page_fault+0x30/0x120
[ 333.505768] async_page_fault+0x3e/0x50
[ 333.506952] RIP: 0033:0x560ec2027e31
[ 333.507943] Code: 00 00 e9 cd 06 00 00 48 c7 45 e8 00 00 00 00 e9 a9 00 00 00 48 8b 15 46 25 20 00 48 8b 05 ff 24 20 00 48 0f af 45 e8 48 01 d0 <48> c7 00 00 00 00 00 48 c7 40 08 00 00 00 00 48 c7 40 10 00 00 00
[ 333.512901] RSP: 002b:00007fff493596f0 EFLAGS: 00010206
[ 333.514483] RAX: 00007f2a830f9000 RBX: 00007fff49359710 RCX: 00007f2a830f8028
[ 333.516445] RDX: 00007f2a8111e000 RSI: 0000000000041000 RDI: 0000000000000000
[ 333.518201] RBP: 00007fff49359780 R08: 00007f2a790dd010 R09: 0000000000000000
[ 333.519643] R10: 0000000000000022 R11: 0000000000000246 R12: 0000560ec2025770
[ 333.521106] R13: 00007fff49359880 R14: 0000000000000000 R15: 0000000000000000
[ 333.610209] # nr_pages: 32768, nr_pages_per_cpu: 16384
[ 333.610213]
[ 333.794961] # bounces: 31, mode: rnd racing ver poll, userfaults: 3529 1538
[ 333.794965]
[ 333.999588] # bounces: 30, mode: racing ver poll, userfaults: 4324 1295
[ 333.999592]
[ 334.185492] # bounces: 29, mode: rnd ver poll, userfaults: 4456 4820
[ 334.185497]
[ 334.394098] # bounces: 28, mode: ver poll, userfaults: 4641 4105
[ 334.394102]
[ 334.578082] # bounces: 27, mode: rnd racing poll, userfaults: 1262 3639
[ 334.578086]
[ 334.795824] # bounces: 26, mode: racing poll, userfaults: 1491 4765
[ 334.795829]
[ 334.970774] # bounces: 25, mode: rnd poll, userfaults: 4311 4383
[ 334.970779]
[ 335.187283] # bounces: 24, mode: poll, userfaults: 4823 5789
[ 335.187288]
[ 335.400788] # bounces: 23, mode: rnd racing ver, userfaults: 4134 4158
[ 335.400792]
[ 335.622943] # bounces: 22, mode: racing ver, userfaults: 4518 2920
[ 335.622947]
[ 335.808147] # bounces: 21, mode: rnd ver, userfaults: 5086 5033
[ 335.808151]
[ 336.023590] # bounces: 20, mode: ver, userfaults: 5732 5550
[ 336.023594]
[ 336.218372] # bounces: 19, mode: rnd racing, userfaults: 4105 3461
[ 336.218376]
[ 336.430885] # bounces: 18, mode: racing, userfaults: 3511 4292
[ 336.430889]
[ 336.614652] # bounces: 17, mode: rnd, userfaults: 5319 5565
[ 336.614656]
[ 336.834908] # bounces: 16, mode:, userfaults: 6213 6358
[ 336.834911]
[ 337.014390] # bounces: 15, mode: rnd racing ver poll, userfaults: 2885 2628
[ 337.014394]
[ 337.218068] # bounces: 14, mode: racing ver poll, userfaults: 2280 3838
[ 337.218073]
[ 337.403837] # bounces: 13, mode: rnd ver poll, userfaults: 4505 4343
[ 337.403859]
[ 337.617792] # bounces: 12, mode: ver poll, userfaults: 4515 4974
[ 337.617796]
[ 337.796881] # bounces: 11, mode: rnd racing poll, userfaults: 3140 2696
[ 337.796885]
[ 338.008456] # bounces: 10, mode: racing poll, userfaults: 2669 3987
[ 338.008460]
[ 338.175515] # bounces: 9, mode: rnd poll, userfaults: 4452 4364
[ 338.175519]
[ 338.410124] # bounces: 8, mode: poll, userfaults: 5900 5150
[ 338.410128]
[ 338.598116] # bounces: 7, mode: rnd racing ver, userfaults: 3842 3735
[ 338.598120]
[ 338.809423] # bounces: 6, mode: racing ver, userfaults: 3677 3278
[ 338.809426]
[ 338.994607] # bounces: 5, mode: rnd ver, userfaults: 6048 5707
To reproduce:
# build kernel
cd linux
cp config-5.5.0-rc1-00011-g11b771ffff8fc .config
make HOSTCC=gcc-7 CC=gcc-7 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
Hi Lakshmi,
On Fri, 2019-12-27 at 22:23 +0800, kernel test robot wrote:
> [ 333.455345] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:281
> [ 333.457243] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 12395, name: userfaultfd
> [ 333.458888] CPU: 1 PID: 12395 Comm: userfaultfd Not tainted 5.5.0-rc1-00011-g11b771ffff8fc #1
> [ 333.461096] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> [ 333.463893] Call Trace:
> [ 333.465287] <IRQ>
> [ 333.466351] dump_stack+0x66/0x8b
> [ 333.467346] ___might_sleep+0x102/0x120
> [ 333.468385] mutex_lock+0x1c/0x40
> [ 333.469421] ima_process_queued_keys+0x24/0x110
> [ 333.470529] ? ima_process_queued_keys+0x110/0x110
> [ 333.471656] call_timer_fn+0x2d/0x140
> [ 333.472707] run_timer_softirq+0x46f/0x4b0
> [ 333.473752] ? enqueue_hrtimer+0x39/0xa0
> [ 333.474780] __do_softirq+0xe3/0x2f8
> [ 333.475768] irq_exit+0xd5/0xe0
> [ 333.476738] smp_apic_timer_interrupt+0x74/0x140
> [ 333.477834] apic_timer_interrupt+0xf/0x20
> [ 333.478858] </IRQ>
I think this is an instance where defining timer_expired as atomic and
then testing it using atomic_dec_and_test() would help. Either the
queued keys would be deleted in ima_timer_handler() or measured in
ima_process_queued_keys().
Mimi
On 12/30/19 9:01 AM, Mimi Zohar wrote:
Hi Mimi,
> Hi Lakshmi,
>
> On Fri, 2019-12-27 at 22:23 +0800, kernel test robot wrote:
>> [ 333.455345] BUG: sleeping function called from invalid context at kernel/locking/mutex.c:281
>> [ 333.457243] in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 12395, name: userfaultfd
>> [ 333.458888] CPU: 1 PID: 12395 Comm: userfaultfd Not tainted 5.5.0-rc1-00011-g11b771ffff8fc #1
>> [ 333.461096] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
>> [ 333.463893] Call Trace:
>> [ 333.465287] <IRQ>
>> [ 333.466351] dump_stack+0x66/0x8b
>> [ 333.467346] ___might_sleep+0x102/0x120
>> [ 333.468385] mutex_lock+0x1c/0x40
>> [ 333.469421] ima_process_queued_keys+0x24/0x110
>> [ 333.470529] ? ima_process_queued_keys+0x110/0x110
>> [ 333.471656] call_timer_fn+0x2d/0x140
>> [ 333.472707] run_timer_softirq+0x46f/0x4b0
>> [ 333.473752] ? enqueue_hrtimer+0x39/0xa0
>> [ 333.474780] __do_softirq+0xe3/0x2f8
>> [ 333.475768] irq_exit+0xd5/0xe0
>> [ 333.476738] smp_apic_timer_interrupt+0x74/0x140
>> [ 333.477834] apic_timer_interrupt+0xf/0x20
>> [ 333.478858] </IRQ>
>
> I think this is an instance where defining timer_expired as atomic and
> then testing it using atomic_dec_and_test() would help. Either the
> queued keys would be deleted in ima_timer_handler() or measured in
> ima_process_queued_keys().
>
> Mimi
Would it be better to use a spinlock (instead of a mutex) to synchronize
access to the queued keys list? That would work for timer callback
function also.
Before submitting the patch for freeing the keys I had tested the case
where queued keys are freed in timer callback. But I did not hit the
above break.
I will follow the steps given by Rong and validate the fix.
thanks,
-lakshmi
On 12/27/19 6:23 AM, kernel test robot wrote:
Hi Rong,
>
>
> To reproduce:
>
> # build kernel
> cd linux
> cp config-5.5.0-rc1-00011-g11b771ffff8fc .config
> make HOSTCC=gcc-7 CC=gcc-7 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
>
Thanks for reporting this issue.
I built the kernel with the config you'd provided.
When running lkp-tests using the command line given, I see the following
error and the test stops.
bin/lkp qemu -k ../linux-5.5/arch/x86/boot/bzImage job-script
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
-N -P
/root/.lkp/cache/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c
Failed to download
pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
Please let me know what I am missing.
Full output of the command is given below:
bin/lkp qemu -k ../linux-5.5/arch/x86/boot/bzImage job-script
result_root:
/root/.lkp//result/kernel_selftests/kselftests-03/vm-snb/debian-x86_64-2019-11-14.cgz/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/8
downloading initrds ...
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/osimage/debian/debian-x86_64-2019-11-14.cgz
-N -P /root/.lkp/cache/osimage/debian
408859 blocks
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/run-ipconfig_2018-04-03.cgz
-N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
1414 blocks
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/lkp_2019-08-05.cgz
-N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
1670 blocks
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/rsync-rootfs_2018-04-03.cgz
-N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
8268 blocks
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/kernel_selftests_2019-12-25.cgz
-N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
932372 blocks
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/osimage/pkg/debian-x86_64-2018-04-03.cgz/kernel_selftests-x86_64-0dcf36db-1_2019-12-25.cgz
-N -P /root/.lkp/cache/osimage/pkg/debian-x86_64-2018-04-03.cgz
30125 blocks
/usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
https://download.01.org/0day-ci/lkp-qemu/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
-N -P
/root/.lkp/cache/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c
Failed to download
pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
On 12/31/2019 5:14 AM, Lakshmi Ramasubramanian wrote:
> On 12/27/19 6:23 AM, kernel test robot wrote:
>
> Hi Rong,
>
>>
>>
>> To reproduce:
>>
>> ???????? # build kernel
>> ????cd linux
>> ????cp config-5.5.0-rc1-00011-g11b771ffff8fc .config
>> ????make HOSTCC=gcc-7 CC=gcc-7 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
>>
>
> Thanks for reporting this issue.
>
> I built the kernel with the config you'd provided.
>
> When running lkp-tests using the command line given, I see the
> following error and the test stops.
>
> ????bin/lkp qemu -k ../linux-5.5/arch/x86/boot/bzImage job-script
>
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
> -N -P
> /root/.lkp/cache/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c
>
> Failed to download
> pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
>
> Please let me know what I am missing.
>
> Full output of the command is given below:
>
> bin/lkp qemu -k ../linux-5.5/arch/x86/boot/bzImage job-script
>
> result_root:
> /root/.lkp//result/kernel_selftests/kselftests-03/vm-snb/debian-x86_64-2019-11-14.cgz/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/8
> downloading initrds ...
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/osimage/debian/debian-x86_64-2019-11-14.cgz
> -N -P /root/.lkp/cache/osimage/debian
> 408859 blocks
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/run-ipconfig_2018-04-03.cgz
> -N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
> 1414 blocks
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/lkp_2019-08-05.cgz
> -N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
> 1670 blocks
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/rsync-rootfs_2018-04-03.cgz
> -N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
> 8268 blocks
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/osimage/deps/debian-x86_64-2018-04-03.cgz/kernel_selftests_2019-12-25.cgz
> -N -P /root/.lkp/cache/osimage/deps/debian-x86_64-2018-04-03.cgz
> 932372 blocks
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/osimage/pkg/debian-x86_64-2018-04-03.cgz/kernel_selftests-x86_64-0dcf36db-1_2019-12-25.cgz
> -N -P /root/.lkp/cache/osimage/pkg/debian-x86_64-2018-04-03.cgz
> 30125 blocks
> /usr/bin/wget -q --timeout=1800 --tries=1 --local-encoding=UTF-8
> https://download.01.org/0day-ci/lkp-qemu/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
> -N -P
> /root/.lkp/cache/pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c
> Failed to download
> pkg/linux/x86_64-rhel-7.6/gcc-7/11b771ffff8fc0bfc176b829d986896a7d97a44c/linux-headers.cgz
>
>
Hi,
Sorry for the delay, we updated the lkp-tests code and uploaded the
missing cgz files for this case.
Best Regards,
Rong Chen
On 1/4/2020 3:49 AM, Chen, Rong A wrote:
Hi Rong,
>
> Hi,
>
> Sorry for the delay, we updated the lkp-tests code and uploaded the
> missing cgz files for this case.
>
> Best Regards,
> Rong Chen
Thanks - I was able to execute the test and validate the fix.
-lakshmi