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 <[email protected]> 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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][536607]: DeprecationWarning) Feb 04 12:13:55 localhost.localdomain [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 [email protected][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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
