| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2024-08-20 | |||
| 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:13 | leavelet | HEhqQ. Should I file an issue on Launchpad, or is this likely a configuration problem on my end? | |
| 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 | 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: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: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 | |
| 10:29:38 | sean-k-mooney | ovn, iptables and the ovs security group driver do have some diffent behaivor | |
| 10:30:05 | sean-k-mooney | although maybing im thinkign of arp not icmp | |
| 10:30:36 | sean-k-mooney | is the test stopping the ping when it removes the rule | |
| 10:30:45 | sean-k-mooney | it could be related to contrack | |
| 10:30:56 | ralonsoh | sorry, not ping but nc command | |
| 10:31:26 | sean-k-mooney | :) ok agian it could be related to contrack i dont think we terminate established connections | |
| 12:49:56 | sean-k-mooney | mikal: https://review.opendev.org/c/openstack/nova/+/926126 is correct although dansmith for valid reasons prefer we now split this type of change into 2 commits 1 for the object change and 1 for the driver change. | |
| 13:26:31 | opendevreview | Takashi Kajinami proposed openstack/nova master: libvirt: Launch instances with stateless firmware https://review.opendev.org/c/openstack/nova/+/908890 | |
| 13:29:59 | tkajinam | sean-k-mooney, I've added functional test coverage but I'm struggling to understand why rebuild test fails... I'll dig into it further but it'd be really appreciated if you can take a look to find out what I've overlooked. | |
| 13:30:29 | tkajinam | also there is a bit tricky problem with assertion in live migration. I've summarized it (as well as the problem with rescue) so it'd be nice if you can check it when you have time | |
| 13:36:11 | sean-k-mooney | tkajinam: if i can find time to run it locally ill try and do that | |
| 13:36:34 | tkajinam | sean-k-mooney, thx | |
| 13:36:46 | sean-k-mooney | tkajinam: we have test helper for rebuild by the way adn some of the other actions | |
| 13:36:53 | sean-k-mooney | so you shoudl not need to do a raw post | |
| 13:37:31 | tkajinam | ah, ok. let me find these. I found these bare posts in a few other test files but we can probably replace these, too | |
| 13:37:41 | tkajinam | (in a separate follow-up | |
| 13:37:47 | sean-k-mooney | https://github.com/openstack/nova/blob/master/nova/tests/functional/integrated_helpers.py#L550 | |
| 13:38:07 | sean-k-mooney | most of the actions shoudl be there and if you need a new one you should just ad it ther | |
| 13:38:35 | sean-k-mooney | thats not yoru issue but just good to know they exist to aovid code duplication | |
| 13:40:03 | sean-k-mooney | OS-DCF:diskConfig is not generaly requrie by the way and it default to auto which iswhy we dont actully set it today | |
| 13:41:27 | sean-k-mooney | oh hehe | |
| 13:41:45 | sean-k-mooney | https://review.opendev.org/c/openstack/nova/+/908890/15/nova/tests/functional/libvirt/test_stateless_firmware.py#246 | |
| 13:42:00 | sean-k-mooney | tkajinam: your not using the updated server object | |
| 13:42:29 | sean-k-mooney | oh your passing the id and doing the db lookup | |
| 13:42:38 | sean-k-mooney | internally | |
| 13:43:32 | sean-k-mooney | but you rusing self.guest_configs[server_id].os_loader_stateless | |
| 13:43:59 | sean-k-mooney | so i wonder if that has stale info | |
| 13:45:11 | tkajinam | sean-k-mooney, I'm fixing it now. However the current blocker appears in the rescue API call so that line is not related | |
| 13:45:32 | opendevreview | Takashi Kajinami proposed openstack/nova master: libvirt: Launch instances with stateless firmware https://review.opendev.org/c/openstack/nova/+/908890 | |
| 13:46:29 | sean-k-mooney | ok so rescue is your main consern https://review.opendev.org/c/openstack/nova/+/908890/16/nova/tests/functional/libvirt/test_stateless_firmware.py#208 | |
| 13:46:40 | sean-k-mooney | ill quickly pull that review and see what happens locally | |
| 14:09:30 | sean-k-mooney | tkajinam: so rescue is failing beucase the test is tryign to open the unrescue_xml_path i.e. its tryign to write to disk | |
| 14:09:53 | sean-k-mooney | tkajinam: so there is a missing mock somewhere | |
| 14:10:02 | sean-k-mooney | https://paste.opendev.org/show/bCsw4SkPFosMTi0pL4yd/ | |