<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
<meta name="Generator" content="Microsoft Word 14 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";
mso-fareast-language:EN-US;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:blue;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:purple;
text-decoration:underline;}
pre
{mso-style-priority:99;
mso-style-link:"HTML Preformatted Char";
margin:0cm;
margin-bottom:.0001pt;
font-size:10.0pt;
font-family:"Courier New";}
span.EmailStyle17
{mso-style-type:personal-compose;
font-family:"Calibri","sans-serif";
color:windowtext;}
span.HTMLPreformattedChar
{mso-style-name:"HTML Preformatted Char";
mso-style-priority:99;
mso-style-link:"HTML Preformatted";
font-family:"Courier New";
mso-fareast-language:EN-IN;}
.MsoChpDefault
{mso-style-type:export-only;
font-family:"Calibri","sans-serif";
mso-fareast-language:EN-US;}
@page WordSection1
{size:612.0pt 792.0pt;
margin:72.0pt 72.0pt 72.0pt 72.0pt;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-IN" link="blue" vlink="purple">
<div class="WordSection1">
<pre>Excerpts from Kekane, Abhishek's message of 2016-03-01 06:17:15 +0000:<o:p></o:p></pre>
<pre>><i> Hi Devs,<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Considering return request-id to caller specs [1] is implemented in<o:p></o:p></i></pre>
<pre>><i> python-*client, I would like to begin discussion on how these request-ids<o:p></o:p></i></pre>
<pre>><i> will be logged in cross-projects. In logging work-group meeting (11-Nov-2015)<o:p></o:p></i></pre>
<pre>><i> [2] there was a discussion about how to log request-id in the log messages.<o:p></o:p></i></pre>
<pre>><i> In same meeting it wass decided to write oslo.log specs but as of now no specs has been submitted.<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> I would like to share our approach to log request-ids and seek suggestions<o:p></o:p></i></pre>
<pre>><i> for the same. We are planning to use request_utils module [3] which was<o:p></o:p></i></pre>
<pre>><i> earlier part of oslo-incubator but removed as no one was using it.<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> A typical use case is: Tempest asking Nova to perform some action and Nova<o:p></o:p></i></pre>
<pre>><i> calling Glance internally, then the linkages might look like this:<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> RequestID mapping in nova for nova and glance:<o:p></o:p></i></pre>
<pre>><i> ---------------------------------------------<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> 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<o:p></o:p></i></pre>
<pre><o:p> </o:p></pre>
<pre>When is that message emitted? After glance returns a value? What logs<o:p></o:p></pre>
<pre>the message?<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> RequestID mapping in tempest for tempest and nova:<o:p></o:p></i></pre>
<pre>><i> -------------------------------------------------<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> 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<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> As there is a reference of nova's request-id in tempest and glance's<o:p></o:p></i></pre>
<pre>><i> request-id in nova, operator can easily trace the cause of failure.<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Using request_utils module we can also mention the 'stage' parameter to<o:p></o:p></i></pre>
<pre>><i> divide the entire api cycle with stages, e.g. create server can be<o:p></o:p></i></pre>
<pre>><i> staged as start, get-image can be staged as download-image and active instance<o:p></o:p></i></pre>
<pre>><i> can be staged as end of the operation.<o:p></o:p></i></pre>
<pre><o:p> </o:p></pre>
<pre>><i> </i>I think this is conflating the request stages and "linking" in a way<o:p></o:p></pre>
<pre>><i> </i>that isn't going to always apply.<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i>It really seems like what we want it to just log the request id(s)<o:p></o:p></pre>
<pre>><i> </i>returned from each call made using a client. The format you proposed<o:p></o:p></pre>
<pre>><i> </i>includes all of that data, it's just a bit more verbose than I think we<o:p></o:p></pre>
<pre>><i> </i>really need.<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i>Given that we want to log the information regardless of whether<o:p></o:p></pre>
<pre>><i> </i>there was an error, we need to put the logging inside the client<o:p></o:p></pre>
<pre>><i> </i>libraries themselves where we can always log before raising an<o:p></o:p></pre>
<pre>><i> </i>exception. As a bonus, this significantly reduces the number of<o:p></o:p></pre>
<pre>><i> </i>places we need to make code changes to log the request id chain.<o:p></o:p></pre>
<pre>><i> </i>The clients don't know the request id for the current context, but<o:p></o:p></pre>
<pre>><i> </i>that's OK because oslo.context does and apps using oslo.log will<o:p></o:p></pre>
<pre>><i> </i>get that for free (that's the repeated value in your example above).<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i>So, we could, from the client, do something like:<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i> LOG.info('call to %(my_service_name)s.%(my_endpoint_name)s used request id %(response_request_id)s',<o:p></o:p></pre>
<pre>><i> </i> extras={'my_service_name': 'nova', 'my_endpoint_name':<o:p></o:p></pre>
<pre>> 'create_server', 'response_request_id': request_id})<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i>That would produce something like:<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i> 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<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i>and in the JSON formatter output, you would have separate fields for<o:p></o:p></pre>
<pre>><i> </i>request_id (the current request) and response_request_id (the value just<o:p></o:p></pre>
<pre>><i> </i>returned to the client by the service).<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i>I don't know if we want to use INFO or DEBUG level, so I've used INFO to<o:p></o:p></pre>
<pre>><i> </i>be consistent with your example.<o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre><o:p> </o:p></pre>
<pre>Hi Doug,<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>With your solution only minimal changes are required to log request-ids in client libraries.<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>I have tried to implement your solution in python-cinderclient and found that 'endpoint_name' (callee function) is not accessible.<o:p></o:p></pre>
<pre>We can use inspect module for this purpose but I am not sure whether it is advisable or not.<o:p></o:p></pre>
<pre>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.<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>If we log request method and url instead of endpoint_name in the log then IMO it will be more helpful for the operator.<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>For example something like this:<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>LOG.debug(_('%(method)s call to %(my_service_name)s for %(my_url)s '<o:p></o:p></pre>
<pre> 'used request id %(response_request_id)s') %<o:p></o:p></pre>
<pre> {'method': resp.request.method,<o:p></o:p></pre>
<pre> 'my_service_name': 'cinder',<o:p></o:p></pre>
<pre> 'my_url': resp.url,<o:p></o:p></pre>
<pre> 'response_request_id': request_ids})<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>Which would produce something like:<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>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<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>Please let me know your opinion about the same.<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>Abhishek<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Advantages:<o:p></o:p></i></pre>
<pre>><i> -----------<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> With stages provided for API, it's easy for the operator to find out the failure stage from entire API cycle.<o:p></o:p></i></pre>
<pre><o:p> </o:p></pre>
<pre>><i> </i>I think the "stages" concept is better addressed by updating the<o:p></o:p></pre>
<pre>><i> </i>way we log to match the "unit of work" pattern described in our log<o:p></o:p></pre>
<pre>><i> </i>guidelines [1].<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>><i> </i>[1] <a href="http://specs.openstack.org/openstack/openstack-specs/specs/log-guidelines.html#log-messages-at-info-and-above-should-be-a-unit-of-work">http://specs.openstack.org/openstack/openstack-specs/specs/log-guidelines.html#log-messages-at-info-and-above-should-be-a-unit-of-work</a><o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> An example with 'stage' is,<o:p></o:p></i></pre>
<pre>><i> Tempest asking Nova to perform some action and Nova calling Glance internally,<o:p></o:p></i></pre>
<pre>><i> then the linkages might look like this:<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> INFO tempest.tests [req-a0df655b-18a2-4510-9e85-b9435dh8ye4 admin admin] Request ID Link: request.link.start 'req-a0df655b-18a2-4510-9e85-b9435dh8ye4'<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> 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<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> INFO tempest.tests [req-b0df857fb-18a2-4510-9e85-b9435dh8ye4 admin admin] Request ID Link: request.link.end 'req-b0df857fb-18a2-4510-9e85-b9435dh8ye4'<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Concern:<o:p></o:p></i></pre>
<pre>><i> --------<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> As request_utils module is removed from oslo-incubator and this module is<o:p></o:p></i></pre>
<pre>><i> also getting deprecated, I have following options to add it back to OpenStack.<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Option 1: Add request_utils module in oslo.log (as it is related to logging<o:p></o:p></i></pre>
<pre>><i> request_ids)<o:p></o:p></i></pre>
<pre>><i> Option 2: Add request_utils module in oslo.utils<o:p></o:p></i></pre>
<pre>><i> Option 3: Add link_request_ids method in utils.py of individual projects.<o:p></o:p></i></pre>
<pre>><i> (this will cause code duplication)<o:p></o:p></i></pre>
<pre><o:p> </o:p></pre>
<pre>><i> </i>Is this the request_utils you mean?<o:p></o:p></pre>
<pre>><i> </i><a href="https://review.openstack.org/#/c/170074/2/openstack/common/request_utils.py">https://review.openstack.org/#/c/170074/2/openstack/common/request_utils.py</a><o:p></o:p></pre>
<pre>><o:p> </o:p></pre>
<pre>><i> </i>It's not clear why we need a special module for something that should<o:p></o:p></pre>
<pre>><i> </i>just be a simple call to the logger.<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>><i> </i>Doug<o:p></o:p></pre>
<pre><o:p> </o:p></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Please let me know your thoughts about the same.<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> [1] <a href="http://specs.openstack.org/openstack/openstack-specs/specs/return-request-id.html">http://specs.openstack.org/openstack/openstack-specs/specs/return-request-id.html</a><o:p></o:p></i></pre>
<pre>><i> [2] <a href="http://eavesdrop.openstack.org/meetings/log_wg/2015/log_wg.2015-11-11-20.02.log.html">http://eavesdrop.openstack.org/meetings/log_wg/2015/log_wg.2015-11-11-20.02.log.html</a><o:p></o:p></i></pre>
<pre>><i> [3] <a href="http://docs.openstack.org/developer/oslo-incubator/api/openstack.common.request_utils.html">http://docs.openstack.org/developer/oslo-incubator/api/openstack.common.request_utils.html</a><o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Thank You,<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<pre>><i> Abhishek Kekane<o:p></o:p></i></pre>
<pre>><i> <o:p></o:p></i></pre>
<p class="MsoNormal"><o:p> </o:p></p>
</div>
<br clear="both">
______________________________________________________________________<BR>
Disclaimer: This email and any attachments are sent in strictest confidence<BR>
for the sole use of the addressee and may contain legally privileged,<BR>
confidential, and proprietary data. If you are not the intended recipient,<BR>
please advise the sender by replying promptly to this email and then delete<BR>
and destroy this email and any attachments without any further use, copying<BR>
or forwarding.<BR>
</body>
</html>