| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-07-25 | |||
| 19:48:11 | mriedem | it's not a result of this change | |
| 19:48:19 | sdague | mriedem: sure | |
| 19:48:23 | sdague | it's just not good | |
| 19:48:37 | mriedem | yeah, i don't like it either | |
| 19:48:42 | sdague | ok, http://logs.openstack.org/56/477556/5/experimental/gate-tempest-dsvm-neutron-dvr-ha-multinode-full-ubuntu-xenial-nv/432c235/logs/subnode-3/screen-n-cpu.txt.gz#_Jul_25_15_07_02_323379 is where the compute node is built, that's about 7 seconds later | |
| 19:48:54 | mriedem | yes | |
| 19:49:51 | mriedem | i'm not sure why these stacktrace | |
| 19:50:21 | mriedem | i guess because of https://github.com/openstack/nova/blob/master/nova/virt/libvirt/driver.py#L3567 ? | |
| 19:50:33 | mriedem | so it hits the generic Exception block as ComputeHostNotFound_Remote? | |
| 19:50:39 | openstackgerrit | Dan Smith proposed openstack/nova master: [WIP] Add some more cellsv2 doc goodness https://review.openstack.org/487183 | |
| 19:52:56 | sdague | mriedem: yeh | |
| 19:59:42 | sdague | mriedem: do we have a way of telling that nova-compute is ready. Is that resource tracker at 07_02 the event we need? | |
| 20:00:26 | openstackgerrit | Merged openstack/nova master: API ref: associate floating IP requires Active status https://review.openstack.org/363642 | |
| 20:00:48 | sdague | I'm trying to think about who should wait for what to get us there. Is there something we could tell from the subnode easily about it being ready so we knew we were in the clear when stack.sh finished? | |
| 20:01:18 | mriedem | sdague: our docs tell you to run 'nova service-list --binary nova-compute' and make sure the compute shows up before you run discover_hosts | |
| 20:02:37 | mriedem | because that API iterates all cells and gathers up the services running in them | |
| 20:02:42 | mriedem | so the host mapping isn't required for that | |
| 20:03:24 | sdague | so we could put a flag in to wait for compute | |
| 20:03:29 | sdague | and run: nova service-list --host `hostname` --binary nova-compute | |
| 20:03:43 | sdague | on the child until it is true? | |
| 20:08:00 | dansmith | not on the child, on the main node | |
| 20:08:41 | mriedem | right we run discover_hosts from the primary | |
| 20:08:48 | mriedem | b/c it needs to get to the api db to find the cell mappings | |
| 20:08:58 | mriedem | and the compute nodes don't have access to that | |
| 20:09:00 | dansmith | well and you need the main node to do the waiting | |
| 20:09:16 | dansmith | because it's going to run tests that need to wait until all the nodes are up | |
| 20:10:52 | mriedem | this is what i see for the 'host is not mapped to any cell' failures in voting jobs | |
| 20:10:57 | mriedem | http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Host%5C%22%20AND%20message%3A%5C%22is%20not%20mapped%20to%20any%20cell%5C%22%20AND%20tags%3A%5C%22console%5C%22%20AND%20voting%3A1%20AND%20build_status%3A%5C%22FAILURE%5C%22&from=7d | |
| 20:11:24 | mriedem | they are all grenade multinode jobs | |
| 20:12:34 | openstackgerrit | Dan Smith proposed openstack/nova master: Add some more cellsv2 doc goodness https://review.openstack.org/487183 | |
| 20:26:01 | sdague | dansmith: if the child doesn't return until n-cpu has checked in, that also works, right? | |
| 20:26:16 | sdague | basically make stack.sh synchronous on nova-compute being up | |
| 20:27:31 | dansmith | sdague: by child you mean the subnode right? | |
| 20:32:27 | mriedem | right so there are two places you could do that in the ComputeManager, | |
| 20:32:29 | mriedem | 1. init_host() | |
| 20:32:33 | mriedem | 2. pre_start_hook() | |
| 20:32:38 | mriedem | the latter already tries to get the compute node | |
| 20:32:46 | mriedem | *post_start_hook() i mean | |
| 20:33:07 | mriedem | damn, sorry, no i meant pre_start_hook | |
| 20:33:51 | mriedem | i did think that pre_start_hook should do it | |
| 20:34:00 | mriedem | because it calls update_available_resource_for_node | |
| 20:34:11 | mriedem | which calls rt.update_available_resource | |
| 20:34:32 | mriedem | which should then do the init compute node stuff | |
| 20:34:32 | sdague | dansmith: yeh | |
| 20:34:44 | mriedem | so i'm not entirely sure why that doesn't happen in the pre_start_hook phase | |
| 20:35:57 | sdague | mriedem: are you sure it didn't? | |
| 20:37:51 | mriedem | i'm not sure no | |
| 20:37:52 | mriedem | i can dig | |
| 20:38:06 | mriedem | my shovel is going to be pretty gd blunt after the end of this day | |
| 20:38:15 | sdague | mriedem: I was assuming that virt driver init host just took that long to start | |
| 20:38:28 | mriedem | the virt driver init_host doesn't do much | |
| 20:38:44 | mriedem | at least for the libvirt driver, it registers event listeners and connects to libvirt | |
| 20:39:11 | mriedem | ok so this is a subnode starting up | |
| 20:39:12 | mriedem | http://logs.openstack.org/79/487179/1/check/gate-tempest-dsvm-neutron-multinode-full-ubuntu-xenial-nv/1dd9db5/logs/subnode-2/screen-n-cpu.txt.gz#_Jul_25_19_30_42_125360 | |
| 20:39:16 | mriedem | Jul 25 19:30:42.125360 ubuntu-xenial-2-node-osic-cloud1-disk-10073644-745537 nova-compute[711]: INFO nova.service [-] Starting compute node (version 16.0.0) | |
| 20:39:30 | mriedem | that's in nova.service.Service.start() | |
| 20:40:15 | mriedem | then you see the libvirt event stuff | |
| 20:41:03 | mriedem | then you see this from the libvirt driver http://logs.openstack.org/79/487179/1/check/gate-tempest-dsvm-neutron-multinode-full-ubuntu-xenial-nv/1dd9db5/logs/subnode-2/screen-n-cpu.txt.gz#_Jul_25_19_30_42_150823 | |
| 20:41:10 | mriedem | because the compute node doesn't exist yet | |
| 20:41:41 | mriedem | then you see this in the compute manager http://logs.openstack.org/79/487179/1/check/gate-tempest-dsvm-neutron-multinode-full-ubuntu-xenial-nv/1dd9db5/logs/subnode-2/screen-n-cpu.txt.gz#_Jul_25_19_30_44_394800 | |
| 20:41:49 | mriedem | which is from _get_compute_nodes_in_db | |
| 20:43:18 | mriedem | i'm not sure why that traces | |
| 20:43:58 | mriedem | that warning is here https://github.com/openstack/nova/blob/master/nova/compute/manager.py#L6627 | |
| 20:47:28 | mriedem | anyway then we call the resource tracker https://github.com/openstack/nova/blob/master/nova/compute/manager.py#L6602 | |
| 20:47:44 | mriedem | http://logs.openstack.org/79/487179/1/check/gate-tempest-dsvm-neutron-multinode-full-ubuntu-xenial-nv/1dd9db5/logs/subnode-2/screen-n-cpu.txt.gz#_Jul_25_19_30_44_399281 | |
| 20:47:52 | mriedem | Jul 25 19:30:44.399281 ubuntu-xenial-2-node-osic-cloud1-disk-10073644-745537 nova-compute[711]: DEBUG nova.compute.resource_tracker [None req-9286123e-31d0-45c4-a951-fe1e3947db00 None None] Auditing locally available compute resources for ubuntu-xenial-2-node-osic-cloud1-disk-10073644-745537 (node: ubuntu-xenial-2-node-osic-cloud1-disk-10073644-745537) {{(pid=711) update_available_resource /opt/stack/new/nova/nova/compute/res | |
| 20:47:52 | mriedem | e_tracker.py:609}} | |
| 20:49:41 | mriedem | then we should get in here https://github.com/openstack/nova/blob/master/nova/compute/resource_tracker.py#L488 | |
| 20:50:43 | mriedem | and we'll hit this https://github.com/openstack/nova/blob/master/nova/compute/resource_tracker.py#L709 | |
| 20:50:57 | mriedem | http://logs.openstack.org/79/487179/1/check/gate-tempest-dsvm-neutron-multinode-full-ubuntu-xenial-nv/1dd9db5/logs/subnode-2/screen-n-cpu.txt.gz#_Jul_25_19_30_44_441734 | |
| 20:51:39 | mriedem | and so we'll create the compute node record here https://github.com/openstack/nova/blob/master/nova/compute/resource_tracker.py#L531 | |
| 20:51:58 | mriedem | http://logs.openstack.org/79/487179/1/check/gate-tempest-dsvm-neutron-multinode-full-ubuntu-xenial-nv/1dd9db5/logs/subnode-2/screen-n-cpu.txt.gz#_Jul_25_19_30_44_459686 | |
| 20:52:27 | mriedem | sdague: but does systemd wait or does it just launch off the service start and not block on it? | |
| 20:52:50 | sdague | mriedem: define wait | |
| 20:55:20 | sdague | mriedem: we're starting in the foreground, it's tracking the parent process, but the issue is it's much later that things are ready | |
| 20:56:21 | sdague | anyway, I need to work on dinner, I've got this half assed patch running locally, if it works I'll push it | |
| 20:56:24 | mriedem | right when we start the n-cpu service, and the service is launched, that's all async | |
| 20:56:31 | sdague | mriedem: it's not async | |
| 20:56:38 | jangutter | mriedem, jaypipes: should I assert on exception.NovaException or exception.InternalError at https://review.openstack.org/#/c/486426/6/nova/tests/unit/virt/libvirt/test_vif.py@1616 | |
| 20:56:49 | sdague | it's that it's not ready for 25 - 30 seconds after start | |
| 20:57:00 | sdague | and, there is no /health to know that | |
| 20:57:19 | sdague | we poll api processes that we start to know they are ready before we move on | |
| 20:57:26 | sdague | but there isn't a direct interface for that | |
| 20:57:34 | mriedem | right i meant https://github.com/openstack/nova/blob/master/nova/service.py#L138 | |
| 20:57:47 | mriedem | which is what calls compute manager pre_start_hook that sets this all up | |
| 20:58:09 | sdague | mriedem: ok, before I leave, I want to make sure we get this question clear :) | |
| 20:58:30 | sdague | systemd is starting things, and it's running as parent process as soon as python exec happens | |
| 20:59:00 | mriedem | i guess i was thinking about like sysv init scripts and services, | |
| 20:59:05 | mriedem | where you can run service nova-compute status | |
| 20:59:08 | mriedem | and see if it's started or not | |
| 20:59:19 | sdague | sure, but all that tells you is if the process is running | |
| 20:59:25 | sdague | the process is running | |
| 20:59:38 | sdague | eventually the process is ready | |
| 20:59:42 | mriedem | but can't the start routine block until it's actually started or crashed? | |
| 20:59:51 | sdague | it is started | |
| 20:59:58 | sdague | the process is running | |
| 21:00:27 | sdague | how does anything external know if a process is ready other than pid existing? | |
| 21:00:31 | mriedem | ok, well this is all latent stuff and shouldn't block https://review.openstack.org/#/c/477556/ | |
| 21:00:35 | mriedem | so can we get that in? | |
| 21:00:54 | mriedem | like, this behavior goes back to ocata | |