To Reproduce
sudo venv/bin/python3.12 ./run_tests.py -n tests.fault_injection.test_fault_injection_base.TestSchedConfig.test_init_modules_tfw_kvmalloc_node
I see this BUG two times.
It's very hard to reproduce. Previously I see it on master branch on my local vm (but I though that my be it was problem in my build, because I can't reproduce it).
I catch it again on CI on the new PR (but I am sure that it has nothing to do with the changes from the PR). Also as I catch it on master a long time ago).
Version or commit hash
Tempesta FW 2a35da6
Tempesta test fbcd279ea65454d5f54dc16e7f1ef0055444c498
Stacktrace or debug log
May 5 12:38:11 192.168.122.82 [ 3503.705579] [tdb] Shutdown Tempesta DB
May 5 12:38:11 192.168.122.82 [ 3504.235153] [tempesta sc] OS configuration or hardware is not suitable/ (Total 1 errors)
May 5 12:38:11 192.168.122.82 [ 3504.235313] [tempesta sc] 1. The minimal amount of RAM required by Tempesta is 8192 MB, but you have 7428 MB
May 5 12:38:11 192.168.122.82 [ 3504.249492] [tempesta sc] Kernel config params are missing or have different values. Please, check configuration of `/boot/config-6.12.12.tfw-b158a7a`/ (Total 2 errors)
May 5 12:38:11 192.168.122.82 [ 3504.251252] [tempesta sc] 1. `CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE={'1'}` is not defined.
May 5 12:38:11 192.168.122.82 [ 3504.253736] [tempesta sc] 2. `CONFIG_BOOTPARAM_HARDLOCKUP_PANIC_VALUE={'1'}` is not defined.
May 5 12:38:11 192.168.122.82 [ 3504.255360] [tempesta sc] Verification passed with errors!
May 5 12:38:12 192.168.122.82 [ 3504.256855] [tempesta sc] Skipped Netconsole configuration and Support Server connection
May 5 12:38:12 192.168.122.82 [ 3504.416788] [tdb] Start Tempesta DB
May 5 12:38:12 192.168.122.82 [ 3504.456572] [tempesta fw] Initializing Tempesta FW kernel module...
May 5 12:38:12 192.168.122.82 [ 3504.693535] [tempesta fw] Warning: Vhost default doesn't have certificate with matching SAN/CN.
[ 3504.693535] Maybe that's fine, but it's worth checking the
[ 3504.693535] config - if there is no relations between the
[ 3504.693535] names, then host name confusion attack is possible.
May 5 12:38:12 192.168.122.82 [ 3504.702005] [tempesta fw] Configuration processing is completed.
May 5 12:38:12 192.168.122.82 [ 3504.744111] [tdb] Opened table /opt/tempesta/db/filter0.tdb: size=16777216 rec_size=32 base=0000000001c94e4e
May 5 12:38:12 192.168.122.82 [ 3504.857431] BUG: unable to handle page fault for address: ffff970960a600c8
May 5 12:38:12 192.168.122.82 [ 3504.858183] #PF: supervisor read access in kernel mode
May 5 12:38:12 192.168.122.82 [ 3504.858706] #PF: error_code(0x0000) - not-present page
May 5 12:38:12 192.168.122.82 [ 3504.859236] PGD 0 P4D 0
May 5 12:38:12 192.168.122.82 [ 3504.859502] Oops: Oops: 0000 [#1] PREEMPT SMP NOPTI
May 5 12:38:12 192.168.122.82 [ 3504.860001] CPU: 0 UID: 0 PID: 327253 Comm: tempesta.sh Tainted: G OE 6.12.12.tfw-b158a7a #1
May 5 12:38:12 192.168.122.82 [ 3504.860969] Tainted: [O]=OOT_MODULE, [E]=UNSIGNED_MODULE
May 5 12:38:12 192.168.122.82 [ 3504.861514] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
May 5 12:38:12 192.168.122.82 [ 3504.862444] RIP: 0010:tfw_apm_prcntl_tmfn+0x157/0x600 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.863106] Code: c5 00 48 8b 02 48 83 f8 ff 74 e1 49 89 c4 89 c0 48 c7 02 ff ff ff ff 48 8d 1c 80 48 8b 04 24 49 c1 ec 20 48 c1 e3 07 48 01 c3 <44> 39 63 20 0f 83 3f ff ff ff 8b 73 28 45 89 e7 44 39 63 2c 0f 82
May 5 12:38:12 192.168.122.82 [ 3504.864953] RSP: 0018:ffffb1a0c0005e48 EFLAGS: 00010282
May 5 12:38:12 192.168.122.82 [ 3504.865470] RAX: ffff94edca06e0a8 RBX: ffff970960a600a8 RCX: 0000000000000003
May 5 12:38:12 192.168.122.82 [ 3504.866191] RDX: ffff94edc504d900 RSI: 0000000000000004 RDI: ffffffffbb925f20
May 5 12:38:12 192.168.122.82 [ 3504.866914] RBP: ffff94edc504d780 R08: 0000000000000003 R09: ffffb1a0c0005f10
May 5 12:38:12 192.168.122.82 [ 3504.867620] R10: 0000000000000201 R11: 0000000000000bfa R12: 00000000ffff94ed
May 5 12:38:12 192.168.122.82 [ 3504.868345] R13: 0000000000000030 R14: ffffd1a0bfd877c8 R15: ffff94edc504d780
May 5 12:38:12 192.168.122.82 [ 3504.869066] FS: 00007ff138d85740(0000) GS:ffff94ef37c00000(0000) knlGS:0000000000000000
May 5 12:38:12 192.168.122.82 [ 3504.869880] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
May 5 12:38:12 192.168.122.82 [ 3504.870458] CR2: ffff970960a600c8 CR3: 000000012a636004 CR4: 0000000000772ef0
May 5 12:38:12 192.168.122.82 [ 3504.871180] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
May 5 12:38:12 192.168.122.82 [ 3504.871896] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
May 5 12:38:12 192.168.122.82 [ 3504.872613] PKRU: 55555554
May 5 12:38:12 192.168.122.82 [ 3504.872899] Call Trace:
May 5 12:38:12 192.168.122.82 [ 3504.873170] <IRQ>
May 5 12:38:12 192.168.122.82 [ 3504.873396] ? __die+0x24/0x80
May 5 12:38:12 192.168.122.82 [ 3504.873733] ? page_fault_oops+0x158/0x500
May 5 12:38:12 192.168.122.82 [ 3504.874194] ? search_module_extables+0x3e/0x80
May 5 12:38:12 192.168.122.82 [ 3504.874667] ? search_bpf_extables+0x63/0xa0
May 5 12:38:12 192.168.122.82 [ 3504.875146] ? exc_page_fault+0xf1/0x1a0
May 5 12:38:12 192.168.122.82 [ 3504.875548] ? asm_exc_page_fault+0x26/0x40
May 5 12:38:12 192.168.122.82 [ 3504.875985] ? tfw_apm_prcntl_tmfn+0x157/0x600 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.876584] ? tfw_apm_prcntl_tmfn+0x47/0x600 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.877158] ? task_tick_fair+0x40/0x2a0
May 5 12:38:12 192.168.122.82 [ 3504.877576] ? sched_clock+0x10/0x40
May 5 12:38:12 192.168.122.82 [ 3504.877962] ? __pfx_tfw_apm_prcntl_tmfn+0x20/0x20 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.878585] ? __pfx_tfw_apm_prcntl_tmfn+0x20/0x20 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.879199] call_timer_fn+0x27/0x120
May 5 12:38:12 192.168.122.82 [ 3504.879598] __run_timers+0x1c9/0x280
May 5 12:38:12 192.168.122.82 [ 3504.879982] ? enqueue_hrtimer+0x35/0xa0
May 5 12:38:12 192.168.122.82 [ 3504.880378] ? __hrtimer_run_queues+0x141/0x2a0
May 5 12:38:12 192.168.122.82 [ 3504.880852] ? kvm_clock_get_cycles+0x18/0x40
May 5 12:38:12 192.168.122.82 [ 3504.881311] run_timer_softirq+0x76/0xe0
May 5 12:38:12 192.168.122.82 [ 3504.881720] handle_softirqs+0xcd/0x2c0
May 5 12:38:12 192.168.122.82 [ 3504.882143] __irq_exit_rcu+0x63/0x80
May 5 12:38:12 192.168.122.82 [ 3504.882531] sysvec_apic_timer_interrupt+0x75/0xa0
May 5 12:38:12 192.168.122.82 [ 3504.883041] </IRQ>
May 5 12:38:12 192.168.122.82 [ 3504.883268] <TASK>
May 5 12:38:12 192.168.122.82 [ 3504.883494] asm_sysvec_apic_timer_interrupt+0x1a/0x20
May 5 12:38:12 192.168.122.82 [ 3504.884072] RIP: 0010:folio_mark_accessed+0x18/0xe0
May 5 12:38:12 192.168.122.82 [ 3504.884578] Code: 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 0f 1f 44 00 00 53 48 8b 07 48 89 fb a8 04 75 19 f0 80 0f 04 <48> 8b 03 a9 00 00 40 00 74 05 f0 80 63 02 bf 5b c3 cc cc cc cc 48
May 5 12:38:12 192.168.122.82 [ 3504.886411] RSP: 0018:ffffb1a0c0caba18 EFLAGS: 00000202
May 5 12:38:12 192.168.122.82 [ 3504.886950] RAX: 0017ffffc0000028 RBX: ffffe04c48e1f1c0 RCX: ffffb1a0c0cabbb8
May 5 12:38:12 192.168.122.82 [ 3504.887650] RDX: 000000000387a000 RSI: 0000000000000000 RDI: ffffe04c48e1f1c0
May 5 12:38:12 192.168.122.82 [ 3504.888373] RBP: 0000000010000000 R08: ffffb1a0c0cabba8 R09: 000000000c786000
May 5 12:38:12 192.168.122.82 [ 3504.889087] R10: 0000000000000000 R11: 000000000c786000 R12: 000000000c786000
May 5 12:38:12 192.168.122.82 [ 3504.889794] R13: ffffb1a0c0cabbb8 R14: 0000000000001000 R15: 000000000000000b
May 5 12:38:12 192.168.122.82 [ 3504.890541] filemap_read+0x201/0x340
May 5 12:38:12 192.168.122.82 [ 3504.890937] __kernel_read+0x161/0x300
May 5 12:38:12 192.168.122.82 [ 3504.891368] tdb_file_open+0x25f/0x500 [tempesta_db]
May 5 12:38:12 192.168.122.82 [ 3504.891891] tdb_open+0x12d/0x2e0 [tempesta_db]
May 5 12:38:12 192.168.122.82 [ 3504.892364] tfw_cache_start+0x1c5/0x340 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.892914] tfw_ctlfn_state_io+0x32c/0x580 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.893494] ? __pfx_tfw_ctlfn_state_io+0x20/0x20 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.894126] proc_sys_call_handler+0x1bb/0x2e0
May 5 12:38:12 192.168.122.82 [ 3504.894596] vfs_write+0x301/0x420
May 5 12:38:12 192.168.122.82 [ 3504.894996] ksys_write+0x63/0xe0
May 5 12:38:12 192.168.122.82 [ 3504.895349] do_syscall_64+0x51/0x120
May 5 12:38:12 192.168.122.82 [ 3504.895727] entry_SYSCALL_64_after_hwframe+0x76/0x7e
May 5 12:38:12 192.168.122.82 [ 3504.896254] RIP: 0033:0x7ff138b1c5a4
May 5 12:38:12 192.168.122.82 [ 3504.896634] Code: c7 00 16 00 00 00 b8 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 f3 0f 1e fa 80 3d a5 ea 0e 00 00 74 13 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 54 c3 0f 1f 00 55 48 89 e5 48 83 ec 20 48 89
May 5 12:38:12 192.168.122.82 [ 3504.898484] RSP: 002b:00007fff7276aff8 EFLAGS: 00000202 ORIG_RAX: 0000000000000001
May 5 12:38:12 192.168.122.82 [ 3504.899250] RAX: ffffffffffffffda RBX: 0000000000000006 RCX: 00007ff138b1c5a4
May 5 12:38:12 192.168.122.82 [ 3504.899963] RDX: 0000000000000006 RSI: 000055cb4145b6b0 RDI: 0000000000000001
May 5 12:38:12 192.168.122.82 [ 3504.900681] RBP: 00007fff7276b020 R08: 0000000000000073 R09: 0000000000000000
May 5 12:38:12 192.168.122.82 [ 3504.901403] R10: 00000000ffffffff R11: 0000000000000202 R12: 0000000000000006
May 5 12:38:12 192.168.122.82 [ 3504.902121] R13: 000055cb4145b6b0 R14: 00007ff138c045c0 R15: 00007ff138c01ee0
May 5 12:38:12 192.168.122.82 [ 3504.902853] </TASK>
May 5 12:38:12 192.168.122.82 [ 3504.903091] Modules linked in: tempesta_fw(OE) tempesta_db(OE) tempesta_tls(OE) tempesta_lib(OE) tcp_diag inet_diag nf_conntrack_netlink xt_nat xt_tcpudp veth ib_core tls xt_conntrack nft_chain_nat xt_MASQUERADE nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 bridge stp llc xfrm_user xfrm_algo xt_addrtype nft_compat nf_tables overlay cfg80211 binfmt_misc intel_rapl_msr intel_rapl_common skx_edac_common nfit kvm_intel kvm rapl i2c_i801 i2c_mux i2c_smbus lpc_ich joydev input_leds serio_raw mac_hid sch_fq_codel dm_multipath netconsole msr efi_pstore drm nfnetlink dmi_sysfs qemu_fw_cfg ip_tables x_tables autofs4 btrfs blake2b_generic raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 crct10dif_pclmul crc32_pclmul psmouse ghash_clmulni_intel sha512_ssse3 virtio_blk sha256_ssse3 virtio_net ahci net_failover libahci virtio_rng failover aesni_intel crypto_simd cryptd [last unloaded: tempesta_lib(OE)]
May 5 12:38:12 192.168.122.82 [ 3504.911286] CR2: ffff970960a600c8
May 5 12:38:12 192.168.122.82 [ 3504.911630] ---[ end trace 0000000000000000 ]---
May 5 12:38:12 192.168.122.82 [ 3504.912121] RIP: 0010:tfw_apm_prcntl_tmfn+0x157/0x600 [tempesta_fw]
May 5 12:38:12 192.168.122.82 [ 3504.912770] Code: c5 00 48 8b 02 48 83 f8 ff 74 e1 49 89 c4 89 c0 48 c7 02 ff ff ff ff 48 8d 1c 80 48 8b 04 24 49 c1 ec 20 48 c1 e3 07 48 01 c3 <44> 39 63 20 0f 83 3f ff ff ff 8b 73 28 45 89 e7 44 39 63 2c 0f 82
May 5 12:38:12 192.168.122.82 [ 3504.914629] RSP: 0018:ffffb1a0c0005e48 EFLAGS: 00010282
May 5 12:38:12 192.168.122.82 [ 3504.915166] RAX: ffff94edca06e0a8 RBX: ffff970960a600a8 RCX: 0000000000000003
May 5 12:38:12 192.168.122.82 [ 3504.915881] RDX: ffff94edc504d900 RSI: 0000000000000004 RDI: ffffffffbb925f20
May 5 12:38:12 192.168.122.82 [ 3504.916605] RBP: ffff94edc504d780 R08: 0000000000000003 R09: ffffb1a0c0005f10
May 5 12:38:12 192.168.122.82 [ 3504.917327] R10: 0000000000000201 R11: 0000000000000bfa R12: 00000000ffff94ed
May 5 12:38:12 192.168.122.82 [ 3504.918038] R13: 0000000000000030 R14: ffffd1a0bfd877c8 R15: ffff94edc504d780
May 5 12:38:12 192.168.122.82 [ 3504.918763] FS: 00007ff138d85740(0000) GS:ffff94ef37c00000(0000) knlGS:0000000000000000
May 5 12:38:12 192.168.122.82 [ 3504.919575] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
May 5 12:38:12 192.168.122.82 [ 3504.920162] CR2: ffff970960a600c8 CR3: 000000012a636004 CR4: 0000000000772ef0
May 5 12:38:12 192.168.122.82 [ 3504.920893] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
May 5 12:38:12 192.168.122.82 [ 3504.921616] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
May 5 12:38:12 192.168.122.82 [ 3504.922335] PKRU: 55555554
May 5 12:38:12 192.168.122.82 [ 3504.922634] Kernel panic - not syncing: Fatal exception in interrupt
May 5 12:38:12 192.168.122.82 [ 3504.923660] Kernel Offset: 0x38400000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
May 5 12:38:12 192.168.122.82 [ 3504.924731] Rebooting in 1 seconds..
To Reproduce
sudo venv/bin/python3.12 ./run_tests.py -n tests.fault_injection.test_fault_injection_base.TestSchedConfig.test_init_modules_tfw_kvmalloc_node
I see this BUG two times.
It's very hard to reproduce. Previously I see it on master branch on my local vm (but I though that my be it was problem in my build, because I can't reproduce it).
I catch it again on CI on the new PR (but I am sure that it has nothing to do with the changes from the PR). Also as I catch it on master a long time ago).
Version or commit hash
Tempesta FW 2a35da6
Tempesta test fbcd279ea65454d5f54dc16e7f1ef0055444c498
Stacktrace or debug log