Volume detach failure in devstack-platform-centos-9-stream job

[Ghanshyam Mann]

devstack-platform-centos-9-stream job is failing 100% with the compute server rescue test with volume detach error:

traceback-1: {{{
Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/common/waiters.py", line 316, in wait_for_volume_resource_status
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: volume 70cedb4b-e74d-4a86-a73d-ba8bce29bc99 failed to reach available status (current in-use) within the required time (196 s).
}}}

Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/common/waiters.py", line 384, in wait_for_volume_attachment_remove_from_server
    raise lib_exc.TimeoutException(message)
tempest.lib.exceptions.TimeoutException: Request timed out
Details: Volume 70cedb4b-e74d-4a86-a73d-ba8bce29bc99 failed to detach from server cf57d12b-5e37-431e-8c71-4a7149e963ae within the required time (196 s) from the compute API perspective

https://a886e0e70a23f464643f-7cd608bf14cafb686390b86bc06cde2a.ssl.cf1.rackcdn.com/827576/6/check/devstack-platform-centos-9-stream/53de74e/testr_results.html

https://zuul.openstack.org/builds?job_name=devstack-platform-centos-9-stream&skip=0

[Ghanshyam Mann (ghanshyammann)]

gibi debugged and found that nova fails to detach the volume from the guest via libvirt even after retries

https://zuul.openstack.org/build/3e24d977991d4536b6279afd7f3b5d56/log/controller/logs/screen-n-cpu.txt?severity=4#49433

<gibi>
 about the rescue issue in the centos 9 stream job. In that job I see libvirt 8.0.0 and qemu 6.2.0 that is way newer than what we use in the ubuntu jobs (libvirt 6.0.0 and qemu 4.2.0)

and nova fails to detach the volume from the guest via libvirt even after retries

so if I have to guess then something is changed in the libvirt between 6.0.0 and 8.0.0 that makes this faulty

[Ghanshyam Mann (ghanshyammann)]

anyone from centos9-stream expert/maintainers can help here?

[Kashyap Chamarthy (kashyapc)]

That's one of the affected QEMU instance (as noticed in the libvirtd debug log):

2022-02-08 15:24:23.722+0000: starting up libvirt version: 8.0.0, package: 2.el9 (<email address hidden>, 2022-01-25-13:44:28, ), qemu version: 6.2.0qemu-kvm-6.2.0-5.el9, kernel: 5.14.0-52.el9.x86_64, hostname: centos-9-stream-ovh-bhs1-0028363346
LC_ALL=C \
PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin \
HOME=/var/lib/libvirt/qemu/domain-174-instance-00000079 \
XDG_DATA_HOME=/var/lib/libvirt/qemu/domain-174-instance-00000079/.local/share \
XDG_CACHE_HOME=/var/lib/libvirt/qemu/domain-174-instance-00000079/.cache \
XDG_CONFIG_HOME=/var/lib/libvirt/qemu/domain-174-instance-00000079/.config \
/usr/libexec/qemu-kvm \
-name guest=instance-00000079,debug-threads=on \
-S \
-object '{"qom-type":"secret","id":"masterKey0","format":"raw","file":"/var/lib/libvirt/qemu/domain-174-instance-00000079/master-key.aes"}' \
-machine pc-i440fx-rhel7.6.0,usb=off,dump-guest-core=off,memory-backend=pc.ram \
-accel tcg \
-cpu Nehalem \
-m 128 \
-object '{"qom-type":"memory-backend-ram","id":"pc.ram","size":134217728}' \
-overcommit mem-lock=off \
-smp 1,sockets=1,dies=1,cores=1,threads=1 \
-uuid 62898a79-0554-44fc-8643-21dcf8eb23c4 \
-smbios 'type=1,manufacturer=OpenStack Foundation,product=OpenStack Nova,version=24.1.0,serial=62898a79-0554-44fc-8643-21dcf8eb23c4,uuid=62898a79-0554-44fc-8643-21dcf8eb23c4,family=Virtual Machine' \
-no-user-config \
-nodefaults \
-chardev socket,id=charmonitor,fd=31,server=on,wait=off \
-mon chardev=charmonitor,id=monitor,mode=control \
-rtc base=utc \
-no-shutdown \
-boot strict=on \
-blockdev '{"driver":"file","filename":"/opt/stack/data/nova/instances/_base/0b98895c422e59e9b5ebd04222b3d18863659a49","node-name":"libvirt-3-storage","cache":{"direct":true,"no-flush":false},"auto-read-only":true,"discard":"unmap"}' \
-blockdev '{"node-name":"libvirt-3-format","read-only":true,"cache":{"direct":true,"no-flush":false},"driver":"raw","file":"libvirt-3-storage"}' \
-blockdev '{"driver":"file","filename":"/opt/stack/data/nova/instances/62898a79-0554-44fc-8643-21dcf8eb23c4/disk","node-name":"libvirt-2-storage","cache":{"direct":true,"no-flush":false},"auto-read-only":true,"discard":"unmap"}' \
-blockdev '{"node-name":"libvirt-2-format","read-only":false,"cache":{"direct":true,"no-flush":false},"driver":"qcow2","file":"libvirt-2-storage","backing":"libvirt-3-format"}' \
-device virtio-blk-pci,bus=pci.0,addr=0x4,drive=libvirt-2-format,id=virtio-disk0,bootindex=1,write-cache=on \
-blockdev '{"driver":"file","filename":"/opt/stack/data/nova/instances/62898a79-0554-44fc-8643-21dcf8eb23c4/disk.config","node-name":"libvirt-1-storage","cache":{"direct":true,"no-flush":false},"auto-read-only":true,"discard":"unmap"}' \
-blockdev '{"node-name":"libvirt-1-format","read-only":true,"cache":{"direct":true,"no-flush":false},"driver":"raw","file":"libvirt-1-storage"}' \
-device ide-cd,bus=ide.0,unit=0,drive=libvirt-1-format,id=ide0-0-0,write-cache=on \
-netdev tap,fd=34,id=hostnet0 \
-device virtio-net-pci,host_mtu=1372,netdev=hostnet0,id=net0,mac=fa:16:3e:c6:c5:49,bus=pci.0,addr=0x3 \
-add-fd set=2,fd=33 \
-chardev pty,id=charserial0,logfile=/dev/fdset/2,logappend=on \
-...

[Kashyap Chamarthy (kashyapc)]

So DeviceDetachFailed is raised "if libvirt reported error during detaching from the live domain or we timed out waiting for libvirt events and run out of retries"

In this case, it raised the error because it ran out of retries. The default number of retries for CONF.libvirt.device_detach_attempts is 8.

I'm looking at the libvirt <-> QEMU interaction logs here. And I see several failures related to detach (in QEMU parlance "device_del" and "blockdev-del"):

-----------------------------------------------------------------------
2022-02-08 15:16:14.532+0000: 107878: debug : qemuMonitorJSONIOProcessLine:222 : Line [{"id": "libvirt-414", "error": {"class": "GenericError", "desc": "Device virtio-disk1 is already in the process of unplug"}}]
2022-02-08 15:16:14.532+0000: 107878: info : qemuMonitorJSONIOProcessLine:241 : QEMU_MONITOR_RECV_REPLY: mon=0x7f74e40cd2f0 reply={"id": "libvirt-414", "error": {"class": "GenericError", "desc": "Device virtio-disk1 is already in the process of unplug"}}
2022-02-08 15:16:14.532+0000: 72484: debug : qemuMonitorJSONCheckErrorFull:387 : unable to execute QEMU command {"execute":"device_del","arguments":{"id":"virtio-disk1"},"id":"libvirt-414"}: {"id":"libvirt-414","error":{"class":"GenericError","desc":"Dev
ice virtio-disk1 is already in the process of unplug"}}
2022-02-08 15:16:14.532+0000: 72484: error : qemuMonitorJSONCheckErrorFull:399 : internal error: unable to execute QEMU command 'device_del': Device virtio-disk1 is already in the process of unplug

[...]

2022-02-08 15:24:09.134+0000: 111449: debug : qemuMonitorJSONIOProcessLine:222 : Line [{"id": "libvirt-415", "error": {"class": "GenericError", "desc": "Failed to find node with node-name='libvirt-5-format'"}}]
2022-02-08 15:24:09.134+0000: 111449: info : qemuMonitorJSONIOProcessLine:241 : QEMU_MONITOR_RECV_REPLY: mon=0x7f74e40cde70 reply={"id": "libvirt-415", "error": {"class": "GenericError", "desc": "Failed to find node with node-name='libvirt-5-format'"}}
2022-02-08 15:24:09.134+0000: 72483: debug : qemuMonitorJSONCheckErrorFull:387 : unable to execute QEMU command {"execute":"blockdev-del","arguments":{"node-name":"libvirt-5-format"},"id":"libvirt-415"}: {"id":"libvirt-415","error":{"class":"GenericError
","desc":"Failed to find node with node-name='libvirt-5-format'"}}
2022-02-08 15:24:09.134+0000: 72483: error : qemuMonitorJSONCheckErrorFull:399 : internal error: unable to execute QEMU command 'blockdev-del': Failed to find node with node-name='libvirt-5-format'
2022-02-08 15:24:09.134+0000: 72483: debug : qemuMonitorBlockdevDel:4265 : nodename=libvirt-5-storage
2022-02-08 15:24:09.134+0000: 72483: debug : qemuMonitorBlockdevDel:4267 : mon:0x7f74e40cde70 vm:0x7f751401e920 fd:36
2022-02-08 15:24:09.134+0000: 72483: info : qemuMonitorSend:914 : QEMU_MONITOR_SEND_MSG: mon=0x7f74e40cde70 msg={"execute":"blockdev-del","arguments":{"node-name":"libvirt-5-storage"},"id":"libvirt-416"}
 fd=-1
2022-02-08 15:24:09.134+0000: 111449: info : qemuMonitorIOWrite:402 : QEMU_MONITOR_IO_WRITE: mon=0x7f74e40cde70 buf={"execute":"blockdev-del","arguments":{"node-name":"libvirt-5-storage"},"id":"libvirt-416"}
 len=93 ret=93 errno=0
2022-02-08 15:24:09.136+0000: ...

[Balazs Gibizer (balazs-gibizer)]

This is the filtered nova log from the test_rescued_vm_detach_volume test case: https://paste.opendev.org/show/bEtFDBoLqDfotDMPDOq8/

Nova boots a VM with a cinder volume then start a rescue, which destroys the domain and starts a new one with a modified disk config (boot it from a rescue image). Then tries to detach the volume

These are the domain xmls of the nova server during the test case https://paste.opendev.org/show/bf9JaJYMYDOX9onjFFy0/

[Balazs Gibizer (balazs-gibizer)]

The logs a bit misleading as tempest reuses the nova instance for multiple test case so the compute log has more actions about this instance that can be connected to the tempest test case.

Here are a full mapping of compute reques IDs back to tempest actions:

req-5f5fdb2d-b1af-4e2a-a5ec-80db7af960d1 -- server create -- ServerRescueNegativeTestJSON:setUpClass
req-9840039d-e48d-4470-81fc-53bd2f4c22d8 -- pausing -- ServerRescueNegativeTestJSON:test_rescue_paused_instance
req-63e1e0df-866d-472d-bd8a-2b7b25d6b099 -- unpausing -- ServerRescueNegativeTestJSON:_run_cleanups
req-f5ed05e5-e2c7-4f12-906a-bb6e46318ef9 -- rescue -- ServerRescueNegativeTestJSON:test_rescued_vm_attach_volume
req-8fb1ec02-603b-482f-8da9-e5334aa15185 -- unrescue -- ServerRescueNegativeTestJSON:_run_cleanups
req-f3015900-509f-411c-86c3-7c5c69e75999 -- attach volume -- ServerRescueNegativeTestJSON:test_rescued_vm_detach_volume
req-f7fc5f0d-c9d5-4a39-8776-62dfc470a3bb -- rescue -- ServerRescueNegativeTestJSON:test_rescued_vm_detach_volume
req-e1add0c3-2d20-48ef-b9a9-82eb8ab577da -- unrescue -- ServerRescueNegativeTestJSON:_run_cleanups
req-f89675d8-1e01-4212-b55e-e43c56b48ec7 -- detach volume --> ERROR -- ServerRescueNegativeTestJSON:_run_cleanups
req-d02f5915-b91f-4e49-9714-f3957557b063 -- get console -- ServerRescueNegativeTestJSON:_run_cleanups
req-a1de94e4-1cbc-44cb-bec5-5f4469081b2f -- delete server -- ServerRescueNegativeTestJSON:tearDownClass

This also shows that the actual tempest test case succeeds. The fauilure happens during the cleanup phase.

So the actually interesting sequence of events are:

req-f7fc5f0d-c9d5-4a39-8776-62dfc470a3bb -- rescue -- ServerRescueNegativeTestJSON:test_rescued_vm_detach_volume
--- test case passes, tempest starts cleaning up ---
req-e1add0c3-2d20-48ef-b9a9-82eb8ab577da -- unrescue -- ServerRescueNegativeTestJSON:_run_cleanups
req-f89675d8-1e01-4212-b55e-e43c56b48ec7 -- detach volume --> ERROR -- ServerRescueNegativeTestJSON:_run_cleanups

[Balazs Gibizer (balazs-gibizer)]

Increasing the timeout value in nova from 20 to 60 sec before nova retries the detach did not helped. The detach still timeouts:

https://zuul.opendev.org/t/openstack/build/61f733fc73834ff0924284dac61c9a4b/log/controller/logs/screen-n-cpu.txt?severity=3

[Kashyap Chamarthy (kashyapc)]

Some more debugging context based on Gibi's analysis on IRC (quoting Gibi generously):

In "rescue" mode we don't allow detach. And that part works -- i.e.
throws an error as expected. After that the test framework tries to
clean up. It does so by doing the actions in reverse to move back to
the starting state.

So as the server in RESCUE state it unrescues it. And as a volume was
attached to the server before rescue, it tries to detach the volume
after the unrescue. And that detach should remove the volume from the
domain but fails. So, during this detach:

(1) Nova first detaches the volume from the persistent domain that
    succeeds

(2) Then nova issue the detach command from the live domain and waits
    for the event.

(3) However, the event is not received in 20 seconds so it issues the
    command again, which returns the error:

        error message: internal error: unable to execute QEMU command
        'device_del': Device virtio-disk1 is already in the process of
        unplug

(4) Then Nova retries 6 more times, always getting the same error as
    above, and then gives up.

[Balazs Gibizer (balazs-gibizer)]

Here are the libvirtd logs for the first and second detach trial: https://paste.opendev.org/show/bKANW2WAzfAzEIGcgJX8/

What I can see is that after the first detach is accepted there is no DEVICE_DELETED event received from QEMU. Probably this is why libvirt does not send the corresponding event to nova and this is why nova times out waiting for the event and eventually retry the detach

[Balazs Gibizer (balazs-gibizer)]

There is a reproduction where all the other test cases are turned off so the logs are a lot smaller and less noisy https://zuul.opendev.org/t/openstack/build/3cc7cce20af348649e01ce966d696cdb/logs

[Kashyap Chamarthy (kashyapc)]

Based on a chat with libvirt developers, there seem to be two possibilities:

1) the guest OS didn't confirm the detach
2) there was a recent bug in QEMU triggered by using JSON syntax for `-device`

I wonder we can rule out the possibility (2) here. The QEMU and libvirt
versions in the CI seem to be:

    qemu-kvm-6.2.0-5.el9
    libvirt version: 8.0.0, package: 2.el9

However, based on the QEMU and libvirt RHEL 9 bugs[1][2], they're
already fixed in:

    qemu-kvm-6.2.0-5.el9
    libvirt-8.0.0-0rc1.1.module+el8.6.0+13853+e8cd34b9

                * * *

To _really_ rule out second possibility above, I wonder if we can
try the workaround for the missing DEVICE_DELETED event:

In /etc/libvit/qemu.conf:

        capability_filters = [ "device.json" ]

[1] https://bugzilla.redhat.com/show_bug.cgi?id=2036669 --
    DEVICE_DELETED event is not delivered for device frontend if -device
    is configured via JSON
[2] https://bugzilla.redhat.com/show_bug.cgi?id=2035237 -- devices not
    removed from the definition after hot-unplug when JSON syntax for
    -device is used

[Balazs Gibizer (balazs-gibizer)]

I'm looking into both possibilities:

1) the current test grabs the guest VM consol log after the detach fails. You can see it here https://paste.opendev.org/show/bXXn63wbTPOwiCGC5xDI/
I see nothing obviously wrong in it. But the guest is in a state of getting IP from the DHCP so maybe the guest was not fully booted yet when the detach was requested.

2) I've pushed PS6 of [1] to test the WA.

[1] https://review.opendev.org/c/openstack/devstack/+/828705

[Balazs Gibizer (balazs-gibizer)]

We can rule out #2) I see the same failure happening even after the WA is applied

* qemu.conf with the WA: https://zuul.opendev.org/t/openstack/build/f2bc2a392fe344ca9cf03438ac720dc9/log/controller/logs/libvirt/qemu_conf.txt#962
* nova-compute issuing the detach: https://zuul.opendev.org/t/openstack/build/f2bc2a392fe344ca9cf03438ac720dc9/log/controller/logs/screen-n-cpu.txt#3106
* libvirtd issuing the device_del command: https://zuul.opendev.org/t/openstack/build/f2bc2a392fe344ca9cf03438ac720dc9/log/controller/logs/libvirt/libvirt/libvirtd_log.txt#25894-25912
* nova-compute fails as detach fails: https://zuul.opendev.org/t/openstack/build/f2bc2a392fe344ca9cf03438ac720dc9/log/controller/logs/screen-n-cpu.txt#3220

[Balazs Gibizer (balazs-gibizer)]

I'v pushed PS7 of [1] depending on a tempest change [2] to i) grab the guest console log before tempest issues the detach ii) add an extra delay before the detach to let the VM fully boot. Let's see if this helps.

If the issue is that the guest is not fully booted and the extra sleep will make the detach work then we need Lee's tempest change series where the test waits until VM is accessible via ssh [3]

[1] https://review.opendev.org/c/openstack/devstack/+/828705
[2] https://review.opendev.org/c/openstack/tempest/+/828863
[3] https://review.opendev.org/q/topic:wait_until_sshable_pingable

[Balazs Gibizer (balazs-gibizer)]

After adding an extra 120 sec of delay in the test before issue the detach request the volume is detached successfully. This confirms that the issue is #1). The guest OS did not release the device probably because the guest OS hasn't booted fully up yet when the unplug comes.

As I mentioned above Lee has a tempest change series[3] adding extra waiters before these operations that checks that the VM can be reached via ssh. That series probably solves this issue as well.

[3] https://review.opendev.org/q/topic:wait_until_sshable_pingable

[Ghanshyam Mann (ghanshyammann)]

adding tempest for https://review.opendev.org/q/topic:wait_until_sshable_pingable fixes and we will see if that fixes the things. if it does then we can remove the nova from this bug.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/831608

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/831606
Committed: https://opendev.org/openstack/tempest/commit/952fe9c76deaa16a5b5915ff1f96cc5d752477c2
Submitter: "Zuul (22348)"
Branch: master

commit 952fe9c76deaa16a5b5915ff1f96cc5d752477c2
Author: Ghanshyam Mann <email address hidden>
Date: Wed Mar 2 14:43:34 2022 -0600

    Add tempest-full-centos-9-stream non voting job

    centos 9 stream is testing runtime for Yoga so
    let's add it in tempest gate. This job is failing
    due to bug#1960346 and it will be helpful to know the
    job status when we add the fixes with below series:
    - https://review.opendev.org/q/topic:wait_until_sshable_pingable

    Related-Bug: #1960346
    Change-Id: Ib91f67fb9a592e91649e06bb2821f452b36b49f0

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/817769
Committed: https://opendev.org/openstack/tempest/commit/d548e7a8fb22f4cd9aa6c36ee5ca63857e38e843
Submitter: "Zuul (22348)"
Branch: master

commit d548e7a8fb22f4cd9aa6c36ee5ca63857e38e843
Author: Lee Yarwood <email address hidden>
Date: Fri Nov 12 12:59:22 2021 +0000

    compute: Move volume attach tests to use wait_until=SSHABLE

    Waiting until the test instance is SSH-able before continuing
    the test will help us avoid failures to detach a volume from
    server, more info in the related bug.

    Related-Bug: #1960346
    Change-Id: I5ad4aa04f02001efa06616bf77e03e018206d1fe

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/817770
Committed: https://opendev.org/openstack/tempest/commit/9ba15f64bca77f8d23b1e322a7a6b23c71a2d9d6
Submitter: "Zuul (22348)"
Branch: master

commit 9ba15f64bca77f8d23b1e322a7a6b23c71a2d9d6
Author: Lee Yarwood <email address hidden>
Date: Fri Nov 12 13:01:11 2021 +0000

    compute: Move device tagging tests to use wait_until=SSHABLE

    Waiting until the test instance is SSH-able before continuing
    the test will help us avoid failures to detach a volume from
    server, more info in the related bug.

    Related-Bug: #1960346

    Change-Id: Id5496572ce6cef06e71bae1a1040b274bacf4f79

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/834350

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/831608
Committed: https://opendev.org/openstack/tempest/commit/6fa213cc0fcab744b46109e5f07cb58b0df4a314
Submitter: "Zuul (22348)"
Branch: master

commit 6fa213cc0fcab744b46109e5f07cb58b0df4a314
Author: Ghanshyam Mann <email address hidden>
Date: Thu Mar 17 23:45:41 2022 -0500

    Make rescue, volume attachment compute tests to use SSH-able server

    As you can see the details in bug#1960346, volume detach fails
    on centos 9 stream while server is not fully booted. This
    commit makes sure that erver creation as well as after the unrescue
    server test wait for the server to be SSH-able before test start
    performing the detach operation in cleanup.

    Related-Bug: #1960346
    Change-Id: Ib21a764e3cf81d761d738bf7bfaf5c264b739a16

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/834350
Committed: https://opendev.org/openstack/tempest/commit/7304e3ac8973a42bcfff91d561ac9d238b187334
Submitter: "Zuul (22348)"
Branch: master

commit 7304e3ac8973a42bcfff91d561ac9d238b187334
Author: Ghanshyam Mann <email address hidden>
Date: Fri Mar 18 13:58:25 2022 -0500

    Move ServerStableDeviceRescueTest to wait for SSH-able server

    ServerStableDeviceRescueTest also perform the attach_volume
    on rescue server and in cleanup detach_volume. As described in
    the bug#1960346 we need to wait for server readiness before
    detach volume called.

    Also making centos stream 9 job as voting.

    Closes-Bug: #1960346
    Change-Id: Ia213297b13f42d39213dea9a3b2cfee561cdcf28

[Ghanshyam Mann (ghanshyammann)]

this issue is fixed by making the server ready and SSH-able before detach volume operation is performed.

This series: https://review.opendev.org/q/(topic:bug/1960346+OR+topic:wait_until_sshable_pingable)+status:merged

and now job is also passing and voting
- https://review.opendev.org/c/openstack/tempest/+/834350
- https://review.opendev.org/c/openstack/devstack/+/834546

[Ghanshyam Mann (ghanshyammann)]

Closing it for nova as it is fixed on the tempest side.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/tempest 30.1.0 release.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/840112

[Balazs Gibizer (balazs-gibizer)]

Note that an upstream libvirt bug is opened as the issue was reproduced with pure libvirt / qemu and with Ubuntu 22.04 guest: https://gitlab.com/libvirt/libvirt/-/issues/309

[Balazs Gibizer (balazs-gibizer)]

https://zuul.opendev.org/t/openstack/build/1c500d7165ae4dcd9c11654a849a4aa0/log/controller/logs/screen-n-cpu.txt?severity=4 <-- This shows that tempest.api.compute.base.BaseV2ComputeTest.resize_server() also needs to wait for the guest to boot as otherwise test_resize_server_with_multiattached_volume() can try to detach the volume too early.

[bgibizer (bgibizer-redhat-bugs)]

This bug report is based on the upstream bug: https://gitlab.com/libvirt/libvirt/-/issues/309 but I have updated the description and reproduction based on the discussion in the upstream report.

Description of problem:

If disk is detached from a guest while the guest OS is still booting then that disk get stuck. It seems that the detach succeeds from virsh perspective. But the disk is still visible both from the guest and from virsh as attached. However when the detach is retried, even after the guest OS is fully booted, it fails with "Failed to detach disk
error: internal error: unable to execute QEMU command 'device_del': Device virtio-disk23 is already in the process of unplug".

This was observed in OpenStack upstream CI with cirros 0.5.2 guest OS. But now reproduced without OpenStack with a more normal guest (Ubuntu 22.04). The OpenStack bug is being worked around by changing the test in the CI to wait until the guest is fully booted before trying to attach the volume.

Version-Release number of selected component (if applicable):

Host:

* Operating system: Debian sid
* Architecture: x86_64
* kernel version: 5.17.0-1-amd64 #1 (closed) SMP PREEMPT Debian 5.17.3-1 (2022-04-18) x86_64 GNU/Linux
* libvirt version: 8.2.0-1
* Hypervisor and version: qemu-system-x86_64 1:7.0+dfsg-1

Guest:

* Operating system: Ubuntu 22.04 (cloud image)

How reproducible:
If the guest OS boot is slowed down it is 100% reporducible

Steps to Reproduce:
1. Modify the Ubuntu cloud guest image to have the boot_delay=100 added to the kernel args to simulate a slow host
2. Start the Ubuntu domain and connect to the serial console to see it boot
3. Wait until the first messages appear in the console. This is around T+50sec from the virsh start.
4. From a second terminal attach an additional disk to the guest. It succeeds.
5. Wait a second
6. Detach the additional disk from the guest. The virsh command hangs for couple of seconds, but then succeeds.
7. Check the domain XML, the disk is still attached
8. Check the lsblk command from the guest (after it is fully booted). The disk is still attached.
9. Check the virsh domblklist output. The disk is still attached.
10. Try to detach the disk again. It fails with "Failed to detach disk error: internal error: unable to execute QEMU command 'device_del': Device virtio-disk23 is already in the process of unplug".

Actual results:
The disk cannot be detached even after the guest OS is fully booted. Retrying the detach always fails.

Expected results:
Either the disk is eventually detach from the guest after it is fully booted.
Or the detach can be successfully retried from via libvirt / virsh

Additional info:
Please see the debug logs and detailed reproduction sequence in the upstream bug https://gitlab.com/libvirt/libvirt/-/issues/309

[mkletzan (mkletzan-redhat-bugs)]

This to me looks like a thing that needs some work in QEMU since libvirt is trying to detach the device again, as requested. Looking at the linked issue it confirms my speculations. Therefore I am moving this to QEMU to further triage this.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/842140

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/842240

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/842921

[qinwang (qinwang-redhat-bugs)]

Reproduce it on
Red Hat Enterprise Linux release 9.0 (Plow)
5.14.0-70.13.1.el9_0.x86_64
qemu-kvm-6.2.0-11.el9_0.2.x86_64
seabios-bin-1.15.0-1.el9.noarch
edk2-ovmf-20220126gitbb1bba3d77-3.el9.noarch

Test steps:

1.Create image file if need
qemu-img create -f qcow2 /home/kvm_autotest_root/images/stg1.qcow2 1G

2.Boot vm

/usr/libexec/qemu-kvm \
    -name 'avocado-vt-vm1' \
    -sandbox on \
    -machine q35,memory-backend=mem-machine_mem \
    -device pcie-root-port,id=pcie-root-port-0,multifunction=on,bus=pcie.0,addr=0x1,chassis=1 \
    -device pcie-pci-bridge,id=pcie-pci-bridge-0,addr=0x0,bus=pcie-root-port-0 \
    -nodefaults \
    -device VGA,bus=pcie.0,addr=0x2 \
    -m 8G \
    -object memory-backend-ram,size=8G,id=mem-machine_mem \
    -smp 2 \
   -cpu host,vmx,+kvm_pv_unhalt \
    -device pcie-root-port,id=pcie-root-port-1,port=0x1,addr=0x1.0x1,bus=pcie.0,chassis=2 \
    -device qemu-xhci,id=usb1,bus=pcie-root-port-1,addr=0x0 \
    -device usb-tablet,id=usb-tablet1,bus=usb1.0,port=1 \
    -blockdev node-name=file_image1,driver=file,auto-read-only=on,discard=unmap,aio=threads,filename=/home/kvm_autotest_root/images/rhel900-64-virtio.qcow2,cache.direct=on,cache.no-flush=off \
    -blockdev node-name=drive_image1,driver=qcow2,read-only=off,cache.direct=on,cache.no-flush=off,file=file_image1 \
    -device pcie-root-port,id=pcie-root-port-2,port=0x2,addr=0x1.0x2,bus=pcie.0,chassis=3 \
    -device virtio-blk-pci,id=image1,drive=drive_image1,bootindex=0,write-cache=on,bus=pcie-root-port-2,addr=0x0 \
    \
    -blockdev node-name=file_stg1,driver=file,auto-read-only=on,discard=unmap,aio=threads,filename=/home/kvm_autotest_root/images/stg1.qcow2,cache.direct=on,cache.no-flush=off \
    -blockdev node-name=drive_stg1,driver=qcow2,read-only=off,cache.direct=on,cache.no-flush=off,file=file_stg1 \
    -device pcie-root-port,id=pcie-root-port-3,port=0x3,addr=0x1.0x3,bus=pcie.0,chassis=4 \
    \
    -device pcie-root-port,id=pcie-root-port-5,port=0x5,addr=0x1.0x5,bus=pcie.0,chassis=6 \
    -device virtio-net-pci,mac=9a:e1:e5:87:89:d2,id=idhDtYbt,netdev=id15e8Je,bus=pcie-root-port-5,addr=0x0 \
    -netdev tap,id=id15e8Je,vhost=on \
    -vnc :5 \
    -monitor stdio \
    -qmp tcp:0:5955,server,nowait \
    -rtc base=localtime,clock=host,driftfix=slew \
    -boot menu=off,order=cdn,once=c,strict=off \
    -enable-kvm \
    -device pcie-root-port,id=pcie_extra_root_port_0,multifunction=on,bus=pcie.0,addr=0x3,chassis=7 \
    -chardev socket,id=charserial1,path=/var/tmp/run-serial.log,server=on,wait=off \
   -device isa-serial,chardev=charserial1,id=serial1 \

3.Sleep 3 seconds

4.execute qmp command to hot-plug/unplug disk

{"execute": "device_add", "arguments": {"driver": "virtio-blk-pci", "id": "stg1", "drive": "drive_stg1", "write-cache": "on", "bus": "pcie-root-port-3"}}

{"execute":"device_del","arguments":{"id":"stg1"}}

No any error on qmp command

5.wait for guest finish booting the login and check disk
lsblk
there is new disk found in guest. It expect the disk non-exist in guest

6.execute qmp command to unplug disk again
{"execute":"device_del","arguments":{"id":"stg1"}}

it get error return
{"error": {"class": "GenericError", "desc": ...

[yiwei (yiwei-redhat-bugs)]

Can reproduce this bug with virtio-net-pci and virtio-blk-pci device on the latest rhel9.1.0 host with the test steps of Comment 2.

host version:
qemu-kvm-7.0.0-4.el9.x86_64
kernel-5.14.0-96.el9.x86_64
seabios-1.16.0-2.el9.x86_64
guest: rhel9.1.0

Test result:
hot-plug/unplug virtio-net-pci device in qmp:
{ "execute": "netdev_add","arguments": { "type": "tap", "id": "hostnet0" } }
{ "execute": "device_add","arguments": { "driver": "virtio-net-pci", "id": "net1", "bus": "pcie-root-port-5", "mac": "52:54:00:12:34:56", "netdev": "hostnet0" } }
{ "execute": "device_del", "arguments": { "id": "net1" } }{"return": {}}
{"return": {}}
{"return": {}}

{ "execute": "device_del", "arguments": { "id": "net1" } }
{"error": {"class": "GenericError", "desc": "Device net1 is already in the process of unplug"}}

hot-plug/unplug virtio-blk-pci device in qmp:
{"execute": "device_add", "arguments": {"driver": "virtio-blk-pci", "id": "stg1", "drive": "drive_stg1", "write-cache": "on", "bus": "pcie-root-port-4"}}
{"execute":"device_del","arguments":{"id":"stg1"}}
{"return": {}}
{"return": {}}

{"execute":"device_del","arguments":{"id":"stg1"}}
{"error": {"class": "GenericError", "desc": "Device stg1 is already in the process of unplug"}}

Boot a guest with cmd:
 /usr/libexec/qemu-kvm \
    -name 'avocado-vt-vm1' \
    -sandbox on \
    -machine q35,memory-backend=mem-machine_mem \
    -device pcie-root-port,id=pcie-root-port-0,multifunction=on,bus=pcie.0,addr=0x1,chassis=1 \
    -device pcie-pci-bridge,id=pcie-pci-bridge-0,addr=0x0,bus=pcie-root-port-0 \
    -nodefaults \
    -device VGA,bus=pcie.0,addr=0x2 \
    -m 16G \
    -object memory-backend-ram,size=16G,id=mem-machine_mem \
    -smp 6,maxcpus=6,cores=2,threads=1,dies=1,sockets=3 \
    -cpu Icelake-Server-noTSX,enforce \
    -device pcie-root-port,id=pcie-root-port-1,port=0x1,addr=0x1.0x1,bus=pcie.0,chassis=2 \
    -device qemu-xhci,id=usb1,bus=pcie-root-port-1,addr=0x0 \
    -device usb-tablet,id=usb-tablet1,bus=usb1.0,port=1 \
    -device pcie-root-port,id=pcie-root-port-2,port=0x2,addr=0x1.0x2,bus=pcie.0,chassis=3 \
    -device virtio-scsi-pci,id=virtio_scsi_pci0,bus=pcie-root-port-2,addr=0x0 \
    -blockdev node-name=file_image1,driver=file,auto-read-only=on,discard=unmap,aio=threads,filename=/home/rhel9.1-seabios.qcow2,cache.direct=on,cache.no-flush=off \
    -blockdev node-name=drive_image1,driver=qcow2,read-only=off,cache.direct=on,cache.no-flush=off,file=file_image1 \
    -device scsi-hd,id=image1,drive=drive_image1,write-cache=on \
    -device pcie-root-port,id=pcie-root-port-3,port=0x3,addr=0x1.0x3,bus=pcie.0,chassis=4 \
    -device virtio-net-pci,mac=9a:5d:b0:f5:04:0f,id=idlokhzs,netdev=id4YbMcO,bus=pcie-root-port-3,addr=0x0 \
    -netdev tap,id=id4YbMcO,vhost=on \
    -vnc :0 \
    -rtc base=utc,clock=host,driftfix=slew \
    -boot menu=off,order=cdn,once=c,strict=off \
    -enable-kvm \
    -monitor stdio \
    -S \
    -qmp tcp:0:4444,server=on,wait=off \
    -device pcie-root-port,id=pcie-root-port-4,port=0x4,addr=0x1.0x4,bus=pcie.0,chassis=5 \
    -blockdev node-name=file_stg1,driver=file,auto-read-only=on,discard=unmap,aio=threads,filename=/home/test.qcow2,cache.direct=on,cach...

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/842140
Committed: https://opendev.org/openstack/tempest/commit/d8bbaba415bc5cc027079b1b45aa5ee6e75faddf
Submitter: "Zuul (22348)"
Branch: master

commit d8bbaba415bc5cc027079b1b45aa5ee6e75faddf
Author: Balazs Gibizer <email address hidden>
Date: Tue May 17 17:15:40 2022 +0200

    Wait for guest after resize

    To stabilize test_resize_server_with_multiattached_volume we need to
    wait for the guest OS to fully boot after the resize and before the test
    attempts to detach the volume.

    Closes-Bug #1960346

    Change-Id: I85ee21868c9281d081c491ee590fe1457f5aa997

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/842921
Committed: https://opendev.org/openstack/tempest/commit/53cd6880d732265c413383b874d288c208954a7f
Submitter: "Zuul (22348)"
Branch: master

commit 53cd6880d732265c413383b874d288c208954a7f
Author: Balazs Gibizer <email address hidden>
Date: Mon May 23 10:16:55 2022 +0200

    Wait for guest to boot before attach a volume

    This patch ensures test under the api.compute.admin package wait until
    the VM is sshable before attaches a volume to it.

    Related-Bug: #1960346
    Change-Id: I5f93effa280725ea41150cd7cebdf29a40db9818

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Balazs Gibizer <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/828863

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/tempest/+/817771
Committed: https://opendev.org/openstack/tempest/commit/db2f561cdf8fb51053373a4d3b0edc0ce8a6578d
Submitter: "Zuul (22348)"
Branch: master

commit db2f561cdf8fb51053373a4d3b0edc0ce8a6578d
Author: Lee Yarwood <email address hidden>
Date: Fri Nov 12 13:03:57 2021 +0000

    Create router and dhcp when create_default_network set

    We are trying to make server SSH-able before detach volume
    is performed (details in bug mentioned below). Creating
    router and dhcp is needed to setup the proper network path
    for server otherwise it fail
    - https://zuul.opendev.org/t/openstack/build/04e11a0eac12447f8a3c47fb385b0753

    Related-Bug: #1960346

    Change-Id: I18eff5a4216d5683a5d49ad0e400ac663650e7a9

[Balazs Gibizer (balazs-gibizer)]

Re-opening this for Nova as we expect a fix from QEMU. The QEMU bug is being tracked in [1]. When the QEMU fix is implemented we have to check if Nova needs to be adapted to the fix or not and we should remove some of the tempest workaround we applied to test the fix.

Making this Medium for nova now and adding the gate-failure tag.

[1]https://bugzilla.redhat.com/show_bug.cgi?id=2087047

[afazekas (afazekas-redhat-bugs)]

IMHO The issue is the guest simply ignores the release requests for devices which he never learned it exists,
it was added and remove requested before it initialized all devices+hotplug.

The hotplug what we are using everywhere is just emulating the hotplug devs meant to be used for physical machines, where
people are not expected to plug and remove a device at the first ms of the boot.

If we really want to solve these kind of issues for once and for all,
probably we should invent a new "cloud-plug" device named hotplug device for virtual machines.

However some mitigation might be possible in same cases.
 - guest OS should acknowledge releasing devices what he never initialized (guest kernel modification)
 - guest kernel (requested by the init system?) should do another pci rescan to avoid not detected devices from the blind spot.
    The blind spot is between the pciscan and the hotplug initialization

The feature expected from the cloud-plug device, if the guest os is not booted (yet) it simply allows to remove devices. The virtualization layer would know it is safe.
So the guest os is expected to claim a device from the cloudplug in order to prevent removal, proper handshaking needed.
The challenge here, is what to do with guests which does not supports the new "cloud-plug",
probably we should just wait 3+/5+/.. years before we dare to try making it default expected.

[asyedham (asyedham-redhat-bugs)]

*** Bug 2080893 has been marked as a duplicate of this bug. ***

[smooney (smooney-redhat-bugs)]

We have been discusssing this regression upstream in the virtual OpenStack project team gathering (vPTG)
i just wanted to pass on the feedback that this is still a pain point for us both upstream and in our downstream product.
hopefully this is something that can be addressed with a higher priority.

fell free to reach out to me as the User Advocate for the OpenStack compute team or to our pm Erwan Gallen <email address hidden> if you need
additional information but this is still impacting our downstream product and affecting our upstream si stability.

[sean mooney (sean-k-mooney)]

setting this to invlaid for nova as multiple attempt to work around the issue have show we cannot fix it in nova.

[imammedo (imammedo-redhat-bugs)]

Fix posted upstream:
 https://<email address hidden>/msg952944.html
it's too late for merging into this release, but it should make into the next one.

In nutshell, it was regression introduced in QEMU
  * v5.0
      * 'pc' machine with ACPI hotplug
      * 'q35' native PCIe hotplug
  * v6.1
      * + 'q35' with ACPI hotplug (default)
Fixed in:
  * 6.2 'q35' native PCIe hotplug
  * TBD (8.1?): 'q35' and 'pc' ACPI hotplug
       (once it's merged upstream we can backport it)

Need to look into SHPC one, which seems to be broken as well.

[yfu (yfu-redhat-bugs)]

QE bot(pre verify): Set 'Verified:Tested,SanityOnly' as gating/tier1 test pass.

[Alan Pevec (apevec)]

Fixed in qemu-kvm CS9 qemu-kvm-8.0.0-2.el9

and RHEL 9.2 async update qemu-kvm-7.2.0-14.el9_2.1