Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
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
- Loading branch information
Showing
4 changed files
with
268 additions
and
5 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -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) |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -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) |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -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. |