| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-05-03 | |||
| 15:56:03 | mriedem | ooo this looks like a new fun gate bug http://logs.openstack.org/73/461473/3/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/a277636/logs/screen-n-cpu.txt.gz#_May_02_17_49_07_771248 | |
| 15:57:08 | jaypipes | mriedem, sdague: are we still seeing issues with the live-migration jobs? | |
| 15:57:18 | mriedem | jaypipes: no | |
| 15:57:27 | mriedem | cells v1 job is the main failure right now | |
| 15:59:12 | dansmith | FWIW, it looks like my job is going to pass without journal usage | |
| 15:59:13 | dansmith | I'm not sure that makes sense | |
| 15:59:22 | dansmith | I was hoping to just get the rest of my debug with that hack, | |
| 15:59:36 | dansmith | but I suppose it's possible that it's occasionally causing us to deadlock something | |
| 15:59:46 | dansmith | I'll recheck a few times to see if I just got uber lucky this time | |
| 16:07:50 | sdague | dansmith: ok, cool | |
| 16:08:02 | sdague | I did one more tweak on my general patch, once that's passes, I'll get that in | |
| 16:08:11 | dansmith | sdague: that "okay cool" was for the rechecking right? | |
| 16:08:16 | dansmith | I was not expecting it to actually make it pass | |
| 16:08:24 | dansmith | I was expecting it to let me see my own debug for the real failure | |
| 16:08:49 | sdague | yes, for rechecking | |
| 16:09:16 | sdague | ok, so someone that understands more about eventlet than might be needed to understand why this fails | |
| 16:11:02 | sdague | https://github.com/systemd/python-systemd/blob/c06c5d401d60ae9175367be0797a6c2b562ac5ba/systemd/journal.py#L412-L457 is the function we're calling into | |
| 16:11:54 | sdague | https://github.com/systemd/python-systemd/blob/c06c5d401d60ae9175367be0797a6c2b562ac5ba/systemd/_journal.c which I goes into native code | |
| 16:12:17 | sdague | jaypipes so presumably related to the same reason gRPC doesn't work | |
| 16:15:41 | mriedem | melwitt: ^ see in that first link to journal.py "MESSAGE must be a string and will be sent as UTF-8 to the journal." | |
| 16:16:03 | jaypipes | sdague: maybe, not sure though. the grpc vs. eventlet thing was around how grpc's generated python code doesn't play well with monkey-patched envs | |
| 16:17:01 | sdague | jaypipes: potentially similar issue? | |
| 16:17:09 | mriedem | sdague: was it intentional to enable syslog handler to put all of the service logs into syslog? because syslog is huge now, and basically unusable in a browser | |
| 16:17:26 | mriedem | http://logs.openstack.org/73/461473/3/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/a277636/logs/syslog.txt.gz | |
| 16:17:31 | jaypipes | sdague: maybe. I'm no eventlet expert though :( perhaps worth asking vstinner or dims to take a look into it. | |
| 16:17:46 | jaypipes | sdague: or perhaps one of the swift folks? | |
| 16:17:50 | sdague | mriedem: we didn't enable the syslog handler | |
| 16:17:54 | sdague | this is the journal | |
| 16:18:26 | sdague | mriedem: this is what things under systemd look like, we can trim what ends up in the extracted syslog.txt | |
| 16:18:29 | openstackgerrit | melanie witt proposed openstack/nova master: WIP Use six.text_type() when logging Instance object https://review.openstack.org/461912 | |
| 16:18:46 | mriedem | sdague: i thought this did something | |
| 16:18:47 | mriedem | https://github.com/openstack/oslo.log/commit/391635475a5877c2078856b5c3a7d2929682764a | |
| 16:18:49 | sdague | mriedem: https://github.com/openstack-infra/devstack-gate/blob/87a9ef290fa371862f30702497238fffdfdfe8fe/functions.sh#L647-L649 | |
| 16:19:06 | sdague | mriedem: nope, unrelated | |
| 16:19:36 | dansmith | sdague: don't we have a global log lock or something? | |
| 16:20:01 | dansmith | that was the reason why logging in the db api was so problematic I think | |
| 16:20:17 | dansmith | we wouldn't have deadlocks in the same way here I think, but it could still be a problem | |
| 16:20:20 | melwitt | mriedem: okay. I wrote a better commit message to explain what I was seeing in local debugging. the ContextFormatter tries to convert every message to unicode, it was failing on the Instance object, and I found to convert it properly I had to specify the encoding to six.text_type() | |
| 16:20:32 | dansmith | we can't really hold any locks while making a native call or we're going to cause problems | |
| 16:23:28 | sdague | dansmith: I didn't think we did | |
| 16:23:31 | sdague | at least not in our code | |
| 16:23:48 | dansmith | not in nova, but I thought oslo.logging did or something | |
| 16:23:57 | sdague | oslo.logging is really thin | |
| 16:24:02 | dansmith | I didn't follow that whole thing way back then | |
| 16:24:11 | sdague | I don't think there is any locking there | |
| 16:24:38 | dansmith | okay, well, the problem was that we'd do a database thing, which would grab a lock in mysql, then do a logging statement, which would grab a lock, | |
| 16:24:45 | dansmith | and if the opposite was happening elsewhere, we'd deadlock | |
| 16:25:14 | dansmith | not sure how that would have happened if it wasn't a lock in oslo.logging or python. | |
| 16:25:19 | sdague | there is nothing that looks like a lock in oslo.logging | |
| 16:25:24 | dansmith | maybe logging to a file in python does a flock on the log file? | |
| 16:25:37 | sdague | maybe, but we're not doing that here | |
| 16:25:50 | dansmith | no, I know, | |
| 16:26:03 | dansmith | I'm just trying to point to something similar that may be happening | |
| 16:26:05 | melwitt | mriedem: this is where I saw it blowing up https://github.com/openstack/oslo.log/blob/3ee14a1/oslo_log/formatters.py#L83-L93 | |
| 16:26:28 | dansmith | with making a native call that could block | |
| 16:27:17 | sdague | dansmith: yeh | |
| 16:27:50 | sdague | so this eventually turns into a C sendmsg to push things over the unix domain socket for systemd | |
| 16:28:11 | sdague | anyway, I'm going to drop the debug thread here, as I'm over my depth on what bits of eventlet would make it weird | |
| 16:29:44 | mriedem | melwitt: here https://github.com/openstack/oslo.log/blob/3ee14a1/oslo_log/formatters.py#L89 ? | |
| 16:30:28 | melwitt | mriedem: eh, I'm not sure how I saw that locally now that I think about it. it's not the same as what we see in the gate | |
| 16:31:02 | sdague | melwitt: in the gate isn't it that we're sending it an Instance Object | |
| 16:31:14 | sdague | it's implicitly turning it into a string with __repr__ | |
| 16:31:23 | sdague | and that is the thing that might be encoded weird? | |
| 16:31:45 | sdague | melwitt: at least, your work around seemed to imply that | |
| 16:31:52 | clarkb | the journald write is blocking I think | |
| 16:31:55 | melwitt | sdague: yeah. and then at the log message format() step it blows up but I don't know exactly how | |
| 16:31:59 | clarkb | but I don't know that it will hold a lock | |
| 16:32:17 | sdague | clarkb: I don't know, the man pages say it's thread safe | |
| 16:32:31 | sdague | which could mean locks in there | |
| 16:32:44 | sdague | it also keeps monotonic time (or can) which makes me wonder | |
| 16:32:46 | dansmith | or locks in journald that cause that call to block | |
| 16:32:53 | dansmith | even if not locks in the sending code | |
| 16:32:54 | sdague | but, it's a whole research bit on it's own | |
| 16:34:02 | clarkb | dansmith: well that call can block regardless of locks | |
| 16:34:11 | clarkb | because its a synchronous write | |
| 16:34:38 | dansmith | yeah | |
| 16:34:45 | melwitt | mriedem, sdague: in the gate it blows up here https://github.com/python/cpython/blob/master/Lib/logging/__init__.py#L338 | |
| 16:35:47 | sdague | melwitt: right | |
| 16:36:14 | sdague | but one of those args is an Instance | |
| 16:36:16 | sdague | object | |
| 16:38:14 | sdague | dansmith: are there utf8 tests in oslo.versionedobjects for object stringification? | |
| 16:38:42 | melwitt | sdague: yeah. and like you said it gets turned into a str by __repr__ but there are unicode chars in it | |
| 16:39:05 | sdague | clarkb / dansmith - anyway on the journal issue, I think the near term is to shut that bit off | |
| 16:39:12 | dansmith | sdague: you mean for the repr? | |
| 16:39:17 | sdague | dansmith: yeh | |
| 16:39:37 | sdague | or just in general, I'm not seeing any grepping around | |
| 16:39:45 | dansmith | sdague: is the problem really repr'ing the instance in the log call? I thought we just grab the uuid out of the instance when we do LOG.foo(..., instance=instance) ? | |
| 16:39:57 | mriedem | dansmith: no, | |
| 16:40:00 | mriedem | this is a full dump of the instance | |
| 16:40:02 | mriedem | and all of it's fields | |
| 16:40:05 | dansmith | ah | |
| 16:40:07 | sdague | right | |
| 16:40:08 | mriedem | and the display_name in one test is unicode | |
| 16:40:17 | sdague | which is when it all blows up | |
| 16:40:25 | mriedem | not using the instance=instance kwarg | |
| 16:40:26 | melwitt | the __repr__ returns a bytes string in PY2 to be native with the rest | |
| 16:40:26 | dansmith | I dunno, I thought someone did a few utf tweaks when they py3-ified it, but I dunno | |
| 16:41:50 | melwitt | and converting it to unicode before logging it makes it work. it's just I had to repr(instance) and then six.text_type(instance_repr, 'utf-8') | |
| 16:47:01 | clarkb | this would be a general issue for things like https://git.openstack.org/cgit/openstack/oslo.log/tree/oslo_log/handlers.py#n56 too right? | |
| 16:47:12 | clarkb | eg its not specific to the journald handler we juts happen to be using it in testing so catch it | |