Add labeled metrics to proxy-logging
Modified code to use native labeled metrics API introduced by the Related-Change. Co-Authored-By: Tim Burke <tim.burke@gmail.com> Co-Authored-By: Alistair Coles <alistairncoles@gmail.com> Co-Authored-By: Shreeya Deshpande <shreeyad@nvidia.com> Co-Authored-By: Clay Gerrard <clay.gerrard@gmail.com> Related-Change: I115ffb1dc601652a979895d7944e011b951a91c1 Change-Id: I5a96626862644fe23a0d4bc53e85989770c8ceec
This commit is contained in:
Yan Xiao
committed by
Shreeya Deshpande
parent
b735b3d034
commit
82b1964479
2 changed files with 661 additions and 167 deletions
@@ -23,14 +23,14 @@ from logging.handlers import SysLogHandler
from urllib.parse import unquote
from swift.common.utils import get_swift_logger, split_path
from swift.common.statsd_client import StatsdClient
from swift.common.middleware import proxy_logging
from swift.common.registry import register_sensitive_header, \
register_sensitive_param, get_sensitive_headers
from swift.common.swob import Request, Response, HTTPServiceUnavailable
from swift.common import constraints, registry
from swift.common import constraints, registry, statsd_client
from swift.common.storage_policy import StoragePolicy
from test.debug_logger import debug_logger, FakeStatsdClient
from test.debug_logger import debug_logger, FakeStatsdClient, \
FakeLabeledStatsdClient, debug_labeled_statsd_client
from test.unit import patch_policies
from test.unit.common.middleware.helpers import FakeAppThatExcepts, FakeSwift
@@ -124,6 +124,52 @@ class TestProxyLogging(unittest.TestCase):
# get_logger, ultimately tracing back to our hard-coded
# statsd_tail_prefix
self.logger.logger.statsd_client._prefix = 'proxy-server.'
conf = {
'log_statsd_host': 'host',
'log_statsd_port': 8125,
'statsd_label_mode': 'dogstatsd',
'statsd_emit_legacy': True,
}
self.statsd = debug_labeled_statsd_client(conf)
account_labels = {
'account': 'a',
'resource': 'account',
}
container_labels = {
'account': 'a',
'container': 'c',
'resource': 'container',
}
object_labels = {
'account': 'a',
'container': 'c',
'resource': 'object',
'policy': '0',
}
self.path_labels = {
'/v1/a': account_labels,
'/v1/a/': account_labels,
'/v1/a/c': container_labels,
'/v1/a/c/': container_labels,
'/v1/a/c/o': object_labels,
'/v1/a/c/o/': object_labels,
'/v1/a/c/o/p': object_labels,
'/v1/a/c/o/p/': object_labels,
'/v1/a/c/o/p/p2': object_labels,
'/v1.0/a': account_labels,
'/v1.0/a/': account_labels,
'/v1.0/a/c': container_labels,
'/v1.0/a/c/': container_labels,
'/v1.0/a/c/o': object_labels,
'/v1.0/a/c/o/': object_labels,
'/v1.0/a/c/o/p': object_labels,
'/v1.0/a/c/o/p/': object_labels,
'/v1.0/a/c/o/p/p2': object_labels,
}
def _clear(self):
self.logger.clear()
self.statsd.clear()
def _log_parts(self, app, should_be_empty=False):
info_calls = app.access_logger.log_dict['info']
@@ -169,7 +215,24 @@ class TestProxyLogging(unittest.TestCase):
('host', 8125)),
app.access_logger.statsd_client.sendto_calls)
def test_init_statsd_options_log_prefix(self):
def assertLabeledTimingStats(self, exp_metrics_values_labels):
statsd_calls = self.statsd.calls['timing']
exp_calls = []
for metric, value, labels in exp_metrics_values_labels:
exp_calls.append(((metric, mock.ANY), {'labels': labels}))
self.assertEqual(exp_calls, statsd_calls)
for i, (metric, value, labels) in enumerate(exp_metrics_values_labels):
self.assertAlmostEqual(
value, statsd_calls[i][0][1], places=4, msg=i)
def assertLabeledUpdateStats(self, exp_metrics_values_labels):
statsd_calls = self.statsd.calls['update_stats']
exp_calls = []
for metric, value, labels in exp_metrics_values_labels:
exp_calls.append(((metric, value), {'labels': labels}))
self.assertEqual(exp_calls, statsd_calls)
def test_init_logger_and_legacy_statsd_options_log_prefix(self):
conf = {
'log_headers': 'no',
'log_statsd_valid_http_methods': 'GET',
@@ -208,7 +271,7 @@ class TestProxyLogging(unittest.TestCase):
[(b'foo.proxy-server.baz:1|c|@0.4', ('example.com', 1234))],
statsd_client.sendto_calls)
def test_init_statsd_options_access_log_prefix(self):
def test_init_logger_and_legacy_statsd_options_access_log_prefix(self):
# verify that access_log_ prefix has precedence over log_
conf = {
'access_log_route': 'my-proxy-access',
@@ -261,12 +324,78 @@ class TestProxyLogging(unittest.TestCase):
[(b'access_foo.proxy-server.baz:1|c|@0.6', ('access.com', 5678))],
statsd_client.sendto_calls)
def test_init_labeled_statsd_options_log_prefix(self):
# verify that log_ prefix options are passed to LabeledStatsdClient
conf = {
'log_statsd_host': 'example.com',
'log_statsd_port': '1234',
'log_statsd_default_sample_rate': 10,
'log_statsd_sample_rate_factor': .04,
'statsd_label_mode': 'dogstatsd',
}
with mock.patch('swift.common.statsd_client.LabeledStatsdClient',
FakeLabeledStatsdClient):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
statsd_client = app.statsd
self.assertIsInstance(statsd_client, FakeLabeledStatsdClient)
with mock.patch.object(statsd_client, 'random', return_value=0):
statsd_client.increment('baz', labels={'test': 'label'})
self.assertEqual(
[(b'baz:1|c|@0.4|#test:label', ('example.com', 1234))],
statsd_client.sendto_calls)
def test_init_labeled_statsd_options_access_log_prefix(self):
# verify that access_log_ prefix has precedence over log_ prefix
conf = {
'access_log_statsd_host': 'access.com',
'access_log_statsd_port': '5678',
'access_log_statsd_default_sample_rate': 20,
'access_log_statsd_sample_rate_factor': .03,
'log_statsd_host': 'example.com',
'log_statsd_port': '1234',
'log_statsd_default_sample_rate': 10,
'log_statsd_sample_rate_factor': .04,
'statsd_label_mode': 'dogstatsd',
}
with mock.patch('swift.common.statsd_client.LabeledStatsdClient',
FakeLabeledStatsdClient):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
statsd_client = app.statsd
self.assertIsInstance(statsd_client, FakeLabeledStatsdClient)
with mock.patch.object(statsd_client, 'random', return_value=0):
statsd_client.increment('baz', labels={'test': 'label'})
self.assertEqual(
[(b'baz:1|c|@0.6|#test:label', ('access.com', 5678))],
statsd_client.sendto_calls)
def test_init_statsd_options_user_labels(self):
conf = {
'log_statsd_host': 'example.com',
'log_statsd_port': '1234',
'statsd_label_mode': 'dogstatsd',
'statsd_emit_legacy': False,
'statsd_user_label_reqctx': 'subrequest',
}
with mock.patch('swift.common.statsd_client.LabeledStatsdClient',
FakeLabeledStatsdClient):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
statsd = app.statsd
self.assertIsInstance(statsd, FakeLabeledStatsdClient)
with mock.patch.object(statsd, 'random', return_value=0):
statsd.increment('baz', labels={'label_foo': 'foo'})
self.assertEqual(
[(b'baz:1|c|#label_foo:foo,user_reqctx:subrequest',
('example.com', 1234))],
statsd.sendto_calls)
def test_logger_statsd_prefix(self):
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(), {'log_statsd_host': 'example.com'})
self.assertIsNotNone(app.access_logger.logger.statsd_client)
self.assertIsInstance(app.access_logger.logger.statsd_client,
StatsdClient)
statsd_client.StatsdClient)
self.assertEqual('proxy-server.',
app.access_logger.logger.statsd_client._prefix)
@@ -277,99 +406,161 @@ class TestProxyLogging(unittest.TestCase):
'log_statsd_host': 'example.com'})
self.assertIsNotNone(app.access_logger.logger.statsd_client)
self.assertIsInstance(app.access_logger.logger.statsd_client,
StatsdClient)
statsd_client.StatsdClient)
self.assertEqual('foo.proxy-server.',
app.access_logger.logger.statsd_client._prefix)
def test_log_request_statsd_invalid_stats_types(self):
def test_log_request_stat_type_bad_GET(self):
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(), {}, logger=self.logger)
for url in ['/', '/foo', '/foo/bar', '/v1', '/v1.0']:
self.logger.clear()
req = Request.blank(url, environ={'REQUEST_METHOD': 'GET'})
FakeApp(body=b'7 bytes'), {}, logger=self.logger)
app.statsd = self.statsd
exp_labels = {'resource': 'UNKNOWN',
'method': 'GET',
'status': 200}
def do_test(bad_path):
self._clear()
req = Request.blank(bad_path, environ={'REQUEST_METHOD': 'GET'})
with mock.patch('time.time',
side_effect=[18.0, 18.5, 20.71828182846]):
resp = app(req.environ, start_response)
# get body
b''.join(resp)
self.assertTiming('UNKNOWN.GET.200.first-byte.timing', app, 500.0)
self.assertTiming('UNKNOWN.GET.200.timing', app,
2718.2818284600216)
self.assertUpdateStats([('UNKNOWN.GET.200.xfer', 7)], app)
self.assertLabeledTimingStats([
('swift_proxy_server_request_ttfb', 0.5 * 1000, exp_labels),
('swift_proxy_server_request_timing', 2.71828182846 * 1000,
exp_labels)
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 0, exp_labels),
('swift_proxy_server_response_body_bytes', 7, exp_labels),
])
do_test('')
do_test('/')
do_test('/bad')
do_test('/baddy/mc_badderson')
do_test('/v1')
do_test('/v1/')
do_test('/v1.0')
do_test('/v1.0/')
do_test('/v1.0//')
do_test('/v1.0//c')
do_test('/v1.0/a//')
do_test('/v1.0/a//o')
def _do_test_log_request_s3(self, method, path, backend_path):
self._clear()
fake_app = FakeApp(body=b'7 bytes')
def app_wrapper(env, start_response):
# Fake how s3api would set swift.backend_path. We need to set
# PATH_INFO to be the backend_path so that FakeApp does the right
# thing w.r.t. the policy index headers, but the original request's
# PATH_INFO should be unchanged.
env_copy = dict(env)
env_copy['PATH_INFO'] = backend_path
env['swift.backend_path'] = backend_path
return fake_app(env_copy, start_response)
app = proxy_logging.ProxyLoggingMiddleware(
app_wrapper, {}, logger=self.logger)
app.statsd = self.statsd
req = Request.blank(path, environ={'REQUEST_METHOD': method})
with mock.patch('time.time',
side_effect=[18.0, 18.5, 20.71828182846]):
resp = app(req.environ, start_response)
# get body
b''.join(resp)
self.assertEqual(
[(('UNKNOWN.GET.200.first-byte.timing', mock.ANY), {}),
(('UNKNOWN.GET.200.timing', mock.ANY), {})],
app.access_logger.statsd_client.calls['timing'])
self.assertEqual(
[(('UNKNOWN.GET.200.xfer', mock.ANY), {})],
app.access_logger.statsd_client.calls['update_stats'])
return app
def test_log_request_stat_type_bad(self):
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(), {}, logger=self.logger)
for bad_path in [
'',
'/',
'/bad',
'/baddy/mc_badderson',
'/v1',
'/v1/',
'/v1.0',
'/v1.0/',
'/v1.0//',
'/v1.0//c',
'/v1.0/a//',
'/v1.0/a//o',
]:
req = Request.blank(bad_path, environ={'REQUEST_METHOD': 'GET'})
now = 10000.0
app.log_request(req, 123, 7, 13, now, now + 2.71828182846)
self.assertEqual(
[(('UNKNOWN.GET.123.timing', 2718.2818284600216), {})],
app.access_logger.statsd_client.calls['timing'])
self.assertEqual(
[(('UNKNOWN.GET.123.xfer', 20), {})],
app.access_logger.statsd_client.calls['update_stats'])
app.access_logger.clear()
def test_log_request_stat_type_good_PUT_s3_container(self):
def check_stats(app, exp_labels):
self.assertTiming(
'container.PUT.200.timing', app, 500)
self.assertUpdateStats([('container.PUT.200.xfer', 7)], app)
self.assertLabeledTimingStats([
('swift_proxy_server_request_timing', 500, exp_labels)
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 0, exp_labels),
('swift_proxy_server_response_body_bytes', 7, exp_labels),
])
def test_log_request_stat_type_good(self):
exp_labels = {
'method': 'PUT',
'status': 200,
'resource': 'container',
'account': 'AUTH_test',
'container': 'bucket'}
check_stats(self._do_test_log_request_s3(
'PUT', '/bucket', '/v1/AUTH_test/bucket'), exp_labels)
# swift.backend_path is authoritative...
exp_labels['container'] = 'bucket+segments'
check_stats(self._do_test_log_request_s3(
'PUT', '/bucket', '/v1/AUTH_test/bucket+segments'), exp_labels)
def test_log_request_stat_type_good_GET_s3_object(self):
def check_stats(app, exp_labels):
self.assertTiming(
'object.GET.200.first-byte.timing', app, 500.0)
self.assertTiming(
'object.GET.200.timing', app, 2718.2818284600216)
self.assertUpdateStats(
[('object.GET.200.xfer', 7),
('object.policy.0.GET.200.xfer', 7)], app)
self.assertLabeledTimingStats([
('swift_proxy_server_request_ttfb', 0.5 * 1000, exp_labels),
('swift_proxy_server_request_timing', 2.71828182846 * 1000,
exp_labels)
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 0, exp_labels),
('swift_proxy_server_response_body_bytes', 7, exp_labels),
])
exp_labels = {
'method': 'GET',
'status': 200,
'resource': 'object',
'policy': '0',
'account': 'AUTH_test',
'container': 'bucket'}
check_stats(self._do_test_log_request_s3(
'GET', '/bucket/obj', '/v1/AUTH_test/bucket/obj'), exp_labels)
check_stats(self._do_test_log_request_s3(
'GET', '/bucket/obj/blah', '/v1/AUTH_test/bucket/obj/blah'),
exp_labels)
exp_labels['container'] = 'bucket+segments'
check_stats(self._do_test_log_request_s3(
'GET', '/bucket/obj', '/v1/AUTH_test/bucket+segments/obj1234'),
exp_labels)
def test_log_request_stat_type_good_GET(self):
"""
log_request() should send timing and byte-count counters for GET
requests. Also, __call__()'s iter_response() function should
statsd-log time to first byte (calling the passed-in start_response
function), but only for GET requests.
"""
stub_times = []
def stub_time():
return stub_times.pop(0)
path_types = {
'/v1/a': 'account',
'/v1/a/': 'account',
'/v1/a/c': 'container',
'/v1/a/c/': 'container',
'/v1/a/c/o': 'object',
'/v1/a/c/o/': 'object',
'/v1/a/c/o/p': 'object',
'/v1/a/c/o/p/': 'object',
'/v1/a/c/o/p/p2': 'object',
'/v1.0/a': 'account',
'/v1.0/a/': 'account',
'/v1.0/a/c': 'container',
'/v1.0/a/c/': 'container',
'/v1.0/a/c/o': 'object',
'/v1.0/a/c/o/': 'object',
'/v1.0/a/c/o/p': 'object',
'/v1.0/a/c/o/p/': 'object',
'/v1.0/a/c/o/p/p2': 'object',
}
with mock.patch("time.time", stub_time):
for path, exp_type in path_types.items():
# GET
self.logger.clear()
for path, exp_labels in self.path_labels.items():
self._clear()
with mock.patch("time.time",
side_effect=[18.0, 18.5, 20.71828182846]):
exp_labels = dict(exp_labels)
exp_type = exp_labels['resource']
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'7654321', response_str='321 Fubar'),
{},
logger=self.logger)
app.statsd = self.statsd
req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET',
'wsgi.input': BytesIO(b'4321')})
stub_times = [18.0, 18.5, 20.71828182846]
iter_response = app(req.environ, lambda *_: None)
self.assertEqual(b'7654321', b''.join(iter_response))
@@ -394,37 +585,80 @@ class TestProxyLogging(unittest.TestCase):
self.assertUpdateStats([('%s.GET.321.xfer' % exp_type,
4 + 7)],
app)
exp_labels.update({
'method': 'GET',
'status': 321,
})
self.assertLabeledTimingStats([
('swift_proxy_server_request_ttfb', 0.5 * 1000,
exp_labels),
('swift_proxy_server_request_timing', 2.71828182846 * 1000,
exp_labels)
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 4, exp_labels),
('swift_proxy_server_response_body_bytes', 7, exp_labels),
])
# GET Repeat the test above, but with a non-existent policy
# Do this only for object types
if exp_type == 'object':
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'7654321', response_str='321 Fubar',
policy_idx='-1'), {}, logger=self.logger)
req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET',
'wsgi.input': BytesIO(b'4321')})
stub_times = [18.0, 18.5, 20.71828182846]
iter_response = app(req.environ, lambda *_: None)
def test_log_request_stat_type_good_GET_no_policy(self):
# GET Repeat the test above, but with a non-existent policy
# Do this only for object types
for path, exp_labels in self.path_labels.items():
self._clear()
with mock.patch("time.time",
side_effect=[18.0, 18.5, 20.71828182846]):
exp_labels = dict(exp_labels)
exp_type = exp_labels['resource']
if exp_type != 'object':
continue
self.assertEqual(b'7654321', b''.join(iter_response))
self.assertTiming('%s.GET.321.timing' % exp_type, app,
exp_timing=2.71828182846 * 1000)
# No results returned for the non-existent policy
self.assertUpdateStats([('%s.GET.321.xfer' % exp_type,
4 + 7)],
app)
# GET with swift.proxy_access_log_made already set
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'7654321', response_str='321 Fubar'), {})
app.access_logger= debug_logger()
FakeApp(body=b'7654321', response_str='321 Fubar',
policy_idx='-1'), {}, logger=self.logger)
app.statsd = self.statsd
req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET',
'wsgi.input': BytesIO(b'4321')})
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)
# No results returned for the non-existent policy
exp_labels.pop('policy')
exp_labels.update({
'method': 'GET',
'status': 321,
})
self.assertUpdateStats([('%s.GET.321.xfer' % exp_type,
4 + 7)],
app)
self.assertLabeledTimingStats([
('swift_proxy_server_request_ttfb', 0.5 * 1000,
exp_labels),
('swift_proxy_server_request_timing', 2.71828182846 * 1000,
exp_labels)
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 4, exp_labels),
('swift_proxy_server_response_body_bytes', 7, exp_labels),
])
def test_log_request_stat_type_good_GET_log_made(self):
# GET with swift.proxy_access_log_made already set
for path, exp_labels in self.path_labels.items():
self._clear()
with mock.patch("time.time",
side_effect=[18.0, 18.5, 20.71828182846]):
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'7654321', response_str='321 Fubar'), {},
logger=self.logger
)
app.statsd = self.statsd
req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET',
'swift.proxy_access_log_made': True,
'wsgi.input': BytesIO(b'4321')})
stub_times = [18.0, 20.71828182846]
iter_response = app(req.environ, lambda *_: None)
self.assertEqual(b'7654321', b''.join(iter_response))
self.assertEqual(
@@ -433,17 +667,25 @@ class TestProxyLogging(unittest.TestCase):
[], app.access_logger.statsd_client.calls['timing_since'])
self.assertEqual(
[], app.access_logger.statsd_client.calls['update_stats'])
self.assertLabeledUpdateStats([])
self.assertLabeledTimingStats([])
# PUT (no first-byte timing!)
self.logger.clear()
def test_log_request_stat_type_good_PUT(self):
# PUT (no first-byte timing!)
# (it's not a GET, so time() doesn't have a 2nd call)
for path, exp_labels in self.path_labels.items():
self._clear()
with mock.patch("time.time", side_effect=[58.2, 58.2 + 7.3321]):
exp_labels = dict(exp_labels)
exp_type = exp_labels['resource']
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'87654321', response_str='314 PiTown'), {},
logger=self.logger)
app.statsd = self.statsd
req = Request.blank(path, environ={
'REQUEST_METHOD': 'PUT',
'wsgi.input': BytesIO(b'654321')})
# (it's not a GET, so time() doesn't have a 2nd call)
stub_times = [58.2, 58.2 + 7.3321]
iter_response = app(req.environ, lambda *_: None)
self.assertEqual(b'87654321', b''.join(iter_response))
self.assertTiming('%s.PUT.314.timing' % exp_type, app,
@@ -461,33 +703,69 @@ class TestProxyLogging(unittest.TestCase):
self.assertUpdateStats(
[('object.PUT.314.xfer', 6 + 8),
('object.policy.0.PUT.314.xfer', 6 + 8)], app)
exp_labels['policy'] = '0'
else:
self.assertUpdateStats(
[('%s.PUT.314.xfer' % exp_type, 6 + 8)], app)
exp_labels.update({
'method': 'PUT',
'status': 314,
})
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 6, exp_labels),
('swift_proxy_server_response_body_bytes', 8, exp_labels),
])
self.assertLabeledTimingStats([
('swift_proxy_server_request_timing', 7.3321 * 1000,
exp_labels)
])
# PUT Repeat the test above, but with a non-existent policy
# Do this only for object types
if exp_type == 'object':
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'87654321', response_str='314 PiTown',
policy_idx='-1'), {}, logger=self.logger)
req = Request.blank(path, environ={
'REQUEST_METHOD': 'PUT',
'wsgi.input': BytesIO(b'654321')})
# (it's not a GET, so time() doesn't have a 2nd call)
stub_times = [58.2, 58.2 + 7.3321]
iter_response = app(req.environ, lambda *_: None)
self.assertEqual(b'87654321', b''.join(iter_response))
self.assertTiming('%s.PUT.314.timing' % exp_type, app,
exp_timing=7.3321 * 1000)
self.assertNotTiming(
'%s.GET.314.first-byte.timing' % exp_type, app)
self.assertNotTiming(
'%s.PUT.314.first-byte.timing' % exp_type, app)
# No results returned for the non-existent policy
self.assertUpdateStats(
[('object.PUT.314.xfer', 6 + 8)], app)
def test_log_request_stat_type_good_PUT_no_policy(self):
# PUT Repeat the test above, but with a non-existent policy
# Do this only for object types
for path, exp_labels in self.path_labels.items():
self._clear()
with mock.patch("time.time", side_effect=[58.2, 58.2 + 7.3321]):
exp_labels = dict(exp_labels)
exp_type = exp_labels['resource']
if exp_type != 'object':
continue
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'87654321', response_str='314 PiTown',
policy_idx='-1'), {}, logger=self.logger)
app.statsd = self.statsd
req = Request.blank(path, environ={
'REQUEST_METHOD': 'PUT',
'wsgi.input': BytesIO(b'654321')})
iter_response = app(req.environ, lambda *_: None)
self.assertEqual(b'87654321', b''.join(iter_response))
self.assertTiming('%s.PUT.314.timing' % exp_type, app,
exp_timing=7.3321 * 1000)
self.assertNotTiming(
'%s.GET.314.first-byte.timing' % exp_type, app)
self.assertNotTiming(
'%s.PUT.314.first-byte.timing' % exp_type, app)
# No results returned for the non-existent policy
exp_labels.pop('policy')
exp_labels.update({
'method': 'PUT',
'status': 314,
})
self.assertUpdateStats(
[('object.PUT.314.xfer', 6 + 8)], app)
self.assertLabeledTimingStats([
('swift_proxy_server_request_timing', 7.3321 * 1000,
exp_labels),
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 6, exp_labels),
('swift_proxy_server_response_body_bytes', 8, exp_labels),
])
self.assertLabeledTimingStats([
('swift_proxy_server_request_timing', 7.3321 * 1000,
exp_labels)
])
def test_log_request_stat_method_filtering_default(self):
method_map = {
@@ -504,16 +782,31 @@ class TestProxyLogging(unittest.TestCase):
'OPTIONS': 'OPTIONS',
}
for method, exp_method in method_map.items():
self.logger.clear()
self._clear()
app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(), {}, logger=self.logger)
app.statsd = self.statsd
req = Request.blank('/v1/a/', environ={'REQUEST_METHOD': method})
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,
11 + 3)], app)
self.assertUpdateStats([
('account.%s.299.xfer' % exp_method, 11 + 3),
], app)
exp_labels = {
'resource': 'account',
'method': exp_method,
'status': 299,
'account': 'a'
}
self.assertLabeledTimingStats([
('swift_proxy_server_request_timing', 1.17 * 1000, exp_labels),
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 11, exp_labels),
('swift_proxy_server_response_body_bytes', 3, exp_labels)
])
def test_log_request_stat_method_filtering_custom(self):
method_map = {
@@ -529,18 +822,35 @@ class TestProxyLogging(unittest.TestCase):
for conf_key in ['access_log_statsd_valid_http_methods',
'log_statsd_valid_http_methods']:
for method, exp_method in method_map.items():
self.logger.clear()
self._clear()
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {
conf_key: 'SPECIAL, GET,PUT ', # crazy spaces ok
}, logger=self.logger)
app.statsd = self.statsd
req = Request.blank('/v1/a/c',
environ={'REQUEST_METHOD': method})
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,
4 + 43)], app)
self.assertUpdateStats([
('container.%s.911.xfer' % exp_method, 4 + 43),
], app)
exp_labels = {
'resource': 'container',
'method': exp_method,
'status': 911,
'account': 'a',
'container': 'c'
}
self.assertLabeledTimingStats([
('swift_proxy_server_request_timing', 1.01 * 1000,
exp_labels),
])
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 4, exp_labels),
('swift_proxy_server_response_body_bytes', 43, exp_labels)
])
def test_basic_req(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
@@ -712,6 +1022,7 @@ class TestProxyLogging(unittest.TestCase):
'{protocol}{path}{method}'
'{account}{container}{object}')
}, logger=self.logger)
app.statsd = self.statsd
req = Request.blank('/bucket/path/to/key', environ={
'REQUEST_METHOD': 'GET',
# This would actually get set in the app, but w/e
@@ -733,9 +1044,26 @@ class TestProxyLogging(unittest.TestCase):
self.assertEqual(resp_body, b'FAKE APP')
self.assertTiming('object.policy.0.GET.200.timing',
app, exp_timing=2.71828182846 * 1000)
self.assertUpdateStats([('object.GET.200.xfer', 8),
('object.policy.0.GET.200.xfer', 8)],
app)
self.assertUpdateStats([
('object.GET.200.xfer', 8),
('object.policy.0.GET.200.xfer', 8),
], app)
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 0, {
'resource': 'object',
'method': 'GET',
'status': 200,
'account': 'AUTH_test',
'container': 'bucket',
'policy': '0'}),
('swift_proxy_server_response_body_bytes', 8, {
'resource': 'object',
'method': 'GET',
'status': 200,
'account': 'AUTH_test',
'container': 'bucket',
'policy': '0'})
])
def test_invalid_log_config(self):
with self.assertRaises(ValueError):
@@ -752,6 +1080,7 @@ class TestProxyLogging(unittest.TestCase):
def test_multi_segment_resp(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(
[b'some', b'chunks', b'of data']), {}, logger=self.logger)
app.statsd = self.statsd
req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
'swift.source': 'SOS'})
resp = app(req.environ, start_response)
@@ -763,12 +1092,23 @@ class TestProxyLogging(unittest.TestCase):
self.assertEqual(log_parts[6], '200')
self.assertEqual(resp_body, b'somechunksof data')
self.assertEqual(log_parts[11], str(len(resp_body)))
self.assertUpdateStats([('SOS.GET.200.xfer', len(resp_body))],
app)
self.assertUpdateStats([
('SOS.GET.200.xfer', len(resp_body)),
], app)
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 0, {
'resource': 'SOS',
'method': 'GET',
'status': 200}),
('swift_proxy_server_response_body_bytes', 17, {
'resource': 'SOS',
'method': 'GET',
'status': 200})
])
def test_log_headers(self):
for conf_key in ['access_log_headers', 'log_headers']:
self.logger.clear()
self._clear()
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
{conf_key: 'yes'},
logger=self.logger)
@@ -805,6 +1145,7 @@ class TestProxyLogging(unittest.TestCase):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
{'log_headers': 'yes'},
logger=self.logger)
app.statsd = self.statsd
req = Request.blank(
'/v1/a/c/o/foo',
environ={'REQUEST_METHOD': 'PUT',
@@ -815,17 +1156,35 @@ class TestProxyLogging(unittest.TestCase):
log_parts = self._log_parts(app)
self.assertEqual(log_parts[11], str(len('FAKE APP')))
self.assertEqual(log_parts[10], str(len('some stuff')))
self.assertUpdateStats([('object.PUT.200.xfer',
len('some stuff') + len('FAKE APP')),
('object.policy.0.PUT.200.xfer',
len('some stuff') + len('FAKE APP'))],
app)
self.assertUpdateStats([
('object.PUT.200.xfer',
len('some stuff') + len('FAKE APP')),
('object.policy.0.PUT.200.xfer',
len('some stuff') + len('FAKE APP')),
], app)
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 10, {
'resource': 'object',
'method': 'PUT',
'status': 200,
'account': 'a',
'container': 'c',
'policy': '0'}),
('swift_proxy_server_response_body_bytes', 8, {
'resource': 'object',
'method': 'PUT',
'status': 200,
'account': 'a',
'container': 'c',
'policy': '0'})
])
# Using a non-existent policy
self.logger.clear()
self._clear()
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(policy_idx='-1'),
{'log_headers': 'yes'},
logger=self.logger)
app.statsd = self.statsd
req = Request.blank(
'/v1/a/c/o/foo',
environ={'REQUEST_METHOD': 'PUT',
@@ -836,14 +1195,30 @@ class TestProxyLogging(unittest.TestCase):
log_parts = self._log_parts(app)
self.assertEqual(log_parts[11], str(len('FAKE APP')))
self.assertEqual(log_parts[10], str(len('some stuff')))
self.assertUpdateStats([('object.PUT.200.xfer',
len('some stuff') + len('FAKE APP'))],
app)
self.assertUpdateStats([
('object.PUT.200.xfer',
len('some stuff') + len('FAKE APP')),
], app)
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 10, {
'resource': 'object',
'method': 'PUT',
'status': 200,
'account': 'a',
'container': 'c'}),
('swift_proxy_server_response_body_bytes', 8, {
'resource': 'object',
'method': 'PUT',
'status': 200,
'account': 'a',
'container': 'c'})
])
def test_upload_size_no_policy(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(policy_idx=None),
{'log_headers': 'yes'},
logger=self.logger)
app.statsd = self.statsd
req = Request.blank(
'/v1/a/c/o/foo',
environ={'REQUEST_METHOD': 'PUT',
@@ -854,14 +1229,30 @@ class TestProxyLogging(unittest.TestCase):
log_parts = self._log_parts(app)
self.assertEqual(log_parts[11], str(len('FAKE APP')))
self.assertEqual(log_parts[10], str(len('some stuff')))
self.assertUpdateStats([('object.PUT.200.xfer',
len('some stuff') + len('FAKE APP'))],
app)
self.assertUpdateStats([
('object.PUT.200.xfer',
len('some stuff') + len('FAKE APP')),
], app)
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', 10, {
'resource': 'object',
'method': 'PUT',
'status': 200,
'account': 'a',
'container': 'c'}),
('swift_proxy_server_response_body_bytes', 8, {
'resource': 'object',
'method': 'PUT',
'status': 200,
'account': 'a',
'container': 'c'})
])
def test_upload_line(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(),
{'log_headers': 'yes'},
logger=self.logger)
app.statsd = self.statsd
req = Request.blank(
'/v1/a/c',
environ={'REQUEST_METHOD': 'POST',
@@ -872,9 +1263,24 @@ class TestProxyLogging(unittest.TestCase):
log_parts = self._log_parts(app)
self.assertEqual(log_parts[11], str(len('FAKE APP')))
self.assertEqual(log_parts[10], str(len('some stuff\n')))
self.assertUpdateStats([('container.POST.200.xfer',
len('some stuff\n') + len('FAKE APP'))],
app)
self.assertUpdateStats([
('container.POST.200.xfer',
len('some stuff\n') + len('FAKE APP')),
], app)
self.assertLabeledUpdateStats([
('swift_proxy_server_request_body_bytes', len('some stuff\n'), {
'resource': 'container',
'method': 'POST',
'status': 200,
'account': 'a',
'container': 'c'}),
('swift_proxy_server_response_body_bytes', len('FAKE APP'), {
'resource': 'container',
'method': 'POST',
'status': 200,
'account': 'a',
'container': 'c'})
])
def test_log_query_string(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
@@ -969,6 +1375,33 @@ class TestProxyLogging(unittest.TestCase):
handler = get_swift_logger.handler4logger[app.access_logger.logger]
self.assertEqual(SysLogHandler.LOG_LOCAL7, handler.facility)
def test_conf_statsd_label_mode(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
self.assertIsNone(app.statsd.label_formatter)
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
self.assertIsNone(app.statsd.label_formatter)
conf = {'statsd_label_mode': 'dogstatsd'}
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
self.assertEqual(statsd_client.dogstatsd, app.statsd.label_formatter)
conf = {'statsd_label_mode': 'graphite'}
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
self.assertEqual(statsd_client.graphite, app.statsd.label_formatter)
conf = {'statsd_label_mode': 'librato'}
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
self.assertEqual(statsd_client.librato, app.statsd.label_formatter)
conf = {'statsd_label_mode': 'influxdb'}
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
self.assertEqual(statsd_client.influxdb, app.statsd.label_formatter)
def test_conf_statsd_emit_legacy(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {})
self.assertTrue(app.access_logger.logger.statsd_client.emit_legacy)
conf = {'statsd_emit_legacy': 'no'}
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), conf)
self.assertFalse(app.access_logger.logger.statsd_client.emit_legacy)
def test_filter(self):
factory = proxy_logging.filter_factory({})
self.assertTrue(callable(factory))
Reference in New Issue
Block a user
Blocking a user prevents them from interacting with repositories, such as opening or commenting on pull requests or issues. Learn more about blocking a user.