| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-01-22 | |||
| 17:56:24 | TheJulia | I don't believe so, however we had two different grenade breaks in about 24 hours | |
| 17:56:25 | dansmith | why is nova-conductor not segfaulting like crazy after the thing that upgrades g-reqs (swift/glance) in other jobs? | |
| 17:56:49 | TheJulia | I think because it gets restarted | |
| 17:56:55 | dansmith | or is it and we don't notice because we don't care until after? | |
| 17:57:12 | jroll | I think nova gets upgraded first in most grenade runs, right? | |
| 17:57:17 | dansmith | okay and so it matters for you because you never upgrade nova at the end? | |
| 17:57:23 | TheJulia | the state it is left in prior to that restart is referring to a bunch of modules/libraries/paths that have been deleted due to prior python module upgrades | |
| 17:57:30 | dansmith | jroll: no I don't think so | |
| 17:57:53 | jroll | hm | |
| 17:58:25 | TheJulia | just restarting didn't work because of a sqlalchemy change | |
| 17:58:54 | TheJulia | since python requirements no longer match up because some processes have upgraded parts and pieces of the libraries | |
| 17:59:09 | sean-k-mooney | TheJulia: ie ironic installed new sqlalcamy and since nova is not upgraded its not compatible? | |
| 17:59:15 | TheJulia | sean-k-mooney: no | |
| 17:59:21 | TheJulia | Ironic has not yet upgraded at that point | |
| 17:59:48 | TheJulia | it is earlier on in the glance execution | |
| 17:59:55 | dansmith | what is the sqlalchemy fail? because that seems like a bad thing | |
| 18:00:31 | TheJulia | yes, an argument was removed from sqlalchemy and oslo_db changed accordingly | |
| 18:00:37 | TheJulia | I believe | |
| 18:01:55 | TheJulia | https://github.com/openstack/oslo.db/commit/4a727233dc2b7d1021ed7932d2cd27d8053dca31 | |
| 18:03:02 | jroll | looks like oslo.middleware 3.34.0, oslo.utils 3.35.0, and osprofiler 1.15.1 are the most relevant g-r updates | |
| 18:03:03 | TheJulia | jroll: but also, our grenade jobs were failing due to a neutron change for about 24-36 hours prior to that | |
| 18:03:09 | dansmith | so some glue around this change might get us out of the jam? https://review.openstack.org/#/c/501073/1/nova/db/sqlalchemy/api.py | |
| 18:03:09 | sean-k-mooney | is this for master? g-r for SQLAlchemy on master has a minium of 1.0.10 and pike has an upperconstaint of 1.1.12 so you should be able to install master without needing to upgrade SQLAlchemy | |
| 18:03:38 | jroll | TheJulia: oh right, were they getting into the upgrade bits? | |
| 18:03:40 | sean-k-mooney | i guess it upgrades because we allway install the newest requirement allowed in greade | |
| 18:03:46 | dansmith | I'd guess that's just a library API breakage in oslo.db | |
| 18:04:15 | TheJulia | jroll: what do you mean? | |
| 18:04:39 | jroll | TheJulia: with the neutron failure, was that before or after the upgrade, do you remember? | |
| 18:05:03 | dansmith | TheJulia: yeah, so that commit you linked from oslo.db needs to be graceful I think as it's an API breakage, AFAICT | |
| 18:05:18 | TheJulia | before, neutron's upgrade would fail | |
| 18:05:27 | jroll | TheJulia: ah, thanks. | |
| 18:05:28 | TheJulia | because of networking-generic-swtich | |
| 18:05:49 | dansmith | or, maybe since it was deprecated we need to backport a fix to nova pike to stop passing it? | |
| 18:06:38 | jroll | oslo.concurrency feels like a likely suspect in that range then, too (believe that touches some C libraries) | |
| 18:06:41 | mriedem | how is nova-conductor even picking up the new oslo.db if it's not being restarted? | |
| 18:06:52 | jroll | dansmith: that would let us restart it, yeah, though that isn't ideal | |
| 18:06:52 | dansmith | mriedem: worker forking | |
| 18:07:00 | jroll | well, there's two things going on | |
| 18:07:09 | jroll | the worker fork segfaults | |
| 18:07:17 | dansmith | jroll: ah right I got lost that this can't be the segv issue, it's the breakage that prevents the restart, correct | |
| 18:07:18 | jroll | if we restart the main process, it fails due to oslo.db | |
| 18:07:23 | dansmith | right right | |
| 18:07:33 | mriedem | ah ok, so not an intentional restart | |
| 18:07:44 | mriedem | something triggers a failure and restart, which then fails | |
| 18:08:10 | dansmith | mriedem: it's just workers being cycled in and out I think, not failure related initially | |
| 18:09:11 | mriedem | i'll go ahead and say i don't understand | |
| 18:09:17 | mriedem | i welcome the ridicule | |
| 18:09:37 | sean-k-mooney | dansmith: the minium version of SQLAlchemy on master is below the max on pike currently. the commit TheJulia referenced does not seem to indicate what version of SQLAlchemy removed the retry arg. it sound like there is a min version bump missing also if that change is not graceful | |
| 18:09:43 | jroll | mriedem: it looks like this http://logs.openstack.org/36/509336/31/check/ironic-grenade-dsvm-multinode-multitenant/6da9163/logs/screen-n-cond.txt.gz#_Jan_18_05_52_41_241366 | |
| 18:09:46 | TheJulia | if the fork causes a dynamic library to be referenced that hasn't already been opened by the parent process, that would explain the segfault in that some of the things the parent was still running with that spanws the worker is gone because pip deleted them | |
| 18:09:55 | jroll | and then systemd starts killing n-cpu and such, because insanity | |
| 18:10:19 | TheJulia | and then people begin drinking fine spirits | |
| 18:11:30 | dansmith | I have to run to a thing for a bit, back in a bit | |
| 18:12:30 | jroll | I feel like this is related but I can't prove it https://github.com/openstack/oslo.concurrency/commit/55e06261aa86c87c7c059fbddc97cdbaae06e8dd | |
| 18:12:39 | sean-k-mooney | jroll: i would assume systemd did not kill n-cpu and it segfaulted by trying to deref a fuction pointer from a module that nologer existed due to the upgrade and systemd just noticed the process died. | |
| 18:13:23 | jroll | sean-k-mooney: n-conductor does the segfaulting, n-cpu gets killed by systemd | |
| 18:13:37 | jroll | iirc | |
| 18:14:09 | mriedem | if this has been happening for <=10 days we could hopefully figure out when it started from logstash | |
| 18:14:15 | TheJulia | jroll: that is correct | |
| 18:14:41 | jroll | mriedem: we had another failure for about 24-36 hours before that, so it's a bit masked, but the first instance is 2018-01-17T09:52:37.119Z in logstash | |
| 18:15:02 | mriedem | http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22Forking%20too%20fast%2C%20sleeping%5C%22%20AND%20tags%3A%5C%22screen-n-cond.txt%5C%22&from=10d | |
| 18:16:38 | mriedem | https://github.com/openstack/requirements/commit/482fca3e04b820045bb87d9b37470bc076d2216d was 1/16 | |
| 18:17:40 | jroll | right | |
| 18:18:01 | mriedem | not sure that commit should be a problem though since something has to opt into passing the new kwarg, else it defaults to the same as before | |
| 18:18:10 | mriedem | https://github.com/openstack/oslo.concurrency/compare/3.24.0...3.25.0 | |
| 18:18:33 | jroll | ah true | |
| 18:18:53 | mriedem | and i don't think we run with osprofiler enabled in this job do we? | |
| 18:18:56 | mriedem | worth checking | |
| 18:18:59 | jroll | not that I know of | |
| 18:19:10 | jroll | I don't think any ironic jobs have ever enabled that | |
| 18:19:28 | mriedem | Jan 18 04:49:32.628690 ubuntu-xenial-inap-mtl01-0001976291 nova-conductor[19600]: DEBUG oslo_service.service [None req-db5ca533-98f7-4358-8448-0201fe9a04d8 None None] profiler.enabled = False {{(pid=19600) log_opt_values /usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py:2883}} | |
| 18:19:33 | mriedem | yeah osprofiler isn't enabled | |
| 18:20:24 | mriedem | https://github.com/openstack/requirements/commit/34d56244a87ac2a61170ab8fa81dc86dba70fc1f was 1/17 | |
| 18:20:25 | mriedem | cffi? | |
| 18:20:53 | jroll | could be | |
| 18:21:03 | mriedem | could try reverting that back to 1.11.2 and run a depends-on with an ironic patch | |
| 18:21:11 | jroll | https://github.com/cffi/cffi/compare/1.11.2...1.11.4 | |
| 18:21:19 | jroll | nothing O_o | |
| 18:21:45 | jroll | oh, they don't tag, good | |
| 18:21:55 | mriedem | http://cffi.readthedocs.io/en/latest/whatsnew.html#v1-11-4 | |
| 18:22:26 | jroll | windows, py3, meh | |
| 18:22:44 | mriedem | that's just the stuff they call out in the release notes | |
| 18:22:50 | mriedem | but yeah | |
| 18:24:04 | mriedem | https://github.com/openstack/requirements/commit/93d488328bfc780c322338226b6c62e9141637f4 | |
| 18:24:12 | mriedem | note the "and introduces a file handel leak due to an upstream bug in pyroute2" | |
| 18:24:46 | mriedem | https://github.com/openstack/os-vif/compare/1.7.0...1.9.0 | |
| 18:24:49 | jroll | mmmm | |
| 18:26:37 | mriedem | https://github.com/openstack/os-vif/commit/570c05266fa6231a21d70f2917ac0a933ac8ce7b | |
| 18:26:46 | sean-k-mooney | i dont think os-vif is the cause as in 1.7 we did not use pyroute2 and in 1.9.0 we have disabled and use ip tools instead. | |
| 18:26:46 | jroll | doesn't look like os-vif gets upgraded, though: http://logs.openstack.org/36/509336/31/check/ironic-grenade-dsvm-multinode-multitenant/6da9163/logs/grenade.sh.txt.gz | |
| 18:27:15 | sean-k-mooney | jroll: the only project useing os-vif are nova and kuyr-kubernetes | |
| 18:27:50 | efried | rgerganov yt? | |
| 18:27:54 | sean-k-mooney | im assumeing you dont have the later installed in this gate and you disable nova upgrade right ? | |
| 18:28:10 | mriedem | yeah os-vif is 1.7.0 in pip freeze | |
| 18:28:13 | mriedem | http://logs.openstack.org/36/509336/31/check/ironic-grenade-dsvm-multinode-multitenant/6da9163/logs/pip2-freeze.txt.gz | |
| 18:28:49 | jroll | so in this run, it started segfaulting at 05:49:48.642840 | |
| 18:28:56 | jroll | here is grenade.txt at that time-ish http://logs.openstack.org/36/509336/31/check/ironic-grenade-dsvm-multinode-multitenant/6da9163/logs/grenade.sh.txt.gz#_2018-01-18_05_49_47_199 | |
| 18:29:12 | jroll | gotta be one of those first few imo | |
| 18:29:35 | cdent | efried: he's a time zone before me, and usually pretty sane with regards to going home, so he's probably not around | |
| 18:30:24 | efried | cdent Swhat I figured, but it was worth a shot. Perhaps you can see it: https://review.openstack.org/#/c/533821/6/nova/scheduler/client/report.py@1399 | |