Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-05-03
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 dansmith I dunno, I thought someone did a few utf tweaks when they py3-ified it, but I dunno
16:40:26 melwitt the __repr__ returns a bytes string in PY2 to be native with the rest
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
16:49:13 sdague clarkb: it blows up on the format()
16:49:16 sdague not on the send
16:49:27 sdague that solution would be too late
16:49:43 sdague there would be an exception at L73
16:49:45 clarkb right I'm saying the syslog handler does the format in emit too
16:49:58 clarkb so the bug is also in that handler
16:51:06 sdague clarkb: ok, so the solution is?
16:52:10 clarkb I think what melwitt described, do your formatting outside of the logger (which has the downside of possibly being unnecessary depending on log level)?
16:53:13 clarkb or possibly you can manipulate locks within logging?
16:53:27 clarkb that seems fragile
16:53:40 sdague clarkb: ?? the locking issue is different
16:54:06 sdague so, if I dive down the FileHandler -> StreamHandler path
16:54:08 clarkb sdague: oh I understood it as oyu need db lock to format the instance repr and you need logging lock to use the logger
16:54:25 sdague clarkb: no you have mixed up 2 different issues
16:54:29 clarkb ah sorry
16:54:46 sdague StreamHandler does the same - msg = self.format(record)
16:55:14 abhishek melwitt: just a reminder, https://review.openstack.org/#/c/460305/
16:55:30 melwitt sdague: yeah, I'm trying to figure out what is different. does StreamHandler use the same formatter as OSJournalHandler? I don't get what is different here
16:55:40 sdague melwitt: yep
16:55:48 sdague melwitt: so these things have definitely been around before
16:56:10 sdague I went diving after one of these before
16:56:26 sdague and there are as many successes as fails on mriedem's issue
16:56:32 clarkb the format issue is purely a unicode problem?
16:56:40 sdague clarkb: that is my believe
16:56:44 sdague belief
16:56:58 melwitt sdague: oh, so something else about the change to the journal logger has just made this happen or timed in a way that we see it in gate failures now?
16:57:04 sdague I'm actually starting to think it's a red herring
16:57:27 sdague melwitt: I expect the deadlocking that was causing dansmith's bugs is actually the issue
16:58:23 melwitt sdague: yeah, I think you're right
16:58:30 sdague https://review.openstack.org/#/c/462163/2/functions will fix that
16:58:56 sdague melwitt: that being said, I still think there is a general utf8 bug in ovo repr that would be good to fix :)

Earlier   Later