proxy-logging: add fields ttfb and pid

Change-Id: I1611e34846e586703e9d3709fa64e8df41f2d685

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
 

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.

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(
+                    self.access_logger.timing(
-                        metric_name + '.first-byte.timing', start_time)
+                        metric_name + '.first-byte.timing', ttfb * 1000)
                 if metric_name_policy:
-                    self.access_logger.timing_since(
+                    self.access_logger.timing(
-                        metric_name_policy + '.first-byte.timing', start_time)
+                        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()

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)