20:02:21 <Rockyg> #startmeeting log_wg
20:02:22 <openstack> Meeting started Wed Jul  8 20:02:21 2015 UTC and is due to finish in 60 minutes.  The chair is Rockyg. Information about MeetBot at http://wiki.debian.org/MeetBot.
20:02:23 <openstack> Useful Commands: #action #agreed #help #info #idea #link #topic #startvote.
20:02:25 <openstack> The meeting name has been set to 'log_wg'
20:02:34 <jokke_> o/
20:03:25 <Rockyg> bknudson: dhellmann, who else?
20:03:29 <bknudson> hi
20:03:33 <Rockyg> need to expand this group.
20:04:05 <Rockyg> Well, what do folks want to discuss?
20:04:11 <jokke_> we really should start using https://etherpad.openstack.org/p/log-wg-meeting-agenda or something like that ;)
20:04:28 <Rockyg> agreed.
20:04:38 <jokke_> I have the template there
20:05:29 <jokke_> nicely "borrowed" from glance equivalent
20:05:42 <Rockyg> How about we start with error codes....
20:05:58 <Rockyg> #topic error codes
20:06:33 <Rockyg> I would like everyone to review #link https://blueprints.launchpad.net/nova/+spec/cross-service-request-id
20:07:00 <jokke_> that's for req IDs?
20:07:22 <Rockyg> Oops. wrong one
20:07:39 <Rockyg> #link https://blueprints.launchpad.net/nova/+spec/formal-message-ids
20:08:07 <Rockyg> It's a dead ringer for what we wrote.  Ill see if we can get Mark here...
20:08:33 <bknudson> Rockyg: mark's on vacay
20:08:37 <Rockyg> vanderwl  does not appear to be on line at the move
20:08:54 <bknudson> that was written in 2013
20:09:01 <Rockyg> Yup.
20:09:02 <bknudson> I assume he's moved on
20:09:07 <jokke_> yeah looks to be pretty darn close ... and I hadn't seen that when I wrote the original
20:09:30 <Rockyg> It's amazing what is floating around the archives that was suggested by never carried through
20:09:34 <jokke_> meaning that there has been others with pretty much same requirements as we came out with ... which is really good
20:09:56 <bknudson> lots of developers aren't willing to hang in there for the years or months it takes anything to get implemented
20:09:58 <Rockyg> But, we know why it wasn't carried through, because it's *hard* to get it through
20:10:16 <jokke_> yeah
20:10:29 <Rockyg> Yeah, he's on chef mostly
20:10:56 <jokke_> funny thing is that the BP has been actually approved for nova ;)
20:11:14 <jokke_> perhaps we should reference it on the spec
20:11:31 <Rockyg> I'm going to see if we can add him as a coauthor for our spec and co-opt what he wrote to flesh out what we wrote.
20:12:08 <jokke_> I'd be happy with that ... and if he wants to take part at least to the review if not implementing
20:12:53 <Rockyg> It seems that nova has the most impetus for a lot of these formalizations.  Maybe we should try to make it the pilot for the xprojects.
20:13:13 <bknudson> I don't see where the bp is approved for nova?
20:13:29 <Rockyg> It's still in drafting.
20:13:43 <jokke_> oh ... I was looking the approver being there
20:13:44 <Rockyg> the first one was implemented, but that was request ids
20:14:08 <jokke_> I'm from the generation that has not seen the best or worst of bps :P
20:15:43 <Rockyg> Yeah.  When I started, I wrote a bp for a Qa doc.  It had the general outline and stuff.  but, they said it wasn't detailed enough.  then I look at all these others and they aren't even a complete sentence.
20:16:18 <Rockyg> A team really needs to go through and mine these things and the specs for info.
20:16:38 <Rockyg> Anyway, bknudson, doyou kno when Mark gets back?
20:17:12 <bknudson> Rockyg: not sure... I think next week he'll be back
20:17:42 <Rockyg> Thanks!  In the mean time, I'll see what I can do to beef up our spec with his stuff
20:17:56 <Rockyg> if company politics don't distract me.
20:18:48 <Rockyg> #action rocky to look to merge Error code spec with info from https://blueprints.launchpad.net/nova/+spec/formal-message-ids
20:19:33 <Rockyg> #topic feedback on our efforts
20:20:16 <Rockyg> bknudson: I'd like to know what you think about our direction, etc and if you have any suggestions on what to change/what to add/etc?
20:20:31 <bknudson> I can't complain
20:20:50 <bknudson> I'd like to have more time to work on this stuff myself but it's hard to make it the top priority
20:21:01 <bknudson> my goal is to work on logging for keystone in particular
20:21:16 <Rockyg> Yah, I keep getting pulled to do other stuff.
20:21:35 <bknudson> and then if keystone logging gets up to where I'd like it to be then we can use that as an exemplar
20:21:42 <Rockyg> did you see the xproject discussion on requestIDs?
20:21:44 <bknudson> but we're nowhere near that.
20:21:57 <bknudson> I did see the x-project discussion on request IDs
20:22:03 <Rockyg> I hear you.  so, keystone could be the pilot
20:22:31 <bknudson> if you guys have anything you want to get working in keystone I'll sign up to review it.
20:22:42 <Rockyg> Just want to point out that oslo middleware already has what is needed for that in the code base.
20:23:06 <bknudson> keystone already has the middleware in the paste pipeline
20:23:15 <bknudson> the default / sample paste pipeline
20:23:22 <jokke_> :)
20:23:22 <Rockyg> Nova already does it, maybe we can get keystone to do it, too.
20:23:58 <Rockyg> so, that's cool.  I just hope that it meshes fairly well with the way nova did it.
20:24:04 <bknudson> I wonder if we log the request ID
20:24:11 <bknudson> probably not
20:24:35 <Rockyg> It should be.  Ops wants it.  But, their needs are different from devs on that
20:25:01 <Rockyg> They want the original caller and the number of hops from the first request.
20:25:22 <bknudson> http://logs.openstack.org/73/195873/14/check/check-tempest-dsvm-full/aff87a6/logs/apache/keystone.txt.gz -- sample keystone log
20:25:37 <Rockyg> otherwise, the log message could get too long
20:25:43 <bknudson> I don't see any request IDs in the log.
20:25:58 <bknudson> another item for the list o' things to do
20:27:15 <Rockyg> Yeah.  We weren't gonna tackle it until they get it straightened out in passing between project boundaries.
20:28:04 <bknudson> having the client API return request ID would be a lot more useful if it could be correlated with the logs
20:28:32 <jokke_> bknudson: well it's absolutely pointless if it does not
20:28:33 <bknudson> I wonder if we have request ID in the common log format?
20:28:44 <Rockyg> nope
20:28:57 <Rockyg> but, there are places it could be put
20:29:10 <jokke_> otherwise it's just decorator (here is some random characters for you, dear user, that has absolutely no use) ;)
20:29:33 <bknudson> http://git.openstack.org/cgit/openstack/oslo.log/tree/oslo_log/_options.py#n99
20:29:33 <Rockyg> it could go in the body and the body could be more formalized
20:29:45 <bknudson> there's [%(request_id)s ...
20:30:17 <bknudson> keystone doesn't use context so I assume it can't use logging_context_format_string but instead has to use logging_default_format_string
20:30:23 <bknudson> and logging_default_format_string doesn't have request_id
20:31:10 <bknudson> maybe keystone needs to switch to using logging_context_format_string or somerhing.
20:31:37 <bknudson> we'd just leave "instance" blank since there are no instances in keystone!
20:31:50 <jokke_> bknudson: or just adobt the string without context but the formatted bits there
20:32:11 <jokke_> bknudson: put that "-" there ;)
20:32:19 <jokke_> ops will love you for that
20:32:42 <bknudson> I bet they would like that.
20:32:45 <Rockyg> the syslog format has a structured field in its header.  It could be used for rID airs
20:32:51 <Rockyg> ^airs^pairs
20:33:48 <jokke_> one of the biggest points what ops raised already in paris was, do not leave empty fields, if you have nothing to put there, put - so the log parsers have still marker that it's a field
20:34:15 <bknudson> I'll put that on the list o' things to do instead
20:34:33 <Rockyg> jokke_: ++
20:35:04 <Rockyg> and bknudson++
20:35:49 <Rockyg> Yeah.  Maybe we could deprecate default and get everyone using context....
20:36:26 <jokke_> Rockyg: easy now ... one small step at the time
20:37:17 <Rockyg> Heh heh
20:39:51 <jokke_> do we have something else for this weeks list?
20:40:07 <Rockyg> so, I'm looking at the keystone log you linked and there are like 100= lines for every normal log message ???
20:41:49 <Rockyg> but I guess the callback stuff is really the stuff that is mostly used.  those log files must be really thin with debug turned off.
20:42:02 <bknudson> Rockyg: what do you mena?
20:42:03 <bknudson> mean?
20:42:36 <bknudson> Rockyg: the logging of the config options?
20:43:12 <Rockyg> so, like 100+ lines of wsgi option values, then the call backs, a couple of deprecation warnings, then an actual REST call
20:43:49 <Rockyg> so, yeah.  config options
20:43:55 <bknudson> Rockyg: that's a side-effect of running under apache
20:44:05 <jokke_> Rockyg: yeah, the debugging logs tends to be chatty ... that's why we want to get the logging on the state that people can run these things in production without having it enabled ;)
20:44:07 <Rockyg> Ah.  Thanks
20:44:09 <bknudson> it starts up several processes to handle requests
20:44:23 <bknudson> and each time it starts a process the config gets logged
20:44:28 <bknudson> not sure how that could be fixed
20:44:42 <bknudson> eventually it's got all the processes started so you don't see it
20:44:54 <bknudson> unless apache for some reason decides to discard a worker
20:45:10 <bknudson> I think you can configure apache to discard a worker after 100 requests or something
20:45:11 <jokke_> bknudson: you can set the oslo.config logging level to something more reasonable than debug to clean those out
20:45:33 <bknudson> I think infra likes debug since it allows figuring out gate problems
20:45:59 <bknudson> if problems could be diagnosed using info then they'd be happy with that I'm sure
20:46:14 <jokke_> bknudson: it helps debugging test failures as well, but you don't need to have debug everywhere
20:46:38 <jokke_> like oslo.log filters lots of stuff per default nowadays from the libs
20:46:39 <bknudson> I think even the debug logs are useless in keystone
20:46:51 <jokke_> bknudson: I just can't remember if you guys use oslo.log or not
20:46:59 <bknudson> keystone uses oslo.log
20:47:18 <jokke_> ok, so oslo.conf is probably not one of the silenced ones then ;)
20:47:28 <Rockyg> one of the other things ops wants is a way to see the event messages.  so they can see where a multistep call goes south
20:49:15 <Rockyg> it looks like keystone records the events at the info level
20:49:28 <jokke_> bknudson: tbh by quick eyeing over the keystone DEBUG logs does not look that bad
20:50:04 <jokke_> Rockyg: every request is logged once on info level by the logging standards
20:50:11 <bknudson> debug doesn't log enough to be useful for debugging
20:50:35 <Rockyg> Yeah.  once you get past initialization, it's not too bad,
20:50:36 <bknudson> http://logs.openstack.org/73/195873/14/check/check-tempest-dsvm-full/aff87a6/logs/apache/keystone_access.txt.gz
20:50:46 <bknudson> keystone also generates an access log since it runs in apache
20:51:20 <bknudson> "POST /v2.0/OS-KSADM/roles HTTP/1.1" 200 71 "-" "python-keystoneclient" 2330969(us)
20:51:24 <bknudson> that's not the fastest!
20:51:30 <Rockyg> but I see that a warning about not finding admin role doesn't seem to generate more debug info than a normal call
20:51:44 <jokke_> bknudson: fair enough ... I've never needed to debug keystone so couldn't tell ... but you guys seriously doesn't seem to log too much other than the requests
20:54:23 <Rockyg> Well.  Food for thought.  I think we might be done for the day.
20:54:33 <jokke_> ++
20:54:48 <Rockyg> thanks jokke_ and bknudson
20:54:52 <jokke_> thanks
20:54:56 <bknudson> thansk
20:54:58 <Rockyg> #endmeeting