openstack/swift
Code Issues Proposed changes

Merge "Output logs of policy index"

Browse Source
This commit is contained in:
Jenkins 2015-02-10 22:21:13 +00:00 committed by Gerrit Code Review
commit 0186194e96
9 changed files with 109 additions and 16 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
doc/source/logs.rst
View File

@ -32,7 +32,7 @@ is::
client_ip remote_addr datetime request_method request_path protocol
status_int referer user_agent auth_token bytes_recvd bytes_sent
client_etag transaction_id headers request_time source log_info
request_start_time request_end_time
request_start_time request_end_time policy_index
=================== ==========================================================
**Log Field** **Value**
@ -66,6 +66,7 @@ log_info Various info that may be useful for diagnostics, e.g. the
value of any x-delete-at header.
request_start_time High-resolution timestamp from the start of the request.
request_end_time High-resolution timestamp from the end of the request.
policy_index The value of the storage policy index.
=================== ==========================================================
In one log line, all of the above fields are space-separated and url-encoded.
@ -114,7 +115,7 @@ these log lines is::
remote_addr - - [datetime] "request_method request_path" status_int
content_length "referer" "transaction_id" "user_agent" request_time
additional_info
additional_info server_pid policy_index
=================== ==========================================================
**Log Field** **Value**
@ -136,4 +137,5 @@ user_agent The value of the HTTP User-Agent header. Swift services
request_time The duration of the request.
additional_info Additional useful information.
server_pid The process id of the server
policy_index The value of the storage policy index.
=================== ==========================================================

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

@ -77,7 +77,7 @@ from urllib import quote, unquote
from swift.common.swob import Request
from swift.common.utils import (get_logger, get_remote_client,
get_valid_utf8_str, config_true_value,
InputProxy, list_from_csv)
InputProxy, list_from_csv, get_policy_index)
QUOTE_SAFE = '/:'
@ -135,7 +135,7 @@ class ProxyLoggingMiddleware(object):
return value
def log_request(self, req, status_int, bytes_received, bytes_sent,
start_time, end_time):
start_time, end_time, resp_headers=None):
"""
Log a request.
@ -145,7 +145,9 @@ class ProxyLoggingMiddleware(object):
:param bytes_sent: bytes yielded to the WSGI server
:param start_time: timestamp request started
:param end_time: timestamp request completed
:param resp_headers: dict of the response headers
"""
resp_headers = resp_headers or {}
req_path = get_valid_utf8_str(req.path)
the_request = quote(unquote(req_path), QUOTE_SAFE)
if req.query_string:
@ -166,6 +168,7 @@ class ProxyLoggingMiddleware(object):
duration_time_str = "%.4f" % (end_time - start_time)
start_time_str = "%.9f" % start_time
end_time_str = "%.9f" % end_time
policy_index = get_policy_index(req.headers, resp_headers)
self.access_logger.info(' '.join(
quote(str(x) if x else '-', QUOTE_SAFE)
for x in (
@ -188,7 +191,8 @@ class ProxyLoggingMiddleware(object):
req.environ.get('swift.source'),
','.join(req.environ.get('swift.log_info') or ''),
start_time_str,
end_time_str
end_time_str,
policy_index
)))
# Log timing and bytes-transferred data to StatsD
metric_name = self.statsd_metric_name(req, status_int, method)
@ -257,6 +261,7 @@ class ProxyLoggingMiddleware(object):
elif isinstance(iterable, list):
start_response_args[0][1].append(
('Content-Length', str(sum(len(i) for i in iterable))))
resp_headers = dict(start_response_args[0][1])
start_response(*start_response_args[0])
req = Request(env)
@ -283,7 +288,7 @@ 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())
start_time, time.time(), resp_headers=resp_headers)
try:
iterable = self.app(env, my_start_response)

20
swift/common/utils.py
View File

@ -329,6 +329,21 @@ def generate_trans_id(trans_id_suffix):
uuid.uuid4().hex[:21], time.time(), quote(trans_id_suffix))
def get_policy_index(req_headers, res_headers):
"""
Returns the appropriate index of the storage policy for the request from
a proxy server
:param req: dict of the request headers.
:param res: dict of the response headers.
:returns: string index of storage policy, or None
"""
header = 'X-Backend-Storage-Policy-Index'
policy_index = res_headers.get(header, req_headers.get(header))
return str(policy_index) if policy_index is not None else None
def get_log_line(req, res, trans_time, additional_info):
"""
Make a line for logging that matches the documented log line format
@ -342,14 +357,15 @@ def get_log_line(req, res, trans_time, additional_info):
:returns: a properly formated line for logging.
"""
return '%s - - [%s] "%s %s" %s %s "%s" "%s" "%s" %.4f "%s" %d' % (
policy_index = get_policy_index(req.headers, res.headers)
return '%s - - [%s] "%s %s" %s %s "%s" "%s" "%s" %.4f "%s" %d %s' % (
req.remote_addr,
time.strftime('%d/%b/%Y:%H:%M:%S +0000', time.gmtime()),
req.method, req.path, res.status.split()[0],
res.content_length or '-', req.referer or '-',
req.headers.get('x-trans-id', '-'),
req.user_agent or '-', trans_time, additional_info or '-',
os.getpid())
os.getpid(), policy_index or '-')
def get_trans_id_time(trans_id):

8
swift/container/server.py
View File

@ -378,9 +378,13 @@ class ContainerController(BaseStorageServer):
if resp:
return resp
if created:
return HTTPCreated(request=req)
return HTTPCreated(request=req,
headers={'x-backend-storage-policy-index':
broker.storage_policy_index})
else:
return HTTPAccepted(request=req)
return HTTPAccepted(request=req,
headers={'x-backend-storage-policy-index':
broker.storage_policy_index})
@public
@timing_stats(sample_rate=0.1)

2
test/unit/account/test_server.py
View File

@ -1722,7 +1722,7 @@ class TestAccountController(unittest.TestCase):
self.assertEqual(
self.controller.logger.log_dict['info'],
[(('1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD /sda1/p/a" 404 '
'- "-" "-" "-" 2.0000 "-" 1234',), {})])
'- "-" "-" "-" 2.0000 "-" 1234 -',), {})])
def test_policy_stats_with_legacy(self):
ts = itertools.count()

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

@ -752,7 +752,7 @@ class TestProxyLogging(unittest.TestCase):
resp = app(req.environ, start_response)
resp_body = ''.join(resp)
log_parts = self._log_parts(app)
self.assertEquals(len(log_parts), 20)
self.assertEquals(len(log_parts), 21)
self.assertEquals(log_parts[0], '-')
self.assertEquals(log_parts[1], '-')
self.assertEquals(log_parts[2], '26/Apr/1970/17/46/41')
@ -774,6 +774,7 @@ class TestProxyLogging(unittest.TestCase):
self.assertEquals(log_parts[17], '-')
self.assertEquals(log_parts[18], '10000000.000000000')
self.assertEquals(log_parts[19], '10000001.000000000')
self.assertEquals(log_parts[20], '-')
def test_dual_logging_middlewares(self):
# Since no internal request is being made, outer most proxy logging
@ -856,6 +857,39 @@ class TestProxyLogging(unittest.TestCase):
self.assertEquals(resp_body, 'FAKE MIDDLEWARE')
self.assertEquals(log_parts[11], str(len(resp_body)))
def test_policy_index(self):
# Policy index can be specified by X-Backend-Storage-Policy-Index
# in the request header for object API
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
app.access_logger = FakeLogger()
req = Request.blank('/v1/a/c/o', environ={'REQUEST_METHOD': 'PUT'},
headers={'X-Backend-Storage-Policy-Index': '1'})
resp = app(req.environ, start_response)
''.join(resp)
log_parts = self._log_parts(app)
self.assertEquals(log_parts[20], '1')
# Policy index can be specified by X-Backend-Storage-Policy-Index
# in the response header for container API
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
app.access_logger = FakeLogger()
req = Request.blank('/v1/a/c', environ={'REQUEST_METHOD': 'GET'})
def fake_call(app, env, start_response):
start_response(app.response_str,
[('Content-Type', 'text/plain'),
('Content-Length', str(sum(map(len, app.body)))),
('X-Backend-Storage-Policy-Index', '1')])
while env['wsgi.input'].read(5):
pass
return app.body
with mock.patch.object(FakeApp, '__call__', fake_call):
resp = app(req.environ, start_response)
''.join(resp)
log_parts = self._log_parts(app)
self.assertEquals(log_parts[20], '1')
if __name__ == '__main__':
unittest.main()

29
test/unit/common/test_utils.py
View File

@ -2713,6 +2713,33 @@ cluster_dfw1 = http://dfw1.host/v1/
utils.get_hmac('GET', '/path', 1, 'abc'),
'b17f6ff8da0e251737aa9e3ee69a881e3e092e2f')
def test_get_policy_index(self):
# Account has no information about a policy
req = Request.blank(
'/sda1/p/a',
environ={'REQUEST_METHOD': 'GET'})
res = Response()
self.assertEquals(None, utils.get_policy_index(req.headers,
res.headers))
# The policy of a container can be specified by the response header
req = Request.blank(
'/sda1/p/a/c',
environ={'REQUEST_METHOD': 'GET'})
res = Response(headers={'X-Backend-Storage-Policy-Index': '1'})
self.assertEquals('1', utils.get_policy_index(req.headers,
res.headers))
# The policy of an object to be created can be specified by the request
# header
req = Request.blank(
'/sda1/p/a/c/o',
environ={'REQUEST_METHOD': 'PUT'},
headers={'X-Backend-Storage-Policy-Index': '2'})
res = Response()
self.assertEquals('2', utils.get_policy_index(req.headers,
res.headers))
def test_get_log_line(self):
req = Request.blank(
'/sda1/p/a/c/o',
@ -2722,7 +2749,7 @@ cluster_dfw1 = http://dfw1.host/v1/
additional_info = 'some information'
server_pid = 1234
exp_line = '1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD ' \
'/sda1/p/a/c/o" 200 - "-" "-" "-" 1.2000 "some information" 1234'
'/sda1/p/a/c/o" 200 - "-" "-" "-" 1.2000 "some information" 1234 -'
with mock.patch(
'time.gmtime',
mock.MagicMock(side_effect=[time.gmtime(10001.0)])):

7
test/unit/container/test_server.py
View File

@ -386,6 +386,8 @@ class TestContainerController(unittest.TestCase):
policy.idx})
resp = req.get_response(self.controller)
self.assertEquals(resp.status_int, 201)
self.assertEquals(resp.headers.get('X-Backend-Storage-Policy-Index'),
str(policy.idx))
# now make sure we read it back
req = Request.blank('/sda1/p/a/c', environ={'REQUEST_METHOD': 'GET'})
@ -399,6 +401,8 @@ class TestContainerController(unittest.TestCase):
headers={'X-Timestamp': Timestamp(1).internal})
resp = req.get_response(self.controller)
self.assertEquals(resp.status_int, 201)
self.assertEquals(resp.headers.get('X-Backend-Storage-Policy-Index'),
str(POLICIES.default.idx))
# now make sure the default was used (pol 1)
req = Request.blank('/sda1/p/a/c', environ={'REQUEST_METHOD': 'GET'})
@ -414,6 +418,7 @@ class TestContainerController(unittest.TestCase):
resp = req.get_response(self.controller)
# make sure we get bad response
self.assertEquals(resp.status_int, 400)
self.assertNotIn('X-Backend-Storage-Policy-Index', resp.headers)
def test_PUT_no_policy_change(self):
ts = (Timestamp(t).internal for t in itertools.count(time.time()))
@ -2595,7 +2600,7 @@ class TestContainerController(unittest.TestCase):
self.assertEqual(
self.controller.logger.log_dict['info'],
[(('1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD /sda1/p/a/c" '
'404 - "-" "-" "-" 2.0000 "-" 1234',), {})])
'404 - "-" "-" "-" 2.0000 "-" 1234 0',), {})])
@patch_policies([

4
test/unit/obj/test_server.py
View File

@ -4168,7 +4168,7 @@ class TestObjectController(unittest.TestCase):
self.object_controller.logger.log_dict['info'],
[(('None - - [01/Jan/1970:02:46:41 +0000] "PUT'
' /sda1/p/a/c/o" 405 - "-" "-" "-" 1.0000 "-"'
' 1234',),
' 1234 -',),
{})])
def test_call_incorrect_replication_method(self):
@ -4350,7 +4350,7 @@ class TestObjectController(unittest.TestCase):
self.assertEqual(
self.object_controller.logger.log_dict['info'],
[(('1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD /sda1/p/a/c/o" '
'404 - "-" "-" "-" 2.0000 "-" 1234',), {})])
'404 - "-" "-" "-" 2.0000 "-" 1234 -',), {})])
@patch_policies([storage_policy.StoragePolicy(0, 'zero', True),
storage_policy.StoragePolicy(1, 'one', False)])