Re: [Openstack-operators] [openstack-dev] [all][log] Ideas to log request-ids in cross-projects
-Original Message- From: Doug Hellmann [mailto:d...@doughellmann.com] Sent: Wednesday, March 16, 2016 8:35 PM 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-16 05:56:25 +: > 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 >> You already have a spec for this work. If the details are wrong or >> incomplete, it can be updated. Otherwise, you should be able to just submit >> the patches necessary to complete the spec already defined. Hi Doug, As per suggestion, I have registered a blueprint [1] to target this work. I will submit patches against this blueprint. [1] https://blueprints.launchpad.net/python-cinderclient/+spec/log-request-id >> Doug ___ OpenStack-operators mailing list OpenStack-operators@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. ___ OpenStack-operators mailing list OpenStack-operators@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-operators
Re: [Openstack-operators] [openstack-dev] [all][log] Ideas to log request-ids in cross-projects
Excerpts from Kekane, Abhishek's message of 2016-03-16 05:56:25 +: > 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 You already have a spec for this work. If the details are wrong or incomplete, it can be updated. Otherwise, you should be able to just submit the patches necessary to complete the spec already defined. Doug ___ OpenStack-operators mailing list OpenStack-operators@lists.openstack.org http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-operators
Re: [Openstack-operators] [openstack-dev] [all][log] Ideas to log request-ids in cross-projects
-Original Message-
From: Doug Hellmann [mailto:d...@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 +:
> 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 servic
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 +:
> 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.
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
Re: [Openstack-operators] [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-operators] [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 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:
