20:01:53 <Rockyg> #startmeeting log_wg
20:01:53 <openstack> Meeting started Wed Jul  1 20:01:53 2015 UTC and is due to finish in 60 minutes.  The chair is Rockyg. Information about MeetBot at http://wiki.debian.org/MeetBot.
20:01:55 <openstack> Useful Commands: #action #agreed #help #info #idea #link #topic #startvote.
20:01:58 <openstack> The meeting name has been set to 'log_wg'
20:02:27 <Rockyg> pings:  jokke_, bknudson
20:02:41 <Rockyg> and who am I forgetting?  Gotta build a list.
20:03:15 <bknudson> hi
20:03:58 <Rockyg> hey there!
20:04:16 <Rockyg> So, the new meeting stuff is very non-dev unfriendly.
20:04:32 <bknudson> new meeting stuff?
20:04:53 <dhellmann> ?
20:05:10 <Rockyg> Yeah.  On the ML, there was discussion on app agnostic log parameters.
20:05:37 <Rockyg> Wasn't aware of the BP, but something we should track/comment/provide resources if possible?
20:05:41 <dhellmann> #link http://lists.openstack.org/pipermail/openstack-dev/2015-June/067970.html
20:05:49 <dhellmann> #link https://blueprints.launchpad.net/oslo.log/+spec/app-agnostic-logging-parameters
20:05:49 <Rockyg> Thanks dhellmann!
20:06:23 <Rockyg> #topic app agnostic logging
20:06:42 <bknudson> log file formats always seem to be a pain
20:06:51 <bknudson> probably just a bad design
20:07:11 <dhellmann> this spec is somewhat related, as well: https://review.openstack.org/196752
20:07:49 <Rockyg> #link https://review.openstack.org/196752
20:08:09 <dhellmann> I haven't started work on any of those, yet, but do expect to "soon" when I make a little progress on the release and python 3 work I have on my backlog.
20:08:38 <Rockyg> any way we can help?
20:09:23 <dhellmann> it would be useful to know which projects are not already using the oslo.context and oslo.log libraries
20:09:41 <Rockyg> I can likely get that info.
20:09:56 <Rockyg> other than swift, of course ;-)
20:10:03 <bknudson> keystone isn't using oslo.context
20:10:12 <dhellmann> we can use https://etherpad.openstack.org/p/liberty-app-agnostic-logging-parameters for notes
20:10:44 <Rockyg> #action document which projects using 1) oslo.log libraries 2) oslo.context
20:11:37 <Rockyg> Another question I have wrt: does the mistral approach seem reasonable?
20:11:48 <dhellmann> what is their approach?
20:12:56 <Rockyg> #link https://blueprints.launchpad.net/mistral/+spec/mistral-log-enhancement
20:13:33 <Rockyg> posted in ML yesterday.  I guess it should have also had [log] in the title
20:14:28 <Rockyg> spec #link https://review.openstack.org/#/c/173700/
20:14:54 <Rockyg> Sorry.  Wrong link.
20:15:02 <Rockyg> lemme find the email link.
20:15:15 <dhellmann> I haven't read the whole patch on that blueprint, but the first few changes look right
20:15:28 <bknudson> looks like they were still using log from oslo-incubator
20:15:33 <dhellmann> yeah
20:16:10 <bknudson> makes you wonder how far behind they are in switch to oslo libs
20:16:27 <dhellmann> my guess is pretty far
20:16:35 <Rockyg> #link http://lists.openstack.org/pipermail/openstack-dev/2015-June/068314.html
20:16:56 <bknudson> http://git.openstack.org/cgit/openstack/mistral/tree/mistral -- maybe not
20:17:00 <bknudson> I don't see any openstack in there
20:17:07 <Rockyg> I can find out.  The dev working this stuff works for Huawei and I've actually got a connection
20:17:32 <dhellmann> oh, I think someone working on this asked me about it on irc a few days ago
20:18:00 <dhellmann> they were looking for a way to include more information in the logging context by default, like the task ids they have in mistral
20:18:14 <Rockyg> Yeah.  They just added a new core.  Seems activity is picking up.
20:18:22 <Rockyg> dhellmann: exactly.
20:18:42 <Rockyg> That's the plan laid out in the above email
20:19:07 <dhellmann> oh, no, that was email: http://lists.openstack.org/pipermail/openstack-dev/2015-June/068089.html
20:19:21 <Rockyg> Oh.  oops.
20:19:49 * dhellmann has too many digital interactions to remember the medium any more
20:19:53 <Rockyg> Oh, right.  The email I posted was the proposal based on your responses.
20:20:03 <dhellmann> yeah, it was all running together in my head
20:20:10 <Rockyg> It's written like a spec.  Take a look.
20:20:39 <Rockyg> dhellmann: just consider me your secretary wrt logging ;-)
20:21:49 <dhellmann> I'll have to find that email and reply. I'm not sure overloading resource like that is the right approach, but I don't know what mistral has as an addressable resource
20:22:00 <bknudson> do we just set extra=context?
20:22:08 <Rockyg> http://lists.openstack.org/pipermail/openstack-dev/2015-June/068314.html
20:22:35 <dhellmann> bknudson: the keyword adapter in oslo.log pulls any extra keyword args and adds them to extras, so either form works
20:23:13 <Rockyg> sorry.  wrong link again.  try : http://lists.openstack.org/pipermail/openstack-dev/2015-June/068314.html
20:24:31 <dhellmann> Rockyg: I'll find that message in my email client and reply later today or early tomorrow
20:24:51 <bknudson> found it http://git.openstack.org/cgit/openstack/oslo.log/tree/oslo_log/log.py#n105
20:24:51 <Rockyg> Cool.  Thanks.  that will give me the info I need.
20:24:59 <Rockyg> ready for next topic?
20:25:20 <dhellmann> ++
20:25:22 <Rockyg> #topic requestID
20:25:35 <Rockyg> It's been getting lots of play in xproject.
20:26:06 <Rockyg> #link https://review.openstack.org/#/c/156508/
20:26:50 <Rockyg> talks about using tuples, modifying all clients then all projects.  Hmmm.
20:27:23 <Rockyg> Will it work?
20:27:38 <dhellmann> they've dropped that approach, and I think the new version is workable
20:27:48 <dhellmann> there are some details to work out, as bknudson points out in the review
20:27:49 <bknudson> I doubt it will work in all cases
20:27:53 <Rockyg> I'm worried about the same thing the ops guys are worried about:  too many UUIDs and the log messages get too long.
20:28:06 <bknudson> in the simplest case looks like it'll be adequate
20:28:11 <Rockyg> dhellmann: oh, good.
20:28:34 <Rockyg> Simple case is a good start if it doesn't make the hard case impossible
20:28:35 <bknudson> all the new version does is make the request ID available
20:28:46 <bknudson> it doesn't cover actually logging the value
20:28:56 <dhellmann> right, that was part 1
20:28:59 <Rockyg> bknudson: kewl!
20:30:28 <Rockyg> I was catching up on all the comments and missed that the logging part was out.
20:31:21 <Rockyg> I think for logging, it could be done with 3 UUIDs: originating, last referring, current
20:32:00 <Rockyg> Linked list kinda, with originating being the "reference" id
20:32:00 <bknudson> what are we logging/
20:32:01 <bknudson> ?
20:32:08 <Rockyg> request IDs
20:32:23 <dhellmann> this is why I want to see what the osprofiler folks have, because they've figured out how to build the call tree properly so it seems there's no need to redo that work
20:32:29 <bknudson> so when the request is complete log the request IDs?
20:33:04 <bknudson> or when the request is made?
20:33:10 <Rockyg> As long as it gets pulled out of the profiler and put into an oslo library or some such.  Ops are unlikely to install the profiler on prod
20:33:18 <bknudson> or is it when the request comes in?
20:33:27 <dhellmann> Rockyg: yeah, don't obsess over where that lives. The point is to look at their implementation.
20:33:34 <Rockyg> Yah.
20:34:14 <Rockyg> bknudson: first action taken to complete the "task" would have get the originating RId
20:34:47 <Rockyg> Then each handoff to another project/module gets one (depends on how the project implements internally)
20:35:19 <Rockyg> So, the hand-off passes the original RId and the previous step's RId
20:36:54 <Rockyg> I would think the first RId would be created when the call is moved to actionable code/put on a waiting queue.  It needs to be associated with the call.
20:36:56 <bknudson> what's correlation ID? http://git.openstack.org/cgit/openstack/oslo.middleware/tree/oslo_middleware/correlation_id.py
20:37:31 <Rockyg> I think that's the RIDs for notivications.
20:37:43 <Rockyg> But, dhellmann is the expert.
20:37:54 <dhellmann> gordc is the middleware expert, I don't know what that is
20:38:40 <Rockyg> OK.  ready for my next topic/question?
20:39:09 <bknudson> http://git.openstack.org/cgit/openstack/oslo.middleware/tree/oslo_middleware/request_id.py -- the request ID that the server is going to assign is in openstack.request_id in the request env
20:39:39 <bknudson> so you've got it if you want to log it I guess
20:40:03 <bknudson> then do you have to pass that along when you make the request to the next service?
20:40:15 <Rockyg> So, yeah.  RId for notifications.  Jay Pipes is pushing this and the Ops want events to log, which would need these
20:40:46 <Rockyg> bknudson: You would think.  But I don't think many have thought it out that far yet.
20:41:16 <bknudson> correlation ID and request ID look pretty similar
20:41:34 <bknudson> only diff is the request ID has req- prefix
20:41:44 <Rockyg> Yup.  One for APIs, one for events
20:42:29 <dhellmann> bknudson: here's where correlation_id was added: http://git.openstack.org/cgit/openstack/oslo.middleware/commit/?id=758263a8fba5870f48d2e8d15a13bf383eb389d2
20:43:07 <bknudson> looks like correlation ID is to also track requests across services
20:44:01 <Rockyg> Yup. But outside of the API path.  So, the RPCs,Rabbitq, etc.
20:44:24 <bknudson> it's middleware so it's generated from the api request coming in
20:44:38 <bknudson> unless there's some other user of middleware
20:44:58 <dhellmann> no, that's a wsgi middleware, so it's the rest call
20:45:27 <Rockyg> hmm.
20:45:32 <dhellmann> one of our pain points on these libraries is definitely documentation :-(
20:46:24 <bknudson> maybe we can deprecate correlation-id in favor of x-openstack-request-id ?
20:46:38 <dhellmann> I wonder if that header name is some sort of standard
20:46:53 <Rockyg> or vice versa ;-)
20:47:55 <dhellmann> well, searching for X_CORRELATION_ID does turn up some hits
20:48:43 <bknudson> keystone has request_id in the default pipeline, no correlation id
20:49:51 <dhellmann> here's the old spec for that middleware: https://blueprints.launchpad.net/oslo-incubator/+spec/create-a-unified-correlation-id
20:49:55 <Rockyg> bp doesn't link to anything.
20:50:05 <Rockyg> Ah!  you found it.
20:50:13 <dhellmann> and a related old email thread: https://lists.launchpad.net/openstack/msg13082.html
20:50:14 <bknudson> I don't see any paste.ini with CorrelationId. It doesn't have a factory function either
20:50:42 <dhellmann> it might not be used yet
20:51:16 <bknudson> Tue, 12 Jun 2012 -- the dream will eventually come true!
20:51:25 <Rockyg> It looks like Nova was supposed to put it in v2.1 (roginally v3)
20:52:02 <dhellmann> the old nova spec: http://git.openstack.org/cgit/openstack/oslo.middleware/commit/?id=758263a8fba5870f48d2e8d15a13bf383eb389d2
20:52:03 <Rockyg> It was supposed to be in Juno.
20:52:19 <dhellmann> oops
20:52:24 <dhellmann> https://blueprints.launchpad.net/nova/+spec/cross-service-request-id
20:52:44 <Rockyg> Yup.
20:53:18 <dhellmann> anyway, it looks like there is lots of prior art here and whoever is pushing this now should pull it all together, summarize the state of what we have and how that's different from what we want
20:53:22 <dhellmann> instead of starting from scratch
20:54:02 <bknudson> we might be trying to make something perfect when we should start out with whatever's easy
20:54:08 <Rockyg> Sounds good to me.  I think we have an action and that we have a chance of getting a start on this in Liberty
20:54:14 <dhellmann> and we might already have half of what we want
20:54:55 <Rockyg> #action pull all the correlation-id threads together, document, and discuss with Abhishek, etc.
20:55:05 <bknudson> well, it seems like all we're going to get accomplished in L is being able to get the request ID from the response in the python apis.
20:55:26 <Rockyg> Well, I think we've gotten some useful work done here today.  I'm happy.
20:56:13 <dhellmann> ++
20:56:16 <Rockyg> I'll pull the threads together and post to the ML referring to the current Request-ID spec.
20:56:56 <Rockyg> And with that any other things to discuss, or close it down?
20:57:26 <bknudson> happy canada day
20:57:38 <Rockyg> Happy Canada Day!
20:57:42 * dhellmann salutes his northern neighbors
20:58:05 <Rockyg> #endmeeting