Duplicated request ids in the logs

[Gorka Eguileor]

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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[536607]: DeprecationWarning)
Feb 04 12:13:55 localhost.localdomain <email address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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 address hidden>[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.

[Gorka Eguileor (gorka)]

It's even easier to check just running multiple times (in devstack 4 times is enough) the curl command to query the root endpoint.

For Nova:
 curl -v http://<IP>/compute

For Cinder:
 curl -v http://<IP>/volume

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/cinder/+/827860

[OpenStack Infra (hudson-openstack)]

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 address hidden>
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

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/cinder 20.0.0.0rc1 release candidate.