Unexpected KVM_EXIT_SHUTDOWN on snapshot load

[aledbf]

Firecracker v1.7.0
Snapshot created with the same version

firecracker --api-sock /tmp/firecracker.socket --level Debug --show-level --show-log-origin
2024-04-04T09:08:26.292257371 [anonymous-instance:main:INFO:src/firecracker/src/main.rs:309] Running Firecracker v1.7.0
2024-04-04T09:08:30.320611802 [anonymous-instance:fc_api:INFO:src/firecracker/src/api_server/parsed_request.rs:69] The API server received a Put request on "/snapshot/load" with body "{\n            \"snapshot_path\": \"./snapshot_file\",\n            \"mem_file_path\": \"./mem_file\"\n    }".
2024-04-04T09:08:30.320668210 [anonymous-instance:main:WARN:src/vmm/src/logger/mod.rs:33] [DevPreview] Virtual machine snapshots is in development preview.
2024-04-04T09:08:30.320994325 [anonymous-instance:main:INFO:src/vmm/src/persist.rs:278] Host CPU vendor ID: [71, 101, 110, 117, 105, 110, 101, 73, 110, 116, 101, 108]
2024-04-04T09:08:30.321004479 [anonymous-instance:main:INFO:src/vmm/src/persist.rs:279] Snapshot CPU vendor ID: [71, 101, 110, 117, 105, 110, 101, 73, 110, 116, 101, 108]
2024-04-04T09:08:30.321101485 [anonymous-instance:main:DEBUG:src/vmm/src/builder.rs:441] event_start: build microvm from snapshot
2024-04-04T09:08:30.330623867 [anonymous-instance:main:WARN:src/vmm/src/logger/mod.rs:33] [DevPreview] Async file IO is in development preview.
2024-04-04T09:08:30.331423448 [anonymous-instance:main:DEBUG:src/vmm/src/builder.rs:528] event_end: build microvm from snapshot
2024-04-04T09:08:30.331951284 [anonymous-instance:main:WARN:src/vmm/src/logger/mod.rs:35] [DevPreview] Virtual machine snapshots is in development preview - 'load snapshot' VMM action took 11259 us.
2024-04-04T09:08:30.331987746 [anonymous-instance:fc_api:INFO:src/firecracker/src/api_server/parsed_request.rs:162] The request was executed successfully. Status code: 204 No Content.
2024-04-04T09:08:30.331998162 [anonymous-instance:fc_api:INFO:src/firecracker/src/api_server/mod.rs:181] 'load snapshot' API request took 11395 us.
2024-04-04T09:08:30.332002696 [anonymous-instance:fc_api:WARN:src/firecracker/src/api_server/mod.rs:134] PUT /snapshot/load: mem_file_path field is deprecated.
2024-04-04T09:08:30.332011104 [anonymous-instance:fc_api:DEBUG:src/firecracker/src/api_server/mod.rs:115] Total previous API call duration: 11408 us.
2024-04-04T09:08:35.947479820 [anonymous-instance:fc_api:INFO:src/firecracker/src/api_server/parsed_request.rs:69] The API server received a Patch request on "/vm" with body "{\n            \"state\": \"Resumed\"\n    }".
2024-04-04T09:08:35.947509638 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:384] Artificially kick devices.
2024-04-04T09:08:35.947521078 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:410] kick block rootfs.
2024-04-04T09:08:35.947532260 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:422] kick net eth0.
2024-04-04T09:08:35.947617021 [anonymous-instance:fc_vcpu 0:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.947667321 [anonymous-instance:fc_vcpu 2:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.947692583 [anonymous-instance:fc_vcpu 1:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.947706098 [anonymous-instance:fc_vcpu 5:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.947714462 [anonymous-instance:fc_vcpu 6:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.947737612 [anonymous-instance:main:INFO:src/vmm/src/rpc_interface.rs:722] 'resume vm' VMM action took 159 us.
2024-04-04T09:08:35.947756850 [anonymous-instance:main:INFO:src/vmm/src/lib.rs:805] Vmm is stopping.
2024-04-04T09:08:35.947764859 [anonymous-instance:fc_api:INFO:src/firecracker/src/api_server/parsed_request.rs:162] The request was executed successfully. Status code: 204 No Content.
2024-04-04T09:08:35.947776235 [anonymous-instance:fc_vcpu 4:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.947809555 [anonymous-instance:fc_api:INFO:src/firecracker/src/api_server/mod.rs:181] 'resume vm' API request took 300 us.
2024-04-04T09:08:35.947827887 [anonymous-instance:fc_api:DEBUG:src/firecracker/src/api_server/mod.rs:115] Total previous API call duration: 350 us.
2024-04-04T09:08:35.947836521 [anonymous-instance:fc_vcpu 3:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.947865371 [anonymous-instance:fc_vcpu 7:INFO:src/vmm/src/vstate/vcpu/mod.rs:472] Received KVM_EXIT_SHUTDOWN signal
2024-04-04T09:08:35.948345282 [anonymous-instance:fc_api:DEBUG:src/firecracker/src/api_server/mod.rs:94] shutdown request received, API server thread ending.
2024-04-04T09:08:35.948410074 [anonymous-instance:main:INFO:src/vmm/src/lib.rs:805] Vmm is stopping.
2024-04-04T09:08:35.960613545 [anonymous-instance:main:INFO:src/firecracker/src/main.rs:101] Firecracker exiting successfully. exit_code=0

How can I get more details about the reason for the exit?
Thanks

[bchalios]

Hello @aledbf and thanks for opening this discussion :)

Could you please provide some more info regarding this? What kernel versions (host & guest) are you using, which CPU are you running this on?

Also, it looks like you are seeing this while trying to resume from a snapshot. Do you see this only on the snapshot resume path? What happens with the original VM, i.e. if you resume the original microVM after you take the snapshot?

Also, I think this looks like something that should be opened as an issue rather than a discussion. Would you mind opening an issue and this information?

Cheers,
Babis

[aledbf]

What kernel versions (host & guest) are you using,

Same version in both 6.7.0-rc6.

which CPU are you running this on?

I am using a c6i.8xlarge instance. I also tried m7i.4xlarge with the same result.

Do you see this only on the snapshot resume path? What happens with the original VM, i.e. if you resume the original microVM after you take the snapshot?

After the snapshot and resuming, the VM continues to work without issues.

[bchalios]

Same version in both 6.7.0-rc6.

We do not officially support 6.7.0 (see here for supported kernels), so we don't test this combination.

I am using a c6i.8xlarge instance. I also tried m7i.4xlarge with the same result.

That sounds weird. I thought that .*xlarge instances did not have KVM available. I guess you are building your own kernel (?)

Any chance you could provide console output from the resumed initial microVM just before you snapshot it?

[aledbf]

@bchalios I am sorry for not posting the whole context.

We are testing a new KVM module that removes the requirement of nested virtualization (that's the reason for the EC2 instances)

Here's the pdf and kernel announcement

• https://github.com/virt-pvm/misc/blob/main/sosp2023-pvm-paper.pdf
• https://lore.kernel.org/lkml/CABgObfaSGOt4AKRF5WEJt2fGMj_hLXd7J2x2etce2ymvT4HkpA@mail.gmail.com/T/#me17e5aa8923b210192c673fa1b09192ac6acf7d6

The issue with the snapshot was already reported, and with the firecracker patch included in the issue, there are no issues with the restoration virt-pvm/linux#2

[bchalios]

Hi @aledbf, thanks for the update and happy it worked out for you.