| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-02-23 | |||
| 17:47:51 | openstack | Launchpad bug 1708039 in devstack "gate-grenade-dsvm-neutron-multinode-ubuntu-xenial fails with "No host-to-cell mapping found for selected host"" [Medium,Fix released] - Assigned to Sean Dague (sdague) | |
| 17:47:51 | mnaser | sigh https://bugs.launchpad.net/grenade/+bug/1708039 looks like it was 'supposed' to be fixed | |
| 17:49:09 | mnaser | it looks like it regressed | |
| 17:49:12 | mnaser | and its all stable/pike hits | |
| 17:54:40 | mnaser | "Didn't find service registered by hostname after 60 seconds" .. found it | |
| 17:54:49 | mnaser | it's actually listed but the bash for some reason doesnt find it | |
| 17:55:51 | efried | leakypipes: You around today? | |
| 17:55:58 | efried | Hoho, it's Friday | |
| 17:56:14 | andreaf | mriedem hey I'm setting up a zuul-v3 multinode job, and everything works fine apart from nova that gives me "Host is not mapped to any cell" http://logs.openstack.org/24/545724/9/check/tempest-multinode-full/1bbec81/ara/result/525a60bd-ac22-4fc4-9db7-e61fce8ac1f5/ | |
| 17:56:45 | andreaf | mriedem: I compared configs in localrc and nova and I don't see anything obvious - do you have any idea about what this could be? | |
| 17:56:52 | leakypipes | fried_rice_jfk: ues | |
| 17:56:54 | leakypipes | yes | |
| 17:57:06 | fried_rice_jfk | leakypipes: It looks like alex_xu may be right. I wrote a gabbit for it. | |
| 17:57:49 | mnaser | andreaf: im actually looking into this right ow | |
| 17:57:55 | mnaser | im seeing this issue in stable/pike | |
| 17:58:38 | andreaf | mnaser oh ok at least it's not just me :P | |
| 17:59:00 | mnaser | andreaf: i'm seeing the devstack start waiting for compute to go up at "2018-02-23 04:24:33.575" (with a 60s timeout) and the compute record get created at "2018-02-23 04:25:44.182" | |
| 17:59:31 | mnaser | with a 60 second timeout, it means that devstack gives up at 04:25:33, but the compute record actually gets created 11 seconds later | |
| 18:01:29 | fried_rice_jfk | leakypipes: Trying to figure out why. Is the order in which I construct my query supposed to not matter? | |
| 18:03:26 | fried_rice_jfk | leakypipes: Maybe query.select_from() overwrites any previous .select_from()? | |
| 18:04:16 | mnaser | so it takes 42 seconds to go from "Connecting to libvirt: qemu:///system _get_new_connection /opt/stack/old/nova/nova/virt/libvirt/host.py:366" => "Registering for lifecycle events" | |
| 18:04:38 | mnaser | and those 42 seconds are enough for devstack to timeout waiting for compute | |
| 18:05:42 | mnaser | so somehow "wrapped_conn = self._connect(self._uri, self._read_only)" takes 42 seconds here https://github.com/openstack/nova/blob/stable/pike/nova/virt/libvirt/host.py#L368 | |
| 18:07:52 | mnaser | libvirtd starts at "2018-02-23 04:23:59.741" from devstack | |
| 18:07:57 | fried_rice_jfk | leakypipes: Gah, my apologies; I was misreading my test failure. It's fine, it's cumulative as we expected. | |
| 18:08:42 | openstackgerrit | Eric Fried proposed openstack/nova master: rp: GET /resource_providers?required= |
|
| 18:08:52 | leakypipes | fried_rice_jfk: k | |
| 18:08:54 | fried_rice_jfk | leakypipes, alex_xu: Added a gabbit to prove ANDness with resources ^ | |
| 18:18:25 | mnaser | who's the person to bug for libvirt related questions | |
| 18:19:01 | mnaser | i'm seeing 1116 "device-list-properties" on service start | |
| 18:22:05 | figleaf | fried_rice_jfk: looks good! | |
| 18:22:22 | fried_rice_jfk | Thanks figleaf | |
| 18:25:06 | openstackgerrit | Eric Berglund proposed openstack/nova master: PowerVM Driver: vSCSI volume driver https://review.openstack.org/526094 | |
| 19:17:12 | mnaser | o/ | |
| 19:20:33 | mriedem | andreaf: mnaser: maybe on a slow test node, | |
| 19:20:58 | mriedem | devstack times out waiting for the compute host to get mapped to the cell, which won't happen until after the compute node record gets auto-created when the nova-compute service starts up | |
| 19:21:29 | mnaser | mriedem: exactly, but libvirt takes 42 seconds to start up and seems to be doing a ton of commands before starting up | |
| 19:21:38 | mnaser | sorry, not 42 | |
| 19:21:40 | mnaser | it takes 1m22s | |
| 19:22:01 | mnaser | i wonder if we should add wait_for_libvirt :\ | |
| 19:22:26 | mnaser | seeing a tooon of "Send command '{"execute":"device-list-properties","arguments":{"typename":"kvm-pci-assign"},"id":"libvirt-19"}' for write with FD -1" | |
| 19:22:50 | mriedem | not sure why libvirt would take a long time to startup in pike and not ocata...or is it the old side of grenade failing, meaning it's ocata? | |
| 19:23:04 | mnaser | mriedem: old side is failing | |
| 19:23:08 | mriedem | ok so that's ocata | |
| 19:23:19 | mriedem | but not sure why anything would have changed there wrt libvirt | |
| 19:25:39 | mnaser | looks like uca published libvirt-bin_2.5.0-3ubuntu5.6~cloud2_amd64.deb on 9th of february | |
| 19:26:06 | mnaser | prior to that libvirt-bin_2.5.0-3ubuntu5.6~cloud1_amd64.deb was released 23 jan 2018 | |
| 19:26:11 | mnaser | and before that.. nothing in 2.x series | |
| 19:27:29 | mriedem | ocata and pike are both using the ocata UCA https://github.com/openstack-dev/devstack/blob/stable/ocata/tools/fixup_stuff.sh#L84 | |
| 19:27:38 | mriedem | https://github.com/openstack-dev/devstack/blob/stable/pike/tools/fixup_stuff.sh#L87 | |
| 19:29:46 | mnaser | mriedem: interesting, the issue doesnt seem to be there with the master which uses 3.6.0 | |
| 19:31:32 | mnaser | mriedem: i dunno, i feel like bumping that timeout to 120s, but that might mask regressions with nova taking too long to register for whatever reason | |
| 19:31:53 | mnaser | i guess i can write a wait_for_libvirt | |
| 19:33:38 | mriedem | i'd be ok with i think bumping the timeout on pike/ocata | |
| 19:34:04 | mriedem | we know we have slower nodes now, | |
| 19:34:34 | mriedem | and if there were some changes to libvirt on stable that makes it take longer to start in the ocata UCA, we can workaround it with a slower timeout; ocata is only around for a few more weeks anyway | |
| 19:36:26 | mriedem | looks like some recent cve fixes went into the libvirt packages | |
| 19:36:29 | mriedem | so that's probably the cause | |
| 19:37:54 | mriedem | https://launchpad.net/~ubuntu-cloud-archive/+archive/ubuntu/ocata-staging/+sourcepub/8774271/+listing-archive-extra | |
| 19:38:01 | mriedem | SECURITY UPDATE: Add support for Spectre mitigations | |
| 19:38:20 | mriedem | so there is your slowdown | |
| 19:39:52 | mriedem | looks like the pike package has some security fixes but not that same one https://launchpad.net/~ubuntu-cloud-archive/+archive/ubuntu/pike-staging/+sourcepub/8806001/+listing-archive-extra | |
| 19:59:00 | openstackgerrit | Logan V proposed openstack/nova stable/pike: Allow os_interface and os_region_name on Keystone reqs https://review.openstack.org/547654 | |
| 20:43:43 | andreaf | mriedem thanks for the follow up | |
| 20:44:08 | andreaf | mriedem I see that same issue on a new multinode job I'm working on, which runs on master | |
| 20:44:32 | andreaf | mriedem two runs twice the same issue, but maybe I've been unlucky with slow nodes... | |
| 20:57:51 | mriedem | i see a neutron-grenade-multinode job of mnaser's fail on pike, and it's running on rax-dfw nodes which i've always seen to be slows since the spectre patches http://logs.openstack.org/19/546219/3/check/neutron-grenade-multinode/ae7d292/zuul-info/inventory.yaml | |
| 20:57:58 | mriedem | *slow | |
| 20:58:26 | mnaser | im writing a short wait_for_libvirt | |
| 20:59:50 | mriedem | we could just hack it on pike and ocata for now and set https://github.com/openstack-dev/devstack/blob/stable/pike/lib/nova#L966 to 120 | |
| 21:00:52 | mriedem | and site https://launchpad.net/~ubuntu-cloud-archive/+archive/ubuntu/ocata-staging/+sourcepub/8774271/+listing-archive-extra | |
| 21:01:10 | mnaser | mriedem: i can do that too, probably easier and quicker | |
| 21:01:22 | mriedem | *cite ? | |
| 21:01:31 | mriedem | mnaser: it would be easier and quicker for now yeah, | |
| 21:01:40 | mriedem | could get mtreinish to take a gander | |
| 21:01:59 | mriedem | alternatively we could run the pike UCA on stable/pike... | |
| 21:02:13 | andreaf | mriedem mnaser there's a patch up to make that value configurable already | |
| 21:02:20 | mriedem | https://review.openstack.org/#/c/536798/ | |
| 21:02:32 | andreaf | https://review.openstack.org/#/c/547431/ | |
| 21:02:38 | andreaf | mriedem mnaser ^^^ | |
| 21:02:39 | mnaser | mriedem: grenade uses stable/ocata though | |
| 21:02:59 | mriedem | mnaser: yeah the old side does | |
| 21:03:00 | mriedem | true | |
| 21:03:30 | mnaser | andreaf: thats a nice patch, what does the gate use for SERVICE_TIMEOUT ? | |
| 21:03:39 | mriedem | it defaults to 60 | |
| 21:04:18 | mnaser | so i guess we use that patch+backport+bump up SERVICE_TIMEOUT in stable/ocata + stable/pike ? | |
| 21:04:55 | mriedem | i guess...i'm not sure how much people are going to want to bump the default timeout | |
| 21:04:58 | mriedem | globally i mean | |
| 21:05:16 | mriedem | that seems worse than just hard-coding the wait_for_compute timeout to 120 | |
| 21:05:51 | mnaser | yeah i think i'd want to bump up wait_for_compute because then everything will wait 120s which might be hiding regressions | |
| 21:07:21 | mriedem | so i suggest a new stackrc variable that defaults to $SERVICE_TIMEOUT, but that we can bump to be higher in stable/ocata/pike if we want | |
| 21:07:30 | mriedem | noted that in frickler's patch | |
| 21:14:41 | andreaf | mriedem this is the log line in devstack where there is some sign of the issue going on I think http://logs.openstack.org/24/545724/9/check/tempest-multinode-full/1bbec81/compute1/logs/devstacklog.txt.gz#_2018-02-23_17_22_21_709 | |
| 21:15:16 | andreaf | mriedem but I few lines later it seems to be fine | |
| 21:15:19 | mnaser | mriedem, andreaf, mtreinish: https://review.openstack.org/547431 Create NOVA_COMPUTE_SERVICE_TIMEOUT in is_nova_ready function | |
| 21:15:20 | mriedem | that's normal | |
| 21:15:38 | mriedem | andreaf: n-cpu barfs that the compute node that represents the local host doesn't exist, and then it creates it | |
| 21:15:42 | mriedem | and stops the barfing | |
| 21:15:42 | mnaser | if that can be approved, i can backport it and then bump it in stable/ocata and stable/pike | |
| 21:16:33 | andreaf | mriedem so I don't know why I get http://logs.openstack.org/24/545724/9/check/tempest-multinode-full/1bbec81/job-output.txt.gz#_2018-02-23_17_22_40_367118 on every single VM created in that job | |