Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2021-06-10
10:01:37 elodilles this volume failure seems quite frequent (however, mostly with volume stuck in 'in-use' state)
10:01:40 elodilles http://logstash.openstack.org/#/dashboard/file/logstash.json?query=message:%5C%22failed%20to%20reach%20available%20status%20(current%5C%22
10:02:33 gibi elodilles: both in-use and detaching state happens
10:02:34 bauzas elodilles: gibi: which jobs are we talking about ?
10:02:55 bauzas I see nova-live-migrate and nova-ceph-multistore, right?
10:02:56 gibi bauzas: I'm looking at the last failure in https://review.opendev.org/c/openstack/nova/+/795533 which is in nova-grenade-multinode
10:03:04 bauzas holy snap
10:03:47 bauzas I was about to propose to make some failing jobs non-voting until we identify a proper fix, but if that's an issue occurring on a large set of jobs, neverming this proposal
10:04:18 bauzas we're in a fscking bad situation :/
10:06:18 bauzas elodilles: the in-use issue seems to not happen for a while
10:09:59 gibi I see both
10:10:10 gibi in http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22failed%20to%20reach%20available%20status%5C%22
10:14:05 elodilles well, i haven't realized but logstash shows only failures from 4th June
10:16:13 elodilles i mean, only that day
10:16:36 bauzas yep
10:16:43 bauzas some transient issue I think
10:16:44 gibi elodilles: I think that is a shortcoming of logstash
10:16:52 bauzas ... or this ?
10:16:53 gibi I see the same recently
10:17:16 bauzas anyway, logstash is sunsetting unfortunately
10:17:18 elodilles i also think it's some indexing issue, or something like that...
10:17:33 bauzas so we can no longer count on it :(
10:17:41 bauzas (even if i told about it)
10:33:09 gibi I cannot figure out this failure
10:33:14 gibi I lost in cinder
10:38:34 gibi I wait for lyarwood to look at it but other than that I can only file a bug on cinder
10:53:35 gibi lyarwood: o/
10:53:38 lyarwood gibi: Can you throw me a pointer to some logs?
10:53:59 gibi sure
10:55:05 gibi https://f141fb01d9c1d07df646-94aaf0771088c81abb9a09d47e91a608.ssl.cf1.rackcdn.com/795533/5/check/nova-grenade-multinode/24485b8/testr_results.html
10:55:17 gibi this is the recent grenade job failure on https://review.opendev.org/c/openstack/nova/+/795533
10:55:57 gibi but I think this 'failed to reach available status (current detaching)' and 'failed to reach available status (current in-use)' are pretty common failures
10:56:21 lyarwood right it's still the detach logic
10:56:59 lyarwood https://zuul.opendev.org/t/openstack/build/24485b8c450740c5946c39dcf310a746/log/controller/logs/screen-n-cpu.txt#25665
10:57:16 lyarwood I had a few hits of this last week and wanted to dump the instance console on failure
10:57:31 lyarwood led me down a rabbit hole that I've not had time to revisit this week
10:57:48 lyarwood https://review.opendev.org/c/openstack/tempest/+/794757 was my initial attempt
10:58:01 gibi ohh
10:58:13 gibi thanks for the info
10:58:23 gibi I went to the cinder side
10:58:26 gibi and lost
11:00:24 gibi lyarwood: what I saw that the tempest sent a volume detachment https://zuul.opendev.org/t/openstack/build/24485b8c450740c5946c39dcf310a746/log/job-output.txt#58720 and that led to the volume being in detaching state
11:02:05 gibi and that succeeded in nova https://zuul.opendev.org/t/openstack/build/24485b8c450740c5946c39dcf310a746/log/controller/logs/screen-n-cpu.txt#23456
11:03:37 gibi ohh it does not
11:03:48 gibi it oly succeded from the persistent domain
11:04:10 lyarwood right req-6f7d27cf-3d82-4e8d-ad25-7f53249a05a0 fails to detach the volume from the live domain
11:04:17 gibi yeah, now I see
11:04:54 lyarwood I traced this all through previously and couldn't see any issues with n-cpu, libvirt or even QEMU tbh
11:05:04 lyarwood so I wanted to see what the state of the guest OS was
11:05:14 lyarwood before I reported a bug to the QEMU folks
11:05:18 lyarwood and/or cirros
11:07:33 lyarwood https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_ec1/795533/5/check/nova-live-migration/ec1e40c/testr_results.html - the latest run has failed in nova-live-migration
11:07:58 lyarwood with a timeout during the initial POST, odd.
11:08:57 lyarwood oh I wonder if it's https://bugs.launchpad.net/nova/+bug/1929446
11:08:57 opendevmeet Launchpad bug 1929446 in OpenStack Compute (nova) "check_can_live_migrate_source taking > 60 seconds in CI" [Medium,Triaged]
11:09:14 lyarwood sean-k-mooney: ^ did you get anywhere with that?
11:09:21 bauzas fwiw, the mypy removal is green from the CI https://review.opendev.org/c/openstack/nova/+/795744
11:11:11 lyarwood It's still likely to fail in the actual gate with all of these failures however right?
11:12:45 sean-k-mooney i think its stil ovsdbapp but i did not see a way to stop the polling in the lib
11:13:32 sean-k-mooney i can take another look im wondering if we need to move the polling to the prive sep deamon or into a real pthread
11:16:16 lyarwood sean-k-mooney: I still don't understand the timing here
11:16:42 lyarwood sean-k-mooney: is there a long running os-vif thing in the background or is it related to check_can_live_migrate_source?
11:17:13 sean-k-mooney the first
11:17:32 lyarwood kk the short term workaround is just to bump the rpc timeout I guess
11:17:45 lyarwood just in the LM jobs
11:18:21 sean-k-mooney or rather os-vif usese ovsdbapp which create a connection to ovs and then it kicks off a pooling loop that monitors ovs for the addtion and removal of ports
11:18:32 sean-k-mooney os-vif never uses that feature of ovsdbapp
11:18:48 sean-k-mooney it is used by the neutron l2 agent which uses ovsdbapp directly
11:18:57 sean-k-mooney to know when we add and remove vm ports
11:19:15 sean-k-mooney but ovsdbapp appears to not have an obvios way to turn it off
11:19:39 lyarwood ah so we do this once via os-vif and ovsdbapp keeps polling in the background forever?
11:20:19 sean-k-mooney yep
11:20:24 lyarwood ewwww
11:20:28 sean-k-mooney im sure you have seen it in the debug logs
11:20:29 lyarwood so we don't even need this?!
11:20:34 sean-k-mooney correct
11:20:36 lyarwood yeah I just assumed we needed it
11:20:39 lyarwood christ
11:20:41 lyarwood :D
11:20:51 sean-k-mooney so there is a better workaround
11:20:53 sean-k-mooney https://github.com/openstack/os-vif/blob/master/vif_plug_ovs/ovs.py#L65-L75
11:21:05 sean-k-mooney go back to the old cli based backend
11:22:24 sean-k-mooney sorry i proably have to expand on that more
11:23:00 sean-k-mooney [os_vif_ovs]/ovsdb_interface=vsctl
11:23:07 lyarwood tbh if the native approach is broken and stealing this much time from actual n-cpu requests I'd suggest we do that
11:23:10 sean-k-mooney set that in the nova.conf
11:23:33 sean-k-mooney well the native implemation is much much faster espaically at scale
11:24:20 sean-k-mooney but for right now we could go back to the old one which i was ment to delete last cycle until i can fix the native implementation
11:26:36 lyarwood question is do we do this for all CI envs or just the live migration ones?
11:27:03 sean-k-mooney at the scale we operate at in the ci its safe to do it for all if we want too
11:27:20 sean-k-mooney the performace delta only becomes appearent if you have 100s of ports
11:27:29 gibi I'm not be surpised if this polling interferese with out eventlet monkey patching as internally it also patches some eventlet things
11:27:50 lyarwood fun
11:27:54 sean-k-mooney gibi: well os-vif intentionally does not use eventlets
11:28:16 sean-k-mooney although its always or almost always loaded into an enve that is monkypatched already
11:28:21 gibi /usr/lib/python3/dist-packages/ovs/poller.py
11:28:29 gibi i mean
11:28:30 gibi https://github.com/openvswitch/ovs/blob/210c4cba9bc69412473a2fee8e9b6f023150e6e6/python/ovs/poller.py#L270
11:28:36 gibi it does have eventlet patching
11:29:09 sean-k-mooney that is in the ovs python binding but ya

Earlier   Later