request_log addition for running under uwsgi

If someone chooses to run under uwsgi/apache instead of eventlet, the
basic logging of requests goes away (as that was an eventlet.wsgi
function). This is a critical piece of information for understanding
how services are working, and we need to retain it under uwsgi/apache.

This creates a new request_log middleware, inspired by the one in
placement, to provide that functionality. This includes all the same
information as before: http method, uri, status, content length, time
for the request. It also includes the microversion the request was
processed as, "-" if no microversion.

The middleware does not emit anything if it detects that it's running
under eventlet, to prevent duplicate log messages.

Release notes provided as this will be a manual transition for folks
as it's an api-paste.ini change.

Change-Id: I3a597b06d3501c765e2d7805c6c1375d6f4e40db

etc/nova/api-paste.ini

@@ -28,17 +28,20 @@ use = call:nova.api.openstack.urlmap:urlmap_factory
 
 [composite:openstack_compute_api_v21]
 use = call:nova.api.auth:pipeline_factory_v21
-noauth2 = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler noauth2 osapi_compute_app_v21
+noauth2 = cors http_proxy_to_wsgi compute_req_id faultwrap request_log sizelimit osprofiler noauth2 osapi_compute_app_v21
-keystone = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler authtoken keystonecontext osapi_compute_app_v21
+keystone = cors http_proxy_to_wsgi compute_req_id faultwrap request_log sizelimit osprofiler authtoken keystonecontext osapi_compute_app_v21
 
 [composite:openstack_compute_api_v21_legacy_v2_compatible]
 use = call:nova.api.auth:pipeline_factory_v21
-noauth2 = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler noauth2 legacy_v2_compatible osapi_compute_app_v21
+noauth2 = cors http_proxy_to_wsgi compute_req_id faultwrap request_log sizelimit osprofiler noauth2 legacy_v2_compatible osapi_compute_app_v21
-keystone = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler authtoken keystonecontext legacy_v2_compatible osapi_compute_app_v21
+keystone = cors http_proxy_to_wsgi compute_req_id faultwrap request_log sizelimit osprofiler authtoken keystonecontext legacy_v2_compatible osapi_compute_app_v21
 
 [filter:request_id]
 paste.filter_factory = oslo_middleware:RequestId.factory
 
+[filter:request_log]
+paste.filter_factory = nova.api.openstack.requestlog:RequestLog.factory
+
 [filter:compute_req_id]
 paste.filter_factory = nova.api.compute_req_id:ComputeReqIdMiddleware.factory
 
@@ -64,7 +67,7 @@ paste.filter_factory = nova.api.openstack:LegacyV2CompatibleWrapper.factory
 paste.app_factory = nova.api.openstack.compute:APIRouterV21.factory
 
 [pipeline:oscomputeversions]
-pipeline = cors faultwrap http_proxy_to_wsgi oscomputeversionapp
+pipeline = cors faultwrap request_log http_proxy_to_wsgi oscomputeversionapp
 
 [app:oscomputeversionapp]
 paste.app_factory = nova.api.openstack.compute.versions:Versions.factory

nova/api/openstack/requestlog.py

@@ -0,0 +1,92 @@
+# 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.
+"""Simple middleware for request logging."""
+
+import time
+
+from oslo_log import log as logging
+from oslo_utils import excutils
+import webob.dec
+import webob.exc
+
+from nova.api.openstack import wsgi
+from nova import wsgi as base_wsgi
+
+# TODO(sdague) maybe we can use a better name here for the logger
+LOG = logging.getLogger(__name__)
+
+
+class RequestLog(base_wsgi.Middleware):
+    """WSGI Middleware to write a simple request log to.
+
+    Borrowed from Paste Translogger
+    """
+
+    # This matches the placement fil
+    _log_format = ('%(REMOTE_ADDR)s "%(REQUEST_METHOD)s %(REQUEST_URI)s" '
+                   'status: %(status)s len: %(len)s '
+                   'microversion: %(microversion)s time: %(time).6f')
+
+    @staticmethod
+    def _get_uri(environ):
+        req_uri = (environ.get('SCRIPT_NAME', '') +
+                   environ.get('PATH_INFO', ''))
+        if environ.get('QUERY_STRING'):
+            req_uri += '?' + environ['QUERY_STRING']
+        return req_uri
+
+    @staticmethod
+    def _should_emit(req):
+        """Conditions under which we should skip logging.
+
+        If we detect we are running under eventlet wsgi processing, we
+        already are logging things, let it go. This is broken out as a
+        separate method so that it can be easily adjusted for testing.
+        """
+        if req.environ.get('eventlet.input', None) is not None:
+            return False
+        return True
+
+    def _log_req(self, req, res, start):
+        if not self._should_emit(req):
+            return
+
+        # in the event that things exploded really badly deeper in the
+        # wsgi stack, res is going to be an empty dict for the
+        # fallback logging. So never count on it having attributes.
+        status = getattr(res, "status", "500 Error").split(None, 1)[0]
+        data = {
+            'REMOTE_ADDR': req.environ.get('REMOTE_ADDR', '-'),
+            'REQUEST_METHOD': req.environ['REQUEST_METHOD'],
+            'REQUEST_URI': self._get_uri(req.environ),
+            'status': status,
+            'len': getattr(res, "content_length", 0),
+            'time': time.time() - start,
+            'microversion': '-'
+        }
+        # set microversion if it exists
+        if not req.api_version_request.is_null():
+            data["microversion"] = req.api_version_request.get_string()
+        LOG.info(self._log_format, data)
+
+    @webob.dec.wsgify(RequestClass=wsgi.Request)
+    def __call__(self, req):
+        res = {}
+        start = time.time()
+        try:
+            res = req.get_response(self.application)
+            self._log_req(req, res, start)
+            return res
+        except Exception:
+            with excutils.save_and_reraise_exception():
+                self._log_req(req, res, start)

nova/tests/unit/api/openstack/test_requestlog.py

@@ -0,0 +1,157 @@
+# Copyright 2017 IBM Corp.
+# 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.
+
+import mock
+
+import fixtures as fx
+import testtools
+
+from nova.tests import fixtures
+from nova.tests.unit import conf_fixture
+
+"""Test request logging middleware under various conditions.
+
+The request logging middleware is needed when running under something
+other than eventlet. While Nova grew up on eventlet, and it's wsgi
+server, it meant that our user facing data (the log stream) was a mix
+of what Nova was emitting, and what eventlet.wsgi was emitting on our
+behalf. When running under uwsgi we want to make sure that we have
+equivalent coverage.
+
+All these tests use GET / to hit an endpoint that doesn't require the
+database setup. We have to do a bit of mocking to make that work.
+"""
+
+
+class TestRequestLogMiddleware(testtools.TestCase):
+
+    def setUp(self):
+        super(TestRequestLogMiddleware, self).setUp()
+        # this is the minimal set of magic mocks needed to convince
+        # the API service it can start on it's own without a database.
+        mocks = ['nova.objects.Service.get_by_host_and_binary',
+                 'nova.objects.Service.create']
+        for m in mocks:
+            p = mock.patch(m)
+            self.addCleanup(p.stop)
+            p.start()
+
+    @mock.patch('nova.api.openstack.requestlog.RequestLog._should_emit')
+    def test_logs_requests(self, emit):
+        """Ensure requests are logged.
+
+        Make a standard request for / and ensure there is a log entry.
+        """
+
+        emit.return_value = True
+        self.useFixture(fixtures.OutputStreamCapture())
+        log = fixtures.StandardLogging()
+        self.useFixture(log)
+        self.useFixture(conf_fixture.ConfFixture())
+        self.useFixture(fixtures.RPCFixture('nova.test'))
+        api = self.useFixture(fixtures.OSAPIFixture()).api
+
+        resp = api.api_request('/', strip_version=True)
+        log1 = ('INFO [nova.api.openstack.requestlog] 127.0.0.1 '
+                '"GET /v2" status: 204 len: 0 microversion: - time:')
+        self.assertIn(log1, log.logger.output)
+
+        # the content length might vary, but the important part is
+        # what we log is what we return to the user (which turns out
+        # to excitingly not be the case with eventlet!)
+        content_length = resp.headers['content-length']
+
+        log2 = ('INFO [nova.api.openstack.requestlog] 127.0.0.1 '
+                '"GET /" status: 200 len: %s' % content_length)
+        self.assertIn(log2, log.logger.output)
+
+    @mock.patch('nova.api.openstack.requestlog.RequestLog._should_emit')
+    def test_logs_mv(self, emit):
+        """Ensure logs register microversion if passed.
+
+        This makes sure that microversion logging actually shows up
+        when appropriate.
+        """
+
+        emit.return_value = True
+        self.useFixture(fixtures.OutputStreamCapture())
+        log = fixtures.StandardLogging()
+        self.useFixture(log)
+        self.useFixture(conf_fixture.ConfFixture())
+        # NOTE(sdague): all these tests are using the
+        self.useFixture(
+            fx.MonkeyPatch(
+                'nova.api.openstack.compute.versions.'
+                'Versions.support_api_request_version',
+            True))
+
+        self.useFixture(fixtures.RPCFixture('nova.test'))
+
+        api = self.useFixture(fixtures.OSAPIFixture()).api
+        api.microversion = '2.25'
+
+        resp = api.api_request('/', strip_version=True)
+        content_length = resp.headers['content-length']
+
+        log1 = ('INFO [nova.api.openstack.requestlog] 127.0.0.1 '
+                '"GET /" status: 200 len: %s microversion: 2.25 time:' %
+                content_length)
+        self.assertIn(log1, log.logger.output)
+
+    @mock.patch('nova.api.openstack.compute.versions.Versions.index')
+    @mock.patch('nova.api.openstack.requestlog.RequestLog._should_emit')
+    def test_logs_under_exception(self, emit, v_index):
+        """Ensure that logs still emit under unexpected failure.
+
+        If we get an unexpected failure all the way up to the top, we should
+        still have a record of that request via the except block.
+        """
+
+        emit.return_value = True
+        v_index.side_effect = Exception("Unexpected Error")
+        self.useFixture(fixtures.OutputStreamCapture())
+        log = fixtures.StandardLogging()
+        self.useFixture(log)
+        self.useFixture(conf_fixture.ConfFixture())
+        self.useFixture(fixtures.RPCFixture('nova.test'))
+        api = self.useFixture(fixtures.OSAPIFixture()).api
+
+        api.api_request('/', strip_version=True)
+        log1 = ('INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /"'
+                ' status: 500 len: 0 microversion: - time:')
+        self.assertIn(log1, log.logger.output)
+
+    @mock.patch('nova.api.openstack.requestlog.RequestLog._should_emit')
+    def test_no_log_under_eventlet(self, emit):
+        """Ensure that logs don't end up under eventlet.
+
+        We still set the _should_emit return value directly to prevent
+        the situation where eventlet is removed from tests and this
+        preventing that.
+
+        NOTE(sdague): this test can be deleted when eventlet is no
+        longer supported for the wsgi stack in Nova.
+        """
+
+        emit.return_value = False
+        self.useFixture(fixtures.OutputStreamCapture())
+        log = fixtures.StandardLogging()
+        self.useFixture(log)
+        self.useFixture(conf_fixture.ConfFixture())
+        self.useFixture(fixtures.RPCFixture('nova.test'))
+        api = self.useFixture(fixtures.OSAPIFixture()).api
+
+        api.api_request('/', strip_version=True)
+        self.assertNotIn("nova.api.openstack.requestlog", log.logger.output)

releasenotes/notes/request_log-e7680b3276910743.yaml

@@ -0,0 +1,11 @@
+---
+upgrade:
+  - |
+    A new request_log middleware is created to log REST HTTP requests
+    even if Nova API is not running under eventlet.wsgi. Because this
+    is an api-paste.ini change, you will need to manually update your
+    api-paste.ini with the one from the release to get this
+    functionality. The new request logs will only emit when it is
+    detected that nova-api is not running under eventlet, and will
+    include the microversion of the request in addition to all the
+    previously logged information.