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.

> 
> 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
>