Guest does not boot when resuming before Linux boot

[retrage]

This issue appears when booting from firmware.

1. Start CH with --kernel=hypervisor-fw and --api-socket $API_SOCK
2. Run ch-remote --api-socket $API_SOCK pause before starting Linux
3. Run ch-remote --api-socket $API_SOCK resume
   Both pause and resume command returns success, and the virtio devices are resuming as far as I see the log, but the guest does not boot after sending the resume.

CH version: cloud-hypervisor v21.0-67-g0dafd47a
Build command: cargo build

VM configuration:

$CH_BIN \                                                                       
  --kernel $FW_BIN \                                                            
  --disk path=$IMG \ 
  --cpus boot=1 \
  --memory size=1024M \
  --net "tap=,mac=,ip=,mask=" \
  --console off \
  --serial tty \
  --log-file $LOG \
  -vvvv \
  --api-socket $API_SOCK

Log:

cloud-hypervisor: 129.715515981s: <vmm> INFO:vmm/src/lib.rs:1340 -- API request event: VmPause(Sender { .. })
cloud-hypervisor: 129.715605731s: <vmm> INFO:virtio-devices/src/transport/pci_device.rs:697 -- _virtio-pci-_disk0: Device does not need activation
cloud-hypervisor: 129.715642006s: <vmm> INFO:virtio-devices/src/transport/pci_device.rs:697 -- _virtio-pci-_net1: Device does not need activation
cloud-hypervisor: 129.715673586s: <vmm> INFO:virtio-devices/src/transport/pci_device.rs:697 -- _virtio-pci-_rng: Device does not need activation
cloud-hypervisor: 129.716899947s: <vmm> INFO:virtio-devices/src/device.rs:342 -- Pausing virtio-block
cloud-hypervisor: 129.716982961s: <_disk0_q0> INFO:virtio-devices/src/epoll_helper.rs:139 -- PAUSE_EVENT received, pausing epoll loop
cloud-hypervisor: 129.717063684s: <vmm> INFO:virtio-devices/src/device.rs:342 -- Pausing virtio-rng
cloud-hypervisor: 129.717106452s: <vmm> INFO:virtio-devices/src/device.rs:342 -- Pausing virtio-net
cloud-hypervisor: 132.211447234s: <vmm> INFO:vmm/src/lib.rs:1340 -- API request event: VmResume(Sender { .. })
cloud-hypervisor: 132.211577872s: <vmm> INFO:virtio-devices/src/device.rs:364 -- Resuming virtio-block
cloud-hypervisor: 132.211618658s: <vmm> INFO:virtio-devices/src/device.rs:364 -- Resuming virtio-rng
cloud-hypervisor: 132.211652359s: <vmm> INFO:virtio-devices/src/device.rs:364 -- Resuming virtio-net

[rbradford]

@retrage Unfortunately i'm having trouble reproducing. Can you:

• Attach the full log
• Attach gdb to the process after a failed resume and include the output of thread apply all bt

My hunch is that we're getting a vCPU process deadlock (like #3585) possibly around the same issue of pending virtio device barriers.

[retrage]

Thank you for taking a look into this issue.

Here is the full log and GDB output:
ch-resuming-log.txt
ch-threads-bt-log.txt

[rbradford]

Can you combine the log file and the serial output together (i.e. remove --log-file) so we can see the output from the fw interleaved with the log so we can see what the fw is doing when the pause/resume happens.

[rbradford]

@retrage I was able to reproduce with the debug build of rust-hypervisor-firmware. It looks like we end up in this tight loop:

https://github.com/cloud-hypervisor/rust-hypervisor-firmware/blob/main/src/block.rs#L278-L281

        // Check for the completion of the request
        while unsafe { core::ptr::read_volatile(&state.used.idx) } != state.avail.idx {
            core::sync::atomic::fence(core::sync::atomic::Ordering::Acquire);
        }

I think what is happening is that the asynchronous MMIO write to an ioeventfd is getting lost and the queue is not being processed resulting in the used.idx not being updated.

[rbradford]

@retrage With the patch in #3665 I wasn't able to reproduce any more but it should be noted I didn't have a 100% reproduce rate without it. Please can you test.

[retrage]

@rbradford I confirmed it fixed with #3665. Thanks!