Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2022-02-10
12:35:16 kashyap What exactly is the negative test doing? /me looks...
12:35:18 sean-k-mooney gibi: in terms of the exact vesion i think its in the release notes but ill see if i can find it
12:35:43 kashyap sean-k-mooney: Are you confident it is "related to hardware interupts that are sent by QEMU?" What evidence there is for it?
12:36:12 gibi sean-k-mooney: thanks. if we know the version number then I can craft a patch that conditionally set the detach attempts to 1 if the qemu is new enough
12:37:02 sean-k-mooney kashyap: we dont know that for certin and in fact i think https://bugzilla.redhat.com/show_bug.cgi?id=2007129 is a large part of the problem
12:37:55 sean-k-mooney unless you use virtio-scsi which we dont by default each volume attach and deatch is a pci hotplug form teh guest perspective as we add a seperte pci device for each virtio-blk device
12:38:28 frickler kashyap: for downloading logs, I think wget may have issues because the source is swift and not a "normal" webserver. you may want to look at https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_3e2/828280/1/check/devstack-platform-centos-9-stream/3e24d97/download-logs.sh and maybe filter if you need only some subdirs
12:38:44 kashyap Okay, that bug is about PCI hotplug emulation
12:38:46 sean-k-mooney kashyap: that bug might be unrealted but artom suggested it might be in a different context
12:38:52 kashyap sean-k-mooney: Do you know what the negative test is exaclty doing?
12:39:09 sean-k-mooney i have not looked expictly
12:39:34 sean-k-mooney i guess botting into rescue mode and detaching a cinder volume
12:40:21 sean-k-mooney https://github.com/openstack/tempest/blob/7e96c8e854386f43604ad098a6ec7606ee676145/tempest/api/compute/servers/test_server_rescue_negative.py#L136
12:40:21 gibi yepp it does that, I try to correlate that with the logs
12:40:26 kashyap So it is trying to rescue a paused instance, and a non-existing instance
12:40:44 sean-k-mooney no
12:41:17 sean-k-mooney its booting a vm, attaching a volume, then puting it in rescue mode which reboot with a new root disk
12:41:26 sean-k-mooney waiting for ti to get to rescue meaning its running
12:41:57 sean-k-mooney then asserting that detach raises a 409 conflict
12:42:25 sean-k-mooney there is not paused instance
12:42:47 kashyap sean-k-mooney: Well. What do you think this is doing, then? - test_rescue_non_existent_server()?
12:43:01 kashyap And test_rescue_paused_instance()
12:43:22 sean-k-mooney its just asserting that if the server does not exist the rescue call returns a 404
12:43:40 kashyap And there are also: test_rescued_vm_attach_volume() and test_rescued_vm_detach_volume()
12:43:42 sean-k-mooney paused is asserting that you cant call resuce when its paused
12:43:56 sean-k-mooney yep
12:43:59 sean-k-mooney how is this relevent
12:44:38 sean-k-mooney the test all look valid and are asserting what i woudl expect
12:44:47 kashyap It is relevant in the sense that these are the different tests being run here
12:45:09 sean-k-mooney yes they are differnt test but they are not using the same vm
12:45:18 kashyap Yep, noted
12:45:22 sean-k-mooney so they should have no impact on each other
12:45:58 sean-k-mooney although i will say if we get very very unlucky the random uuid could colide with a real on ein the non_existent_instance test
12:46:24 sean-k-mooney statistically however we are not going to get uuid collisions
12:48:46 gibi wait a bit I think we are looking at the wrong test case
12:49:29 kashyap gibi: So you don't think this is the failing test? test_rescued_vm_detach_volume()?
12:49:40 gibi Im confused
12:49:51 gibi Im looking at this run https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_3e2/828280/1/check/devstack-platform-centos-9-stream/3e24d97/controller/logs/index.html
12:50:29 kashyap Same here.
12:53:10 kashyap gibi: If we can narrow down the exact test action that is causing this, then we can debug it further from libvirt/QEMU angle.
12:53:26 gibi yeah I'm trying that
12:53:42 gibi I mean trying to collect the steps the test took
12:53:43 kashyap Sure, no rush. (I just want to arrive at a reproducer w/ just libvirt - APIs or shell)
12:55:53 gibi https://paste.opendev.org/show/bEtFDBoLqDfotDMPDOq8/
12:56:16 gibi OK so that test case is failing similarly than the other so we can look at any of the too
12:56:26 gibi that paste has the steps from test_rescued_vm_detach_volume
12:57:06 gibi so yeah the log correlates with the test case
12:57:39 kashyap gibi: So, it is indeed test_rescued_vm_detach_volume(), then
12:57:48 gibi we boot an instance then rescue it (basically destory the domina and start it again with different disk config) then we attempt to detach a volume while the rescue domin is running
12:57:52 gibi kashyap: yes
12:58:02 kashyap gibi: Please post this info in the bug as a record.
12:58:11 gibi kashyap: but the other test_stable_device_rescue_disk_virtio_with_volume_attached also failing similarly
12:58:23 gibi kashyap: hence my confusion
12:58:37 kashyap Hm, so both positive and negative are failing similarly
12:58:43 gibi updating the bug...
13:00:11 kashyap gibi: During rescue, by "different disk config" do you mean a fresh, similar config? Or actually different? If so, how is the disk config different before rescue?
13:00:47 gibi we create a domain in a way that it boots from a rescue image but also has the original root fs attached
13:02:28 kashyap I see, noted.
13:05:21 gibi kashyap: https://paste.opendev.org/show/bf9JaJYMYDOX9onjFFy0/ here are the domain xmls for that nova instance
13:07:38 kashyap gibi: Excellent; I just asked Peter Krempa (he meditates on libvirt block layer) on #virt (OFTC)
13:10:13 kashyap Corresponding QEMU log:
13:10:15 kashyap https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_3e2/828280/1/check/devstack-platform-centos-9-stream/3e24d97/controller/logs/libvirt/libvirt/qemu/instance-0000004d_log.txt
13:10:47 sean-k-mooney kashyap: lyarwood implemented a stabel rescue feature but basiclly we add a new disk on the hw_rescue_bus typeicly usb as the boot disk
13:11:27 sean-k-mooney the default rescue disk is the same image from glance that the vm booted wiht but it will be a clean copy of it
13:11:50 sean-k-mooney you can specify an alternitive image to use via config or the rescue action but these tests do not
13:12:26 kashyap I see, noted.
13:26:52 gibi kashyap: these are the nova request ids from the compute log correlated with actions: https://paste.opendev.org/show/bS5Jmmw4PbLirMXtAUyj/
13:27:03 gibi there is two rescue / unrescue pair
13:27:19 kashyap gibi: Noted; meanwhile, the libvirt dev says:
13:27:29 kashyap "weird, we [libvirt] indeed try to detach a blockdev node that wasn't ever attached"
13:27:43 gibi that is wierd indeed :)
13:27:45 kashyap gibi: I sent him an email with you in Cc. He asked it, as he's in a hurry
13:28:23 gibi thanks for the cc
13:28:32 gibi I have to jump on a call I will be back in an hour
13:28:41 kashyap No rush; we can deal with this async.
13:29:35 kashyap gibi: Oh, I don't think we have this output captured anywhere, right? The dev was asking me
13:29:39 kashyap "please also get me the output of 'qemu-img info' of the copy destination image if it wasn't removed"
13:30:41 gibi copy destination?
13:31:11 kashyap [quote] What breaks is a block copy into a image with "--reuse-external" [this is what Nova uses - i.e. reuse an external file], so we try to obey the metadata. [/quote]
13:31:37 kashyap gibi: Here an image copy is involved under the hood
13:31:48 gibi interesting..
13:32:03 kashyap Okay, Peter says: "it's okay to just point me to the place formatting the image, I don't need an actual example, just what's put into the metadata"
13:33:58 kashyap gibi: He does admit that there's a potential libvirt bug here.
13:43:57 gibi bahh there are multiple test cases reusing the same nova instance during the testing https://paste.opendev.org/show/b0OYtRRb5FyZ5pyWgBCu/
13:44:15 gibi hence the more action on the instance in the compute log than what is in the test case that fails
13:48:16 gibi OK, see a bit more.
13:50:51 gibi The actual tempest test case passes. The detach returns conflict when the instance is in RESCUE state. That is the end of the test case. _THEN_ the tempest starts cleaning up the pieces, and during that first it unrescues the VM and then detached the volume. This detach should work and remove the volume but it fails with the error in libvirt
14:07:58 gibi btw increasing the timeout from 20 to 60 did not helped detach still timeouts
14:08:04 gibi https://zuul.opendev.org/t/openstack/build/61f733fc73834ff0924284dac61c9a4b/log/controller/logs/screen-n-cpu.txt?severity=3
14:17:59 gibi I don't know what block copy action we do during these sequences
14:23:35 gibi hopefully with this patch I can run only the singe test case we want to troubleshoot so the logs will be smaller an cleaner https://review.opendev.org/c/openstack/devstack/+/828705
14:24:17 opendevreview Erlon R. Cruz proposed openstack/nova master: Adds regression test for bug LP#1944619 https://review.opendev.org/c/openstack/nova/+/821840
14:24:17 opendevreview Erlon R. Cruz proposed openstack/nova master: Fix pre_live_migration rollback https://review.opendev.org/c/openstack/nova/+/815324
14:31:31 kashyap gibi: So the block copy is definitely there, looking at the commands libvirt has sent to QEMU (from the CI log):
14:31:34 kashyap 2022-02-08 15:24:09.109+0000: 72482: info : qemuMonitorSend:914 : QEMU_MONITOR_SEND_MSG: mon=0x7f74e40cde70 msg={"execute":"blockdev-mirror","arguments":{"job-id":"copy-vda-libvirt-2-format","device":"libvirt-2-format","target":"libvirt-4-format","sync":
14:31:38 kashyap "top","auto-finalize":true,"auto-dismiss":false},"id":"libvirt-408"}
14:31:55 kashyap The QEMU keyword here is "blockdev-mirror"
14:32:21 kashyap ... which is what libvirt calls "block copy".
14:33:30 kashyap gibi: When you get a minute, please post your above observation about how the Tempest test passes, but the detach returns conflict in RESCUE. It is useful for the record.
14:34:18 gibi kashyap: sure. the conflict is from nova, in rescue we don't allow detach. And that part works.

Earlier   Later