Open Stack

-----Original Message-----
From: Doug Hellmann [mailto:doug at doughellmann.com] 
Sent: 15 March 2016 19:29
To: openstack-operators
Subject: Re: [Openstack-operators] [openstack-dev] [all][log] Ideas to log request-ids in cross-projects

Excerpts from Kekane, Abhishek's message of 2016-03-15 08:28:13 +0000:
> Excerpts from Kekane, Abhishek's message of 2016-03-01 06:17:15 +0000:
> 
> > Hi Devs,
> 
> >
> 
> > Considering return request-id to caller specs [1] is implemented in
> 
> > python-*client, I would like to begin discussion on how these 
> > request-ids
> 
> > will be logged in cross-projects. In logging work-group meeting 
> > (11-Nov-2015)
> 
> > [2] there was a discussion about how to log request-id in the log messages.
> 
> > In same meeting it wass decided to write oslo.log specs but as of now no specs has been submitted.
> 
> >
> 
> > I would like to share our approach to log request-ids and seek 
> > suggestions
> 
> > for the same. We are planning to use request_utils module [3] which 
> > was
> 
> > earlier part of oslo-incubator but removed as no one was using it.
> 
> >
> 
> > A typical use case is: Tempest asking Nova to perform some action 
> > and Nova
> 
> > calling Glance internally, then the linkages might look like this:
> 
> >
> 
> > RequestID mapping in nova for nova and glance:
> 
> > ---------------------------------------------
> 
> >
> 
> > INFO nova.utils [req-f0fb885b-18a2-4510-9e85-b9066b410ee4 admin 
> > admin] Request ID Link: request.link 
> > 'req-f0fb885b-18a2-4510-9e85-b9066b410ee4' -> Target='glance' 
> > TargetId=req-a1ac739c-c816-4f82-ad82-9a9b1a603f43
> 
> 
> 
> When is that message emitted? After glance returns a value? What logs
> 
> the message?
> 
> >
> 
> > RequestID mapping in tempest for tempest and nova:
> 
> > -------------------------------------------------
> 
> >
> 
> > INFO tempest.tests [req-a0df655b-18a2-4510-9e85-b9435dh8ye4 admin 
> > admin] Request ID Link: request.link 
> > 'req-a0df655b-18a2-4510-9e85-b9435dh8ye4' -> Target='nova' 
> > TargetId=req-f0fb885b-18a2-4510-9e85-b9066b410ee4
> 
> >
> 
> > As there is a reference of nova's request-id in tempest and glance's
> 
> > request-id in nova, operator can easily trace the cause of failure.
> 
> >
> 
> > Using request_utils module we can also mention the 'stage' parameter 
> > to
> 
> > divide the entire api cycle with stages, e.g. create server can be
> 
> > staged as start, get-image can be staged as download-image and 
> > active instance
> 
> > can be staged as end of the operation.
> 
> > I think this is conflating the request stages and "linking" in a way
> 
> > that isn't going to always apply.
> 
> >
> 
> > It really seems like what we want it to just log the request id(s)
> 
> > returned from each call made using a client. The format you proposed
> 
> > includes all of that data, it's just a bit more verbose than I think 
> > we
> 
> > really need.
> 
> >
> 
> > Given that we want to log the information regardless of whether
> 
> > there was an error, we need to put the logging inside the client
> 
> > libraries themselves where we can always log before raising an
> 
> > exception. As a bonus, this significantly reduces the number of
> 
> > places we need to make code changes to log the request id chain.
> 
> > The clients don't know the request id for the current context, but
> 
> > that's OK because oslo.context does and apps using oslo.log will
> 
> > get that for free (that's the repeated value in your example above).
> 
> >
> 
> > So, we could, from the client, do something like:
> 
> >
> 
> >   LOG.info('call to %(my_service_name)s.%(my_endpoint_name)s used 
> > request id %(response_request_id)s',
> 
> >            extras={'my_service_name': 'nova', 'my_endpoint_name':
> 
> >                 'create_server', 'response_request_id': request_id})
> 
> >
> 
> > That would produce something like:
> 
> >
> 
> >   INFO tempest.tests [req-a0df655b-18a2-4510-9e85-b9435dh8ye4 admin 
> > admin] call to nova.create_server used request id 
> > req-f0fb885b-18a2-4510-9e85-b9066b410ee4
> 
> >
> 
> > and in the JSON formatter output, you would have separate fields for
> 
> > request_id (the current request) and response_request_id (the value 
> > just
> 
> > returned to the client by the service).
> 
> >
> 
> > I don't know if we want to use INFO or DEBUG level, so I've used 
> > INFO to
> 
> > be consistent with your example.
> 
> >
> 
> 
> 
> Hi Doug,
> 
> 
> 
> With your solution only minimal changes are required to log request-ids in client libraries.
> 
> 
> 
> I have tried to implement your solution in python-cinderclient and found that 'endpoint_name' (callee function) is not accessible.
> 
> We can use inspect module for this purpose but I am not sure whether it is advisable or not.
> 
> Another thing is as of now oslo.log is not used in any core client so we need to make this change first to use oslo.log in individual python-clients.

You shouldn't need to add oslo.log as a dependency. In projects where oslo.log is used to configure logging, you'll get the full output. In other projects, you'll get the output the user has asked for when they configured logging in some other way.

> 
> 
> 
> If we log request method and url instead of endpoint_name in the log then IMO it will be more helpful for the operator.

Sure, that makes sense. That's the idea of what I meant by endpoint_name.

Hi Doug,

Is there a need to submit a cross-project specs for this or should I create individual blueprints in individual python-client for this.
Please let me know.

Thank you,

Abhishek Kekane

> 
> 
> 
> For example something like this:
> 
> 
> 
> LOG.debug(_('%(method)s call to %(my_service_name)s for %(my_url)s '
> 
>             'used request id %(response_request_id)s') %
> 
>            {'method': resp.request.method,
> 
>             'my_service_name': 'cinder',
> 
>             'my_url': resp.url,
> 
>             'response_request_id': request_ids})
> 
> 
> 
> Which would produce something like:
> 
> 
> 
> DEBUG cinderclient.client [req-22f6b4ed-d746-4af6-b183-073df681d14b 
> demo demo] GET call to cinder for 
> http://172.31.21.78:8776/v2/9ffea7c24c9d440d9690850da90c8bfb/volumes/f
> 5d1aefa-5632-4c42-89ef-c115df659875 used request id 
> req-3a9ba7a3-feca-406b-abce-3cf46c92e235
> 
> 
> 
> Please let me know your opinion about the same.

That looks good, except that we don't translate debug messages so you don't need the _() call wrapping the message string.

Doug

> 
> 
> 
> Abhishek
> 
> >
> 
> > Advantages:
> 
> > -----------
> 
> >
> 
> > With stages provided for API, it's easy for the operator to find out the failure stage from entire API cycle.
> 
> > I think the "stages" concept is better addressed by updating the
> 
> > way we log to match the "unit of work" pattern described in our log
> 
> > guidelines [1].
> 
> > [1] 
> > http://specs.openstack.org/openstack/openstack-specs/specs/log-guide
> > lines.html#log-messages-at-info-and-above-should-be-a-unit-of-work
> 
> >
> 
> > An example with 'stage' is,
> 
> > Tempest asking Nova to perform some action and Nova calling Glance 
> > internally,
> 
> > then the linkages might look like this:
> 
> >
> 
> > INFO tempest.tests [req-a0df655b-18a2-4510-9e85-b9435dh8ye4 admin admin] Request ID Link: request.link.start 'req-a0df655b-18a2-4510-9e85-b9435dh8ye4'
> 
> >
> 
> > INFO nova.utils [req-f0fb885b-18a2-4510-9e85-b9066b410ee4 admin 
> > admin] Request ID Link: request.link.image_download 
> > 'req-f0fb885b-18a2-4510-9e85-b9066b410ee4' -> Target='glance' 
> > TargetId=req-a1ac739c-c816-4f82-ad82-9a9b1a603f43
> 
> >
> 
> > INFO tempest.tests [req-b0df857fb-18a2-4510-9e85-b9435dh8ye4 admin admin] Request ID Link: request.link.end 'req-b0df857fb-18a2-4510-9e85-b9435dh8ye4'
> 
> >
> 
> > Concern:
> 
> > --------
> 
> >
> 
> > As request_utils module is removed from oslo-incubator and this 
> > module is
> 
> > also getting deprecated, I have following options to add it back to OpenStack.
> 
> >
> 
> > Option 1: Add request_utils module in oslo.log (as it is related to 
> > logging
> 
> > request_ids)
> 
> > Option 2: Add request_utils module in oslo.utils
> 
> > Option 3: Add link_request_ids method in utils.py of individual projects.
> 
> > (this will cause code duplication)
> 
> > Is this the request_utils you mean?
> 
> > https://review.openstack.org/#/c/170074/2/openstack/common/request_u
> > tils.py
> 
> >
> 
> > It's not clear why we need a special module for something that 
> > should
> 
> > just be a simple call to the logger.
> 
> > Doug
> 
> >
> 
> > Please let me know your thoughts about the same.
> 
> >
> 
> > [1] 
> > http://specs.openstack.org/openstack/openstack-specs/specs/return-re
> > quest-id.html
> 
> > [2] 
> > http://eavesdrop.openstack.org/meetings/log_wg/2015/log_wg.2015-11-1
> > 1-20.02.log.html
> 
> > [3] 
> > http://docs.openstack.org/developer/oslo-incubator/api/openstack.com
> > mon.request_utils.html
> 
> >
> 
> > Thank You,
> 
> >
> 
> > Abhishek Kekane
> 
> >
> 

_______________________________________________
OpenStack-operators mailing list
OpenStack-operators at lists.openstack.org
http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-operators

______________________________________________________________________
Disclaimer: This email and any attachments are sent in strictest confidence
for the sole use of the addressee and may contain legally privileged,
confidential, and proprietary data. If you are not the intended recipient,
please advise the sender by replying promptly to this email and then delete
and destroy this email and any attachments without any further use, copying
or forwarding.