| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-03-07 | |||
| 19:19:07 | mnaser | yeah, i dug that out, i need a faster way to link from vscode :< | |
| 19:19:23 | mnaser | i'm not sure what or why self._events is, and why it's set to `None` | |
| 19:19:31 | mnaser | the port seems to be plugging fine from the neutron side of things, according to the logs | |
| 19:19:45 | mriedem | self._events = None generally means nova-compute is stopping | |
| 19:20:05 | mnaser | strange, it doesn't seeeeeeem to be in those logs? you can see it continue to do things | |
| 19:20:09 | mriedem | http://git.openstack.org/cgit/openstack/nova/tree/nova/compute/manager.py#n397 | |
| 19:20:33 | mriedem | the only thing that calls that is cleanup_host http://git.openstack.org/cgit/openstack/nova/tree/nova/compute/manager.py#n1236 | |
| 19:20:45 | dansmith | that message is exactly what is supposed to happen if compute is shutting down | |
| 19:20:55 | mriedem | http://git.openstack.org/cgit/openstack/nova/tree/nova/service.py#n286 | |
| 19:21:16 | mnaser | that's so strange, interestingly enough, the logs don't show anything about cleaning up | |
| 19:21:22 | mnaser | or any of the "popping stuff out of event queue" messages | |
| 19:21:50 | mnaser | we did recently merge a change where we had vif_plugging_is_fatal default to true, so this might have exposed something (and it was always failing?! i hope not..) | |
| 19:22:12 | dansmith | vif plugging fatal should be set to true | |
| 19:22:18 | mnaser | sorry, i mean we set it to false | |
| 19:22:22 | dansmith | ack okay | |
| 19:22:34 | dansmith | wait, you mean you had been setting it to false, and recently fixed that yeah? | |
| 19:22:39 | mnaser | yeah | |
| 19:22:44 | dansmith | either way, that won't affect the incoming events, | |
| 19:22:49 | dansmith | just whether or not we wait for them | |
| 19:22:58 | dansmith | and what you show above is just event delivery | |
| 19:23:00 | mnaser | well, if something was broken before, we probably just exposed it (in osa or whatever) | |
| 19:23:13 | mnaser | we might have been just blindly plugging ports and it just worked™ -- this just exposed it | |
| 19:23:29 | mnaser | the interesting thing is i dont see "Canceling in-flight event" in the logs anywhere | |
| 19:23:42 | mnaser | but i guess the blocking new events might do it there | |
| 19:23:42 | mriedem | https://review.openstack.org/#/c/420026/ | |
| 19:23:47 | mriedem | ^ is it this? | |
| 19:23:58 | mriedem | did something sighup the service? | |
| 19:23:59 | dansmith | mnaser: you wouldn't if nothing is waiting when the shutdown starts | |
| 19:24:08 | dansmith | mriedem: see my comments/ | |
| 19:24:15 | dansmith | mriedem: we don't call cleanup_host on sighup | |
| 19:24:28 | mnaser | let me check systemd logs | |
| 19:24:59 | mriedem | well i'm all out of ideas :P | |
| 19:25:02 | dansmith | if we did we'd be tearing down rpc and dropping things all over the place, which would be a pretty big problem for what sighup is supposed to do | |
| 19:25:38 | mriedem | mnaser: are you hitting this consistently in osa ci? because a simple debug patch should tell us what is triggering the stop | |
| 19:25:40 | mnaser | http://logs.openstack.org/08/641308/2/check/openstack-ansible-deploy-aio_lxc-centos-7/2485c9a/logs/host/messages.txt.gz#_Mar__6_12_12_43 we reload here, but that's almost 23 minutes before it happened | |
| 19:25:51 | mnaser | yes, we're perma-borked right now | |
| 19:26:14 | dansmith | mnaser: are you maybe starting to shut down nova services before tests have finished or something? | |
| 19:26:17 | mnaser | that's the latest reference to a the nova-compute service | |
| 19:26:30 | dansmith | or maybe tests are done but instances are still coming up or something? | |
| 19:26:48 | mnaser | system logs would have shown us shutting down the service (it's a systemd unit) | |
| 19:27:05 | mnaser | it is possible that a reload might put the nova-compute in a weird state? | |
| 19:27:06 | dansmith | well, if you're using systemd to shut it down, sure | |
| 19:27:24 | dansmith | mnaser: shouldn't and the code does very little on sighup | |
| 19:29:01 | mnaser | oh thats weird | |
| 19:29:06 | mnaser | the change mriedem linked is missing in master | |
| 19:29:12 | mnaser | https://github.com/openstack/nova/blob/master/nova/compute/manager.py#L548 | |
| 19:29:12 | dansmith | it's unmerged | |
| 19:29:15 | dansmith | because it's bad | |
| 19:29:17 | mnaser | ah oops | |
| 19:29:19 | mnaser | my eyes failed me | |
| 19:30:31 | dansmith | that change would also mean a sighup will cause any instances waiting to boot when you sighup fail with a timeout | |
| 19:30:37 | dansmith | which would be pretty bad | |
| 19:30:44 | dansmith | especially if you're sighup | |
| 19:30:45 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Set min=0 for block_device_allocate_retries option https://review.openstack.org/641770 | |
| 19:30:52 | dansmith | ping nova-compute so you can turn on debug or something :) | |
| 19:31:28 | mnaser | http://logs.openstack.org/08/641308/2/check/openstack-ansible-deploy-aio_lxc-centos-7/2485c9a/logs/openstack/aio1-nova/nova-compute.log.txt.gz#_2019-03-06_12_12_43_207 | |
| 19:31:59 | mriedem | that matches http://logs.openstack.org/08/641308/2/check/openstack-ansible-deploy-aio_lxc-centos-7/2485c9a/logs/host/messages.txt.gz#_Mar__6_12_12_43 | |
| 19:32:03 | dansmith | mnaser: but it also clearly ran the compute manager reset just a couple lines below "reloading" | |
| 19:32:05 | mriedem | but not http://logs.openstack.org/08/641308/2/check/openstack-ansible-deploy-aio_lxc-centos-7/2485c9a/logs/openstack/aio1-nova/nova-compute.log.txt.gz#_2019-03-06_12_35_49_535 | |
| 19:32:15 | dansmith | maybe some oslo.service regression? | |
| 19:32:37 | mnaser | yeah that's what im wondering, if oslo service isn't doing the right thing, i'm gonna try to see in oslo service | |
| 19:32:49 | dansmith | https://bugs.launchpad.net/neutron/+bug/1780139 | |
| 19:32:50 | openstack | Launchpad bug 1780139 in neutron "Sending SIGHUP to neutron-server process causes it to hang" [Undecided,Triaged] - Assigned to Bernard Cafarelli (bcafarel) | |
| 19:33:17 | dansmith | https://github.com/openstack/oslo.service/blob/master/oslo_service/service.py#L375 | |
| 19:33:29 | dansmith | should only exit if it's unhandled I think | |
| 19:33:42 | mnaser | yeah it looks like the exiting is a little misleading there | |
| 19:34:11 | dansmith | https://github.com/openstack/oslo.service/blob/master/oslo_service/service.py#L344 | |
| 19:34:28 | dansmith | so unless it redefined the thing we need to override to handle sighup or something | |
| 19:35:14 | dansmith | but clearly not, | |
| 19:35:18 | dansmith | since we did actually do our own reload | |
| 19:35:34 | dansmith | seems fishy | |
| 19:35:34 | mnaser | yeah the logs show that the correct thing happened | |
| 19:35:44 | dansmith | or ... | |
| 19:35:51 | dansmith | maybe there was actually a respawn in between there? | |
| 19:36:00 | dansmith | maybe it did exit? we don't have pid in the logs to tell I think | |
| 19:36:34 | dansmith | mnaser: because after the log dump: http://logs.openstack.org/08/641308/2/check/openstack-ansible-deploy-aio_lxc-centos-7/2485c9a/logs/openstack/aio1-nova/nova-compute.log.txt.gz#_2019-03-06_12_12_55_326 | |
| 19:36:41 | dansmith | er, conf dump | |
| 19:36:50 | dansmith | that seems extremely wrong | |
| 19:37:09 | dansmith | and may explain why people think that "reset events" change is necessary, because we're incorrectly really exiting? | |
| 19:37:46 | mnaser | it looks like a new startup based on the logs | |
| 19:37:56 | dansmith | yeah that's uncool | |
| 19:38:11 | mnaser | esp with things like updating inventory, libvirt baseline cpu checks, etc | |
| 19:38:19 | dansmith | so I'm guessing some oslo.service regression, or some underlying change that nova didn't adapt to | |
| 19:40:18 | mnaser | following the code it looks like service.Service implements .reset() and hits self.manager.reset() | |
| 19:40:36 | dansmith | our service does yeah | |
| 19:40:54 | dansmith | we also need this to work for things like api to be able to re-calculate service versions, rpc pins,e tc | |
| 19:41:02 | dansmith | and clearing the cells cache | |
| 19:41:14 | mnaser | yeah, so it looks like nova is doing what its supposed to | |
| 19:41:24 | dansmith | so if this is broken it's a real problem, in addition to apparently causing compute to just drop everything on the floor and bail | |
| 19:41:44 | mnaser | the confirmation is the fact all conf params are being logged | |
| 19:41:48 | mnaser | which shouldnt happen | |
| 19:41:58 | mnaser | i think ? because we are handling reset() in our own way | |
| 19:42:04 | dansmith | well, | |
| 19:42:17 | dansmith | sighup is how you're supposed to reload dynamic conf variables | |
| 19:42:26 | dansmith | so I dunno if it should only dump the reloaded ones or the whole new set | |
| 19:42:39 | dansmith | initially that wouldn't have surprised me, but now that I see it saying "starting..." again, I do wonder | |
| 19:42:48 | dansmith | but yeah, this also kills the ability to hot-reload conf options like debug=True | |
| 19:43:18 | mnaser | we probably don't exactly have gating that reloads services and checks if they're still functional after, but that's awfully hard to test in the first place | |
| 19:43:33 | dansmith | yup, definitely hard to test with a parallel tempest | |
| 19:43:38 | dansmith | we could do a post hook though pretty easy | |