| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2024-08-19 | |||
| 17:18:04 | artom | Wait, I skipped 2024.1, didn't I? | |
| 17:18:25 | artom | Actual names were better, fight me | |
| 17:18:44 | sean-k-mooney | yes you did | |
| 17:19:07 | opendevreview | Artom Lifshitz proposed openstack/nova stable/2024.1: Functional test test_boot_reschedule_with_proper_pci_device_count https://review.opendev.org/c/openstack/nova/+/926556 | |
| 17:19:08 | opendevreview | Artom Lifshitz proposed openstack/nova stable/2024.1: Fix PCI passthrough cleanup on reschedule https://review.opendev.org/c/openstack/nova/+/926557 | |
| 17:20:33 | opendevreview | Artom Lifshitz proposed openstack/nova stable/2023.2: Functional test test_boot_reschedule_with_proper_pci_device_count https://review.opendev.org/c/openstack/nova/+/926554 | |
| 17:20:34 | opendevreview | Artom Lifshitz proposed openstack/nova stable/2023.2: Fix PCI passthrough cleanup on reschedule https://review.opendev.org/c/openstack/nova/+/926555 | |
| 17:21:33 | opendevreview | Artom Lifshitz proposed openstack/nova stable/2023.1: Functional test test_boot_reschedule_with_proper_pci_device_count https://review.opendev.org/c/openstack/nova/+/926558 | |
| 17:21:34 | opendevreview | Artom Lifshitz proposed openstack/nova stable/2023.1: Fix PCI passthrough cleanup on reschedule https://review.opendev.org/c/openstack/nova/+/926559 | |
| #openstack-nova - 2024-08-20 | |||
| 00:37:39 | opendevreview | Takashi Kajinami proposed openstack/nova master: libvirt: Launch instances with stateless firmware https://review.opendev.org/c/openstack/nova/+/908890 | |
| 00:37:39 | opendevreview | Takashi Kajinami proposed openstack/nova master: Report availability of stateless firmware support https://review.opendev.org/c/openstack/nova/+/908888 | |
| 00:37:40 | opendevreview | Takashi Kajinami proposed openstack/nova master: Add hw_firmware_stateless image property https://review.opendev.org/c/openstack/nova/+/926590 | |
| 03:37:36 | opendevreview | Merged openstack/nova master: [libvirt]log XML if nova fails to parse it https://review.opendev.org/c/openstack/nova/+/906364 | |
| 05:23:43 | opendevreview | Zhang Hua proposed openstack/nova master: Fix deepcopy usage for BlockDeviceMapping in get_root_info https://review.opendev.org/c/openstack/nova/+/920374 | |
| 08:39:34 | ralonsoh | sean-k-mooney, hello! I have an investigation in progress (well, very little progress so far) | |
| 08:39:57 | ralonsoh | I'm fixing an issue with eventlet, wsgi and tls with ML2/OVN | |
| 08:40:21 | ralonsoh | in a nutshell: I'm pushing https://review.opendev.org/c/openstack/neutron/+/925376/ | |
| 08:40:37 | ralonsoh | this patch works fine with ML2/OVN but not so great with ML2/OVS | |
| 08:41:21 | ralonsoh | the same test is randomly (but very frequently) failing in the OVS jobs: test_established_tcp_session_after_re_attachinging_sg | |
| 08:41:49 | ralonsoh | the issue, so far, is because n-compute is deleting the VM used to test the ping | |
| 08:42:00 | ralonsoh | for example: https://32db135de77b6f5b2e24-00cf68680e4576901ac5e284377f47f2.ssl.cf2.rackcdn.com/924317/7/experimental/neutron-tempest-plugin-openvswitch-distributed-dhcp/43f8b60/controller/logs/index.html | |
| 09:10:11 | ralonsoh | sean-k-mooney, if you have time to review these logs, can you explain why nova is trying to delete the VM? | |
| 09:10:20 | ralonsoh | Aug 19 12:41:14.998800 np0038215967 devstack@n-api.service[58447]: DEBUG nova.compute.api [None req-54123910-92d9-491b-b845-f8e7d37490dd tempest-StatefulNetworkSecGroupTest-1423213631 tempest-StatefulNetworkSecGroupTest-1423213631-project-member] [instance: 4623b509-a848-41a4-9fc2-1cf8227bd4ca] Going to try to terminate instance {{(pid=58447) delete /opt/stack/nova/nova/compute/api.py:2725}} | |
| 09:10:21 | ralonsoh | sorry, I don't find the reason | |
| 09:19:21 | mikal | sean-k-mooney: I'd do a change for the usb redirect devices as extra specs, but I'm starting to be a bit worried about any of these changes landing in time. What would you prefer? | |
| 09:19:45 | mikal | sean-k-mooney: naively I'd just cargo cult the sound device extra spec one for usb redirect devices, so I was kind of waiting for someone to tell me I did that one wrong first. | |
| 09:40:45 | sean-k-mooney[m] | mikal: ill review that shortly and let you know | |
| 09:43:47 | sean-k-mooney[m] | ralonsoh: ill try and take a look nova wont delete the vm unless asked | |
| 09:44:21 | sean-k-mooney[m] | even missing a vif plugged event willl just cause it to go to error althoguh we might stop it | |
| 09:49:43 | mikal | sean-k-mooney: yeah, I wont get to it tonight anyways as I'm oncall and that always makes me tired. But yeah, I'd appreciate the feedback, I've never done one of those before. | |
| 10:00:58 | ralonsoh | sean-k-mooney[m], I think I found something: the VM is created at 12:40:08 | |
| 10:01:25 | ralonsoh | but the OVS agent receives the tap port creation almost one minute later and doesn't have time to send the vif-plugged event | |
| 10:01:38 | ralonsoh | and the same time, n-compute decides to delete the VM | |
| 10:01:49 | ralonsoh | how can I increase this timeout? | |
| 10:02:13 | leavelet | HEhqQ. Should I file an issue on Launchpad, or is this likely a configuration problem on my end? | |
| 10:02:13 | leavelet | Hi! I encountered a cinderclient.exceptions.Unauthorized error when creating an instance. I also received the message: "Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible." I've confirmed that my nova service_user is configured correctly, and nova-status upgrade check shows all checks as successful. The error logs can be found at https://paste.aosc.io/paste/hMJM8omukSVYzgvLj | |
| 10:02:49 | leavelet | I'm new to IRC and not very familiar with it, so if I'm in the wrong place, please let me know | |
| 10:03:28 | ralonsoh | sean-k-mooney[m], vif_plugging_timeout, that by default is 300 (now I don't understand...) | |
| 10:03:33 | sean-k-mooney | ralonsoh: you really should not need too but i think we have a time out that defaults to 300 seconds | |
| 10:03:39 | sean-k-mooney | ya | |
| 10:03:53 | ralonsoh | so I don't understand why the VM is deleted | |
| 10:04:05 | sean-k-mooney | its already longer then is reasonable and you are using kvm in this job | |
| 10:04:14 | ralonsoh | It is not commanded by the tempest test | |
| 10:04:17 | sean-k-mooney | so the vm should be quick to boot/start | |
| 10:05:26 | sean-k-mooney | i did notice that libvirt is a littel unhappy on that node and it failed to detach an interface in one case | |
| 10:05:54 | sean-k-mooney | you are also using very old guest images (20.04 and cirros 0.5.3) im not sure if that is related or not | |
| 10:05:57 | ralonsoh | btw, the VM id is 4623b509-a848-41a4-9fc2-1cf8227bd4ca and the port 9bc40eec-ae67-4b56-9e75-551609520b27 | |
| 10:06:29 | ralonsoh | that is working in the CI well, but not with this patch in particular | |
| 10:07:31 | sean-k-mooney | so the domain was defied at Aug 19 12:40:14.414263 | |
| 10:08:23 | sean-k-mooney | and we get the vif plugged event at ug 19 12:40:16.547804 | |
| 10:08:34 | sean-k-mooney | so 2 seconds later | |
| 10:09:14 | sean-k-mooney | ralonsoh: is this using the iptables firewall or openvswitch i assuem the latter | |
| 10:09:37 | ralonsoh | let me check (by default is the later) | |
| 10:09:46 | sean-k-mooney | "port_filter": true, "ovs_hybrid_plug": false, | |
| 10:09:53 | sean-k-mooney | its the ovs firewall | |
| 10:09:56 | ralonsoh | yes, ovs fw | |
| 10:10:28 | sean-k-mooney | that means that the ml2 agent only sees the tap when the vm is started vs seeign the veth pair | |
| 10:10:40 | sean-k-mooney | slightly earilier | |
| 10:11:13 | sean-k-mooney | so if we look at the ovs log we should see when it sees the tap | |
| 10:11:36 | ralonsoh | at Aug 19 12:41:15.653623 | |
| 10:11:48 | ralonsoh | just before it is deleted | |
| 10:12:02 | sean-k-mooney | 2024-08-19T12:40:15.533Z|02270|bridge|INFO|bridge br-int: added interface tap9bc40eec-ae on port 257 | |
| 10:12:34 | ralonsoh | the ovsdb client detects the tap at 12:41:15 | |
| 10:12:35 | ralonsoh | ],["iface-status","active"],["vm-uuid","4623b509-a848-41a4-9fc2-1cf8227bd4ca"]]]]],"headings":["row","action","name","ofport","external_ids"]} {{(pid=61294) _read_stdout /opt/stack/neutron/neutron/agent/common/async_process.py:285}} | |
| 10:12:35 | ralonsoh | Aug 19 12:41:15.653623 np0038215967 neutron-openvswitch-agent[61294]: DEBUG neutron.agent.common.async_process [-] Output received from [ovsdb-client monitor tcp:127.0.0.1:6640 Interface name,ofport,external_ids --format=json]: {"data":[["18eba42b-2254-46a1-aeb8-2027e39235ed","old",null,257,null],["","new","tap9bc40eec-ae",-1,["map",[["attached-mac","fa:16:3e:ec:7b:05"],["iface-id","9bc40eec-ae67-4b56-9e75-551609520b27" | |
| 10:12:39 | sean-k-mooney | no it sees it just before neutron sends the vif pulgged event | |
| 10:13:14 | sean-k-mooney | i was checking the actual ovs-vswitchd log https://32db135de77b6f5b2e24-00cf68680e4576901ac5e284377f47f2.ssl.cf2.rackcdn.com/924317/7/experimental/neutron-tempest-plugin-openvswitch-distributed-dhcp/43f8b60/controller/logs/openvswitch/ovs-vswitchd_log.txt | |
| 10:14:45 | ralonsoh | then I don't know why this delay between the vswitch detection and the ovsdb-client | |
| 10:14:48 | ralonsoh | that's a lot | |
| 10:15:04 | ralonsoh | actually one minute (could be an error in the timestamp?) | |
| 10:16:45 | sean-k-mooney | ralonsoh: so nova recived the network vif plugged event correctly after 2 seconds | |
| 10:17:11 | sean-k-mooney | the instance delete starts at Aug 19 12:41:15 | |
| 10:17:28 | ralonsoh | yes but why? | |
| 10:17:36 | ralonsoh | why is the VM being deleted? | |
| 10:18:48 | ralonsoh | yes, I see the vif-plugged event at 12:40:16 | |
| 10:19:15 | ralonsoh | no idea why is sending it | |
| 10:19:21 | ralonsoh | who* | |
| 10:20:02 | sean-k-mooney | is the provisioning block stuff broken again? | |
| 10:20:13 | sean-k-mooney | proably not | |
| 10:20:33 | sean-k-mooney | im going to check novas api to see what deleted the instance | |
| 10:20:37 | ralonsoh | I'm checking the neutron API logs and this event is not sent | |
| 10:24:17 | sean-k-mooney | so the delete did happen via the api | |
| 10:24:19 | sean-k-mooney | Aug 19 12:41:15.092746 np0038215967 devstack@n-api.service[58447]: INFO nova.api.openstack.requestlog [None req-54123910-92d9-491b-b845-f8e7d37490dd tempest-StatefulNetworkSecGroupTest-1423213631 tempest-StatefulNetworkSecGroupTest-1423213631-project-member] 149.202.166.120 "DELETE /compute/v2.1/servers/4623b509-a848-41a4-9fc2-1cf8227bd4ca" status: 204 len: 0 microversion: 2.1 | |
| 10:24:21 | sean-k-mooney | time: 0.127466 | |
| 10:24:35 | sean-k-mooney | so the quest is was that tempest | |
| 10:24:50 | sean-k-mooney | it proably was but we can check the request id | |
| 10:25:18 | ralonsoh | yes | |
| 10:25:19 | ralonsoh | 2024-08-19 12:41:15.096 87668 INFO tempest.lib.common.rest_client [req-54123910-92d9-491b-b845-f8e7d37490dd req-54123910-92d9-491b-b845-f8e7d37490dd ] Request (StatefulNetworkSecGroupTest:_run_cleanups): 204 DELETE https://149.202.166.120/compute/v2.1/servers/4623b509-a848-41a4-9fc2-1cf8227bd4ca 0.147s | |
| 10:25:30 | ralonsoh | I didn't find it before... | |
| 10:25:50 | ralonsoh | sean-k-mooney, thanks a lot!! | |
| 10:26:18 | sean-k-mooney | well that proablju just the test cleanup | |
| 10:26:26 | sean-k-mooney | it does not tells use why it decied to do that | |
| 10:26:34 | sean-k-mooney | but im guessing there is a timeout or something | |
| 10:26:37 | ralonsoh | yes, now I need to know why the test is failing | |
| 10:26:48 | ralonsoh | I see the SSH is working | |
| 10:28:12 | sean-k-mooney | and your not expecting too? | |
| 10:28:24 | ralonsoh | no, that' | |
| 10:28:37 | ralonsoh | that's ok, but the test (ping) is working, and should not | |
| 10:28:52 | ralonsoh | add SG rule -> ping; remove SG rule -> no ping | |
| 10:29:18 | sean-k-mooney | so i think for ml2/ovs we alwasy allow icmp but i might be mistaken | |