From d4e02a2e8b50ae9272efc07cd44217333b4aacd6 Mon Sep 17 00:00:00 2001 From: Peter Portante Date: Thu, 19 Sep 2013 16:56:07 -0400 Subject: [PATCH] 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 --- swift/common/middleware/proxy_logging.py | 24 ++++++++++++------- .../common/middleware/test_proxy_logging.py | 23 +++++++++--------- 2 files changed, 28 insertions(+), 19 deletions(-) diff --git a/swift/common/middleware/proxy_logging.py b/swift/common/middleware/proxy_logging.py index 00d182f772..c63425968c 100644 --- a/swift/common/middleware/proxy_logging.py +++ b/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, - time.time() - start_time) + req, status_int, input_proxy.bytes_received, 0, start_time, + time.time()) raise else: return iter_response(iterable) diff --git a/test/unit/common/middleware/test_proxy_logging.py b/test/unit/common/middleware/test_proxy_logging.py index 1629503f88..9663de6858 100644 --- a/test/unit/common/middleware/test_proxy_logging.py +++ b/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', - time=mock.MagicMock( - side_effect=[10000000.0, 10000001.0]), - gmtime=mock.MagicMock( - side_effect=[ - time.gmtime(10000001.00001)])): + with mock.patch('time.time', + mock.MagicMock( + side_effect=[10000000.0, 10000001.0])): 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__':