diff --git a/doc/manpages/proxy-server.conf.5 b/doc/manpages/proxy-server.conf.5 index b23a3a72cb..5ebeef43af 100644 --- a/doc/manpages/proxy-server.conf.5 +++ b/doc/manpages/proxy-server.conf.5 @@ -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 diff --git a/doc/source/logs.rst b/doc/source/logs.rst index e2cd553dc4..cc34215861 100644 --- a/doc/source/logs.rst +++ b/doc/source/logs.rst @@ -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. diff --git a/swift/common/middleware/proxy_logging.py b/swift/common/middleware/proxy_logging.py index 52caed7f58..072ed7e5cb 100644 --- a/swift/common/middleware/proxy_logging.py +++ b/swift/common/middleware/proxy_logging.py @@ -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() diff --git a/test/unit/common/middleware/test_proxy_logging.py b/test/unit/common/middleware/test_proxy_logging.py index ccaa3b9204..29bcd33d8c 100644 --- a/test/unit/common/middleware/test_proxy_logging.py +++ b/test/unit/common/middleware/test_proxy_logging.py @@ -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)