Add accurate timestamps in proxy log

Add accurate timestamps to the proxy-logging middleware log lines for
the start and end of a request. We use 9 digits of precision since on
some systems the clock resolution can be as fine as 1 ns.

The goal is to allow for log processing that can use the more accurate
timestamps to correlate requests, computing number of requests in
flight at a given historical point in time.

Change-Id: I61e8784b1c455d629f1299207fc4fc7e4a134814
Signed-off-by: Peter Portante <peter.portante@redhat.com>

swift/common/middleware/proxy_logging.py

@@ -131,7 +131,7 @@ class ProxyLoggingMiddleware(object):
         return value
 
     def log_request(self, req, status_int, bytes_received, bytes_sent,
-                    request_time):
+                    start_time, end_time):
         """
         Log a request.
 
@@ -139,7 +139,8 @@ class ProxyLoggingMiddleware(object):
         :param status_int: integer code for the response status
         :param bytes_received: bytes successfully read from the request body
         :param bytes_sent: bytes yielded to the WSGI server
-        :param request_time: time taken to satisfy the request, in seconds
+        :param start_time: timestamp request started
+        :param end_time: timestamp request completed
         """
         if self.req_already_logged(req):
             return
@@ -152,12 +153,17 @@ class ProxyLoggingMiddleware(object):
             logged_headers = '\n'.join('%s: %s' % (k, v)
                                        for k, v in req.headers.items())
         method = self.method_from_req(req)
+        end_gmtime_str = time.strftime('%d/%b/%Y/%H/%M/%S',
+                                       time.gmtime(end_time))
+        duration_time_str = "%.4f" % (end_time - start_time)
+        start_time_str = "%.9f" % start_time
+        end_time_str = "%.9f" % end_time
         self.access_logger.info(' '.join(
             quote(str(x) if x else '-', QUOTE_SAFE)
             for x in (
                 get_remote_client(req),
                 req.remote_addr,
-                time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()),
+                end_gmtime_str,
                 method,
                 the_request,
                 req.environ.get('SERVER_PROTOCOL'),
@@ -170,9 +176,11 @@ class ProxyLoggingMiddleware(object):
                 req.headers.get('etag', None),
                 req.environ.get('swift.trans_id'),
                 logged_headers,
-                '%.4f' % request_time,
+                duration_time_str,
                 req.environ.get('swift.source'),
                 ','.join(req.environ.get('swift.log_info') or ''),
+                start_time_str,
+                end_time_str
             )))
         self.mark_req_logged(req)
         # Log timing and bytes-transfered data to StatsD
@@ -181,7 +189,7 @@ class ProxyLoggingMiddleware(object):
         # down (egregious errors will get logged by the proxy server itself).
         if metric_name:
             self.access_logger.timing(metric_name + '.timing',
-                                      request_time * 1000)
+                                      (end_time - start_time) * 1000)
             self.access_logger.update_stats(metric_name + '.xfer',
                                             bytes_received + bytes_sent)
 
@@ -263,7 +271,7 @@ class ProxyLoggingMiddleware(object):
                 status_int = status_int_for_logging(client_disconnect)
                 self.log_request(
                     req, status_int, input_proxy.bytes_received, bytes_sent,
-                    time.time() - start_time)
+                    start_time, time.time())
 
         try:
             iterable = self.app(env, my_start_response)
@@ -271,8 +279,8 @@ class ProxyLoggingMiddleware(object):
             req = Request(env)
             status_int = status_int_for_logging(start_status=500)
             self.log_request(
-                req, status_int, input_proxy.bytes_received, 0,
+                req, status_int, input_proxy.bytes_received, 0, start_time,
-                time.time() - start_time)
+                time.time())
             raise
         else:
             return iter_response(iterable)

test/unit/common/middleware/test_proxy_logging.py

@@ -14,7 +14,6 @@
 # limitations under the License.
 
 import unittest
-import time
 from urllib import unquote
 import cStringIO as StringIO
 from logging.handlers import SysLogHandler
@@ -152,7 +151,8 @@ class TestProxyLogging(unittest.TestCase):
             app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
             app.access_logger = FakeLogger()
             req = Request.blank(bad_path, environ={'REQUEST_METHOD': 'GET'})
-            app.log_request(req, 123, 7, 13, 2.71828182846)
+            now = 10000.0
+            app.log_request(req, 123, 7, 13, now, now + 2.71828182846)
             self.assertEqual([], app.access_logger.log_dict['timing'])
             self.assertEqual([], app.access_logger.log_dict['update_stats'])
 
@@ -254,7 +254,8 @@ class TestProxyLogging(unittest.TestCase):
             app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
             app.access_logger = FakeLogger()
             req = Request.blank('/v1/a/', environ={'REQUEST_METHOD': method})
-            app.log_request(req, 299, 11, 3, 1.17)
+            now = 10000.0
+            app.log_request(req, 299, 11, 3, now, now + 1.17)
             self.assertTiming('account.%s.299.timing' % exp_method, app,
                               exp_timing=1.17 * 1000)
             self.assertUpdateStats('account.%s.299.xfer' % exp_method,
@@ -280,7 +281,8 @@ class TestProxyLogging(unittest.TestCase):
                 app.access_logger = FakeLogger()
                 req = Request.blank('/v1/a/c',
                                     environ={'REQUEST_METHOD': method})
-                app.log_request(req, 911, 4, 43, 1.01)
+                now = 10000.0
+                app.log_request(req, 911, 4, 43, now, now + 1.01)
                 self.assertTiming('container.%s.911.timing' % exp_method, app,
                                   exp_timing=1.01 * 1000)
                 self.assertUpdateStats('container.%s.911.xfer' % exp_method,
@@ -706,16 +708,13 @@ class TestProxyLogging(unittest.TestCase):
         app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
         app.access_logger = FakeLogger()
         req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
-        with mock.patch.multiple('time',
+        with mock.patch('time.time',
-                                 time=mock.MagicMock(
+                        mock.MagicMock(
-                                     side_effect=[10000000.0, 10000001.0]),
+                            side_effect=[10000000.0, 10000001.0])):
-                                 gmtime=mock.MagicMock(
-                                     side_effect=[
-                                         time.gmtime(10000001.00001)])):
             resp = app(req.environ, start_response)
             resp_body = ''.join(resp)
         log_parts = self._log_parts(app)
-        self.assertEquals(len(log_parts), 18)
+        self.assertEquals(len(log_parts), 20)
         self.assertEquals(log_parts[0], '-')
         self.assertEquals(log_parts[1], '-')
         self.assertEquals(log_parts[2], '26/Apr/1970/17/46/41')
@@ -735,6 +734,8 @@ class TestProxyLogging(unittest.TestCase):
         self.assertEquals(log_parts[15], '1.0000')
         self.assertEquals(log_parts[16], '-')
         self.assertEquals(log_parts[17], '-')
+        self.assertEquals(log_parts[18], '10000000.000000000')
+        self.assertEquals(log_parts[19], '10000001.000000000')
 
 
 if __name__ == '__main__':