search

SerenityOS / serenity

The Serenity Operating System 🐞
https://serenityos.org
BSD 2-Clause "Simplified" License
30.56k stars 3.19k forks source link

Kernel: !s_the.is_initialized() assertion failure in TimeManagement::initialize when there is no RDRAND support #8710

Closed Lubrsi closed 3 years ago

Lubrsi commented 3 years ago

CPU: AMD A4-3400 APU with Radeon(tm) HD Graphics Motherboard: ASUS F1A55-M LX

Bisect points to 6938be00f1c2c87a83a173cca0c8a7c78ac88a94 cc @tomuta

Log:

[Kernel]: CPU[0]: Supported features: nx pae pge sse tsc rdtscp constant_tsc nonstop_tsc sep syscall mmx sse2 sse3 fxsr lm
[Kernel]: CPU[0]: No RDRAND support detected, randomness will be poor
[Kernel]: CPU[0]: Physical address bit width: 40
[#0 Kernel]: Initializing unhandled interrupt handlers
[Kernel]: Kernel Commandline: http://192.168.0.10:8080/Kernel root=/dev/ramdisk0 boot_mode=no-fbdev serial_debug switch_to_tty=2
[Kernel]: MM: Multiboot mmap: address=0x00000000, length=645120, type=1
[Kernel]: MM: Got an unaligned physical_region from the bootloader; correcting length 645120 by 2048 bytes
[Kernel]: MM: Multiboot mmap: address=0x00100000, length=3212767232, type=1
[Kernel]: MM: Multiboot mmap: address=0xbfb44000, length=3031040, type=1
[Kernel]: MM: Multiboot mmap: address=0xbfe7f000, length=4096, type=1
[Kernel]: MM: Multiboot mmap: address=0xbfef5000, length=45056, type=1
[Kernel]: MM: Multiboot mmap: address=0x100001000, length=5351927808, type=1
[Kernel]: MM: boot_pdpt @ P0000000000101000
[Kernel]: MM: boot_pd0 @ P0000000000102000
[Kernel]: MM: boot_pd3 @ P0000000000103000
[Kernel]: MM: Physical page entries: 0xc2001000 - 0xc31f9fff (size 0x011f9000)
[Kernel]: MM: Low memory range @ P0000000000000000 - P00000000000fffff (size 0x100000)
[Kernel]: MM: Kernel range @ P0000000000100000 - P00000000019f3fff (size 0x18f4000)
[Kernel]: MM: Boot module range @ P00000000019f5000 - P00000000495f4fff (size 0x47c00000)
[Kernel]: MM: Physical Pages range @ P00000000495f6000 - P000000004a7f7fff (size 0x1202000)
[Kernel]: MM: Super physical region: P0000000000122000 - P0000000000221fff (size 0x100000)
[Kernel]: MM: User physical region: P000000004a7f8000 - P00000000bf8eefff (size 0x750f7000)
[Kernel]: MM: User physical region: P00000000bfb44000 - P00000000bfe27fff (size 0x2e4000)
[Kernel]: MM: User physical region: P00000000bfe7f000 - P00000000bfe7ffff (size 0x1000)
[Kernel]: MM: User physical region: P00000000bfef5000 - P00000000bfefffff (size 0xb000)
[Kernel]: MM: User physical region: P0000000100001000 - P000000023effffff (size 0x3efff000)
[#0 Kernel]: Early access to ACPI tables for interrupt setup
[Kernel]: Interrupts: Switch to Legacy PIC mode
[Kernel]: PIC: Cascading mode, vectors 0x50-0x5f
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Interrupts: Detected Dual i8259
[Kernel]: ACPI: Using RSDP @ P00000000000f0450
[Kernel]: ACPI: Main Description Table valid? true
[Kernel]: ACPI: Using XSDT, enumerating tables @ P00000000bfe74068
[Kernel]: ACPI: XSDT revision 1, total length: 84
[Kernel]: ACPI: Initializing Fixed ACPI data
[Kernel]: ACPI: Searching for the Fixed ACPI Data Table
[Kernel]: ACPI: Fixed ACPI data, Revision 4, length: 244 bytes
[Kernel]: ACPI: DSDT P00000000bfe74150
[Kernel]: ACPI: Dynamic Parsing Enabled, Can parse AML
[Kernel]: RTC: Year: 2021, month: 7, day: 12, hour: 23, minute: 22, second: 24
[Kernel]: HPET @ P00000000bfe7b020
[Kernel]: HPET: Minimum clock tick - 14318
[Kernel]: HPET: Timers count - 3
[Kernel]: HPET: Main counter size: 32-bit
[Kernel]: HPET: Timer[0] comparator size: 32-bit, mode: 32-bit
[Kernel]: HPET: Timer[1] comparator size: 32-bit, mode: 32-bit
[Kernel]: HPET: Timer[2] comparator size: 32-bit, mode: 32-bit
[Kernel]: HPET: frequency 14492753 Hz (14 MHz) resolution: 69 ns
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: Trying to unregister unused handler (?)
[#0 Kernel]: HPET: Setting appropriate functions to timers.
[#0 Kernel]: Time: Scanning for periodic timers
[#0 Kernel]: Time: Scanning for non-periodic timers
[Kernel]: KernelRng: Using HPET as entropy source
[Kernel]: ASSERTION FAILED: !s_the.is_initialized()
[Kernel]: ../../Kernel/Time/TimeManagement.cpp:137 in static void Kernel::TimeManagement::initialize(u32)
[#0 Kernel]: 0xc0c2b6e0 (next: 0xc0120f28)
[#0 Kernel]: 0xc0c2b547 (next: 0xc0120f58)
[#0 Kernel]: 0xc0e4942c (next: 0xc0120fa8)
[#0 Kernel]: 0xc0e7274d (next: 0xc0120ff8)
[#0 Kernel]: 0xc0100356 (next: 0x403e8a10)

Ubuntu dmesg and lspci: dmesg.txt

tomuta commented 3 years ago

Hm can you resolve the stack trace to file/line information? I'm particularly interested in where in Kernel/init.cpp this happens.

Lubrsi commented 3 years ago

Note that this is on latest master and that I've flipped it upside down:

[#0 Kernel]: 0xc0100356 (next: 0x403e8a10)
Kernel/Arch/x86/common/Boot/boot.S:565
[#0 Kernel]: 0xc0e7124f (next: 0xc0120ff8)
Kernel/init.cpp:153
[#0 Kernel]: 0xc0e47f2e (next: 0xc0120fa8)
Kernel/Time/TimeManagement.cpp:138
AK/Singleton.h:107
AK/Singleton.h:76
AK/Singleton.h:46
Kernel/Arch/x86/ScopedCritical.h:20
[#0 Kernel]: 0xc0c2a78b (next: 0xc0120f58)
Kernel/Arch/x86/common/CPU.cpp:23
[#0 Kernel]: 0xc0c2a924 (next: 0xc0120f28)
Kernel/Arch/x86/common/CPU.cpp:31
tomuta commented 3 years ago

Hm can you throw a VERIFY_NOT_REACHED(); into TimeManagement::the() and see where in Kernel/init.cpp that is? Looks like something is calling it before TimeManagement::initialize(0) in this particular setup.

Lubrsi commented 3 years ago 
[Kernel]: ASSERTION FAILED: false
[Kernel]: ../../Kernel/Time/TimeManagement.cpp:136 in static void Kernel::TimeManagement::initialize(u32)

(upside down)

[#0 Kernel]: 0xc0100356 (next: 0x403e8a10)
Kernel/Arch/x86/common/Boot/boot.S:565
[#0 Kernel]: 0xc0e7072d (next: 0xc0120ff8)
Kernel/init.cpp:153
[#0 Kernel]: 0xc0e3ce55 (next: 0xc0120fa8)
??:? (Trying 0xc0e3ce54 gives Kernel/Time/TimeManagement.cpp:136)
[#0 Kernel]: 0xc0c2a78b (next: 0xc0120f88)
Kernel/Arch/x86/common/CPU.cpp:23
[#0 Kernel]: 0xc0c2a924 (next: 0xc0120f58)
Kernel/Arch/x86/common/CPU.cpp:31
Lubrsi commented 3 years ago

I think I see what's happening. Note this line and how it's before the assertion failure:

[Kernel]: KernelRng: Using HPET as entropy source

To do that, it's doing this: https://github.com/SerenityOS/serenity/blob/552185066ed836eef38f1f9088c9482854dcf70a/Kernel/Random.cpp#L51-L53

That call to the() creates an instance if it doesn't already exist.

tomuta commented 3 years ago

Maybe add a call to TimeManagement::initialized() or turn TimeManagement::can_query_precise_time into a static method that also returns false if not initialized.

awesomekling commented 3 years ago

This reproduces in Bochs FWIW

unixinspace commented 3 years ago

I'm seeing this in QEMU as well. Similar result passing -no-hpet flag to qemu. Log attached. serenity_TMassert-nohpet.txt

coyotesphx commented 3 years ago

Anyone figure this out? having the same error, it gets stuck at booting from rom for me. this is using qemu, this is the error I got.

[Kernel]: CPU[0]: No RDRAND support detected, randomness will be poor [Kernel]: CPU[0]: Physical address bit width: 36 [#0 Kernel]: Initializing unhandled interrupt handlers [Kernel]: CPU[0]: CPUID hypervisor signature 'KVMKVMKVM' (0x4b4d564b 0x564b4d56 0x4d), max leaf 0x40000001 [Kernel]: Kernel Commandline: Kernel/Kernel hello [Kernel]: MM: Multiboot mmap: address=0x00000000, length=654336, type=1 [Kernel]: MM: Got an unaligned physical_region from the bootloader; correcting length 654336 by 3072 bytes [Kernel]: MM: Multiboot mmap: address=0x0009fc00, length=1024, type=2 [Kernel]: MM: Multiboot mmap: address=0x000f0000, length=65536, type=2 [Kernel]: MM: Multiboot mmap: address=0x00100000, length=535691264, type=1 [Kernel]: MM: Multiboot mmap: address=0x1ffe0000, length=131072, type=2 [Kernel]: MM: Multiboot mmap: address=0xfeffc000, length=16384, type=2 [Kernel]: MM: Multiboot mmap: address=0xfffc0000, length=262144, type=2 [Kernel]: MM: Contiguous reserved range from P000000000009fc00, length is 394240 [Kernel]: MM: Contiguous reserved range from P000000001ffe0000, length is 3758227456 [Kernel]: MM: boot_pdpt @ P0000000000101000 [Kernel]: MM: boot_pd0 @ P0000000000102000 [Kernel]: MM: boot_pd3 @ P0000000000103000 [Kernel]: MM: Physical page entries: 0xc2001000 - 0xc2801fff (size 0x00801000) [Kernel]: MM: Low memory range @ P0000000000000000 - P00000000000fffff (size 0x100000) [Kernel]: MM: Kernel range @ P0000000000100000 - P0000000001206fff (size 0x1107000) [Kernel]: MM: Physical Pages range @ P0000000001208000 - P0000000001a0dfff (size 0x806000) [Kernel]: MM: Super physical region: P0000000000122000 - P0000000000221fff (size 0x100000) [Kernel]: 1x PhysicalZone (1 MiB) @ 0000000000122000-0000000000121fff [Kernel]: MM: User physical region: P0000000001a0e000 - P000000001ffdffff (size 0x1e5d2000) [Kernel]: 30x PhysicalZone (16 MiB) @ 0000000001a0e000-000000001ea0dfff [Kernel]: * 5x PhysicalZone (1 MiB) @ 000000001fa0e000-000000001fe0dfff [#0 Kernel]: Early access to ACPI tables for interrupt setup [Kernel]: Interrupts: Switch to Legacy PIC mode [Kernel]: PIC: Cascading mode, vectors 0x50-0x5f [#0 Kernel]: Trying to unregister unused handler (?) [#0 Kernel]: Trying to unregister unused handler (?) [#0 Kernel]: Interrupts: Detected Dual i8259 [Kernel]: ACPI: Using RSDP @ P00000000000f5a60 [Kernel]: ACPI: Main Description Table valid? true [Kernel]: ACPI: Using RSDT, enumerating tables @ P000000001ffe2b7b [Kernel]: ACPI: RSDT revision 1, total length: 52 [Kernel]: ACPI: Initializing Fixed ACPI data [Kernel]: ACPI: Searching for the Fixed ACPI Data Table [Kernel]: ACPI: Fixed ACPI data, Revision 1, length: 116 bytes [Kernel]: ACPI: DSDT P000000001ffe0040 [Kernel]: ACPI: Dynamic Parsing Enabled, Can parse AML [Kernel]: RTC: Year: 2021, month: 7, day: 16, hour: 6, minute: 57, second: 16 [Kernel]: HPET @ P000000001ffe2b1b [Kernel]: HPET: Minimum clock tick - 0 [Kernel]: HPET: Timers count - 3 [Kernel]: HPET: Main counter size: 64-bit [Kernel]: HPET: Timer[0] comparator size: 64-bit, mode: 64-bit [Kernel]: HPET: Timer[1] comparator size: 64-bit, mode: 64-bit [Kernel]: HPET: Timer[2] comparator size: 64-bit, mode: 64-bit [Kernel]: HPET: frequency 100000000 Hz (100 MHz) resolution: 10 ns [#0 Kernel]: Trying to unregister unused handler (?) [#0 Kernel]: Trying to unregister unused handler (?) [#0 Kernel]: HPET: Setting appropriate functions to timers. [#0 Kernel]: Time: Scanning for periodic timers [#0 Kernel]: Time: Scanning for non-periodic timers [Kernel]: KernelRng: Using HPET as entropy source [Kernel]: ASSERTION FAILED: !s_the.is_initialized() [Kernel]: ../../Kernel/Time/TimeManagement.cpp:137 in static void Kernel::TimeManagement::initialize(u32) [#0 Kernel]: 0xc072b06d abort +0x17e [#0 Kernel]: 0xc072aecf _abort +0x0 [#0 Kernel]: 0xc0840e24 Kernel::TimeManagement::initialize(unsigned int) +0x1b6 [#0 Kernel]: 0xc0852371 init +0x2bf [#0 Kernel]: 0xc0100356 pae_supported +0x146

edit: posted error

supercomputer7 commented 3 years ago

This reproduces in Bochs FWIW

I'm able to reproduce this by just running the kernel from the terminal like this:

qemu-system-i386 -kernel Kernel/Kernel -m 512 -device isa-debugcon,chardev=stdout -chardev stdio,id=stdout,mux=on