Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2023-02-15
08:14:14 bauzas good morning Nova
08:28:02 bauzas gibi: I thought we merged most of the wait_for_ssh series for volume attachments issues https://storage.bhs.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_6f9/868236/5/gate/nova-next/6f9f3d0/testr_results.html
08:35:53 gibi bauzas: good morning
08:36:39 gibi bauzas: what you see there is that the wait for ssh step we merged times out. based on the guest log, the guest is still waiting for the DHCP to finish when the tempest times out
08:36:59 gibi slow node? slow dhcp?
08:37:00 bauzas oh so this the udhchpd issue
08:37:11 bauzas https://bugs.launchpad.net/nova/+bug/2006467
08:37:42 gibi no
08:37:57 gibi this is the last message from the guest in your case
08:37:58 gibi udhcpc: sending discover
08:38:16 gibi in the bug you linked the discover fails
08:39:13 bauzas yup, now I see the difference
08:39:40 gibi maybe it would have failed the discover there as well if we the test waited enough
08:39:53 bauzas the tempest test finishes sooner before the dhcp lease is attributed
08:39:59 gibi yepp
08:40:17 gibi bumping the ssh timeout in tempest could be an option
08:40:51 gibi also I suggest to look at a successfull case and check the guest log to see how fast the guest boots in a successful case
08:41:14 gibi in the failed case it needs more than 12 sec to cirros to get to dhcp
08:41:44 bauzas hmmm
08:42:12 bauzas the problem here is that I don't know how to identify whether this issue is happening a lot or just unfortunate
08:43:08 gibi we have to check for `wait_for_ssh_or_ping` and remove the cases where the dhcp lease failes as per https://bugs.launchpad.net/nova/+bug/2006467
08:43:22 gibi probably manual work
08:44:09 gibi there is a work in progress to add multiple regex support to logsearch to filter for more than one independent pattern in a file but it is not on main branch yet
08:46:44 bauzas I'm also looking at the job output
08:46:52 bauzas trying to identify the timings
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 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:58:58 gibi [ 12.638156] sr 0:0:0:0: Attached scsi generic sg0 type 5
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 gibi like re-sending the discover
08:59:47 bauzas gibi: I checked n-cpu to get when the instance was spawned
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

Earlier   Later