Greeting,
FYI, we noticed WARNING:at_kernel/printk/printk.c:#console_flush_all due to commit (built with clang-14):
commit: 8fc5f5fc7f52a733fcc8b3939d172b9248e63871 ("printk: introduce console_list_lock")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
in testcase: boot
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
[ 0.000000][ T0] ------------[ cut here ]------------
[ 0.000000][ T0] WARNING: CPU: 0 PID: 0 at kernel/printk/printk.c:116 console_flush_all (printk.c:?)
[ 0.000000][ T0] Modules linked in:
[ 0.000000][ T0] CPU: 0 PID: 0 Comm: swapper Not tainted 6.1.0-rc1-00023-g8fc5f5fc7f52 #1 43391cb98b87f9b922921f2d6247215ade105013
[ 0.000000][ T0] RIP: 0010:console_flush_all (printk.c:?)
[ 0.000000][ T0] ================================================================================
[ 0.000000][ T0] UBSAN: shift-out-of-bounds in arch/x86/include/asm/page.h:76:21
[ 0.000000][ T0] shift exponent 64 is too large for 64-bit type 's64' (aka 'long long')
[ 0.000000][ T0] CPU: 0 PID: 0 Comm: swapper Not tainted 6.1.0-rc1-00023-g8fc5f5fc7f52 #1 43391cb98b87f9b922921f2d6247215ade105013
[ 0.000000][ T0] Call Trace:
[ 0.000000][ T0] <TASK>
[ 0.000000][ T0] ? dump_stack_lvl (??:?)
[ 0.000000][ T0] ? netdev_notice (??:?)
[ 0.000000][ T0] ? vprintk_emit (??:?)
[ 0.000000][ T0] ? __ubsan_handle_shift_out_of_bounds (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? vprintk_emit (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? copy_from_kernel_nofault_allowed (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? copy_from_kernel_nofault (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? show_opcodes (??:?)
[ 0.000000][ T0] ? show_iret_regs (??:?)
[ 0.000000][ T0] ? __show_regs (??:?)
[ 0.000000][ T0] ? dump_stack_print_info (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? show_regs (??:?)
[ 0.000000][ T0] ? __warn (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? report_bug (??:?)
[ 0.000000][ T0] ? early_fixup_exception (??:?)
[ 0.000000][ T0] ? early_idt_handler_common (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? console_unlock (??:?)
[ 0.000000][ T0] ? vprintk_emit (printk.c:?)
[ 0.000000][ T0] ? console_trylock_spinning (??:?)
[ 0.000000][ T0] ? lockdep_init_map_type (??:?)
[ 0.000000][ T0] ? cgroup_init_subsys (cgroup.c:?)
[ 0.000000][ T0] ? lockdep_init_map_type (??:?)
[ 0.000000][ T0] ? vprintk_emit (??:?)
[ 0.000000][ T0] ? _printk (??:?)
[ 0.000000][ T0] ? mutex_unlock (mutex.c:?)
[ 0.000000][ T0] ? panic (??:?)
[ 0.000000][ T0] ? boot_cpu_init (??:?)
[ 0.000000][ T0] ? cgroup_init_early (??:?)
[ 0.000000][ T0] ? start_kernel (??:?)
[ 0.000000][ T0] ? secondary_startup_64_no_verify (??:?)
[ 0.000000][ T0] </TASK>
[ 0.000000][ T0] ================================================================================
[ 0.000000][ T0] UBSAN: shift-out-of-bounds in arch/x86/include/asm/page.h:76:43
[ 0.000000][ T0] shift exponent 64 is too large for 64-bit type 's64' (aka 'long long')
[ 0.000000][ T0] CPU: 0 PID: 0 Comm: swapper Not tainted 6.1.0-rc1-00023-g8fc5f5fc7f52 #1 43391cb98b87f9b922921f2d6247215ade105013
[ 0.000000][ T0] Call Trace:
[ 0.000000][ T0] <TASK>
[ 0.000000][ T0] ? dump_stack_lvl (??:?)
[ 0.000000][ T0] ? netdev_notice (??:?)
[ 0.000000][ T0] ? vprintk_emit (??:?)
[ 0.000000][ T0] ? __ubsan_handle_shift_out_of_bounds (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? copy_from_kernel_nofault_allowed (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? copy_from_kernel_nofault (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? show_opcodes (??:?)
[ 0.000000][ T0] ? show_iret_regs (??:?)
[ 0.000000][ T0] ? __show_regs (??:?)
[ 0.000000][ T0] ? dump_stack_print_info (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? show_regs (??:?)
[ 0.000000][ T0] ? __warn (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? report_bug (??:?)
[ 0.000000][ T0] ? early_fixup_exception (??:?)
[ 0.000000][ T0] ? early_idt_handler_common (??:?)
[ 0.000000][ T0] ? console_flush_all (printk.c:?)
[ 0.000000][ T0] ? console_unlock (??:?)
[ 0.000000][ T0] ? vprintk_emit (printk.c:?)
[ 0.000000][ T0] ? console_trylock_spinning (??:?)
[ 0.000000][ T0] ? lockdep_init_map_type (??:?)
[ 0.000000][ T0] ? cgroup_init_subsys (cgroup.c:?)
[ 0.000000][ T0] ? lockdep_init_map_type (??:?)
[ 0.000000][ T0] ? vprintk_emit (??:?)
[ 0.000000][ T0] ? _printk (??:?)
[ 0.000000][ T0] ? mutex_unlock (mutex.c:?)
[ 0.000000][ T0] ? panic (??:?)
[ 0.000000][ T0] ? boot_cpu_init (??:?)
[ 0.000000][ T0] ? cgroup_init_early (??:?)
[ 0.000000][ T0] ? start_kernel (??:?)
[ 0.000000][ T0] ? secondary_startup_64_no_verify (??:?)
[ 0.000000][ T0] </TASK>
[ 0.000000][ T0] ================================================================================
[ 0.000000][ T0] Code: 0d 2e 86 80 e1 07 80 c1 03 38 c1 0f 8c 9c fe ff ff 48 c7 c7 00 0d 2e 86 e8 8e b4 60 00 e9 8b fe ff ff 48 83 05 71 0e 0d 07 01 <0f> 0b e9 74 fc ff ff 48 c7 c1 94 54 e0 86 80 e1 07 80 c1 03 38 c1
All code
========
0: 0d 2e 86 80 e1 or $0xe180862e,%eax
5: 07 (bad)
6: 80 c1 03 add $0x3,%cl
9: 38 c1 cmp %al,%cl
b: 0f 8c 9c fe ff ff jl 0xfffffffffffffead
11: 48 c7 c7 00 0d 2e 86 mov $0xffffffff862e0d00,%rdi
18: e8 8e b4 60 00 callq 0x60b4ab
1d: e9 8b fe ff ff jmpq 0xfffffffffffffead
22: 48 83 05 71 0e 0d 07 addq $0x1,0x70d0e71(%rip) # 0x70d0e9b
29: 01
2a:* 0f 0b ud2 <-- trapping instruction
2c: e9 74 fc ff ff jmpq 0xfffffffffffffca5
31: 48 c7 c1 94 54 e0 86 mov $0xffffffff86e05494,%rcx
38: 80 e1 07 and $0x7,%cl
3b: 80 c1 03 add $0x3,%cl
3e: 38 c1 cmp %al,%cl
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: e9 74 fc ff ff jmpq 0xfffffffffffffc7b
7: 48 c7 c1 94 54 e0 86 mov $0xffffffff86e05494,%rcx
e: 80 e1 07 and $0x7,%cl
11: 80 c1 03 add $0x3,%cl
14: 38 c1 cmp %al,%cl
[ 0.000000][ T0] RSP: 0000:ffffffff86207c90 EFLAGS: 00010002 ORIG_RAX: 0000000000000000
[ 0.000000][ T0] RAX: 0000000000000000 RBX: ffffffff86207d40 RCX: 0000000086207d00
[ 0.000000][ T0] RDX: ffffffff86207d40 RSI: ffffffff8631a300 RDI: ffffffff86244220
[ 0.000000][ T0] RBP: ffffffff86207dd0 R08: dffffc0000000000 R09: 000000000000010a
[ 0.000000][ T0] R10: dffff7fff0f5daf6 R11: 205453432030343a R12: 0000000000000000
[ 0.000000][ T0] R13: ffffffff86207d50 R14: dffffc0000000000 R15: 1ffffffff0c40fa8
[ 0.000000][ T0] FS: 0000000000000000(0000) GS:ffffffff862ab000(0000) knlGS:0000000000000000
[ 0.000000][ T0] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 0.000000][ T0] CR2: ffff888000015508 CR3: 0000000007679000 CR4: 00000000000000a0
[ 0.000000][ T0] Call Trace:
[ 0.000000][ T0] <TASK>
[ 0.000000][ T0] ? console_unlock (??:?)
[ 0.000000][ T0] ? vprintk_emit (printk.c:?)
[ 0.000000][ T0] ? console_trylock_spinning (??:?)
[ 0.000000][ T0] ? lockdep_init_map_type (??:?)
[ 0.000000][ T0] ? cgroup_init_subsys (cgroup.c:?)
[ 0.000000][ T0] ? lockdep_init_map_type (??:?)
[ 0.000000][ T0] ? vprintk_emit (??:?)
[ 0.000000][ T0] ? _printk (??:?)
[ 0.000000][ T0] ? mutex_unlock (mutex.c:?)
[ 0.000000][ T0] ? panic (??:?)
[ 0.000000][ T0] ? boot_cpu_init (??:?)
[ 0.000000][ T0] ? cgroup_init_early (??:?)
[ 0.000000][ T0] ? start_kernel (??:?)
[ 0.000000][ T0] ? secondary_startup_64_no_verify (??:?)
[ 0.000000][ T0] </TASK>
[ 0.000000][ T0] irq event stamp: 0
[ 0.000000][ T0] hardirqs last enabled at (0): 0x0
[ 0.000000][ T0] hardirqs last disabled at (0): 0x0
[ 0.000000][ T0] softirqs last enabled at (0): 0x0
[ 0.000000][ T0] softirqs last disabled at (0): 0x0
[ 0.000000][ T0] ---[ end trace 0000000000000000 ]---
If you fix the issue, kindly add following tag
| Reported-by: kernel test robot <[email protected]>
| Link: https://lore.kernel.org/oe-lkp/[email protected]
To reproduce:
# build kernel
cd linux
cp config-6.1.0-rc1-00023-g8fc5f5fc7f52 .config
make HOSTCC=clang-14 CC=clang-14 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage modules
make HOSTCC=clang-14 CC=clang-14 ARCH=x86_64 INSTALL_MOD_PATH=<mod-install-dir> modules_install
cd <mod-install-dir>
find lib/ | cpio -o -H newc --quiet | gzip > modules.cgz
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email
# 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://01.org/lkp
On Thu 2022-12-01 00:57:06, kernel test robot wrote:
> Greeting,
>
> FYI, we noticed WARNING:at_kernel/printk/printk.c:#console_flush_all due to commit (built with clang-14):
>
> commit: 8fc5f5fc7f52a733fcc8b3939d172b9248e63871 ("printk: introduce console_list_lock")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
>
> in testcase: boot
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> [ 0.000000][ T0] ------------[ cut here ]------------
> [ 0.000000][ T0] WARNING: CPU: 0 PID: 0 at kernel/printk/printk.c:116 console_flush_all (printk.c:?)
When I checked out the commit 8fc5f5fc7f52a733fcc8b3939d172b9248e63871
("printk: introduce console_list_lock") then
kernel/printk/printk.c:116 is:
114 void lockdep_assert_console_list_lock_held(void)
115 {
116 lockdep_assert_held(&console_mutex);
117 }
118 EXPORT_SYMBOL(lockdep_assert_console_list_lock_held);
It is used in
#define for_each_console(con) \
lockdep_assert_console_list_lock_held(); \
hlist_for_each_entry(con, &console_list, node)
that is used in
static bool console_flush_all(bool do_cond_resched, u64 *next_seq, bool *handover)
{
[...]
for_each_console(con) {
that is called without console_list_lock().
Hmm, we could not take console_list_lock() here. It would violate lock
ordering. console_flush_all() is called under console_lock(). And
console_list_lock() is taken outside of console_lock() in register_console().
Fortunately, we do not have to do it. for_each_console() is still safe
under console_lock() at this stage. And later patches will switch
it to for_each_console_srcu() that will not require
console_list_lock().
So, the solution is to remove the assert in for_each_console() in
the commit 8fc5f5fc7f52a733fcc8b3939d172b9248e63871 ("printk:
introduce console_list_lock").
We need to add the assert later when removing the console_lock()
synchronization of @console_list in register_console().
Best Regards,
Petr