Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2019-05-15
16:57:31 dansmith okay we should not be logging a trace for a check thing, amirite?
16:58:04 melwitt should not, no. I see a LOG.info for it but no re-raise, so not yet sure what's going on
16:58:26 dansmith that's why I'm wondering if we're actually leaking the exception out and not just skipping
16:58:58 melwitt yeah, let's see, the trace is happening in the driver, so that must be where
16:59:08 melwitt there's no re-raise in compute/api, I meant
17:06:41 cdent efried: is ocata nova still an active concern? there's a logging buglet in the reasource tracker + report client that can be pretty misleading but the issue goes away with pike (or maybe queens)
17:09:19 cdent (goes away with pike, just checked)
17:16:29 melwitt weshay: on your latest comment on LP, the log shows the code continuing on to do the volume snapshot http://logs.openstack.org/84/655684/2/check/tripleo-ci-fedora-28-standalone/eda3002/logs/undercloud/var/log/containers/nova/nova-api.log.txt.gz#_2019-05-13_16_03_50_120 so I think that trace is unrelated
17:17:03 melwitt weshay: I don't yet find how that trace is getting logged (it shouldn't be logged), so I'm still looking for how that's happening
17:17:34 weshay k k.. thanks.. so melwitt we're saying it's a red herring and the problem is elsewhere right?
17:17:43 weshay confirming that I guess
17:18:47 melwitt weshay: right. the logging of the trace is bad and I'll have to find how that's occurring to remove it, but AFAICS the code is continuing on after skipping the quiesce and shouldn't affect the pass/fail of the CI
17:19:23 melwitt "Creating snapshot from volume"
17:19:59 weshay k
17:20:04 weshay arxcruz ^
17:20:15 melwitt I'll look at the rest of those logs to see if I can tell where it's failing
17:22:20 melwitt weshay: looking at the test results of that run, the test_volume_boot_pattern passed but test_network_basic_ops failed due to a ssh timeout http://logs.openstack.org/84/655684/2/check/tripleo-ci-fedora-28-standalone/eda3002/logs/tempest.html.gz
17:22:56 weshay aye
17:23:24 weshay ya.. probably not same thing
17:23:36 weshay paste happy
17:23:39 weshay I guess
17:24:11 melwitt definitely not in this particular run. that run ^ failed because of a ssh timeout and test_volume_boot_pattern passed with the log trace
17:24:39 tssurya mriedem: trivial doc change: https://review.opendev.org/#/c/659067/
17:32:28 openstackgerrit Merged openstack/os-resource-classes master: Replace git.openstack.org URLs with opendev.org URLs https://review.opendev.org/658519
17:47:45 mriedem cdent: ocata is in extended maintenance meaning we can fix things if we want, but if it's not a big deal then meh
17:50:05 mriedem i thought VIO was off ocata (and pike for that matter)?
17:51:28 cdent there are lots of supported customers back on ocata, and a few that are -2 or -4 releases from that....
17:51:57 mriedem just tell those banks to upgrade
17:52:30 mriedem do you know if there was a specific fix in pike that fixes it? or was it some big refactor we wouldn't want to backport?
17:52:36 mriedem if it's something dumb easy and backports cleanly than whatever
17:53:17 cdent there was a refactor: the introduction of _ensure_resource_provider
17:53:47 mriedem well then that's probably not something we'll want to backport to ocata at this point
17:53:53 cdent quite
18:16:51 openstackgerrit Merged openstack/nova master: [Trivial doc change] Admin can overwrite the locked_reason of an owner https://review.opendev.org/659067
19:08:52 melwitt mriedem: wondering if you might know anything about this... is it known or expected that the traceback will become part of the printed exception object when that exception occurred on the other side of an rpc call? example http://logs.openstack.org/72/650172/14/check/tempest-full-py3/61914af/controller/logs/screen-n-api.txt.gz#_May_08_08_52_36_106235
19:09:41 melwitt in nova/compute/api.py, we're catching the exception and logging the exception object, which I thought should normally only contain the short message and not the traceback. but the traceback seems to also be part of that
19:10:48 melwitt I looked at exception_wrapper (from our @wrap_exception decorator) and expected_exceptions in oslo.messaging and didn't see how they could be adding the traceback. I wanted to ask you in case you've seen this before and already know what's going on
19:18:06 mriedem i want to say it's a thing in oslo.log if there is an exception in scope
19:19:00 mriedem which is what this is, it's logging the exception within an except block
19:19:45 melwitt hm, I think I found where it's added in oslo.messaging https://github.com/openstack/oslo.messaging/blob/40c25c2bde6d2f5a756e7169060b7ce389caf174/oslo_messaging/_drivers/common.py#L212
19:20:08 mriedem remember this? https://github.com/openstack/oslo.log/commit/a63438cb5b12e2a6973fb0e1b0b9ebce2f8116b6#diff-e121e929b5792521de104c2db0d14d94
19:20:17 mriedem oh, so,
19:20:21 melwitt if I'm understanding this code right, when oslo.messaging deserializes an exception, it tacks on the traceback to the normal message
19:20:26 mriedem if it's an rpc call, which this is, we need to use expected_exceptions on the compute manager method
19:20:28 mriedem are we doing that?
19:20:31 melwitt we are
19:21:01 melwitt https://github.com/openstack/nova/blob/master/nova/compute/manager.py#L8513
19:21:46 melwitt oh hah, I forgot about that commit. reading..
19:22:25 mriedem so my guess is it's related to that magic stuff oslo.log does when you're logging from within an except block
19:22:30 mriedem even if you're not passing exc_info=True
19:25:08 melwitt thanks, this gives me more to look into
19:25:14 mriedem https://github.com/openstack/oslo.log/blob/master/oslo_log/formatters.py#L120 should handle that i'd think, but idk
19:25:28 mriedem light up the doug signal
19:30:41 melwitt yeah... I don't think this has to do with the error summary (I'm having trouble remembering what that is, even with seeing the old commit). but rather that if we catch a remote exception, the 'message' attribute of the object is going to contain the traceback, so if we don't want to log a traceback, we can't be doing "LOG.info('stuff %s', exp)"
19:31:05 melwitt this log line is explicitly doing that
19:39:38 efried cdent: pike just went em, so I'm not sure how much attention we are (or should be) paying to ocata at this point. Probably only security vulnerabilities, kind of thing.
20:45:49 mriedem i'm still fixing shit back in pike so yeah it's still active-ish
20:46:40 dansmith is it easier to land things in pike than master?
20:46:48 dansmith because based on master these days, I'm guessing so
20:47:48 artom What's the company cores policy on stable stuff?
20:48:09 artom So for instance, would Mel be allowed to +W https://review.opendev.org/#/c/657125/ ?
21:04:16 openstackgerrit melanie witt proposed openstack/nova master: Stop logging traceback when skipping quiesce https://review.opendev.org/659374
21:12:14 melwitt mriedem: now I know what format_message() is for ^ and also I found this, from 6 years ago https://github.com/openstack/nova/commit/86031940b313532606449c400bca64707be1797a
21:16:27 mriedem oh geez
21:16:34 melwitt yeah xD
21:16:47 mriedem if we should always be using format_message(), shouldn't we override __str__ or __repr__ or something for NovaExceptions?
21:17:50 melwitt I _think_ that the exception type for remote exceptions is actually generated dynamically by oslo.messaging,
21:18:15 melwitt *_Remote exceptions, and it overrides __str__ and __unicode__ to have the traceback in it
21:19:30 mriedem if it's not a NovaException then we can't call format_message on it can we?
21:19:57 melwitt yeah, maybe it's that NovaException is the base class it uses
21:20:29 mriedem er i guess you're talking about this https://github.com/openstack/oslo.messaging/blob/40c25c2/oslo_messaging/_drivers/common.py#L247
21:20:53 melwitt yes
21:21:05 mriedem f what a mess
21:21:15 melwitt but you're right that it must be deriving somehow from NovaException else format_message wouldn't work
21:21:18 mriedem so NovaException override __str__ won't work b/c we aren't using a NovaException?
21:21:34 mriedem python black magic
21:22:05 melwitt I think probably not, based on this https://github.com/openstack/oslo.messaging/blob/40c25c2/oslo_messaging/_drivers/common.py#L244
21:23:04 melwitt I was also looking at these tests which seem to know all about this issue :P https://github.com/openstack/nova/blob/master/nova/tests/unit/test_exception.py#L203
21:23:53 melwitt FakeNovaException_Remote is presumably simulating what oslo.messaging does
21:25:10 melwitt I'm not seeing though in oslo.messaging code how it's subclassing the original exception type though
21:25:53 mriedem i think that's https://github.com/openstack/oslo.messaging/blob/40c25c2/oslo_messaging/_drivers/common.py#L243
21:26:09 mriedem https://docs.python.org/3.6/library/functions.html#type
21:26:14 melwitt oh, I see yeah
21:26:20 mriedem the first arg is the new type _Remote, 2nd is the parent class which is the NovaException
21:26:23 melwitt the second argument is the base classes
21:26:25 mriedem black
21:26:25 mriedem python
21:26:26 mriedem magic
21:26:28 melwitt right
21:26:38 melwitt yeah, so that's fun
21:28:05 mriedem NotImplementedError doesn't have format_message()...
21:28:12 mriedem i know what we can do!
21:28:18 mriedem monkey patch oslo.messaging,
21:28:23 mriedem extend their dynamic type,
21:28:29 mriedem and override with our own __str__ that does format_message!
21:28:40 melwitt brilliant!
21:28:41 mriedem and somehow do it with eventlet
21:31:05 openstackgerrit Hamdy Khader proposed openstack/nova master: [WIP] OVS DPDK port representors support https://review.opendev.org/658785
21:50:17 openstackgerrit melanie witt proposed openstack/nova master: Stop logging traceback when skipping quiesce https://review.opendev.org/659374
21:53:55 melwitt mriedem: just did a fugly update ^ better ideas welcome

Earlier   Later