Guest booting failed: alloc magic broken

[askfongjojo]

This is an issue encountered both internally and by one customer only during stress testing of instance creation. In our case, the issue happened only when we ran 4 concurrent bash loops with Oxide CLI making small instance (2GB memory) create requests. If I make bigger instances with 4GB memory, I did not encounter this issue. It could be because it took just a bit longer to make the bigger VMs and the level of concurrency didn't hit the tipping point.

The propolis log only has a few log lines from crucible:

BRM42220031 # zlogin oxz_propolis-server_81413e4b-d95d-4485-83ad-8fa5c72b01f9
[Connected to zone 'oxz_propolis-server_81413e4b-d95d-4485-83ad-8fa5c72b01f9' pts/6]
The illumos Project     helios-2.0.22187        September 2023
root@oxz_propolis-server_81413e4b-d95d-4485-83ad-8fa5c72b01f9:~# less /var/svc/log/system-illumos-propolis-server\:default.log | looker
01:45:04.874Z INFO propolis-server (crucible-8e50a4ac-611c-47d8-973c-511ca2b4c05e): Scrub at offset 5033216/6291456 sp:5033216
Sep 28 01:45:14.647 INFO request completed, latency_us: 232, response_code: 200, uri: /collect/47b8e77b-cd18-44bb-9968-942c91116075, method: GET, req_id: d099ec85-9c33-49db-b89f-7d2c832f3596, remote_addr: [fd00:1122:3344:10a::3]:52186, local_addr: [fd00:1122:3344:102::66]:55626, component: dropshot, file: /home/build/.cargo/git/checkouts/dropshot-a4a923d29dccc492/35d4408/dropshot/src/server.rs:853
01:45:40.483Z INFO propolis-server (crucible-8e50a4ac-611c-47d8-973c-511ca2b4c05e): Scrub at offset 5284864/6291456 sp:5284864
Sep 28 01:45:44.649 INFO request completed, latency_us: 234, response_code: 200, uri: /collect/47b8e77b-cd18-44bb-9968-942c91116075, method: GET, req_id: c7c44f32-8bc7-44e1-86d5-0eb67ae91ab3, remote_addr: [fd00:1122:3344:10a::3]:52186, local_addr: [fd00:1122:3344:102::66]:55626, component: dropshot, file: /home/build/.cargo/git/checkouts/dropshot-a4a923d29dccc492/35d4408/dropshot/src/server.rs:853

[askfongjojo]

The complete sled-agent log is located in: catacomb:/staff/dogfood/propolis-535-gc21-sled-agent.log.tar.gz

[gjcolombo]

This looks to be a GRUB error: https://github.com/rhboot/grub2/blob/4f9d3f4f8d7866c69e52ba7d81562daea38b22e6/grub-core/kern/mm.c#L152-153

[jordanhendricks]

I spent some time looking into this today. Not a lot interesting to report yet, but jotting down what I looked at so far. Summary of what I looked at:

• As mentioned above, the error on the console is from GRUB. Specifically, it's from an internal simple memory allocator. The "alloc magic" piece refers to GRUB_MM_ALLOC_MAGIC, which is a sentinel value as a part of the metadata for memory regions in the allocator. The check is what it sounds like: verifying that the header data is not corrupted. There is a distinct magic value for allocated and free memory regions. The magic value is checked any time the allocator fetches the region metadata.
• I was curious if there might be anything interesting in the bootrom debug output. For the customer instance, I don't have that data; for the dogfood reproduction for this issue and Guest booting failed: X64 Exception Type - 0D(#GP - General Protection) CPU Apic ID - 00000000 #533, there is a log message that a command to the NVMe controller timed out (NvmExpressPassThru: Timeout occurs for an NVMe command.). I'm not sure it's particularly interesting, because (1) the timeout message is followed by a reset of the controller (disable, then enable), and both of those operations seem to complete successfully and (2) the bootrom was able to hand off control to the guest bootloader. I also noticed some oddities in the output of what the bootrom thinks CC.IOSQES and CC.IOCQES are set to -- it seems to have requested 6 and 4, respectively, but later log messages indicate it thinks the controller has 0x66 and 0x44. This is also true on healthy instances from the same loop that reproduced Guest booting failed: X64 Exception Type - 0D(#GP - General Protection) CPU Apic ID - 00000000 #533 and Guest booting failed: alloc magic broken #535.
• The customer stuck instance experienced Read only parents can't do LiveRepair crucible#969. Afaict, this did not occur on the dogfood reproduction.

Next up, some things to explore:

• I have been assuming a crucible boot disk is required to reproduce, because otherwise we probably would have seen it trying to reproduce Ubuntu 22.04 guest: "segfault at 10 ip 00007f68a0fd5b41 sp 00007ffc956aa800 error 6 in libc.so.6" during first boot #427? But it would be good to confirm that.
• For what command from the bootrom is the NVMe controller timing out? Why would that happen at all?
• Assuming this is data corruption of some kind, I think I'm probably going to have to reproduce this and go from there to figure out what to look at.

[luqmana]

I also noticed some oddities in the output of what the bootrom thinks CC.IOSQES and CC.IOCQES are set to -- it seems to have requested 6 and 4, respectively, but later log messages indicate it thinks the controller has 0x66 and 0x44.

I think that's ok if what it's printing is the SQES/CQES values read from the Identify Controller command. The first nibble is the required/minimum size and the second is the maximum supported. propolis just always sets required == maximum.

[askfongjojo]

FWIW, the instance with the alloc magic error came up just fine after rebooting when I hit it the first time (before customer reported it). It'd look like there was some resource contention that would trigger it. To replicate the issue, I had to create a high-concurrency provisioning situation.

[jordanhendricks]

@luqmana good call, that's exactly what it was.

Separately, I now have the bootrom debug output from the customer instance and don't see any evidence of a command to the NVMe controller timing out.

I'm going to work on reproducing this today, first seeing how far I can get with using PHD to reproduce it.

[jordanhendricks]

Per the hypervisor huddle last week, we determined that we haven't seen this issue reproduced since a lot of work (perf and architecture changes) has landed on the crucible side. The next step, should we take any, would be to see if this issue is still reproducible. AIUI it is currently not high priority, and I am not actively working on it, so I am unassigning myself for now.