openstack/swift
Code Issues Proposed changes

Merge "proxy-logging: add fields ttfb and pid"

Browse Source
This commit is contained in:
Zuul 2020-01-31 19:01:09 +00:00 committed by Gerrit Code Review
commit e73619b25a
4 changed files with 26 additions and 33 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
doc/manpages/proxy-server.conf.5
View File

@ -766,10 +766,12 @@ Template used to format access logs. All words surrounded by curly brackets will
.IP "log_info"
.IP "start_time (timestamp at the receiving, timestamp)"
.IP "end_time (timestamp at the end of the treatment, timestamp)"
.IP "ttfb (duration between request and first bytes is sent)"
.IP "policy_index"
.IP "account (account name, anonymizable)"
.IP "container (container name, anonymizable)"
.IP "object (object name, anonymizable)"
.IP "pid (PID of the process emitting the log line)"
.PD
.RE

2
doc/source/logs.rst
View File

@ -84,6 +84,7 @@ start_time High-resolution timestamp from the start of the request.
(timestamp)
end_time High-resolution timestamp from the end of the request.
(timestamp)
ttfb Duration between the request and the first bytes is sent.
policy_index The value of the storage policy index.
account The account part extracted from the path of the request.
(anonymizable)
@ -91,6 +92,7 @@ container The container part extracted from the path of the request.
(anonymizable)
object The object part extracted from the path of the request.
(anonymizable)
pid PID of the process emitting the log line.
=================== ==========================================================
In one log line, all of the above fields are space-separated and url-encoded.

23
swift/common/middleware/proxy_logging.py
View File

@ -71,6 +71,7 @@ if this is a middleware subrequest or not. A log processor calculating
bandwidth usage will want to only sum up logs with no swift.source.
"""
import os
import time
from swift.common.swob import Request
@ -90,6 +91,7 @@ class ProxyLoggingMiddleware(object):
def __init__(self, app, conf, logger=None):
self.app = app
self.pid = os.getpid()
self.log_formatter = LogStringFormatter(default='-', quote=True)
self.log_msg_template = conf.get(
'log_msg_template', (
@ -171,7 +173,9 @@ class ProxyLoggingMiddleware(object):
'request_time': '0.05',
'source': '',
'log_info': '',
'policy_index': ''
'policy_index': '',
'ttfb': '0.05',
'pid': '42'
}
try:
self.log_formatter.format(self.log_msg_template, **replacements)
@ -193,7 +197,7 @@ class ProxyLoggingMiddleware(object):
return value
def log_request(self, req, status_int, bytes_received, bytes_sent,
start_time, end_time, resp_headers=None):
start_time, end_time, resp_headers=None, ttfb=0):
"""
Log a request.
@ -269,6 +273,8 @@ class ProxyLoggingMiddleware(object):
'log_info':
','.join(req.environ.get('swift.log_info', '')),
'policy_index': policy_index,
'ttfb': ttfb,
'pid': self.pid,
}
self.access_logger.info(
self.log_formatter.format(self.log_msg_template,
@ -377,18 +383,20 @@ class ProxyLoggingMiddleware(object):
# Log timing information for time-to-first-byte (GET requests only)
method = self.method_from_req(req)
ttfb = 0.0
if method == 'GET':
status_int = status_int_for_logging()
policy_index = get_policy_index(req.headers, resp_headers)
metric_name = self.statsd_metric_name(req, status_int, method)
metric_name_policy = self.statsd_metric_name_policy(
req, status_int, method, policy_index)
ttfb = time.time() - start_time
if metric_name:
self.access_logger.timing_since(
metric_name + '.first-byte.timing', start_time)
self.access_logger.timing(
metric_name + '.first-byte.timing', ttfb * 1000)
if metric_name_policy:
self.access_logger.timing_since(
metric_name_policy + '.first-byte.timing', start_time)
self.access_logger.timing(
metric_name_policy + '.first-byte.timing', ttfb * 1000)
bytes_sent = 0
client_disconnect = False
@ -406,7 +414,8 @@ class ProxyLoggingMiddleware(object):
status_int = status_int_for_logging(client_disconnect)
self.log_request(
req, status_int, input_proxy.bytes_received, bytes_sent,
start_time, time.time(), resp_headers=resp_headers)
start_time, time.time(), resp_headers=resp_headers,
ttfb=ttfb)
close_method = getattr(iterable, 'close', None)
if callable(close_method):
close_method()

32
test/unit/common/middleware/test_proxy_logging.py
View File

@ -128,21 +128,6 @@ class TestProxyLogging(unittest.TestCase):
self.fail('assertTiming: %s not found in %r' % (
exp_metric, timing_calls))
def assertTimingSince(self, exp_metric, app, exp_start=None):
timing_calls = app.access_logger.log_dict['timing_since']
found = False
for timing_call in timing_calls:
self.assertEqual({}, timing_call[1])
self.assertEqual(2, len(timing_call[0]))
if timing_call[0][0] == exp_metric:
found = True
if exp_start is not None:
self.assertAlmostEqual(exp_start, timing_call[0][1],
places=4)
if not found:
self.fail('assertTimingSince: %s not found in %r' % (
exp_metric, timing_calls))
def assertNotTiming(self, not_exp_metric, app):
timing_calls = app.access_logger.log_dict['timing']
for timing_call in timing_calls:
@ -211,15 +196,12 @@ class TestProxyLogging(unittest.TestCase):
req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET',
'wsgi.input': BytesIO(b'4321')})
stub_times = [18.0, 20.71828182846]
stub_times = [18.0, 18.5, 20.71828182846]
iter_response = app(req.environ, lambda *_: None)
self.assertEqual(b'7654321', b''.join(iter_response))
self.assertTiming('%s.GET.321.timing' % exp_type, app,
exp_timing=2.71828182846 * 1000)
self.assertTimingSince(
'%s.GET.321.first-byte.timing' % exp_type, app,
exp_start=18.0)
if exp_type == 'object':
# Object operations also return stats by policy
# In this case, the value needs to match the timing for GET
@ -245,15 +227,12 @@ class TestProxyLogging(unittest.TestCase):
req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET',
'wsgi.input': BytesIO(b'4321')})
stub_times = [18.0, 20.71828182846]
stub_times = [18.0, 18.5, 20.71828182846]
iter_response = app(req.environ, lambda *_: None)
self.assertEqual(b'7654321', b''.join(iter_response))
self.assertTiming('%s.GET.321.timing' % exp_type, app,
exp_timing=2.71828182846 * 1000)
self.assertTimingSince(
'%s.GET.321.first-byte.timing' % exp_type, app,
exp_start=18.0)
# No results returned for the non-existent policy
self.assertUpdateStats([('%s.GET.321.xfer' % exp_type,
4 + 7)],
@ -415,12 +394,12 @@ class TestProxyLogging(unittest.TestCase):
'template which can be edited in config: '
'{protocol} {path} {method} '
'{path.anonymized} {container.anonymized} '
'{request_time} {start_time.datetime} {end_time} ')})
'{request_time} {start_time.datetime} {end_time} {ttfb}')})
app.access_logger = FakeLogger()
req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
with mock.patch('time.time',
mock.MagicMock(
side_effect=[10000000.0, 10000001.0])):
side_effect=[10000000.0, 10000000.5, 10000001.0])):
resp = app(req.environ, start_response)
resp_body = b''.join(resp)
# exhaust generator
@ -435,6 +414,7 @@ class TestProxyLogging(unittest.TestCase):
self.assertEqual(log_parts[11], '-')
self.assertEqual(log_parts[13], '26/Apr/1970/17/46/40')
self.assertEqual(log_parts[14], '10000001.000000000')
self.assertEqual(log_parts[15], '0.5')
self.assertEqual(resp_body, b'FAKE APP')
def test_invalid_log_config(self):
@ -936,7 +916,7 @@ class TestProxyLogging(unittest.TestCase):
req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
with mock.patch('time.time',
mock.MagicMock(
side_effect=[10000000.0, 10000001.0])):
side_effect=[10000000.0, 10000000.5, 10000001.0])):
resp = app(req.environ, start_response)
resp_body = b''.join(resp)
log_parts = self._log_parts(app)