diff --git a/etc/nova/api-paste.ini b/etc/nova/api-paste.ini index f180ab315198..a0563938007a 100644 --- a/etc/nova/api-paste.ini +++ b/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 -keystone = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler authtoken keystonecontext 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 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 -keystone = cors http_proxy_to_wsgi compute_req_id faultwrap sizelimit osprofiler authtoken keystonecontext 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 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 diff --git a/nova/api/openstack/requestlog.py b/nova/api/openstack/requestlog.py new file mode 100644 index 000000000000..85c0e8ed5725 --- /dev/null +++ b/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) diff --git a/nova/tests/unit/api/openstack/test_requestlog.py b/nova/tests/unit/api/openstack/test_requestlog.py new file mode 100644 index 000000000000..7c89acd62da0 --- /dev/null +++ b/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) diff --git a/releasenotes/notes/request_log-e7680b3276910743.yaml b/releasenotes/notes/request_log-e7680b3276910743.yaml new file mode 100644 index 000000000000..2df38af374c0 --- /dev/null +++ b/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.