Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2023-02-14
17:26:59 bauzas if it's cosmetic, then you have MHO
17:27:14 bauzas probably better to just change the docstring
17:27:21 gibi artom: bumping hacking to flake8 5.0.4 causes unit test failures in hacking :/
17:27:41 artom Wow, wtf
17:27:44 bauzas but if that doesn't cause any harm, please defer it to Bobcat
17:28:29 gibi hold on, that might be not due to flake8 5.0.4
17:28:41 gibi bauzas: don't worry we won't bump hacking now :)
17:29:15 bauzas I mean, another library upgrade and then I get a heartbroke
17:30:10 gibi yeah the unit test of hacking fails on me on master too :/
17:30:33 artom Err
17:30:47 artom I guess stuff changed, and the unit tests job just never ran?
17:31:00 gibi anyhow I think the whole 1) bump hacking to use flake8 5.0 3) release a new hacking 2) bump nova to use latest hacking. Is doable probably.
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

Earlier   Later