| *** njohnston has quit IRC | 00:02 | |
| *** njohnston has joined #openstack-oslo | 00:03 | |
| *** threestrands has joined #openstack-oslo | 00:10 | |
| *** threestrands has quit IRC | 03:30 | |
| *** threestrands has joined #openstack-oslo | 03:30 | |
| *** threestrands has quit IRC | 03:31 | |
| *** jaosorior has quit IRC | 04:05 | |
| *** jaosorior has joined #openstack-oslo | 05:04 | |
| *** Luzi has joined #openstack-oslo | 05:05 | |
| *** raildo has quit IRC | 05:11 | |
| *** raildo has joined #openstack-oslo | 05:12 | |
| *** d34dh0r53 has quit IRC | 05:25 | |
| *** shachar has quit IRC | 06:05 | |
| *** shachar has joined #openstack-oslo | 06:05 | |
| *** d34dh0r53 has joined #openstack-oslo | 06:17 | |
| *** jaosorior has quit IRC | 07:01 | |
| *** rcernin has quit IRC | 07:02 | |
| *** hberaud|gone is now known as hberaud | 07:06 | |
| *** tesseract has joined #openstack-oslo | 07:11 | |
| *** tosky has joined #openstack-oslo | 07:24 | |
| *** ralonsoh has joined #openstack-oslo | 07:58 | |
| *** lpetrut has joined #openstack-oslo | 08:18 | |
| *** purplerbot has quit IRC | 08:22 | |
| *** purplerbot has joined #openstack-oslo | 08:22 | |
| *** e0ne has joined #openstack-oslo | 08:45 | |
| *** jaosorior has joined #openstack-oslo | 08:45 | |
| openstackgerrit | pengyuesheng proposed openstack/oslo.config master: Blacklist sphinx 2.1.0 (autodoc bug) https://review.opendev.org/669234 | 08:53 |
|---|---|---|
| *** hberaud is now known as hberaud|lunch | 09:47 | |
| *** dansmith has quit IRC | 09:52 | |
| *** dansmith has joined #openstack-oslo | 09:58 | |
| *** hberaud|lunch is now known as hberaud | 11:08 | |
| *** boden has joined #openstack-oslo | 11:47 | |
| *** ansmith has quit IRC | 11:47 | |
| *** njohnston has quit IRC | 11:56 | |
| *** njohnston has joined #openstack-oslo | 12:05 | |
| *** jaosorior has quit IRC | 12:07 | |
| *** hberaud has quit IRC | 12:29 | |
| *** hberaud has joined #openstack-oslo | 12:33 | |
| *** ansmith has joined #openstack-oslo | 12:40 | |
| *** kgiusti has joined #openstack-oslo | 12:42 | |
| *** jaosorior has joined #openstack-oslo | 12:54 | |
| *** iurygregory has quit IRC | 13:02 | |
| openstackgerrit | Sandeep Yadav proposed openstack/oslo.messaging master: Correcting typo in acknowledge spelling https://review.opendev.org/673514 | 13:16 |
| *** goldyfruit has joined #openstack-oslo | 13:24 | |
| *** iurygregory has joined #openstack-oslo | 13:29 | |
| *** Luzi has quit IRC | 13:55 | |
| *** e0ne has quit IRC | 14:04 | |
| *** e0ne has joined #openstack-oslo | 14:33 | |
| *** bobh has joined #openstack-oslo | 14:36 | |
| *** e0ne has quit IRC | 14:54 | |
| *** takamatsu has joined #openstack-oslo | 14:54 | |
| *** e0ne has joined #openstack-oslo | 15:04 | |
| *** e0ne has quit IRC | 15:59 | |
| *** lpetrut has quit IRC | 16:11 | |
| *** trident has quit IRC | 16:32 | |
| *** trident has joined #openstack-oslo | 16:37 | |
| *** goldyfruit has quit IRC | 16:53 | |
| *** hberaud is now known as hberaud|gone | 17:07 | |
| *** ralonsoh has quit IRC | 17:23 | |
| *** tesseract has quit IRC | 17:34 | |
| openstackgerrit | Merged openstack/oslo.messaging master: Correcting typo in acknowledge spelling https://review.opendev.org/673514 | 17:37 |
| *** tosky has quit IRC | 17:43 | |
| efried | dhellmann: you know oslo.log, don'tcha? | 17:49 |
| dhellmann | efried : some, what's up? | 17:57 |
| efried | dhellmann: http://lists.openstack.org/pipermail/openstack-discuss/2019-July/008059.html | 17:58 |
| efried | TL;DR global_request_id isn't showing up in logs and I don't know why | 17:58 |
| efried | basically I want to understand where oslo.log looks for the %(global_request_id)s part of my configured format string | 17:58 |
| dhellmann | oslo.log is basically for configuring the stdlib logging module and oslo.context together | 17:59 |
| dhellmann | is there a context, and does it have the request id? | 17:59 |
| efried | In nova, a given request gets a context, yeah. And it has a global_id. But we're certainly not passing that context into any LOG.* calls. And if not that, then I'm not sure how oslo.log is supposed to be getting at it. | 18:00 |
| dhellmann | the context is stored in a thread local inside oslo.context | 18:00 |
| efried | oo. who does that? | 18:01 |
| dhellmann | https://opendev.org/openstack/oslo.context/src/branch/master/oslo_context/context.py#L276 | 18:01 |
| dhellmann | unless you tell it otherwise, the library does that every time you make a new context | 18:01 |
| dhellmann | oh, I guess unless there is already one there | 18:01 |
| efried | neat, /me looks at nova's RequestContext subclass... | 18:01 |
| dhellmann | I see where the context is added to the record for json and fluentd, but not standard text | 18:06 |
| dhellmann | oh, duh: https://opendev.org/openstack/oslo.log/src/branch/master/oslo_log/formatters.py#L428 | 18:06 |
| efried | dhellmann: Okay, so if my override [1] doesn't say otherwise, when I ask for context.global_id, I actually get the request_id (which may or may not have been generated, but is for sure there) | 18:06 |
| efried | [1] https://opendev.org/openstack/nova/src/branch/master/nova/context.py#L81 | 18:06 |
| efried | is oslo.log using context.global_request_id (the field) or context.global_id (the @property) in the format? | 18:08 |
| efried | I'm guessing the former, and I'm guessing that's the disconnect. | 18:08 |
| dhellmann | global_id is a dynamic property of the context https://opendev.org/openstack/oslo.context/src/branch/master/oslo_context/context.py#L378 | 18:08 |
| dhellmann | the format string for context-aware log messages is https://opendev.org/openstack/oslo.log/src/branch/master/oslo_log/_options.py#L147 | 18:09 |
| dhellmann | it has request_id | 18:09 |
| dhellmann | which comes from the to_dict() method https://opendev.org/openstack/oslo.context/src/branch/master/oslo_context/context.py#L353 | 18:09 |
| dhellmann | which nova extends https://opendev.org/openstack/nova/src/branch/master/nova/context.py#L165 | 18:10 |
| efried | yeah, but in this case I'm overriding that and including global_request_id (this is devstack standard) | 18:10 |
| dhellmann | including to set request_id https://opendev.org/openstack/nova/src/branch/master/nova/context.py#L177 | 18:10 |
| efried | okay, so the bug here is that to_dict isn't supplying global_request_id! | 18:10 |
| efried | (nova's to_dict override, that is) | 18:10 |
| dhellmann | it should be | 18:10 |
| dhellmann | the base sets it https://opendev.org/openstack/oslo.context/src/branch/master/oslo_context/context.py#L354 | 18:10 |
| efried | agree | 18:10 |
| efried | there's a weird note in there from dansmith | 18:11 |
| dhellmann | I don't see nova deleting it | 18:11 |
| efried | sorry, dims | 18:11 |
| efried | dhellmann: No, nova isn't deleting it - it's overriding to_dict entirely, not calling super() etc. | 18:11 |
| dhellmann | what is the devstack standard you're talking about? overriding the format string? | 18:11 |
| efried | oh | 18:12 |
| dhellmann | nova does call super() line 165 | 18:12 |
| efried | it is calling super | 18:12 |
| efried | hmph | 18:12 |
| efried | http://logs.openstack.org/86/672986/1/check/nova-live-migration/e426c8a/logs/etc/nova/nova-cpu.conf.txt.gz | 18:12 |
| dhellmann | ah | 18:12 |
| efried | logging_context_format_string = %(color)s%(levelname)s %(name)s [[01;36m%(global_request_id)s %(request_id)s [00;36m%(project_name)s %(user_name)s%(color)s] [01;35m%(instance)s%(color)s%(message)s[00m | 18:12 |
| efried | but http://logs.openstack.org/86/672986/1/check/nova-live-migration/e426c8a/logs/screen-n-cpu.txt.gz#_Jul_26_14_57_18_460328 | 18:12 |
| dhellmann | which nova process is this? | 18:13 |
| efried | compute | 18:14 |
| efried | n-cpu | 18:14 |
| dhellmann | so there's no web request, and we're relying on the context to be passed in by oslo.messaging | 18:14 |
| dhellmann | is that bit working? I wonder if we're not (de)serializing that properly? | 18:15 |
| efried | oslo.messaging, oh, because this is at the behest of an RPC call from the API? | 18:15 |
| dhellmann | is the nova rpc receive setting the context? I can't remember if that happens in the RPC layer or the application layer | 18:15 |
| dhellmann | yeah | 18:15 |
| efried | ... | 18:16 |
| dhellmann | bnemec-pto or kgiusti are more familiar with the messaging layer, but you could just test it by dumping the context in an rpc call | 18:16 |
| dhellmann | I do see functions like "unpack_context" in the oslo.messaging code | 18:17 |
| dhellmann | is this working properly for other services with a separate rpc backend like cinder? | 18:17 |
| efried | dunno | 18:17 |
| efried | I can barely spell RPC | 18:17 |
| dhellmann | you're working on a bug. how do you know nova is working differently from anything else? | 18:18 |
| dhellmann | do you see the request ids in the logs of the other services? | 18:18 |
| efried | "working on a bug" is probably giving more credit than due | 18:19 |
| efried | Looking at cinder logs for same patch... | 18:20 |
| efried | would the equivalent be c-vol? | 18:20 |
| dhellmann | probably? | 18:20 |
| efried | same thing appears to be the case there http://logs.openstack.org/86/672986/1/check/nova-live-migration/e426c8a/logs/screen-c-vol.txt.gz | 18:20 |
| dhellmann | ok, so none of the services are working | 18:21 |
| efried | and I'm assuming that guy's conf is http://logs.openstack.org/86/672986/1/check/nova-live-migration/e426c8a/logs/etc/cinder/cinder.conf.txt.gz which has the same placeholder | 18:21 |
| dhellmann | the first thing I would do is try changing the devstack format string to use the name the default in oslo.log uses | 18:21 |
| dhellmann | maybe the library and devstack got out of sync somewhere | 18:21 |
| efried | but the default doesn't have global_request_id in it. | 18:22 |
| efried | and request_id is showing up | 18:22 |
| dhellmann | ah, right | 18:22 |
| dhellmann | and I guess if you change global_request_id to global_id that's just going to log the request_id again | 18:23 |
| dhellmann | it looks like global_request_id is supposed to come from a header https://opendev.org/openstack/oslo.context/src/branch/master/oslo_context/context.py#L62 | 18:23 |
| efried | I reckon it will, yah. | 18:23 |
| dhellmann | does it show up properly in the nova api logs? | 18:23 |
| dhellmann | is the client setting it at all? | 18:24 |
| efried | n-api doesn't have it either: http://logs.openstack.org/86/672986/1/check/nova-live-migration/e426c8a/logs/screen-n-api.txt.gz#_Jul_26_14_57_37_862552 | 18:24 |
| dhellmann | ok, that's telling | 18:24 |
| dhellmann | what do we expect is setting that value? | 18:24 |
| efried | nor does superconductor http://logs.openstack.org/86/672986/1/check/nova-live-migration/e426c8a/logs/screen-n-super-cond.txt.gz | 18:25 |
| efried | I guess based on your explanation above I would have expected it to be set by... wsgi? | 18:25 |
| dhellmann | IIRC, that value is the request id from the originating request and should be set when one service calls another to tie the related service calls together | 18:26 |
| dhellmann | that's how I see it being used in the first few projects that show up in http://codesearch.openstack.org/?q=global_request_id&i=nope&files=&repos= | 18:26 |
| dhellmann | it looks like keystoneauth sets it if it is given a value | 18:27 |
| efried | yes, when we're going across the wire it's supposed to be in the x-openstack-request-id header | 18:27 |
| dhellmann | right | 18:27 |
| efried | Thing is, I know it's in the context being used for that placement call I showed you first | 18:27 |
| efried | because I dumped it | 18:27 |
| efried | and it shows up on the other side of the wire (placement) | 18:28 |
| dhellmann | so why do we think it should be set in this particular case? if OSC talks to nova directly, I wouldn't expect to see it set until nova talks to some other service. | 18:28 |
| efried | it's just... not going into the log | 18:28 |
| dhellmann | ok, so it *is* set? | 18:28 |
| efried | so yeah, good point | 18:28 |
| smcginnis | Not sure if this helps at all - https://review.opendev.org/#/c/472224/ | 18:28 |
| dhellmann | yeah, that's helpful | 18:29 |
| dhellmann | those are good examples of what I was saying before, about how services are supposed to pass this to each other | 18:29 |
| efried | right here is a call from n-cpu to placement http://logs.openstack.org/86/672986/1/check/nova-live-migration/e426c8a/logs/screen-n-cpu.txt.gz#_Jul_26_14_57_18_460328 | 18:29 |
| efried | if you look down a few lines you can see where I dumped the context.global_id | 18:29 |
| efried | so it *is* set in the context. But it's not ending up in the log. | 18:30 |
| efried | could we be using a different context?? | 18:30 |
| dhellmann | that makes me wonder if the context object you were dumping it from is the same one the logging code sees | 18:30 |
| dhellmann | right | 18:30 |
| efried | actually | 18:30 |
| dhellmann | the logging code looks at that thread-local global value | 18:30 |
| dhellmann | where did you get the context you used? | 18:30 |
| * efried backtraces... | 18:32 | |
| efried | nova.context.get_admin_context() | 18:33 |
| *** harlowja has quit IRC | 18:33 | |
| efried | oh | 18:33 |
| dhellmann | that doesn't seem likely to be the same as the original request context | 18:34 |
| efried | actually | 18:34 |
| efried | this call is coming from service start | 18:34 |
| efried | so not a request at all | 18:34 |
| efried | but it's still *making* requests. | 18:34 |
| efried | so it should probably set a global ID. | 18:34 |
| dhellmann | maybe? I'm not sure | 18:37 |
| efried | dhellmann: Okay, I've got some stuff I can play with at this point. Thanks a bunch for the help. | 18:39 |
| dhellmann | sure thing! | 18:40 |
| efried | smcginnis: thanks for that pointer. The service-to-service part is working. I'm trying to figure out why it's not showing up in the log. | 18:40 |
| *** kgiusti has left #openstack-oslo | 18:43 | |
| *** bobh has quit IRC | 18:56 | |
| *** boden has quit IRC | 19:05 | |
| *** boden has joined #openstack-oslo | 19:09 | |
| *** bobh has joined #openstack-oslo | 19:36 | |
| *** bobh has quit IRC | 19:42 | |
| *** boden has quit IRC | 20:15 | |
| *** e0ne has joined #openstack-oslo | 20:16 | |
| *** e0ne has quit IRC | 20:41 | |
| *** bobh has joined #openstack-oslo | 20:42 | |
| *** e0ne has joined #openstack-oslo | 20:42 | |
| *** ansmith has quit IRC | 20:44 | |
| *** zbitter is now known as zaneb | 20:44 | |
| *** bobh has quit IRC | 20:48 | |
| *** bobh has joined #openstack-oslo | 21:05 | |
| *** bobh has quit IRC | 21:05 | |
| *** e0ne has quit IRC | 21:16 | |
| *** njohnston has quit IRC | 21:52 | |
| *** njohnston has joined #openstack-oslo | 21:54 | |
| *** bobh has joined #openstack-oslo | 21:59 | |
| *** raildo has quit IRC | 22:02 | |
| *** ansmith has joined #openstack-oslo | 22:27 | |
| *** bobh has joined #openstack-oslo | 22:54 | |
| *** rcernin has joined #openstack-oslo | 23:01 | |
Generated by irclog2html.py 2.15.3 by Marius Gedminas - find it at mg.pov.lt!