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

cinder/api/middleware/auth.py

@@ -22,7 +22,6 @@ import os
 
 from oslo_config import cfg
 from oslo_log import log as logging
-from oslo_middleware import request_id
 from oslo_serialization import jsonutils
 import webob.dec
 import webob.exc
@@ -60,6 +59,36 @@ def pipeline_factory(loader, global_conf, **local_conf):
     return app
 
 
+def _set_request_context(req, **kwargs):
+    """Sets request context based on parameters and request."""
+    remote_address = getattr(req, 'remote_address', '127.0.0.1')
+
+    service_catalog = None
+    if req.headers.get('X_SERVICE_CATALOG') is not None:
+        try:
+            catalog_header = req.headers.get('X_SERVICE_CATALOG')
+            service_catalog = jsonutils.loads(catalog_header)
+        except ValueError:
+            raise webob.exc.HTTPInternalServerError(
+                explanation=_('Invalid service catalog json.'))
+
+    if CONF.use_forwarded_for:
+        remote_address = req.headers.get('X-Forwarded-For', remote_address)
+
+    kwargs.setdefault('remote_address', remote_address)
+    kwargs.setdefault('service_catalog', service_catalog)
+
+    # Preserve the timestamp set by the RequestId middleware
+    kwargs['timestamp'] = getattr(req.environ.get('cinder.context'),
+                                  'timestamp',
+                                  None)
+
+    # request ID and global ID are present in the environment req.environ
+    ctx = context.RequestContext.from_environ(req.environ, **kwargs)
+    req.environ['cinder.context'] = ctx
+    return ctx
+
+
 class InjectContext(base_wsgi.Middleware):
     """Add a 'cinder.context' to WSGI environ."""
 
@@ -75,53 +104,25 @@ class InjectContext(base_wsgi.Middleware):
 
 class CinderKeystoneContext(base_wsgi.Middleware):
     """Make a request context from keystone headers."""
+    ENV_OVERWRITES = {
+        'X_PROJECT_DOMAIN_ID': 'project_domain_id',
+        'X_PROJECT_DOMAIN_NAME': 'project_domain_name',
+        'X_USER_DOMAIN_ID': 'user_domain_id',
+        'X_USER_DOMAIN_NAME': 'user_domain_name',
+    }
 
     @webob.dec.wsgify(RequestClass=base_wsgi.Request)
     def __call__(self, req):
-
+        params = {'project_name': req.headers.get('X_TENANT_NAME')}
-        # NOTE(jamielennox): from_environ handles these in newer versions
+        for env_name, param_name in self.ENV_OVERWRITES.items():
-        project_name = req.headers.get('X_TENANT_NAME')
+            if req.environ.get(env_name):
-        req_id = req.environ.get(request_id.ENV_REQUEST_ID)
+                params[param_name] = req.environ[env_name]
-
+        ctx = _set_request_context(req, **params)
-        # Build a context, including the auth_token...
-        remote_address = req.remote_addr
-
-        service_catalog = None
-        if req.headers.get('X_SERVICE_CATALOG') is not None:
-            try:
-                catalog_header = req.headers.get('X_SERVICE_CATALOG')
-                service_catalog = jsonutils.loads(catalog_header)
-            except ValueError:
-                raise webob.exc.HTTPInternalServerError(
-                    explanation=_('Invalid service catalog json.'))
-
-        if CONF.use_forwarded_for:
-            remote_address = req.headers.get('X-Forwarded-For', remote_address)
-
-        ctx = context.RequestContext.from_environ(
-            req.environ,
-            request_id=req_id,
-            remote_address=remote_address,
-            project_name=project_name,
-            service_catalog=service_catalog)
 
         if ctx.user_id is None:
             LOG.debug("Neither X_USER_ID nor X_USER found in request")
             return webob.exc.HTTPUnauthorized()
 
-        if req.environ.get('X_PROJECT_DOMAIN_ID'):
-            ctx.project_domain_id = req.environ['X_PROJECT_DOMAIN_ID']
-
-        if req.environ.get('X_PROJECT_DOMAIN_NAME'):
-            ctx.project_domain_name = req.environ['X_PROJECT_DOMAIN_NAME']
-
-        if req.environ.get('X_USER_DOMAIN_ID'):
-            ctx.user_domain_id = req.environ['X_USER_DOMAIN_ID']
-
-        if req.environ.get('X_USER_DOMAIN_NAME'):
-            ctx.user_domain_name = req.environ['X_USER_DOMAIN_NAME']
-
-        req.environ['cinder.context'] = ctx
         return self.application
 
 
@@ -149,15 +150,8 @@ class NoAuthMiddlewareBase(base_wsgi.Middleware):
         token = req.headers['X-Auth-Token']
         user_id, _sep, project_id = token.partition(':')
         project_id = project_id or user_id
-        remote_address = getattr(req, 'remote_address', '127.0.0.1')
+        _set_request_context(req, user_id=user_id, project_id=project_id,
-        if CONF.use_forwarded_for:
+                             is_admin=True)
-            remote_address = req.headers.get('X-Forwarded-For', remote_address)
-        ctx = context.RequestContext(user_id,
-                                     project_id,
-                                     is_admin=True,
-                                     remote_address=remote_address)
-
-        req.environ['cinder.context'] = ctx
         return self.application
 
 

cinder/api/middleware/request_id.py

@@ -0,0 +1,71 @@
+# Copyright 2022 Red Hat, Inc.
+# All Rights Reserved.
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+from oslo_log import log as logging
+from oslo_middleware import request_id as oslo_req_id
+from oslo_utils import timeutils
+
+from cinder import context as cinder_context
+
+
+LOG = logging.getLogger(__name__)
+
+
+class RequestId(oslo_req_id.RequestId):
+    def _context_setter(self, environ, *args, **kwargs):
+        """Wrapper to set a temporary context.
+
+        It is necessary to replace the previous request's context, but at this
+        point when we are generating the new request ID we don't have the
+        keystone info, so use a placeholder with the information we have:
+
+        - global_request_id ==> Extracted from the headers by the parent class
+        - request_id => Generated by the parent class __call__ method
+        - timestamp => The moment Cinder API starts processing the request
+
+        This middleware needs to be the first in ALL the pipelines for things
+        to work as expected, otherwise we'll have the following issues:
+
+        - Logs from other filters reuse a context from a previous request,
+          presenting the wrong request id and project and user info, and then
+          after the request passes the auth filter the request id will change
+          to the right one.  We'll see this when enabling debug mode in the
+          keystonemiddleware module.
+
+        - Requests that don't require authorization (/ and /healthcheck) won't
+          return a request ID in the headers.
+        """
+        # Replace previous request's context with all the info we have now
+        placeholder_ctx = cinder_context.RequestContext(
+            request_id=environ[oslo_req_id.ENV_REQUEST_ID],
+            global_request_id=environ.get(oslo_req_id.GLOBAL_REQ_ID),
+            timestamp=timeutils.utcnow(),
+        )
+
+        # Only update environ, oslo_context local store was updated
+        # automatically when instantiating the request context.
+        environ['cinder.context'] = placeholder_ctx
+
+        # Have a timestamped log with the start of the pipeline processing.
+        LOG.debug('RequestId filter calling following filter/app')
+        return self._application(environ, *args, **kwargs)
+
+    def __init__(self, *args, **kwargs):
+        # Parent __call__ method creates the request id and makes the call to
+        # the chained app one after the other, so we need a wrapper on the app
+        # to set the context.
+        super().__init__(*args, **kwargs)
+        self._application = self.application
+        self.application = self._context_setter

etc/cinder/api-paste.ini

@@ -10,13 +10,10 @@ use = call:cinder.api:root_app_factory
 
 [composite:openstack_volume_api_v3]
 use = call:cinder.api.middleware.auth:pipeline_factory
-noauth = cors http_proxy_to_wsgi request_id faultwrap sizelimit osprofiler noauth apiv3
+noauth = request_id cors http_proxy_to_wsgi faultwrap sizelimit osprofiler noauth apiv3
-noauth_include_project_id = cors http_proxy_to_wsgi request_id faultwrap sizelimit osprofiler noauth_include_project_id apiv3
+noauth_include_project_id = request_id cors http_proxy_to_wsgi faultwrap sizelimit osprofiler noauth_include_project_id apiv3
-keystone = cors http_proxy_to_wsgi request_id faultwrap sizelimit osprofiler authtoken keystonecontext apiv3
+keystone = request_id cors http_proxy_to_wsgi faultwrap sizelimit osprofiler authtoken keystonecontext apiv3
-keystone_nolimit = cors http_proxy_to_wsgi request_id faultwrap sizelimit osprofiler authtoken keystonecontext apiv3
+keystone_nolimit = request_id cors http_proxy_to_wsgi faultwrap sizelimit osprofiler authtoken keystonecontext apiv3
-
-[filter:request_id]
-paste.filter_factory = oslo_middleware.request_id:RequestId.factory
 
 [filter:http_proxy_to_wsgi]
 paste.filter_factory = oslo_middleware.http_proxy_to_wsgi:HTTPProxyToWSGI.factory
@@ -44,11 +41,19 @@ paste.filter_factory = oslo_middleware.sizelimit:RequestBodySizeLimiter.factory
 paste.app_factory = cinder.api.v3.router:APIRouter.factory
 
 [pipeline:apiversions]
-pipeline = cors http_proxy_to_wsgi faultwrap osvolumeversionapp
+pipeline = request_id cors http_proxy_to_wsgi faultwrap osvolumeversionapp
 
 [app:osvolumeversionapp]
 paste.app_factory = cinder.api.versions:Versions.factory
 
+[pipeline:healthcheck]
+pipeline = request_id healthcheckapp
+
+[app:healthcheckapp]
+paste.app_factory = oslo_middleware:Healthcheck.app_factory
+backends = disable_by_file
+disable_by_file_path = /etc/cinder/healthcheck_disable
+
 ##########
 # Shared #
 ##########
@@ -59,7 +64,5 @@ paste.filter_factory = cinder.api.middleware.auth:CinderKeystoneContext.factory
 [filter:authtoken]
 paste.filter_factory = keystonemiddleware.auth_token:filter_factory
 
-[app:healthcheck]
+[filter:request_id]
-paste.app_factory = oslo_middleware:Healthcheck.app_factory
+paste.filter_factory = cinder.api.middleware.request_id:RequestId.factory
-backends = disable_by_file
-disable_by_file_path = /etc/cinder/healthcheck_disable

releasenotes/notes/fix-request_id-6f6972b2c12d1a18.yaml

@@ -0,0 +1,15 @@
+---
+fixes:
+  - |
+    `Bug #1960019 <https://bugs.launchpad.net/cinder/+bug/1960019>`_: Fixed
+    value of the x-openstack-request-id header when Cinder is using noauth.
+  - |
+    `Bug #1960020 <https://bugs.launchpad.net/cinder/+bug/1960020>`_: Fixed
+    duplicated request-id values in logs for different requests, happens only
+    on request to / to get available api versions.
+  - |
+    `Bug #1960021 <https://bugs.launchpad.net/cinder/+bug/1960021>`_: Fixed
+    missing request id headers in requests to / to get available api versions.
+  - |
+    `Bug #1960329 <https://bugs.launchpad.net/cinder/+bug/1960329>`_: Fixed
+    wrong request ID on middleware filters.