Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2022-02-10
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: Fix pre_live_migration rollback https://review.opendev.org/c/openstack/nova/+/815324
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: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.
14:34:33 kashyap Okay, so expected error there.
14:34:56 gibi yepp that is OK and the test case is pass, but after the test case tempest cleans up
14:35:06 gibi basically did the actions in revers to move back to the starting state
14:35:19 gibi so as the server in RESCUE state it unrescues it
14:35:39 gibi and as a volume was attached to the server before rescue, it tries to detach the volume after the unrescue
14:35:52 gibi and that detach should remove the volume from the domian but that fails
14:37:00 kashyap I see. And looks like it couldn't find that volume?
14:37:37 kashyap Maybe this goes back to Peter's comment earlier about how libvirt tries "to detach a blockdev node that wasn't ever attached"
14:38:58 kashyap These weird tests are spinning my head.
14:39:41 gibi during this detach: nova first detaches the volume from the persistent domain that succeeds
14:39:57 gibi then nova issue the detach command from the live domian and waits for the event
14:40:09 gibi that event is not received in 20 sec so it issue the command again
14:40:23 kashyap Ah-ha, that makes sense
14:40:26 gibi that commend returns
14:40:27 gibi error message: internal error: unable to execute QEMU command 'device_del': Device virtio-disk1 is already in the process of unplug
14:40:57 gibi then nova retries 6 more times
14:41:03 kashyap Right, and then times out
14:41:05 gibi always getting the same message
14:41:09 gibi and then gives up
14:41:18 gibi this is the log from the detach attempst https://paste.opendev.org/show/be647YeC57HREuAfwwru/
14:41:49 kashyap gibi: Your last 10-ish messages are a great summary of the prob at hand. Can I take and rephrase them into a paragraph on that mail thread?
14:41:59 gibi sure
14:48:16 kashyap gibi: I've also posted the pimped up version here: https://bugs.launchpad.net/nova/+bug/1960346/comments/8
14:48:46 gibi thanks
14:52:05 gmann gibi: ack. thanks
14:52:09 opendevreview Andre Aranha proposed openstack/nova stable/xena: Add check job for FIPS https://review.opendev.org/c/openstack/nova/+/827895

Earlier   Later