| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2025-07-30 | |||
| 10:58:12 | opendevreview | Ian Watson proposed openstack/nova master: Add migrations_supported methed for resource tracker https://review.opendev.org/c/openstack/nova/+/955690 | |
| 11:00:48 | opendevreview | Ian Watson proposed openstack/nova master: Add migrations_supported methed for resource tracker https://review.opendev.org/c/openstack/nova/+/955690 | |
| 11:02:00 | opendevreview | Ian Watson proposed openstack/nova master: Add migrations_supported methed for resource tracker https://review.opendev.org/c/openstack/nova/+/955690 | |
| 11:02:53 | opendevreview | Ian Watson proposed openstack/nova master: Add migrations_supported methed for resource tracker https://review.opendev.org/c/openstack/nova/+/955690 | |
| 11:04:29 | opendevreview | Ian Watson proposed openstack/nova master: Add migrations_supported methed for resource tracker https://review.opendev.org/c/openstack/nova/+/955690 | |
| 11:04:59 | opendevreview | Ian Watson proposed openstack/nova master: Add migration conditional for resource tracker https://review.opendev.org/c/openstack/nova/+/955690 | |
| 11:06:32 | opendevreview | Ian Watson proposed openstack/nova master: Add migration conditional for resource tracker https://review.opendev.org/c/openstack/nova/+/955690 | |
| 11:49:21 | opendevreview | Merged openstack/nova master: [test]Speed up fs retry tests by mocking sleep https://review.opendev.org/c/openstack/nova/+/955904 | |
| 11:50:56 | opendevreview | Merged openstack/nova master: [test]Speed up ironic console test by decreasing timeout https://review.opendev.org/c/openstack/nova/+/955905 | |
| 11:51:26 | opendevreview | Merged openstack/nova master: [test]Speed up RBD test by decreasing retry interval https://review.opendev.org/c/openstack/nova/+/955906 | |
| 11:57:13 | opendevreview | Merged openstack/nova master: [test]Speed up qemu announce test by mocking sleep https://review.opendev.org/c/openstack/nova/+/955907 | |
| 11:59:16 | stephenfin | gibi: Picking this up from last week: it appears the device detach libvirt event stuff is broken on every release since Caracal and it always times out https://github.com/kubernetes/cloud-provider-openstack/pull/2742#issuecomment-3135940269 | |
| 11:59:32 | stephenfin | I'm still looking so jfyi for now | |
| 11:59:59 | sean-k-mooney | i mean its not optional and i dont think we have see that in devstack in our jobs | |
| 12:00:11 | sean-k-mooney | is this only happing in that ci env | |
| 12:00:16 | sean-k-mooney | or did you hit it locally | |
| 12:00:39 | stephenfin | no, I can reproduce in CI and across multiple PSI instances | |
| 12:01:03 | stephenfin | s/multiple PSI instances/multiple local VMs/ (for the non-RHers) | |
| 12:01:30 | sean-k-mooney | what exactly doe this look like in the nova logs | |
| 12:01:46 | sean-k-mooney | i dont see that in your comment above | |
| 12:03:04 | sean-k-mooney | oh its in drivers | |
| 12:03:08 | sean-k-mooney | https://github.com/kubernetes/cloud-provider-openstack/pull/2742#issuecomment-3114089612 | |
| 12:03:08 | stephenfin | sean-k-mooney: it manifests as a 20 second "stall" while detaching volumes https://paste.opendev.org/show/b6K2tt0kBpOO2liORP7k/ | |
| 12:03:48 | sean-k-mooney | its blocking the comptue agent for 20 seconds | |
| 12:04:03 | sean-k-mooney | or there was jsut nothing else happeing at that time on that host | |
| 12:04:41 | stephenfin | sean-k-mooney, gibi: It's also happening upstream: our CI logs are full of those warnings | |
| 12:05:05 | sean-k-mooney | stephenfin: im going to check the ovs-hybrid plug job | |
| 12:05:17 | sean-k-mooney | i want to see if this is a ubuntu bug or if it show up in debian | |
| 12:05:20 | stephenfin | For example, the tempest-integrated-compute job from a patch in melwitt's vTPM series https://review.opendev.org/c/openstack/nova/+/942501 | |
| 12:05:21 | sean-k-mooney | or rhel | |
| 12:05:27 | stephenfin | https://d6e5655f0b1ee2f8df74-e35c415f7cc7f78f33337c81de121e72.ssl.cf2.rackcdn.com/openstack/52b57c77f805400888762a87e08196f1/controller/logs/screen-n-cpu.txt | |
| 12:05:35 | sean-k-mooney | ya but that also using ubuntu | |
| 12:05:50 | sean-k-mooney | i want to check a non ubuntu job to see if tis a bug in ther elibvirt or if its a nova issue | |
| 12:07:00 | stephenfin | I see 27 hits grepping for 'Waiting for libvirt event', which is over 9 minutes of wasted time (though not really since I think tempest runs in parallel?) | |
| 12:07:04 | stephenfin | sean-k-mooney: ack | |
| 12:07:32 | sean-k-mooney | oh i tured off cinder in that job | |
| 12:07:53 | sean-k-mooney | let me see if i can check the ceph job i just proposed moving to debian | |
| 12:10:35 | stephenfin | sean-k-mooney: do you know how DevStack works on CentOS Stream currently? I can trivially reproduce this locally if needed too | |
| 12:10:42 | sean-k-mooney | Waiting for libvirt event about the detach of device vdb with device alias ua-88d8994a-f5be-42d8-9a2f-5e030b1f4ce8 from instance 621ab0d3-61a0-437f-8d31-e9c3d7ae3eae is timed out. | |
| 12:11:04 | sean-k-mooney | stephenfin: it does | |
| 12:11:09 | sean-k-mooney | so its happenign on debian too | |
| 12:11:37 | sean-k-mooney | with ceph in this case you were using lvm right | |
| 12:11:52 | sean-k-mooney | the backend should not really matter | |
| 12:12:02 | stephenfin | yes (pretty much a "stock" DevStack configuration) | |
| 12:12:04 | sean-k-mooney | but that is both local block and network type covered | |
| 12:12:10 | sean-k-mooney | ack | |
| 12:12:19 | sean-k-mooney | let me see if i still have a c9s devstack somewhere | |
| 12:14:32 | sean-k-mooney | that woudl be no but i can check our watcher ci job | |
| 12:14:46 | sean-k-mooney | actully no | |
| 12:15:04 | sean-k-mooney | we have master jobs that trigger with our new installer on cenetos butthsoe are disbaling cinder right now | |
| 12:15:14 | sean-k-mooney | i think neutorn and maybe cinder have centos josb | |
| 12:15:34 | sean-k-mooney | we might have an experminatal one too | |
| 12:16:07 | stephenfin | I'll just create one locally | |
| 12:16:38 | stephenfin | However, I see a few related changed that I'm going to try reverting out of caracal first | |
| 12:22:52 | gibi | I did the last round of fixes in that codepath so I remember it was working at that time to wait for the events. If the event does not come we still have code to check if the actual detach happened and move on. But as you noted it might be excessive waiting time | |
| 12:23:53 | gibi | if this is visible in upstream CI then please file an upstream bug with the links and I will try to look at it | |
| 12:27:14 | gibi | In https://d6e5655f0b1ee2f8df74-e35c415f7cc7f78f33337c81de121e72.ssl.cf2.rackcdn.com/openstack/52b57c77f805400888762a87e08196f1/controller/logs/screen-n-cpu.txt I see cases when it is on 20 sec wait and we move one | |
| 12:27:32 | gibi | Jul 30 01:36:30.229367 npa183b57ac85f4 nova-compute[75854]: DEBUG nova.virt.libvirt.guest [None req-5859b1ac-1198-4297-845b-2c4ef82e635b tempest-VolumesAssistedSnapshotsTest-257024579 tempest-VolumesAssistedSnapshotsTest-257024579-project-admin] detach device xml: <disk type="block" device="disk"> | |
| 12:27:47 | gibi | Jul 30 01:36:50.849840 npa183b57ac85f4 nova-compute[75854]: WARNING nova.virt.libvirt.driver [None req-5859b1ac-1198-4297-845b-2c4ef82e635b tempest-VolumesAssistedSnapshotsTest-257024579 tempest-VolumesAssistedSnapshotsTest-257024579-project-admin] Waiting for libvirt event about the detach of device vdb with device alias ua-50261be4-1b93-406a-ad22-095d53ab27bb from instance | |
| 12:27:53 | gibi | 8b434db2-72e7-45a7-a946-a43b7e5b04de is timed out. | |
| 12:27:57 | gibi | Jul 30 01:36:50.862330 npa183b57ac85f4 nova-compute[75854]: INFO nova.virt.libvirt.driver [None req-5859b1ac-1198-4297-845b-2c4ef82e635b tempest-VolumesAssistedSnapshotsTest-257024579 tempest-VolumesAssistedSnapshotsTest-257024579-project-admin] Successfully detached device vdb from instance 8b434db2-72e7-45a7-a946-a43b7e5b04de from the live domain config. | |
| 12:29:22 | gibi | obviously it is fishy that the event is never recevied even though the detach happened successfully on libvirt side | |
| 12:29:41 | gibi | so either libvirt does not send the event or nova does not receive it | |
| 12:33:27 | sean-k-mooney | gibi: stephen and i were just lookign at it inhis env | |
| 12:33:38 | sean-k-mooney | the is a virsh command to pretty print the events | |
| 12:33:52 | sean-k-mooney | and we are seeing the evnet form the qemu monitor | |
| 12:34:00 | sean-k-mooney | but nova does not for some reason | |
| 12:34:40 | sean-k-mooney | gibi: stephen goign to head to lunch in a bit but it looks liek somethign broke along the way | |
| 12:34:50 | gibi | cool nice troubleshooting | |
| 12:35:32 | sean-k-mooney | stephens theory was maybe the alisa did not match or it was someithng related to how we were mathcing the event | |
| 12:35:50 | sean-k-mooney | but i think we likely need to add extra loging to print all the libvirt events and confirm if nova even gets it | |
| 12:36:21 | sean-k-mooney | it could be something funky with the sepeate tread we have for that but its definly and upstream bug | |
| 12:39:33 | stephenfin | Yeah, what sean-k-mooney said. The reason it's such a big deal for cloud-provider-openstack is that the tests (a) create and delete a lot of PVCs (which translates to a lot of attach/detach calls), and (b) run serially, so things compound | |
| 12:40:13 | gibi | https://github.com/openstack/nova/blob/3a08a557df7b9a52c8faefe010df0ba9994c63a9/nova/virt/libvirt/driver.py#L312-L319 | |
| 12:40:34 | gibi | this is the code that finds which event waiter to unblock based on incoming events | |
| 12:41:01 | gibi | called from here https://github.com/openstack/nova/blob/3a08a557df7b9a52c8faefe010df0ba9994c63a9/nova/virt/libvirt/driver.py#L385 | |
| 12:41:32 | gibi | https://github.com/openstack/nova/blob/3a08a557df7b9a52c8faefe010df0ba9994c63a9/nova/virt/libvirt/driver.py#L2512-L2542 and this is the place where we get the events from libvirt | |
| 12:41:39 | gibi | it has logs | |
| 12:41:49 | gibi | so if these logs are not visible it means nova is not receiving any events | |
| 12:47:37 | sean-k-mooney | im not sure if that loggin actully works, which thrad is that runign on | |
| 12:47:40 | sean-k-mooney | specificly https://github.com/openstack/nova/blob/3a08a557df7b9a52c8faefe010df0ba9994c63a9/nova/virt/libvirt/driver.py#L2512-L2542 | |
| 12:47:58 | sean-k-mooney | is that on the libvirt pthread or on the nova main thread | |
| 12:48:17 | sean-k-mooney | there is some issue with mixing real thread and oslo.log | |
| 12:50:43 | sean-k-mooney | for what its worht the matching code looks corect | |
| 12:50:44 | gibi | yeah that is likely running on the libvirt pthread | |
| 12:50:45 | sean-k-mooney | https://github.com/openstack/nova/blob/3a08a557df7b9a52c8faefe010df0ba9994c63a9/nova/virt/libvirt/driver.py#L316-L319 | |
| 12:51:28 | gibi | I thought we can still log from the libvirt pthread | |
| 12:51:49 | sean-k-mooney | it was "fixed" by adding a pipemutex in oslo logs | |
| 12:52:01 | sean-k-mooney | but im not sure i really trust that entilry | |
| 12:52:07 | gibi | :) | |
| 12:52:38 | sean-k-mooney | im thinkging we add some good old prints or perhaps writes to a file that we can tail | |
| 12:52:55 | sean-k-mooney | although not right now. | |
| 12:56:28 | gibi | yeah that is always an option locally to troubleshoot it further | |
| 12:58:37 | stephenfin | https://bugs.launchpad.net/nova/+bug/2119114 | |
| 12:59:15 | stephenfin | I marked it as confirmed since eharney also took a look at this and I've reproduced it across multiple environments. I did not set a priority though | |
| 12:59:32 | stephenfin | eharney and sean-k-mooney, naturally | |
| 13:00:16 | gibi | stephenfin: thank you! | |
| 13:00:21 | gibi | Uggla: ^^ for visibility | |
| 13:01:30 | stephenfin | I will dump all this is the bug, but fwiw, I see no entries for `Received event` messages in Caracal or later. I do see them on Bobcat | |
| 13:01:43 | stephenfin | (in the n-cpu logs, that is) | |