| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2018-01-22 | |||
| 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 | |
| 18:31:09 | jroll | simplejson does lots of C things: https://github.com/simplejson/simplejson/compare/v3.11.1...v3.13.2 | |
| 18:32:11 | mriedem | simplejson 3.13.2 has been in u-c for 2 months though | |
| 18:32:13 | mriedem | so it's not that | |
| 18:32:30 | mriedem | looking at things in https://github.com/openstack/requirements/commit/34d56244a87ac2a61170ab8fa81dc86dba70fc1f from 1/17 that are in that list | |
| 18:32:37 | mriedem | and which nova usess | |
| 18:33:08 | mriedem | i think that would only be babel, sphinx and cffi, and runtime code doesn't use sphinx | |
| 18:33:16 | mriedem | nor babel i don't think | |
| 18:33:20 | mriedem | so my money is on cffi | |
| 18:33:23 | jroll | right | |
| 18:33:30 | jroll | cffi isn't being upgraded at that time though | |
| 18:34:25 | cdent | efried: I think you're right | |
| 18:34:31 | efried | cdent Thanks for looking. | |
| 18:34:43 | efried | cdent I coded it all up as if I wasn't, then started writing tests... | |
| 18:34:50 | jroll | mriedem: hrm, there's also 2018-01-18 05:49:32.589 | + /opt/stack/new/grenade/projects/50_neutron/upgrade.sh:main:96 : sudo apt-get -y install python-qpid | |
| 18:35:01 | edleafe | efried: just looked, too, and I can't find any way it could be None, either | |
| 18:35:08 | efried | edleafe Thank you. | |
| 18:35:31 | sean-k-mooney | jroll: the gate runs on rabbitmq but perhaps python-qupid has a dep that upgraded something | |
| 18:35:43 | jroll | mriedem: oh, and from apt-get update about 3 minutes before crashy crashy http://logs.openstack.org/36/509336/31/check/ironic-grenade-dsvm-multinode-multitenant/6da9163/logs/grenade.sh.txt.gz#_2018-01-18_05_46_59_521 | |
| 18:35:48 | cdent | efried: I think one of the thing that makes me confused about the ProviderTree stuff is that it behaves as if it is a strong Type. Which may make sense in this context, but I struggle to get used to it; it changes some idioms. | |
| 18:36:05 | efried | cdent What do you mean by "strong Type"? | |
| 18:36:06 | jroll | nova definitely uses python-libvirt | |
| 18:36:20 | mriedem | qpid shouldn't be getting installed | |
| 18:36:25 | edleafe | cdent: you mean static type? | |
| 18:36:38 | sean-k-mooney | finding the lib that change however wont resolve the issue will it. this seams like a general class of problem. | |
| 18:36:58 | sean-k-mooney | python-libvirt is used by n-cpu but not the conductor | |