yahoo-eng-team team mailing list archive
-
yahoo-eng-team team
-
Mailing list archive
-
Message #88354
[Bug 1960020] Re: Duplicated request ids in the logs
Reviewed: https://review.opendev.org/c/openstack/cinder/+/827860
Committed: https://opendev.org/openstack/cinder/commit/18b8033b6bd1945bd27b03b779a32a883df5fb10
Submitter: "Zuul (22348)"
Branch: master
commit 18b8033b6bd1945bd27b03b779a32a883df5fb10
Author: Gorka Eguileor <geguileo@xxxxxxxxxx>
Date: Fri Feb 4 12:42:25 2022 +0100
Fix request id mess on Cinder-API
This patch fixes multiple issues related to request ids:
- Duplicated request ID in logs
- Missing request id header in response
- Wrong request ID in response header when using noauth
The source of these issues is the fact that the request ID and the
request context are set too late, or not at all, in the paste filter
chain.
And the last bug is fixed as a freebie when the code in auth.py is
refactored to reduce code duplication on setting the cinder.context key
in the request's environment.
The patch fixes these issue by changing the filter chains to have the
request_id filter as the first filter, and using our own filter for it,
to ensure that the context is correctly set.
Not sure if values now defined in ENV_OVERWRITES are still necessary,
so the patch preserves current behavior.
Closes-Bug: #1960019
Closes-Bug: #1960020
Closes-Bug: #1960021
Closes-Bug: #1960329
Change-Id: Ide831a221a7561bbb7da193f0edb011f1989420e
** Changed in: cinder
Status: In Progress => Fix Released
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1960020
Title:
Duplicated request ids in the logs
Status in Cinder:
Fix Released
Status in OpenStack Compute (nova):
Confirmed
Bug description:
In the cinder-api logs we can find duplicated request ids, which may
confound people.
Running the following 2 commands:
$ cinder list
$ cinder api-version
Will result in log entries with duplicated request ids.
In the following log entries, after running those 2 commands, we can
see that there are 4 REST API requests but there are only 2 different
request ids, as req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 and
req-8a27dec8-63de-400b-b955-04d459c104df appear twice each.
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] GET http://192.168.1.89/volume//
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Empty body provided in request {{(pid=536608) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Calling method 'all' {{(pid=536608) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] http://192.168.1.89/volume// returned with HTTP 300
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536608]: [pid: 536608|app: 0|req: 8/15] 192.168.1.89 () {64 vars in 1176 bytes} [Fri Feb 4 12:13:55 2022] GET /volume/ => generated 387 bytes in 2 msecs (HTTP/1.1 300) 5 headers in 170 bytes (1 switches on core 0)
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] GET http://192.168.1.89/volume/v3/9233eaa83fb944cb8fc984ed273db227/volumes/detail
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Empty body provided in request {{(pid=536607) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Calling method 'detail' {{(pid=536607) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.volume.api [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Get all volumes completed successfully.
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: /usr/local/lib/python3.6/site-packages/oslo_context/context.py:108: DeprecationWarning: Policy enforcement is depending on the value of is_admin. This key is deprecated. Please update your policy file to use the standard policy values.
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: DeprecationWarning)
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] http://192.168.1.89/volume/v3/9233eaa83fb944cb8fc984ed273db227/volumes/detail returned with HTTP 200
Feb 04 12:13:55 localhost.localdomain devstack@c-api.service[536607]: [pid: 536607|app: 0|req: 8/16] 192.168.1.89 () {62 vars in 1284 bytes} [Fri Feb 4 12:13:55 2022] GET /volume/v3/9233eaa83fb944cb8fc984ed273db227/volumes/detail => generated 2093 bytes in 36 msecs (HTTP/1.1 200) 7 headers in 286 bytes (1 switches on core 0)
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] GET http://192.168.1.89/volume//
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Empty body provided in request {{(pid=536608) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: DEBUG cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] Calling method 'all' {{(pid=536608) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: INFO cinder.api.openstack.wsgi [None req-e5f2fe4b-bd80-4ccc-87ed-e97aa66d8a89 None None] http://192.168.1.89/volume// returned with HTTP 300
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536608]: [pid: 536608|app: 0|req: 9/17] 192.168.1.89 () {64 vars in 1176 bytes} [Fri Feb 4 12:13:58 2022] GET /volume/ => generated 387 bytes in 1 msecs (HTTP/1.1 300) 5 headers in 170 bytes (1 switches on core 0)
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] GET http://192.168.1.89/volume//
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Empty body provided in request {{(pid=536607) tid=140407477474816 get_body /opt/remote_cinder/cinder/api/openstack/wsgi.py:715}}
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: DEBUG cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] Calling method 'all' {{(pid=536607) tid=140407477474816 _process_stack /opt/remote_cinder/cinder/api/openstack/wsgi.py:869}}
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: INFO cinder.api.openstack.wsgi [None req-8a27dec8-63de-400b-b955-04d459c104df admin admin] http://192.168.1.89/volume// returned with HTTP 300
Feb 04 12:13:58 localhost.localdomain devstack@c-api.service[536607]: [pid: 536607|app: 0|req: 9/18] 192.168.1.89 () {62 vars in 1135 bytes} [Fri Feb 4 12:13:58 2022] GET /volume/ => generated 387 bytes in 1 msecs (HTTP/1.1 300) 5 headers in 169 bytes (1 switches on core 0)
Something similar happens in nova, though an additional call to "nova
version-list" is necessary to see it.
To manage notifications about this bug go to:
https://bugs.launchpad.net/cinder/+bug/1960020/+subscriptions
