openstack/swift
Code Issues Proposed changes

tests: Check proxy-logging stats on the wire

Browse Source 
With labeled metrics on the horizon, I wanted some more end-to-end
tests of stats emission.

Change-Id: I9a016de1010dd17e91bc85877413b34d2c3287c7
This commit is contained in:
Tim Burke
2023-09-29 11:15:51 -07:00
parent ff08a649e0
commit a21d078009
3 changed files with 77 additions and 41 deletions
Download Patch File Download Diff File Expand all files Collapse all files

32
test/debug_logger.py
View File

@@ -12,6 +12,7 @@
# implied. # implied.
# See the License for the specific language governing permissions and # See the License for the specific language governing permissions and
# limitations under the License. # limitations under the License.
import collections
import contextlib import contextlib
import logging import logging
import mock import mock
@@ -29,6 +30,20 @@ class WARN_DEPRECATED(Exception):
print(self.msg) print(self.msg)
SendtoCall = collections.namedtuple('SendToCall', ['payload', 'address'])
class RecordingSocket(object):
def __init__(self):
self.sendto_calls = []
def sendto(self, payload, address):
self.sendto_calls.append(SendtoCall(payload, address))
def close(self):
pass
class FakeStatsdClient(statsd_client.StatsdClient): class FakeStatsdClient(statsd_client.StatsdClient):
def __init__(self, *args, **kwargs): def __init__(self, *args, **kwargs):
super(FakeStatsdClient, self).__init__(*args, **kwargs) super(FakeStatsdClient, self).__init__(*args, **kwargs)
@@ -54,14 +69,7 @@ class FakeStatsdClient(statsd_client.StatsdClient):
return None, None return None, None
def _open_socket(self): def _open_socket(self):
return self return self.recording_socket
# sendto and close are mimicing the socket calls.
def sendto(self, msg, target):
self.sendto_calls.append((msg, target))
def close(self):
pass
def _send(self, *args, **kwargs): def _send(self, *args, **kwargs):
self.send_calls.append((args, kwargs)) self.send_calls.append((args, kwargs))
@@ -70,7 +78,11 @@ class FakeStatsdClient(statsd_client.StatsdClient):
def clear(self): def clear(self):
self.send_calls = [] self.send_calls = []
self.calls = defaultdict(list) self.calls = defaultdict(list)
self.sendto_calls = [] self.recording_socket = RecordingSocket()
@property
def sendto_calls(self):
return self.recording_socket.sendto_calls
def get_increments(self): def get_increments(self):
return [call[0][0] for call in self.calls['increment']] return [call[0][0] for call in self.calls['increment']]
@@ -146,7 +158,7 @@ class FakeLogger(logging.Logger, CaptureLog):
self.level = logging.NOTSET self.level = logging.NOTSET
if 'facility' in kwargs: if 'facility' in kwargs:
self.facility = kwargs['facility'] self.facility = kwargs['facility']
self.statsd_client = FakeStatsdClient(None, 8125) self.statsd_client = FakeStatsdClient('host', 8125)
self.thread_locals = None self.thread_locals = None
self.parent = None self.parent = None
# ensure the NOTICE level has been named, in case it has not already # ensure the NOTICE level has been named, in case it has not already

6
test/unit/account/test_auditor.py
View File

@@ -77,6 +77,9 @@ class TestAuditorRealBroker(unittest.TestCase):
def setUp(self): def setUp(self):
self.logger = debug_logger() self.logger = debug_logger()
# really, this would come by way of base_prefix/tail_prefix in
# get_logger, ultimately tracing back to section_name in daemon...
self.logger.logger.statsd_client._prefix = 'account-auditor.'
@with_tempdir @with_tempdir
def test_db_validate_fails(self, tempdir): def test_db_validate_fails(self, tempdir):
@@ -133,6 +136,9 @@ class TestAuditorRealBroker(unittest.TestCase):
self.assertEqual( self.assertEqual(
test_auditor.logger.statsd_client.get_increment_counts(), test_auditor.logger.statsd_client.get_increment_counts(),
{'failures': 1}) {'failures': 1})
self.assertIn(
(b'account-auditor.failures:1|c', ('host', 8125)),
test_auditor.logger.statsd_client.sendto_calls)
if __name__ == '__main__': if __name__ == '__main__':

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

@@ -118,6 +118,13 @@ def start_response(*args):
@patch_policies([StoragePolicy(0, 'zero', False)]) @patch_policies([StoragePolicy(0, 'zero', False)])
class TestProxyLogging(unittest.TestCase): class TestProxyLogging(unittest.TestCase):
def setUp(self):
self.logger = debug_logger()
# really, this would come by way of base_prefix/tail_prefix in
# get_logger, ultimately tracing back to our hard-coded
# statsd_tail_prefix
self.logger.logger.statsd_client._prefix = 'proxy-server.'
def _log_parts(self, app, should_be_empty=False): def _log_parts(self, app, should_be_empty=False):
info_calls = app.access_logger.log_dict['info'] info_calls = app.access_logger.log_dict['info']
if should_be_empty: if should_be_empty:
@@ -155,6 +162,12 @@ class TestProxyLogging(unittest.TestCase):
for emv in exp_metrics_and_values] for emv in exp_metrics_and_values]
self.assertEqual(got_metrics_values_and_kwargs, self.assertEqual(got_metrics_values_and_kwargs,
exp_metrics_values_and_kwargs) exp_metrics_values_and_kwargs)
self.assertIs(self.logger, app.access_logger)
for metric, value in exp_metrics_and_values:
self.assertIn(
(('proxy-server.%s:%s|c' % (metric, value)).encode(),
('host', 8125)),
app.access_logger.statsd_client.sendto_calls)
def test_logger_statsd_prefix(self): def test_logger_statsd_prefix(self):
app = proxy_logging.ProxyLoggingMiddleware( app = proxy_logging.ProxyLoggingMiddleware(
@@ -177,8 +190,8 @@ class TestProxyLogging(unittest.TestCase):
app.access_logger.logger.statsd_client._prefix) app.access_logger.logger.statsd_client._prefix)
def test_log_request_statsd_invalid_stats_types(self): def test_log_request_statsd_invalid_stats_types(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app = proxy_logging.ProxyLoggingMiddleware(
app.access_logger = debug_logger() FakeApp(), {}, logger=self.logger)
for url in ['/', '/foo', '/foo/bar', '/v1']: for url in ['/', '/foo', '/foo/bar', '/v1']:
req = Request.blank(url, environ={'REQUEST_METHOD': 'GET'}) req = Request.blank(url, environ={'REQUEST_METHOD': 'GET'})
resp = app(req.environ, start_response) resp = app(req.environ, start_response)
@@ -190,8 +203,8 @@ class TestProxyLogging(unittest.TestCase):
def test_log_request_stat_type_bad(self): def test_log_request_stat_type_bad(self):
for bad_path in ['', '/', '/bad', '/baddy/mc_badderson', '/v1', for bad_path in ['', '/', '/bad', '/baddy/mc_badderson', '/v1',
'/v1/']: '/v1/']:
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) app = proxy_logging.ProxyLoggingMiddleware(
app.access_logger = debug_logger() FakeApp(), {}, logger=self.logger)
req = Request.blank(bad_path, environ={'REQUEST_METHOD': 'GET'}) req = Request.blank(bad_path, environ={'REQUEST_METHOD': 'GET'})
now = 10000.0 now = 10000.0
app.log_request(req, 123, 7, 13, now, now + 2.71828182846) app.log_request(req, 123, 7, 13, now, now + 2.71828182846)
@@ -224,9 +237,11 @@ class TestProxyLogging(unittest.TestCase):
with mock.patch("time.time", stub_time): with mock.patch("time.time", stub_time):
for path, exp_type in path_types.items(): for path, exp_type in path_types.items():
# GET # GET
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware( app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'7654321', response_str='321 Fubar'), {}) FakeApp(body=b'7654321', response_str='321 Fubar'),
app.access_logger = debug_logger() {},
logger=self.logger)
req = Request.blank(path, environ={ req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET', 'REQUEST_METHOD': 'GET',
'wsgi.input': BytesIO(b'4321')}) 'wsgi.input': BytesIO(b'4321')})
@@ -259,10 +274,10 @@ class TestProxyLogging(unittest.TestCase):
# GET Repeat the test above, but with a non-existent policy # GET Repeat the test above, but with a non-existent policy
# Do this only for object types # Do this only for object types
if exp_type == 'object': if exp_type == 'object':
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware( app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'7654321', response_str='321 Fubar', FakeApp(body=b'7654321', response_str='321 Fubar',
policy_idx='-1'), {}) policy_idx='-1'), {}, logger=self.logger)
app.access_logger = debug_logger()
req = Request.blank(path, environ={ req = Request.blank(path, environ={
'REQUEST_METHOD': 'GET', 'REQUEST_METHOD': 'GET',
'wsgi.input': BytesIO(b'4321')}) 'wsgi.input': BytesIO(b'4321')})
@@ -295,9 +310,10 @@ class TestProxyLogging(unittest.TestCase):
app.access_logger.log_dict['update_stats']) app.access_logger.log_dict['update_stats'])
# PUT (no first-byte timing!) # PUT (no first-byte timing!)
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware( app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'87654321', response_str='314 PiTown'), {}) FakeApp(body=b'87654321', response_str='314 PiTown'), {},
app.access_logger = debug_logger() logger=self.logger)
req = Request.blank(path, environ={ req = Request.blank(path, environ={
'REQUEST_METHOD': 'PUT', 'REQUEST_METHOD': 'PUT',
'wsgi.input': BytesIO(b'654321')}) 'wsgi.input': BytesIO(b'654321')})
@@ -327,10 +343,10 @@ class TestProxyLogging(unittest.TestCase):
# PUT Repeat the test above, but with a non-existent policy # PUT Repeat the test above, but with a non-existent policy
# Do this only for object types # Do this only for object types
if exp_type == 'object': if exp_type == 'object':
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware( app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(body=b'87654321', response_str='314 PiTown', FakeApp(body=b'87654321', response_str='314 PiTown',
policy_idx='-1'), {}) policy_idx='-1'), {}, logger=self.logger)
app.access_logger = debug_logger()
req = Request.blank(path, environ={ req = Request.blank(path, environ={
'REQUEST_METHOD': 'PUT', 'REQUEST_METHOD': 'PUT',
'wsgi.input': BytesIO(b'654321')}) 'wsgi.input': BytesIO(b'654321')})
@@ -363,8 +379,9 @@ class TestProxyLogging(unittest.TestCase):
'OPTIONS': 'OPTIONS', 'OPTIONS': 'OPTIONS',
} }
for method, exp_method in method_map.items(): for method, exp_method in method_map.items():
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {}) self.logger.clear()
app.access_logger = debug_logger() app = proxy_logging.ProxyLoggingMiddleware(
FakeApp(), {}, logger=self.logger)
req = Request.blank('/v1/a/', environ={'REQUEST_METHOD': method}) req = Request.blank('/v1/a/', environ={'REQUEST_METHOD': method})
now = 10000.0 now = 10000.0
app.log_request(req, 299, 11, 3, now, now + 1.17) app.log_request(req, 299, 11, 3, now, now + 1.17)
@@ -387,10 +404,10 @@ class TestProxyLogging(unittest.TestCase):
for conf_key in ['access_log_statsd_valid_http_methods', for conf_key in ['access_log_statsd_valid_http_methods',
'log_statsd_valid_http_methods']: 'log_statsd_valid_http_methods']:
for method, exp_method in method_map.items(): for method, exp_method in method_map.items():
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {
conf_key: 'SPECIAL, GET,PUT ', # crazy spaces ok conf_key: 'SPECIAL, GET,PUT ', # crazy spaces ok
}) }, logger=self.logger)
app.access_logger = debug_logger()
req = Request.blank('/v1/a/c', req = Request.blank('/v1/a/c',
environ={'REQUEST_METHOD': method}) environ={'REQUEST_METHOD': method})
now = 10000.0 now = 10000.0
@@ -568,8 +585,8 @@ class TestProxyLogging(unittest.TestCase):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), { app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), {
'log_msg_template': ( 'log_msg_template': (
'{protocol} {path} {method} ' '{protocol} {path} {method} '
'{account} {container} {object}')}) '{account} {container} {object}')
app.access_logger = debug_logger() }, logger=self.logger)
req = Request.blank('/bucket/path/to/key', environ={ req = Request.blank('/bucket/path/to/key', environ={
'REQUEST_METHOD': 'GET', 'REQUEST_METHOD': 'GET',
# This would actually get set in the app, but w/e # This would actually get set in the app, but w/e
@@ -609,8 +626,7 @@ class TestProxyLogging(unittest.TestCase):
def test_multi_segment_resp(self): def test_multi_segment_resp(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp( app = proxy_logging.ProxyLoggingMiddleware(FakeApp(
[b'some', b'chunks', b'of data']), {}) [b'some', b'chunks', b'of data']), {}, logger=self.logger)
app.access_logger = debug_logger()
req = Request.blank('/', environ={'REQUEST_METHOD': 'GET', req = Request.blank('/', environ={'REQUEST_METHOD': 'GET',
'swift.source': 'SOS'}) 'swift.source': 'SOS'})
resp = app(req.environ, start_response) resp = app(req.environ, start_response)
@@ -627,16 +643,17 @@ class TestProxyLogging(unittest.TestCase):
def test_log_headers(self): def test_log_headers(self):
for conf_key in ['access_log_headers', 'log_headers']: for conf_key in ['access_log_headers', 'log_headers']:
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
{conf_key: 'yes'}) {conf_key: 'yes'},
app.access_logger = debug_logger() logger=self.logger)
req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'}) req = Request.blank('/', environ={'REQUEST_METHOD': 'GET'})
resp = app(req.environ, start_response) resp = app(req.environ, start_response)
# exhaust generator # exhaust generator
[x for x in resp] [x for x in resp]
log_parts = self._log_parts(app) log_parts = self._log_parts(app)
headers = unquote(log_parts[14]).split('\n') headers = unquote(log_parts[14]).split('\n')
self.assertTrue('Host: localhost:80' in headers) self.assertIn('Host: localhost:80', headers)
def test_access_log_headers_only(self): def test_access_log_headers_only(self):
app = proxy_logging.ProxyLoggingMiddleware( app = proxy_logging.ProxyLoggingMiddleware(
@@ -661,8 +678,8 @@ class TestProxyLogging(unittest.TestCase):
def test_upload_size(self): def test_upload_size(self):
# Using default policy # Using default policy
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(), app = proxy_logging.ProxyLoggingMiddleware(FakeApp(),
{'log_headers': 'yes'}) {'log_headers': 'yes'},
app.access_logger = debug_logger() logger=self.logger)
req = Request.blank( req = Request.blank(
'/v1/a/c/o/foo', '/v1/a/c/o/foo',
environ={'REQUEST_METHOD': 'PUT', environ={'REQUEST_METHOD': 'PUT',
@@ -680,9 +697,10 @@ class TestProxyLogging(unittest.TestCase):
app) app)
# Using a non-existent policy # Using a non-existent policy
self.logger.clear()
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(policy_idx='-1'), app = proxy_logging.ProxyLoggingMiddleware(FakeApp(policy_idx='-1'),
{'log_headers': 'yes'}) {'log_headers': 'yes'},
app.access_logger = debug_logger() logger=self.logger)
req = Request.blank( req = Request.blank(
'/v1/a/c/o/foo', '/v1/a/c/o/foo',
environ={'REQUEST_METHOD': 'PUT', environ={'REQUEST_METHOD': 'PUT',
@@ -699,8 +717,8 @@ class TestProxyLogging(unittest.TestCase):
def test_upload_size_no_policy(self): def test_upload_size_no_policy(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeApp(policy_idx=None), app = proxy_logging.ProxyLoggingMiddleware(FakeApp(policy_idx=None),
{'log_headers': 'yes'}) {'log_headers': 'yes'},
app.access_logger = debug_logger() logger=self.logger)
req = Request.blank( req = Request.blank(
'/v1/a/c/o/foo', '/v1/a/c/o/foo',
environ={'REQUEST_METHOD': 'PUT', environ={'REQUEST_METHOD': 'PUT',
@@ -717,8 +735,8 @@ class TestProxyLogging(unittest.TestCase):
def test_upload_line(self): def test_upload_line(self):
app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(), app = proxy_logging.ProxyLoggingMiddleware(FakeAppReadline(),
{'log_headers': 'yes'}) {'log_headers': 'yes'},
app.access_logger = debug_logger() logger=self.logger)
req = Request.blank( req = Request.blank(
'/v1/a/c', '/v1/a/c',
environ={'REQUEST_METHOD': 'POST', environ={'REQUEST_METHOD': 'POST',