Open Stack

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.



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



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/f5d1aefa-5632-4c42-89ef-c115df659875 used request id req-3a9ba7a3-feca-406b-abce-3cf46c92e235



Please let me know your opinion about the same.



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-guidelines.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_utils.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-request-id.html

> [2] http://eavesdrop.openstack.org/meetings/log_wg/2015/log_wg.2015-11-11-20.02.log.html

> [3] http://docs.openstack.org/developer/oslo-incubator/api/openstack.common.request_utils.html

>

> Thank You,

>

> Abhishek Kekane

>


______________________________________________________________________
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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack-dev/attachments/20160315/187d871b/attachment.html>