| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-02-15 | |||
| 08:47:40 | bauzas | from what I can read, I agree with you, it only calls the dhcp lease after more than 12 secs | |
| 08:53:59 | bauzas | Feb 14 18:18:56.240226 np0033093378 nova-compute[83239]: INFO nova.compute.manager [None req-053318ab-09ad-4a3a-8ddb-633cc0002c3e tempest-AttachVolumeNegativeTest-1605485622 tempest-AttachVolumeNegativeTest-1605485622-project] [instance: 6a265379-ebfd-4aea-a081-8b271f32c0ea] Took 6.36 seconds to spawn the instance on the hypervisor. | |
| 08:54:24 | bauzas | so we waited for the instance to be fully spawned before ssh'ing to it | |
| 08:54:26 | bauzas | 2023-02-14 18:22:39.102680 | controller | 2023-02-14 18:18:59,630 92653 INFO [tempest.lib.common.ssh] Creating ssh connection to '172.24.5.161:22' as 'cirros' with public key authentication | |
| 08:56:07 | bauzas | and that's only 2m30s after this that we give up to connect thru ssh | |
| 08:56:13 | bauzas | 2023-02-14 18:22:39.103394 | controller | 2023-02-14 18:22:31,398 92653 ERROR [tempest.lib.common.ssh] Failed to establish authenticated ssh connection to cirros@172.24.5.161 after 16 attempts. Proxy client: no proxy client | |
| 08:57:11 | bauzas | so, even if the guest took 12 secs to fully boot and being sshable, we still have enough delay here | |
| 08:58:46 | gibi | I only have timestamp until the guest kernel boots | |
| 08:58:56 | gibi | after that the guest logs has no timestamps | |
| 08:58:58 | gibi | [ 12.638156] sr 0:0:0:0: Attached scsi generic sg0 type 5 | |
| 08:58:58 | gibi | currently loaded modules: 8139cp 8390 9pnet 9pnet_virtio ahci drm drm_kms_helper e1000 failover fb_sys_fops hid hid_generic ip_tables isofs libahci mii ne2k_pci net_failover nls_ascii nls_iso8859_1 nls_utf8 pcnet32 qemu_fw_cfg syscopyarea sysfillrect sysimgblt ttm usbhid virtio_blk virtio_gpu virtio_input virtio_net virtio_rng virtio_scsi x_tables | |
| 08:59:03 | gibi | info: copying initramfs to /dev/vda1 | |
| 08:59:05 | gibi | info: initramfs loading root from /dev/vda1 | |
| 08:59:08 | gibi | info: /etc/init.d/rc.sysinit: up at 18.84 | |
| 08:59:10 | gibi | info: container: none | |
| 08:59:13 | gibi | currently loaded modules: 8139cp 8390 9pnet 9pnet_virtio ahci drm drm_kms_helper e1000 failover fb_sys_fops hid hid_generic ip_tables isofs libahci mii ne2k_pci net_failover nls_ascii nls_iso8859_1 nls_utf8 pcnet32 qemu_fw_cfg syscopyarea sysfillrect sysimgblt ttm usbhid virtio_blk virtio_gpu virtio_input virtio_net virtio_rng virtio_scsi x_tables | |
| 08:59:18 | gibi | Initializing random number generator... done. | |
| 08:59:21 | gibi | Starting acpid: OK | |
| 08:59:22 | bauzas | yup, that is what's in the console | |
| 08:59:23 | gibi | Starting network: udhcpc: started, v1.29.3 | |
| 08:59:26 | gibi | udhcpc: sending discover | |
| 08:59:28 | gibi | udhcpc: sending discover | |
| 08:59:31 | gibi | udhcpc: sending discover | |
| 08:59:33 | gibi | so it take at least 12.6 sec to reach this point | |
| 08:59:40 | gibi | but there are things without timestamp that can take time | |
| 08:59:47 | bauzas | gibi: I checked n-cpu to get when the instance was spawned | |
| 08:59:47 | gibi | like re-sending the discover | |
| 09:00:06 | bauzas | https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_6f9/868236/5/gate/nova-next/6f9f3d0/controller/logs/screen-n-cpu.txt | |
| 09:00:24 | bauzas | with instance uuid 6a265379-ebfd-4aea-a081-8b271f32c0ea | |
| 09:00:52 | bauzas | Feb 14 18:19:02.741562 np0033093378 nova-compute[83239]: DEBUG nova.network.neutron [req-1396e9c5-b2f1-4ceb-ac85-97edccc3919a req-5a2c93ac-f84a-44aa-9f96-5cca954570de service nova] [instance: 6a265379-ebfd-4aea-a081-8b271f32c0ea] Updated VIF entry in instance network info cache for port 77cc62f3-8d3f-4a4f-bbef-ac68fdcd9c9e. {{(pid=83239) _build_network_info_model /opt/stack/nova/nova/network/neutron.py:3459}} | |
| 09:01:26 | bauzas | at 18:19:02, the instance network info cache was updated | |
| 09:02:09 | bauzas | so we're still in the ssh connnection attempts window, which started at 18:18:59 and tried until 18:22:31 | |
| 09:07:00 | gibi | my point is if the 3rd discover would succeed then the test could pass if waiting more for ssh | |
| 09:07:12 | gibi | but we don't know that the 3rd will succeed | |
| 09:07:28 | gibi | or fail with https://bugs.launchpad.net/nova/+bug/2006467 as we don't wait enough to see | |
| 09:08:02 | bauzas | gibi: the problem is that we don't know *when* that 3rd discovery was made given it was on the console | |
| 09:08:49 | bauzas | if we assume that the guest starts after the spawn, then the 3rd discover was at 18:18:56+12s-ish | |
| 09:09:11 | bauzas | and we were still trying to connect thru ssh | |
| 09:10:41 | gibi | do you suggest the that after the 3rd discover request the udhcp freeze and never time out? | |
| 09:13:01 | bauzas | yeah, confirmed, the timings match between the job-output and the n-api log | |
| 09:13:18 | bauzas | in n-api I can see Feb 14 18:18:57.185675 np0033093378 devstack@n-api.service[74363]: DEBUG nova.api.openstack.wsgi [None req-de265685-f44e-4d63-98a7-2e38964ce455 tempest-AttachVolumeNegativeTest-1605485622 tempest-AttachVolumeNegativeTest-1605485622-project] Calling method '<bound method ServersController.show of <nova.api.openstack.compute.servers.ServersController object at 0x7f3bd48f7dc0>>' {{(pid=74363) _process_stack /opt/s | |
| 09:13:19 | bauzas | tack/nova/nova/api/openstack/wsgi.py:513}} | |
| 09:13:47 | bauzas | that correlates with job-output : 2023-02-14 18:22:39.100791 | controller | 2023-02-14 18:18:57,782 92653 INFO [tempest.lib.common.rest_client] Request (AttachVolumeNegativeTest:test_attach_attached_volume_to_different_server): 200 GET https://10.176.197.146/compute/v2.1/servers/6a265379-ebfd-4aea-a081-8b271f32c0ea 0.621s | |
| 09:14:31 | gibi | one thing we can do before bump the ssh timeout is to add "os-getConsoleOutput" nova API call to tempest when ssh timeouts to see the guest log at that point in time | |
| 09:14:44 | bauzas | gibi: I dunno what happens but yeah, the discover happens way earlier than the ssh timeout AFAICU | |
| 09:15:22 | bauzas | or | |
| 09:15:53 | bauzas | between the last console timestamp that says [12...] and the 3rd discover, then 2min15s lasted | |
| 09:17:52 | bauzas | https://bugs.launchpad.net/cirros/+bug/1273159 | |
| 09:18:08 | bauzas | "It only sends up to 3 DHCP discover packets with a 60 second pause between." :) | |
| 09:18:21 | bauzas | so yeah, that explains | |
| 09:18:57 | bauzas | that explains why we don't see the dhcp lease failing, but that doesn't explain why after 2mins, the dhcp server wasn't providing a lease | |
| 09:25:07 | gibi_ | bauzas: this was the last thing I saw | |
| 09:25:08 | gibi_ | 10:18 < bauzas> so yeah, that explains | |
| 09:25:33 | bauzas | (10:18:57) bauzas: that explains why we don't see the dhcp lease failing, but that doesn't explain why after 2mins, the dhcp server wasn't providing a lease | |
| 09:25:50 | gibi_ | yeah | |
| 09:26:05 | gibi_ | so it might be a neutron dhcp issue | |
| 09:26:17 | bauzas | gibi: I'm inclined to say that increasing the ssh timeout wouldn't help | |
| 09:26:49 | gibi_ | bauzas: it might prove that the 3rd discover fails too and then udhcp gives up | |
| 09:27:03 | gibi_ | but I agree that it is unlikely that the 3rd discover will succeed | |
| 09:27:16 | gibi_ | (except if this is a slow worker node situation) | |
| 09:28:00 | bauzas | well | |
| 09:28:30 | bauzas | I wouldn't say that a ssh connection successful after 3 mins would be a good user experience | |
| 09:28:46 | bauzas | we asked to bind the port way earlier | |
| 09:29:07 | bauzas | and the network cache was updated | |
| 09:29:15 | bauzas | so this doesn't look a vif plugging issue | |
| 09:29:29 | bauzas | gibi: welcome back :) | |
| 09:29:40 | bauzas | anyway, I gonna drop my investigations | |
| 09:29:54 | bauzas | we identified the problem | |
| 09:30:12 | bauzas | now we now it can somehow be kinda-related to https://bugs.launchpad.net/nova/+bug/2006467 | |
| 09:32:35 | gibi_ | bauzas: would it make sense to ping #openstack-neutron with ^^ | |
| 09:33:14 | bauzas | gibi_: seems to me a good thing to do + adding neutron to the list of projects impacted by that bug | |
| 09:43:38 | opendevreview | Merged openstack/nova-specs master: Amend FQDN in hostname spec to reflect implementation https://review.opendev.org/c/openstack/nova-specs/+/872422 | |
| 10:15:12 | sean-k-mooney | bauzas: its not really a openstack bug is it | |
| 10:15:39 | sean-k-mooney | bauzas: like its not a nova bug we have nothing to do with dhcp | |
| 10:16:05 | sean-k-mooney | bauzas: perhaps we can finally bump the verion of cirros in devstack | |
| 10:16:20 | sean-k-mooney | to a 6.x version | |
| 10:16:31 | sean-k-mooney | that should fix some of the kernel panics we see too | |
| 10:16:56 | stephenfin | Do folks think dropping the legacy migrations and fully supporting SQLA 2.0 is viable during the A cycle? https://review.opendev.org/c/openstack/nova/+/872428/ | |
| 10:17:22 | sean-k-mooney | you mean by tommorow right | |
| 10:17:37 | stephenfin | oof, I thought we had longer for services | |
| 10:17:54 | stephenfin | then I guess that answers my question 0:) | |
| 10:17:54 | sean-k-mooney | i saw you submit that and also use sdk seriese | |
| 10:18:28 | sean-k-mooney | well we might be able too but i have not looked at the patch yet | |
| 10:18:32 | stephenfin | yeah, the use SDK series is a nice-to-have and highlights some SDK gaps. This one's a _little_ more urgent | |
| 10:18:52 | bauzas | stephenfin: while I understand your concern, I'm afraid of merging it 2 days before FF, given the huge number of CI failures we havbe | |
| 10:18:55 | sean-k-mooney | i skimed it when you first submitted it and the second patch failed zuul | |
| 10:19:04 | sean-k-mooney | look liek it passed after a recheck | |
| 10:19:24 | sean-k-mooney | bauzas: why | |
| 10:19:37 | sean-k-mooney | this code is not used currently | |
| 10:20:15 | sean-k-mooney | if i recall correctly its only used if your coming form pre train | |
| 10:20:40 | sean-k-mooney | actully pre wallaby based on the commit message | |
| 10:21:04 | sean-k-mooney | so thsi wont impact any ci jobs | |
| 10:21:31 | sean-k-mooney | stephenfin: for what its worth we can land them early after RC1 if we dont land them now | |
| 10:21:52 | bauzas | sean-k-mooney: because we already have a lot of changes to be merged | |
| 10:22:04 | bauzas | and I'm done with the CI failures | |
| 10:22:07 | stephenfin | yeah, early in RC1 would work also. We just don't want to drag our feet on this. | |
| 10:22:56 | sean-k-mooney | well i ment after RC1 so in bobcat | |
| 10:23:17 | sean-k-mooney | i would be ok with proceedign with this in Antelope however | |
| 10:23:26 | sean-k-mooney | if ci does not object | |
| 10:25:00 | sean-k-mooney | what is the sate of ci in general currently. has the tempest issue been fixed | |