openstack/swift
Code Issues Proposed changes

Merge "Add accurate timestamps in proxy log"

Browse Source
This commit is contained in:
Jenkins 2013-12-03 03:51:42 +00:00 committed by Gerrit Code Review
commit 645d1c93c5
2 changed files with 28 additions and 19 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -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)

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

@ -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__':