Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2022-02-10
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
14:53:01 gmann frickler: I opened it for devstack due to centos9 libvirt version bump but it is ok to add nova too
14:55:23 kashyap frickler: Forgot to respond in the scrollback; yeah, that explains it - why my `wget` didn't work :) Thank you.
14:55:59 gibi kashyap: these are the libvirtd logs from the first and second detach https://paste.opendev.org/show/bKANW2WAzfAzEIGcgJX8/ probably nothing new here I just working through the logs...
14:59:02 kashyap gibi: Nice work narrowing down
14:59:15 kashyap A side-tip is:
14:59:34 kashyap $> grep -Ei '(MONITOR_SEND_MSG|QEMU_MONITOR_RECV_)' libvirtd_log.txt
14:59:46 kashyap (That gets you all the commands and the responses libvirt is sending to QEMU.)
15:43:52 spatel folks i need urgent help to understand what is wrong with nova and rabbitMQ :(
15:44:13 spatel I have rebuild rabbitMQ but now not able to spin up VM
15:44:32 spatel vm getting stuck in BUILD
15:45:02 spatel nova-conductor throwing these errors - https://paste.opendev.org/show/bbSVnr5zGdCCOPdL5tQF/
15:48:37 kashyap No answer, but please don't count on community to provide "urgent help". That's what vendors are for
15:49:02 spatel kashyap i understand just looking for clue to see what is going on
16:04:36 melwitt gibi: ack, will look
16:05:26 gibi melwitt: thanks
16:14:36 opendevreview Erlon R. Cruz proposed openstack/nova master: Fix pre_live_migration rollback https://review.opendev.org/c/openstack/nova/+/815324
16:24:14 opendevreview Andre Aranha proposed openstack/nova stable/xena: Add check job for FIPS https://review.opendev.org/c/openstack/nova/+/827895

Earlier   Later