| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-03-07 | |||
| 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 | |
| 19:44:11 | dansmith | like set debug=False, sighup, and make sure the log didn't get another debug-esque message that would have come | |
| 19:44:23 | dansmith | I bet mriedem gets all tingly just thinking about such at hing | |
| 19:44:38 | dansmith | I think he <3's post hook test validation | |
| 19:45:30 | mriedem | shut up gawd | |
| 19:46:03 | mnaser | the only thing i can imagine is | |
| 19:46:14 | mnaser | https://github.com/openstack/oslo.service/blob/471bfe770808a0348fcce1e83753dcc414b361c1/oslo_service/service.py#L395-L397 | |
| 19:46:26 | mnaser | that somehow evaluating to false and calling self.restart() | |
| 19:46:44 | dansmith | because of systemd not running us in daemon mode or something? | |
| 19:47:02 | dansmith | https://github.com/openstack/oslo.service/blob/471bfe770808a0348fcce1e83753dcc414b361c1/oslo_service/service.py#L58 | |
| 19:47:30 | dansmith | yep, | |
| 19:48:06 | dansmith | if stdout is closed or not a tty, then we're in daemon mode, else no | |
| 19:48:20 | mnaser | but stdout is probably open because of how systemd works | |
| 19:48:21 | dansmith | I'm guessing maybe systemd runs us with a pty for stdout in foreground mode and that's fooling it? | |
| 19:48:28 | mnaser | let me | |
| 19:48:33 | mnaser | lsof a running instance now | |
| 19:48:45 | dansmith | I'm pretty sure it uses a pty, | |
| 19:48:59 | dansmith | because if you run a python program as a systemd unit, you have to turn off output buffering to see live output | |
| 19:50:13 | dansmith | could probably defeat that by running compute |tee and see if that changes the behavior | |
| 19:51:37 | mnaser | looks like there is a systemd option called 'DefaultStandardOutput' | |
| 19:51:44 | mnaser | which defaults to 'journal' | |
| 19:51:56 | dansmith | well, sure. | |
| 19:52:08 | dansmith | but you want that unless you're using native systemd logging | |
| 19:52:29 | mnaser | yeah, but that also means that stdout is not closed => we're not in daemon mode, right? | |
| 19:52:49 | dansmith | it's not just closed, it's closed or not a tty | |
| 19:52:57 | dansmith | per that is_daemon() method right? | |
| 19:53:25 | dansmith | # The process group for a foreground process will match the | |
| 19:53:25 | dansmith | # process group of the controlling terminal. If those values do | |
| 19:53:25 | dansmith | # not match, or ioctl() fails on the stdout file handle, we assume | |
| 19:53:25 | dansmith | # the process is running in the background as a daemon. | |
| 19:54:02 | dansmith | if systemd is running us with a pty for stdio, that will assume we're in interactive mode and say we're not a daemon, which means sighup->restarts (for some reason which I'm not even sure is legit) | |
| 19:54:28 | mnaser | ok let me just drop that python code in a simple systemd unit and see what happens | |
| 19:58:11 | dansmith | also would be useful to just take a system running like this and put a debug print() in that thing to see if we're returning !daemon for any reason | |
| 19:59:51 | mnaser | bleh, returning true | |
| 20:00:51 | mnaser | http://paste.openstack.org/show/747426/ | |
| 20:01:19 | dansmith | not sure that's a really legit test, | |
| 20:01:31 | dansmith | because any other service startup stuff could impact that | |
| 20:01:44 | dansmith | like chdir(), close existing fds, logging setup, etc | |
| 20:01:56 | dansmith | I think it'd be more useful to just instrument a misbehaving openstack service | |
| 20:01:59 | mnaser | ok so let me do it on a machine i have here then | |
| 20:02:03 | mnaser | on an actual nova-compute | |
| 20:04:28 | mnaser | _is_sighup_and_daemon: True | |
| 20:04:50 | mnaser | which means | |
| 20:04:56 | mnaser | if not True: .. so it doesn't break and does a restart | |
| 20:05:05 | mnaser | wait what, shouldn't that be if _is_sighup_and_daemon(signo): break ? | |
| 20:05:26 | mnaser | given that we don't want to restart if we get a sighup and running in daemon mode? | |
| 20:06:22 | dansmith | hrm, yeah | |
| 20:06:25 | mnaser | https://github.com/openstack/oslo.service/commit/94e76035c627e003f601c6501c0f414a13160f1f#diff-49ecd82bf041c1fd494a0bc4a96782deR195 | |
| 20:06:28 | dansmith | tbh, I don't know why this logic is here regardless | |
| 20:06:55 | dansmith | ...newton | |
| 20:07:00 | mnaser | yeah it's been a hot minute | |
| 20:07:05 | mnaser | i really hope it hasn't been broken that whole time | |
| 20:07:05 | mnaser | lol | |
| 20:07:15 | dansmith | that was around the time of the great systemdification of devstack, and because sdague | |
| 20:07:17 | dansmith | so really fishy | |
| 20:07:26 | dansmith | but sounds like something is broken to me | |
| 20:08:05 | mnaser | ok ill try to ping doug | |
| 20:09:19 | dansmith | I don't really agree with the assertion made in the commit message of that | |
| 20:09:33 | dansmith | because it assumes that we're only a long-lived service if we've daemonized ourselves | |