| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-02-23 | |||
| 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 | |
| 21:18:37 | mriedem | is it every one or just the subnode? | |
| 21:18:43 | mriedem | ubuntu-xenial-inap-mtl01-0002692907 is the subnode | |
| 21:19:20 | andreaf | mriedem actually every single VM on the 907 node | |
| 21:19:44 | mriedem | andreaf: so this is the warning you get on first startup | |
| 21:19:45 | mriedem | http://logs.openstack.org/24/545724/9/check/tempest-multinode-full/1bbec81/compute1/logs/screen-n-cpu.txt.gz?level=INFO#_Feb_23_17_22_20_954537 | |
| 21:19:50 | mriedem | No compute node record found for host ubuntu-xenial-inap-mtl01-0002692907. If this is the first time this service is starting on this host, then you can ignore this warning.: ComputeHostNotFound_Remote: Compute host ubuntu-xenial-inap-mtl01-0002692907 could not be found. | |
| 21:20:03 | mriedem | then the compute node record is created | |
| 21:20:04 | mriedem | http://logs.openstack.org/24/545724/9/check/tempest-multinode-full/1bbec81/compute1/logs/screen-n-cpu.txt.gz?level=INFO#_Feb_23_17_22_21_021412 | |
| 21:20:09 | mriedem | Feb 23 17:22:21.021412 ubuntu-xenial-inap-mtl01-0002692907 nova-compute[21947]: INFO nova.compute.resource_tracker [None req-5ceeacfd-f9f6-4b19-9044-6fd13c9adadc None None] Compute node record created for ubuntu-xenial-inap-mtl01-0002692907:ubuntu-xenial-inap-mtl01-0002692907 with uuid: 85868727-6173-4345-bd2e-a92bfaf1de8a | |
| 21:20:29 | openstackgerrit | Matthew Edmonds proposed openstack/nova master: Fix N358 hacking check https://review.openstack.org/547670 | |
| 21:21:06 | mriedem | http://logs.openstack.org/24/545724/9/check/tempest-multinode-full/1bbec81/compute1/logs/devstacklog.txt.gz#_2018-02-23_17_22_18_880 | |
| 21:21:06 | mriedem | on that subnode, wait_for_compute starts here: | |
| 21:21:11 | mriedem | 2018-02-23 17:22:18.880 | + lib/nova:is_nova_ready:1003 : wait_for_compute 60 | |
| 21:21:21 | mriedem | and ends here | |
| 21:21:22 | mriedem | 2018-02-23 17:22:21.607 | + functions:wait_for_compute:463 : return 0 | |
| 21:21:56 | andreaf | so it's successful | |
| 21:21:58 | mriedem | so in that case, it looks like the compute node record was created before devstack started waiting | |
| 21:22:58 | mnaser | mriedem: round 2 https://review.openstack.org/#/c/547431/ | |
| 21:23:07 | andreaf | right... so I'm missing what's going wrong... | |
| 21:23:49 | mnaser | its friday and the servers are lazy | |
| 21:23:51 | mriedem | http://logs.openstack.org/24/545724/9/check/tempest-multinode-full/1bbec81/controller/logs/devstacklog.txt.gz#_2018-02-23_17_13_29_978 | |
| 21:23:51 | mriedem | the host mapping for the n-cpu on the controller node is created here: | |
| 21:23:57 | mriedem | 2018-02-23 17:13:29.978 | Creating host mapping for compute host 'ubuntu-xenial-inap-mtl01-0002692906': adbcb697-55fc-4750-9242-b13aa75cab07 | |
| 21:24:28 | mriedem | discover_hosts doesn't run on the subnode | |