| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2023-02-14 | |||
| 17:31:08 | gibi | artom: or my local env is bork | |
| 17:33:09 | gibi | we will see https://review.opendev.org/c/openstack/hacking/+/873737 | |
| 17:35:04 | gibi | and I'm feeling lucky https://review.opendev.org/c/openstack/hacking/+/873738 | |
| 17:37:47 | artom | You absolute madlad | |
| 17:39:09 | gibi | I don't know what was in my afternoon coffee but I feel like a squirrel on cocain | |
| 17:39:40 | artom | Well you just answered your own questions. You coffee contained squirrels. And cocaine. | |
| 17:39:45 | gibi | :D | |
| 17:40:30 | gibi | interestingly it is from the same batch of beans that I used in the last couple of weeks without such effect. | |
| 17:41:08 | artom | So obviously this morning a squirrel decided to use it to stash its cocaine. | |
| 17:43:26 | gibi | yepp the hacking unit test on master fails in CI too https://13105f8ef823650ec019-cb65abe58d87a1a010092a9adcbaff91.ssl.cf2.rackcdn.com/873737/1/check/openstack-tox-py38/9f6af81/testr_results.html | |
| 17:44:14 | gibi | those squirrels should go and fix it instead of dealing with substances | |
| 17:45:13 | artom | Seriously, what good is a cocaine habit if you're not putting it to good use | |
| 17:48:29 | gibi | you are absolutely right :) | |
| 17:52:19 | gibi | ... when you realize that the last commit in hacking was coming from you... | |
| 18:07:56 | gibi | so the unit test failure in hacking is due to the new tox versions somehow, in a yoga container I can run the test successfuly on master with tox 4 I cannot. There is some magic in load_test in import pdb; pdb.set_trace() | |
| 18:08:03 | gibi | I mean https://github.com/openstack/hacking/blob/2931131b69af7f1e76d8ab506c250a94b330ffb9/hacking/tests/test_doctest.py#L70 | |
| 18:15:10 | gibi | this change makes the tests pass for me https://review.opendev.org/c/openstack/hacking/+/873740 locally. So I moved the flake8 5.0 bump top of it https://review.opendev.org/c/openstack/hacking/+/873738 | |
| 18:22:28 | artom | Nice, thanks for taking care of that | |
| 18:23:18 | gibi | now that the tests are running we see some real failures from the flake8 5.0 bump https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_dcc/873738/2/check/openstack-tox-py310/dccd580/testr_results.html | |
| 18:24:29 | gibi | but the coffee is wearing off so I stop here now. artom feel free to pick ^^ up | |
| 18:35:44 | artom | gibi, ack, cheers! | |
| #openstack-nova - 2023-02-15 | |||
| 05:04:04 | opendevreview | Yusuke Okada proposed openstack/nova master: Fix failed count for anti-affinity check https://review.opendev.org/c/openstack/nova/+/873216 | |
| 07:36:50 | opendevreview | Tobias Urdin proposed openstack/nova master: libvirt: set remaining to 0 when no disk to migrate https://review.opendev.org/c/openstack/nova/+/873846 | |
| 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 | [ 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 | |