Merge request log and request id middlewares

This is done to ensure that both are in the outermost
piece of middleware so that we generate and log the
global request id (if any) as early as possible, and
use it, and the local request id, throughout the entire
middleware stack.

This turned out to be somewhat more complex than desired
because:

* The request id middleware from oslo_middleware is a webob
  wsgi app, so we need to map the request log middleware to
  that style (meaning more changes than strictly necessary).

* The __call__ in the request id middleware is not composed
  to make calling it as a super clean, so instead of doing that
  we are copying code. Which implies some risks for which we
  may wish to consider workarounds.

This is an alternative to I5a80056dd88836a4e79a649fa02d36dc7e75eee4

Change-Id: I7e24b54bfcd296f13ea4f65dbb10ba63679c05b1

placement/deploy.py

@@ -62,7 +62,6 @@ def deploy(conf):
         cors_middleware = None
 
     context_middleware = auth.PlacementKeystoneContext
-    req_id_middleware = oslo_middleware.RequestId
     microversion_middleware = mp_middleware.MicroversionMiddleware
     fault_middleware = fault_wrap.FaultWrapper
     request_log = requestlog.RequestLog
@@ -87,7 +86,7 @@ def deploy(conf):
         json_error_formatter=util.json_error_formatter)
 
     # NOTE(cdent): The ordering here is important. The list is ordered
-    # from the inside out. For a single request req_id_middleware is called
+    # from the inside out. For a single request request_log is called
     # first and microversion_middleware last. Then the request is finally
     # passed to the application (the PlacementHandler). At that point
     # the response ascends the middleware in the reverse of the
@@ -95,11 +94,10 @@ def deploy(conf):
     # all see the same contextual information including request id and
     # authentication information.
     for middleware in (fault_middleware,
-                       request_log,
                        context_middleware,
                        auth_middleware,
                        cors_middleware,
-                       req_id_middleware,
+                       request_log,
                        osprofiler_middleware,
                        ):
         if middleware:

placement/requestlog.py

@@ -10,19 +10,30 @@
 # implied.
 # See the License for the specific language governing permissions and
 # limitations under the License.
-"""Simple middleware for request logging."""
+"""Simple middleware for request logging that also sets request id.
 
+We combine these two pieces of functionality in one middleware because we want
+to be sure that we have a DEBUG log at the very start of the request, with a
+a global request id, and an INFO log at the very end of the request.
+"""
+
+from oslo_context import context
 from oslo_log import log as logging
+from oslo_middleware import request_id
+import webob.dec
 
 from placement import microversion
 
 LOG = logging.getLogger(__name__)
 
 
-class RequestLog(object):
-    """WSGI Middleware to write a simple request log to.
+class RequestLog(request_id.RequestId):
+    """WSGI Middleware to write a simple request log with a global request id.
 
-    Borrowed from Paste Translogger
+    Borrowed from Paste Translogger and incorporating
+    oslo_middleware.request_id.RequestId.
+
+    This also guards against a missing "Accept" header.
     """
 
     format = ('%(REMOTE_ADDR)s "%(REQUEST_METHOD)s %(REQUEST_URI)s" '
@@ -32,19 +43,41 @@ class RequestLog(object):
     def __init__(self, application):
         self.application = application
 
-    def __call__(self, environ, start_response):
+    @webob.dec.wsgify
+    def __call__(self, req):
+        # This duplicates code from __call__ on RequestId, but because of the
+        # way that method is structured, calling super is not workable.
+        self.set_global_req_id(req)
+
+        # We must instantiate a Request context, otherwise the LOG in the
+        # next line will not produce the expected output where we would expect
+        # to see request ids. Instead we get '[-]'. Presumably there be magic
+        # here...
+        ctx = context.RequestContext.from_environ(req.environ)
+        req.environ[request_id.ENV_REQUEST_ID] = ctx.request_id
+
         LOG.debug('Starting request: %s "%s %s"',
-                  environ['REMOTE_ADDR'], environ['REQUEST_METHOD'],
-                  self._get_uri(environ))
+                  req.remote_addr, req.method,
+                  self._get_uri(req.environ))
+
         # Set the accept header if it is not otherwise set or is '*/*'. This
         # ensures that error responses will be in JSON.
-        accept = environ.get('HTTP_ACCEPT')
+        accept = req.environ.get('HTTP_ACCEPT')
         if not accept or accept == '*/*':
-            environ['HTTP_ACCEPT'] = 'application/json'
+            req.environ['HTTP_ACCEPT'] = 'application/json'
+
         if LOG.isEnabledFor(logging.INFO):
-            return self._log_app(environ, start_response)
+            response = req.get_response(self._log_app)
         else:
-            return self.application(environ, start_response)
+            response = req.get_response(self.application)
+
+        return_headers = [request_id.HTTP_RESP_HEADER_REQUEST_ID]
+        return_headers.extend(self.compat_headers)
+
+        for header in return_headers:
+            if header not in response.headers:
+                response.headers.add(header, ctx.request_id)
+        return response
 
     @staticmethod
     def _get_uri(environ):