Re: [openstack-dev] [all][log] Ideas to log request-ids in cross-projects
Excerpts from Kekane, Abhishek's message of 2016-03-01 06:17:15 +:
> 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
Re: [openstack-dev] [all][log] Ideas to log request-ids in cross-projects
Excerpts from Kekane, Abhishek's message of 2016-03-01 06:17:15 +:
> 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.
>
>
Re: [openstack-dev] [all][log] Ideas to log request-ids in cross-projects
Hi, Added openstack-operators in cc so that they can share there views as well. Abhishek From: Bogdan Dobrelya [bdobre...@mirantis.com] Sent: Tuesday, March 01, 2016 3:55 AM To: OpenStack Development Mailing List (not for usage questions) Subject: Re: [openstack-dev] [all][log] Ideas to log request-ids in cross-projects On 01.03.2016 07:17, Kekane, Abhishek wrote: > 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 > > 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. > > Advantages: > --- > > With stages provided for API, it's easy for the operator to find out the > failure stage from entire API cycle. > > 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) > > Please let me know your thoughts about the same. I believe the former option should work good as well. By the way, any plans to track requests down to the root wrappers' shell commands? There is also interesting R related to the topic directly [0], see "4. Logging and coordination". Would be nice to reach those people and ask for code snippets or cooperation as well... [0] https://kabru.eecs.umich.edu/papers/publications/2013/socc2013_ju.pdf > > [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 promptl
Re: [openstack-dev] [all][log] Ideas to log request-ids in cross-projects
On 01.03.2016 07:17, Kekane, Abhishek wrote: > 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 > > 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. > > Advantages: > --- > > With stages provided for API, it's easy for the operator to find out the > failure stage from entire API cycle. > > 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) > > Please let me know your thoughts about the same. I believe the former option should work good as well. By the way, any plans to track requests down to the root wrappers' shell commands? There is also interesting R related to the topic directly [0], see "4. Logging and coordination". Would be nice to reach those people and ask for code snippets or cooperation as well... [0] https://kabru.eecs.umich.edu/papers/publications/2013/socc2013_ju.pdf > > [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. > > > __ > OpenStack Development Mailing List (not for usage questions) > Unsubscribe: openstack-dev-requ...@lists.openstack.org?subject:unsubscribe > http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev > -- Best regards, Bogdan Dobrelya, Irc #bogdando __ OpenStack Development Mailing List (not for usage questions) Unsubscribe:
[openstack-dev] [all][log] Ideas to log request-ids in cross-projects
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 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. Advantages: --- With stages provided for API, it's easy for the operator to find out the failure stage from entire API cycle. 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) 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.__ OpenStack Development Mailing List (not for usage questions) Unsubscribe: openstack-dev-requ...@lists.openstack.org?subject:unsubscribe http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
