How to fail a test run on kernel warnings that happen after the boot action?
Hi,
we have a testsuite that is able to trigger a RCU WARNING inside the Linux kernel. My expectation was that whenever a kernel warning / oops / call stack dump / ... occurs the LAVA job is marked as "failed".
This assumption seems to be wrong. It took some time to realize that we have a real issue as manual inspection of test logs only happens from time to time.
After scanning the code my understanding is that the output of the connection (serial connection in my case) is only parsed during kernel boot (until the login action takes over). That is not sufficient for detecting problems that happen during test execution.
Is there a way to scan the full log for the same patterns that are used by the boot action? If so, how to configure that? Whenever a kernel problem occurs my test run should be marked as "failed".
RCU warning
2022-11-21T11:14:27 [ 14.713422] =============================
2022-11-21T11:14:27 [ 14.713422] WARNING: suspicious RCU usage
2022-11-21T11:14:27 [ 14.713422] 5.10.153+ #1 Not tainted
2022-11-21T11:14:27 [ 14.713423] -----------------------------
2022-11-21T11:14:27 [ 14.713423] include/linux/rcupdate.h:701 rcu_read_unlock() used illegally while idle!
2022-11-21T11:14:27 [ 14.713423]
2022-11-21T11:14:27 [ 14.713423] other info that might help us debug this:
2022-11-21T11:14:27 [ 14.713424]
2022-11-21T11:14:27 [ 14.713424]
2022-11-21T11:14:27 [ 14.713424] rcu_scheduler_active = 2, debug_locks = 1
2022-11-21T11:14:27 [ 14.713424] RCU used illegally from extended quiescent state!
2022-11-21T11:14:27 [ 14.713425] no locks held by smokey/346.
2022-11-21T11:14:27 [ 14.713425]
2022-11-21T11:14:27 [ 14.713425] stack backtrace:
2022-11-21T11:14:27 [ 14.713425] CPU: 0 PID: 346 Comm: smokey Not tainted 5.10.153+ #1
2022-11-21T11:14:27 [ 14.713426] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.12.0-1 04/01/2014
2022-11-21T11:14:27 [ 14.713426] IRQ stage: Xenomai
2022-11-21T11:14:27 [ 14.713426] Call Trace:
2022-11-21T11:14:27 [ 14.713426] dump_stack+0x82/0x9a
2022-11-21T11:14:27 [ 14.713427] __is_insn_slot_addr+0x109/0x120
2022-11-21T11:14:27 [ 14.713427] kernel_text_address+0xf2/0x120
2022-11-21T11:14:27 [ 14.713427] ? get_stack_info+0x30/0x90
2022-11-21T11:14:27 [ 14.713427] __kernel_text_address+0xe/0x40
2022-11-21T11:14:27 [ 14.713428] show_trace_log_lvl+0x179/0x2b6
2022-11-21T11:14:27 [ 14.713428] ? printk_safe_log_store+0xca/0xe0
2022-11-21T11:14:27 [ 14.713428] ? dump_stack+0x82/0x9a
2022-11-21T11:14:27 [ 14.713428] dump_stack+0x82/0x9a
2022-11-21T11:14:27 [ 14.713429] __is_insn_slot_addr+0xd3/0x120
2022-11-21T11:14:27 [ 14.713429] kernel_text_address+0xf2/0x120
2022-11-21T11:14:27 [ 14.713429] ? create_prof_cpu_mask+0x20/0x20
2022-11-21T11:14:27 [ 14.713429] __kernel_text_address+0xe/0x40
2022-11-21T11:14:27 [ 14.713430] unwind_get_return_address+0x1f/0x40
2022-11-21T11:14:27 [ 14.713430] ? create_prof_cpu_mask+0x20/0x20
2022-11-21T11:14:27 [ 14.713430] arch_stack_walk+0x9e/0xf0
2022-11-21T11:14:27 [ 14.713430] stack_trace_save+0x4b/0x70
2022-11-21T11:14:27 [ 14.713431] save_trace+0x3e/0x200
2022-11-21T11:14:27 [ 14.713431] mark_lock+0x1c3/0x780
2022-11-21T11:14:27 [ 14.713431] mark_usage+0xea/0x150
2022-11-21T11:14:27 [ 14.713431] __lock_acquire+0x1e6/0x6b0
2022-11-21T11:14:27 [ 14.713432] lock_acquire+0xce/0x2f0
2022-11-21T11:14:27 [ 14.713432] ? get_random_u32+0x4e/0x210
2022-11-21T11:14:27 [ 14.713432] ? xnlock_dbg_release+0x1c/0xc0
2022-11-21T11:14:27 [ 14.713432] get_random_u32+0x83/0x210
2022-11-21T11:14:27 [ 14.713433] ? get_random_u32+0x4e/0x210
2022-11-21T11:14:27 [ 14.713433] test_seq+0x63d/0x8d0
2022-11-21T11:14:27 [ 14.713433] ? find_held_lock+0x2b/0x80
2022-11-21T11:14:27 [ 14.713433] ? ktime_get_mono_fast_ns+0x4b/0xa0
2022-11-21T11:14:27 [ 14.713434] heapcheck_ioctl+0x62/0x140
2022-11-21T11:14:27 [ 14.713434] rtdm_fd_ioctl+0xfb/0x350
2022-11-21T11:14:27 [ 14.713434] ? CoBaLt_fcntl+0x20/0x20
2022-11-21T11:14:27 [ 14.713434] CoBaLt_ioctl+0xa/0x20
2022-11-21T11:14:27 [ 14.713435] handle_head_syscall+0x1b7/0x5c0
2022-11-21T11:14:27 [ 14.713435] pipeline_syscall+0x68/0xf0
2022-11-21T11:14:27 [ 14.713435] syscall_enter_from_user_mode+0x32/0xa0
2022-11-21T11:14:27 [ 14.713435] do_syscall_64+0xf/0x50
2022-11-21T11:14:27 [ 14.713436] entry_SYSCALL_64_after_hwframe+0x61/0xc6
2022-11-21T11:14:27 [ 14.713436] RIP: 0033:0x7f2281373679
2022-11-21T11:14:27 [ 14.713436] Code: Unable to access opcode bytes at RIP 0x7f228137364f.
2022-11-21T11:14:27 [ 14.713436] RSP: 002b:00007ffe5829be60 EFLAGS: 00000202 ORIG_RAX: 0000000010000050
2022-11-21T11:14:27 [ 14.713437] RAX: ffffffffffffffda RBX: 0000000000000010 RCX: 00007f2281373679
2022-11-21T11:14:27 [ 14.713437] RDX: 00007ffe5829bf00 RSI: 0000000080180644 RDI: 000000000000000b
2022-11-21T11:14:27 [ 14.713438] RBP: 000000000000000b R08: 00007f2281163640 R09: 00007f2281333be0
2022-11-21T11:14:27 [ 14.713438] R10: 00007ffe5829be5c R11: 0000000000000202 R12: 0000000080180644
2022-11-21T11:14:27 [ 14.713438] R13: 00007f2281163640 R14: 00007ffe5829bf00 R15: 0000000000002000
2022-11-21T11:14:27 [ 14.713439] dump_stack+0x82/0x9a
2022-11-21T11:14:27 [ 14.713439] __is_insn_slot_addr+0xd3/0x120
2022-11-21T11:14:27 [ 14.713439] kernel_text_address+0xf2/0x120
2022-11-21T11:14:27 [ 14.713439] ? create_prof_cpu_mask+0x20/0x20
2022-11-21T11:14:27 [ 14.713440] __kernel_text_address+0xe/0x40
2022-11-21T11:14:27 [ 14.713440] unwind_get_return_address+0x1f/0x40
2022-11-21T11:14:27 [ 14.713440] ? create_prof_cpu_mask+0x20/0x20
2022-11-21T11:14:27 [ 14.713440] arch_stack_walk+0x9e/0xf0
2022-11-21T11:14:27 [ 14.713441] stack_trace_save+0x4b/0x70
2022-11-21T11:14:27 [ 14.713441] save_trace+0x3e/0x200
2022-11-21T11:14:27 [ 14.713441] mark_lock+0x1c3/0x780
2022-11-21T11:14:27 [ 14.713441] mark_usage+0xea/0x150
2022-11-21T11:14:27 [ 14.713441] __lock_acquire+0x1e6/0x6b0
2022-11-21T11:14:27 [ 14.713442] lock_acquire+0xce/0x2f0
2022-11-21T11:14:27 [ 14.713442] ? get_random_u32+0x4e/0x210
2022-11-21T11:14:27 [ 14.713442] ? xnlock_dbg_release+0x1c/0xc0
2022-11-21T11:14:27 [ 14.713442] get_random_u32+0x83/0x210
2022-11-21T11:14:27 [ 14.713443] ? get_random_u32+0x4e/0x210
2022-11-21T11:14:27 [ 14.713443] test_seq+0x63d/0x8d0
2022-11-21T11:14:27 [ 14.713443] ? find_held_lock+0x2b/0x80
2022-11-21T11:14:27 [ 14.713443] ? ktime_get_mono_fast_ns+0x4b/0xa0
2022-11-21T11:14:27 [ 14.713444] heapcheck_ioctl+0x62/0x140
2022-11-21T11:14:27 [ 14.713444] rtdm_fd_ioctl+0xfb/0x350
2022-11-21T11:14:27 [ 14.713444] ? CoBaLt_fcntl+0x20/0x20
2022-11-21T11:14:27 [ 14.713444] CoBaLt_ioctl+0xa/0x20
2022-11-21T11:14:27 [ 14.713445] handle_head_syscall+0x1b7/0x5c0
2022-11-21T11:14:27 [ 14.713445] pipeline_syscall+0x68/0xf0
2022-11-21T11:14:27 [ 14.713445] syscall_enter_from_user_mode+0x32/0xa0
2022-11-21T11:14:27 [ 14.713445] do_syscall_64+0xf/0x50
2022-11-21T11:14:27 [ 14.713446] entry_SYSCALL_64_after_hwframe+0x61/0xc6
2022-11-21T11:14:27 [ 14.713446] RIP: 0033:0x7f2281373679
2022-11-21T11:14:27 [ 14.713446] Code: Unable to access opcode bytes at RIP 0x7f228137364f.
2022-11-21T11:14:27 [ 14.713446] RSP: 002b:00007ffe5829be60 EFLAGS: 00000202 ORIG_RAX: 0000000010000050
2022-11-21T11:14:27 [ 14.713447] RAX: ffffffffffffffda RBX: 0000000000000010 RCX: 00007f2281373679
2022-11-21T11:14:27 [ 14.713447] RDX: 00007ffe5829bf00 RSI: 0000000080180644 RDI: 000000000000000b
2022-11-21T11:14:27 [ 14.713448] RBP: 000000000000000b R08: 00007f2281163640 R09: 00007f2281333be0
2022-11-21T11:14:27 [ 14.713448] R10: 00007ffe5829be5c R11: 0000000000000202 R12: 0000000080180644
2022-11-21T11:14:27 [ 14.713448] R13: 00007f2281163640 R14: 00007ffe5829bf00 R15: 0000000000002000
2022-11-21T11:14:27 [ 14.713448]
2022-11-21T11:14:27 [ 14.713449] ================================
2022-11-21T11:14:27 [ 14.713449] WARNING: inconsistent lock state
2022-11-21T11:14:27 [ 14.713449] 5.10.153+ #1 Not tainted
2022-11-21T11:14:27 [ 14.713449] --------------------------------
2022-11-21T11:14:27 [ 14.713450] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage.
2022-11-21T11:14:27 [ 14.713450] smokey/346 [HC0[0]:SC0[0]:HE0:SE1] takes:
2022-11-21T11:14:27 [ 14.713450] ffff88803e8360a8 (crngs.lock){+.?.}-{2:2}, at: crng_make_state+0x7f/0x2f0
2022-11-21T11:14:27 [ 14.713452] {IN-SOFTIRQ-W} state was registered at:
2022-11-21T11:14:27 [ 14.713452] __lock_acquire+0x1e6/0x6b0
2022-11-21T11:14:27 [ 14.713452] lock_acquire+0xce/0x2f0
2022-11-21T11:14:27 [ 14.713452] crng_make_state+0xc1/0x2f0
2022-11-21T11:14:27 [ 14.713453] _get_random_bytes.part.0+0x4d/0x190
2022-11-21T11:14:27 [ 14.713453] get_random_u64+0xd9/0x210
2022-11-21T11:14:27 [ 14.713453] prandom_reseed+0x88/0x130
2022-11-21T11:14:27 [ 14.713453] call_timer_fn+0xab/0x2d0
2022-11-21T11:14:27 [ 14.713454] __run_timers.part.0+0x1fa/0x300
2022-11-21T11:14:27 [ 14.713454] run_timer_softirq+0x31/0x70
2022-11-21T11:14:27 [ 14.713454] __do_softirq+0xdb/0x4ce
2022-11-21T11:14:27 [ 14.713454] asm_call_irq_on_stack+0xf/0x20
2022-11-21T11:14:27 [ 14.713455] do_softirq_own_stack+0x72/0xc0
2022-11-21T11:14:27 [ 14.713455] irq_exit_rcu+0xf5/0x130
2022-11-21T11:14:27 [ 14.713455] arch_do_IRQ_pipelined+0x16b/0x2b0
2022-11-21T11:14:27 [ 14.713455] sync_current_irq_stage+0x157/0x1f0
2022-11-21T11:14:27 [ 14.713456] __inband_irq_enable+0x4b/0x70
2022-11-21T11:14:27 [ 14.713456] __slab_alloc.constprop.0+0x56/0xa0
2022-11-21T11:14:27 [ 14.713456] kmem_cache_alloc_trace+0x1f2/0x300
2022-11-21T11:14:27 [ 14.713456] populate_error_injection_list+0x97/0x140
2022-11-21T11:14:27 [ 14.713457] init_error_injection+0x16/0x6e
2022-11-21T11:14:27 [ 14.713457] do_one_initcall+0x61/0x310
2022-11-21T11:14:27 [ 14.713457] do_initcalls+0xc6/0xdf
2022-11-21T11:14:27 [ 14.713457] kernel_init_freeable+0x186/0x1b6
2022-11-21T11:14:27 [ 14.713458] kernel_init+0xa/0x116
2022-11-21T11:14:27 [ 14.713458] ret_from_fork+0x1f/0x30
2022-11-21T11:14:27 [ 14.713458] irq event stamp: 91454
2022-11-21T11:14:27 [ 14.713458] hardirqs last enabled at (91453): [<ffffffff81c27ce6>] _raw_spin_unlock_irqrestore+0x56/0x70
2022-11-21T11:14:27 [ 14.713459] hardirqs last disabled at (91454): [<ffffffff81c20fff>] __schedule+0x52f/0xb30
2022-11-21T11:14:27 [ 14.713459] softirqs last enabled at (87000): [<ffffffff820002b3>] __do_softirq+0x2b3/0x4ce
2022-11-21T11:14:27 [ 14.713459] softirqs last disabled at (86991): [<ffffffff81e0101f>] asm_call_irq_on_stack+0xf/0x20
2022-11-21T11:14:27 [ 14.713460]
2022-11-21T11:14:27 [ 14.713460] other info that might help us debug this:
2022-11-21T11:14:27 [ 14.713460] Possible unsafe locking scenario:
2022-11-21T11:14:27 [ 14.713460]
2022-11-21T11:14:27 [ 14.713461] CPU0
2022-11-21T11:14:27 [ 14.713461] ----
2022-11-21T11:14:27 [ 14.713461] lock(crngs.lock);
2022-11-21T11:14:27 [ 14.713462] <Interrupt>
2022-11-21T11:14:27 [ 14.713462] lock(crngs.lock);
2022-11-21T11:14:27 [ 14.713463]
2022-11-21T11:14:27 [ 14.713463] *** DEADLOCK ***
2022-11-21T11:14:27 [ 14.713463]
2022-11-21T11:14:27 [ 14.713463] 1 lock held by smokey/346:
2022-11-21T11:14:27 [ 14.713464] #0: ffff88803e835fa0 (batched_entropy_u32.lock){+.+.}-{2:2}, at: get_random_u32+0x4e/0x210
2022-11-21T11:14:27 [ 14.713465]
2022-11-21T11:14:27 [ 14.713465] stack backtrace:
2022-11-21T11:14:27 [ 14.713466] CPU: 0 PID: 346 Comm: smokey Not tainted 5.10.153+ #1
2022-11-21T11:14:27 [ 14.713466] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.12.0-1 04/01/2014
2022-11-21T11:14:27 [ 14.713466] IRQ stage: Xenomai
2022-11-21T11:14:27 [ 14.713466] Call Trace:
2022-11-21T11:14:27 [ 14.713467] dump_stack+0x82/0x9a
2022-11-21T11:14:27 [ 14.713467] mark_lock_irq.cold+0x15/0x3c
2022-11-21T11:14:27 [ 14.713467] mark_lock+0x1ec/0x780
2022-11-21T11:14:27 [ 14.713467] mark_usage+0xcf/0x150
2022-11-21T11:14:27 [ 14.713468] __lock_acquire+0x1e6/0x6b0
2022-11-21T11:14:27 [ 14.713468] lock_acquire+0xce/0x2f0
2022-11-21T11:14:27 [ 14.713468] ? crng_make_state+0x7f/0x2f0
2022-11-21T11:14:27 [ 14.713468] ? mark_lock+0x223/0x780
2022-11-21T11:14:27 [ 14.713468] crng_make_state+0xc1/0x2f0
2022-11-21T11:14:27 [ 14.713469] ? crng_make_state+0x7f/0x2f0
2022-11-21T11:14:27 [ 14.713469] _get_random_bytes.part.0+0x4d/0x190
2022-11-21T11:14:27 [ 14.713469] ? lock_acquire+0xce/0x2f0
2022-11-21T11:14:27 [ 14.713469] ? lock_acquire+0x100/0x2f0
2022-11-21T11:14:27 [ 14.713470] ? xnlock_dbg_release+0x1c/0xc0
2022-11-21T11:14:27 [ 14.713470] get_random_u32+0xd9/0x210
2022-11-21T11:14:27 [ 14.713470] test_seq+0x63d/0x8d0
2022-11-21T11:14:27 [ 14.713470] ? find_held_lock+0x2b/0x80
2022-11-21T11:14:27 [ 14.713471] ? ktime_get_mono_fast_ns+0x4b/0xa0
2022-11-21T11:14:27 [ 14.713471] heapcheck_ioctl+0x62/0x140
2022-11-21T11:14:27 [ 14.713471] rtdm_fd_ioctl+0xfb/0x350
2022-11-21T11:14:27 [ 14.713471] ? CoBaLt_fcntl+0x20/0x20
2022-11-21T11:14:27 [ 14.713472] CoBaLt_ioctl+0xa/0x20
2022-11-21T11:14:27 [ 14.713472] handle_head_syscall+0x1b7/0x5c0
2022-11-21T11:14:27 [ 14.713472] pipeline_syscall+0x68/0xf0
2022-11-21T11:14:27 [ 14.713472] syscall_enter_from_user_mode+0x32/0xa0
2022-11-21T11:14:27 [ 14.713473] do_syscall_64+0xf/0x50
2022-11-21T11:14:27 [ 14.713473] entry_SYSCALL_64_after_hwframe+0x61/0xc6
2022-11-21T11:14:27 [ 14.713473] RIP: 0033:0x7f2281373679
2022-11-21T11:14:27 [ 14.713473] Code: Unable to access opcode bytes at RIP 0x7f228137364f.
2022-11-21T11:14:27 [ 14.713474] RSP: 002b:00007ffe5829be60 EFLAGS: 00000202 ORIG_RAX: 0000000010000050
2022-11-21T11:14:27 [ 14.713474] RAX: ffffffffffffffda RBX: 0000000000000010 RCX: 00007f2281373679
2022-11-21T11:14:27 [ 14.713475] RDX: 00007ffe5829bf00 RSI: 0000000080180644 RDI: 000000000000000b
2022-11-21T11:14:27 [ 14.713475] RBP: 000000000000000b R08: 00007f2281163640 R09: 00007f2281333be0
2022-11-21T11:14:27 [ 14.713475] R10: 00007ffe5829be5c R11: 0000000000000202 R12: 0000000080180644
2022-11-21T11:14:27 [ 14.713475] R13: 00007f2281163640 R14: 00007ffe5829bf00 R15: 0000000000002000
To upload designs, you'll need to enable LFS and have an admin enable hashed storage. More information