diff --git a/.travis.yml b/.travis.yml index b60528c..317cad4 100644 --- a/.travis.yml +++ b/.travis.yml @@ -29,8 +29,6 @@ jobs: env: DEPS="nameko>=2.12.0" - python: 3.5 env: DEPS="nameko>=2.12.0" - -matrix: allow_failures: - python: 3.6 env: DEPS="--pre nameko" diff --git a/CHANGELOG.rst b/CHANGELOG.rst index f1346b3..3a42d5c 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -2,6 +2,15 @@ Release Notes ============= +Version 1.3.0 +------------- + +Release 2020-12-02 + +* Add PrettyJSONFormatter useful for development of Nameko services +* Add HealthCheckTraceFilter useful for filtering out healthcheck entrypoint traces + + Version 1.2.0 ------------- diff --git a/README.rst b/README.rst index e6bc9a8..d2002c0 100644 --- a/README.rst +++ b/README.rst @@ -5,8 +5,6 @@ Nameko Entrypoint Tracer ======================== -TODO introduction ... - Usage ===== diff --git a/nameko_tracer/filters.py b/nameko_tracer/filters.py index 9604587..e2688cb 100644 --- a/nameko_tracer/filters.py +++ b/nameko_tracer/filters.py @@ -97,3 +97,15 @@ def truncate(self, data): TruncateRequestFilter = TruncateCallArgsFilter + + +class HealthCheckTraceFilter(logging.Filter): + def filter(self, record): + try: + return record.worker_ctx.entrypoint.url not in [ + "/health-check", + "/health_check", + "/healthcheck", + ] + except AttributeError: + return True diff --git a/nameko_tracer/formatters.py b/nameko_tracer/formatters.py index 77e4132..a12be2b 100644 --- a/nameko_tracer/formatters.py +++ b/nameko_tracer/formatters.py @@ -1,5 +1,6 @@ import json import logging +from functools import partial from nameko_tracer import constants @@ -8,16 +9,20 @@ def default(obj): return str(obj) -def serialise(obj): - return json.dumps(obj, default=default) +serialise = partial(json.dumps, default=default) class JSONFormatter(logging.Formatter): """ Format trace data as JSON string """ + def __init__(self, **option): + self.option = option def format(self, record): - return serialise(getattr(record, constants.TRACE_KEY)) + return serialise(getattr(record, constants.TRACE_KEY), **self.option) + + +PrettyJSONFormatter = partial(JSONFormatter, indent=4, sort_keys=True) class ElasticsearchDocumentFormatter(JSONFormatter): diff --git a/setup.py b/setup.py index 88a445b..5e4b4d0 100644 --- a/setup.py +++ b/setup.py @@ -3,7 +3,7 @@ setup( name='nameko-tracer', - version='1.2.0', + version='1.3.0', description='Nameko extension logging entrypoint processing metrics', author='student.com', author_email='wearehiring@student.com', diff --git a/tests/test_filters.py b/tests/test_filters.py index aff0907..b833a92 100644 --- a/tests/test_filters.py +++ b/tests/test_filters.py @@ -1,4 +1,5 @@ import logging +from unittest.mock import Mock import pytest @@ -7,9 +8,7 @@ @pytest.fixture def handler(): - class LRUTracker(logging.Handler): - def __init__(self, *args, **kwargs): self.log_record = None super(LRUTracker, self).__init__(*args, **kwargs) @@ -22,7 +21,7 @@ def emit(self, log_record): @pytest.yield_fixture def logger(handler): - logger = logging.getLogger('test') + logger = logging.getLogger("test") logger.setLevel(logging.INFO) logger.addHandler(handler) yield logger @@ -34,44 +33,55 @@ def logger(handler): @pytest.mark.parametrize( ( - 'entrypoints', 'max_len', 'expected_request', - 'expected_request_length', 'truncated', 'stage' + "entrypoints", + "max_len", + "expected_request", + "expected_request_length", + "truncated", + "stage", ), ( # should truncate call args of 'spam' entrypoint - (['spam'], 5, '12345', 9, True, constants.Stage.request), - (['^ham|spam'], 5, '12345', 9, True, constants.Stage.request), - (['^spam'], 5, '12345', 9, True, constants.Stage.request), - (['^spam'], 5, '12345', 9, True, constants.Stage.response), + (["spam"], 5, "12345", 9, True, constants.Stage.request), + (["^ham|spam"], 5, "12345", 9, True, constants.Stage.request), + (["^spam"], 5, "12345", 9, True, constants.Stage.request), + (["^spam"], 5, "12345", 9, True, constants.Stage.response), # call args of 'spam' entrypoint shorter than max len - (['^spam'], 10, '123456789', 9, False, constants.Stage.request), + (["^spam"], 10, "123456789", 9, False, constants.Stage.request), # 'spam' entrypoint does not match the regexp - (['^ham'], 5, '123456789', None, False, constants.Stage.request), + (["^ham"], 5, "123456789", None, False, constants.Stage.request), # no entrypoint should be truncated - (None, 5, '123456789', None, False, constants.Stage.request), - ([], 5, '123456789', None, False, constants.Stage.request), - ('', 5, '123456789', None, False, constants.Stage.request), - ) + (None, 5, "123456789", None, False, constants.Stage.request), + ([], 5, "123456789", None, False, constants.Stage.request), + ("", 5, "123456789", None, False, constants.Stage.request), + ), ) def test_truncate_call_args( - handler, logger, entrypoints, max_len, expected_request, - expected_request_length, truncated, stage + handler, + logger, + entrypoints, + max_len, + expected_request, + expected_request_length, + truncated, + stage, ): filter_ = filters.TruncateCallArgsFilter( - entrypoints=entrypoints, max_len=max_len) + entrypoints=entrypoints, max_len=max_len + ) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: stage.value, - constants.ENTRYPOINT_NAME_KEY: 'spam', - constants.REQUEST_KEY: '123456789', + constants.ENTRYPOINT_NAME_KEY: "spam", + constants.REQUEST_KEY: "123456789", }, } - logger.info('request', extra=extra) + logger.info("request", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) @@ -82,60 +92,60 @@ def test_truncate_call_args( def test_truncate_no_call_args(handler, logger): - filter_ = filters.TruncateCallArgsFilter(entrypoints=['spam'], max_len=5) + filter_ = filters.TruncateCallArgsFilter(entrypoints=["spam"], max_len=5) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: constants.Stage.request, - constants.ENTRYPOINT_NAME_KEY: 'spam', + constants.ENTRYPOINT_NAME_KEY: "spam", }, } - logger.info('request', extra=extra) + logger.info("request", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) - assert data[constants.ENTRYPOINT_NAME_KEY] == 'spam' + assert data[constants.ENTRYPOINT_NAME_KEY] == "spam" assert constants.REQUEST_KEY not in data assert constants.REQUEST_TRUNCATED_KEY not in data assert constants.REQUEST_LENGTH_KEY not in data @pytest.mark.parametrize( - ('request_in', 'expected_request_out'), + ("request_in", "expected_request_out"), ( ( - ['too', 'short'], - ['too', 'short'], # untouched + ["too", "short"], + ["too", "short"], # untouched ), ( - 'a long string should stay a string', - 'a long string should sta', + "a long string should stay a string", + "a long string should sta", ), ( - {'a': ('more', 'complex', 'data', 'structure')}, + {"a": ("more", "complex", "data", "structure")}, "{'a': ['more', 'complex'", # turned to string - ) - ) + ), + ), ) def test_truncate_call_args_to_string_casting( handler, logger, request_in, expected_request_out ): - filter_ = filters.TruncateCallArgsFilter(entrypoints=['spam'], max_len=24) + filter_ = filters.TruncateCallArgsFilter(entrypoints=["spam"], max_len=24) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: constants.Stage.request.value, - constants.ENTRYPOINT_NAME_KEY: 'spam', + constants.ENTRYPOINT_NAME_KEY: "spam", constants.REQUEST_KEY: request_in, }, } - logger.info('request', extra=extra) + logger.info("request", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) @@ -144,43 +154,52 @@ def test_truncate_call_args_to_string_casting( @pytest.mark.parametrize( ( - 'entrypoints', 'max_len', 'expected_response', - 'expected_response_length', 'truncated' + "entrypoints", + "max_len", + "expected_response", + "expected_response_length", + "truncated", ), ( # should truncate return value of 'spam' entrypoint - (['spam'], 5, '12345', 9, True), - (['^ham|spam'], 5, '12345', 9, True), - (['^spam'], 5, '12345', 9, True), + (["spam"], 5, "12345", 9, True), + (["^ham|spam"], 5, "12345", 9, True), + (["^spam"], 5, "12345", 9, True), # return value of 'spam' entrypoint shorter than max len - (['^spam'], 10, '123456789', 9, False), + (["^spam"], 10, "123456789", 9, False), # 'spam' entrypoint does not match the regexp - (['^ham'], 5, '123456789', None, False), + (["^ham"], 5, "123456789", None, False), # no entrypoint should be truncated - (None, 5, '123456789', None, False), - ([], 5, '123456789', None, False), - ('', 5, '123456789', None, False), - ) + (None, 5, "123456789", None, False), + ([], 5, "123456789", None, False), + ("", 5, "123456789", None, False), + ), ) def test_truncate_response( - handler, logger, entrypoints, max_len, expected_response, - expected_response_length, truncated + handler, + logger, + entrypoints, + max_len, + expected_response, + expected_response_length, + truncated, ): filter_ = filters.TruncateResponseFilter( - entrypoints=entrypoints, max_len=max_len) + entrypoints=entrypoints, max_len=max_len + ) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: constants.Stage.response.value, - constants.ENTRYPOINT_NAME_KEY: 'spam', - constants.RESPONSE_KEY: '123456789', + constants.ENTRYPOINT_NAME_KEY: "spam", + constants.RESPONSE_KEY: "123456789", }, } - logger.info('response', extra=extra) + logger.info("response", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) @@ -190,39 +209,39 @@ def test_truncate_response( @pytest.mark.parametrize( - ('response_in', 'expected_response_out'), + ("response_in", "expected_response_out"), ( ( - ['too', 'short'], - ['too', 'short'], # untouched + ["too", "short"], + ["too", "short"], # untouched ), ( - 'a long string should stay a string', - 'a long string should sta', + "a long string should stay a string", + "a long string should sta", ), ( - {'a': ('more', 'complex', 'data', 'structure')}, + {"a": ("more", "complex", "data", "structure")}, "{'a': ['more', 'complex'", # turned to string - ) - ) + ), + ), ) def test_truncate_response_to_string_casting( handler, logger, response_in, expected_response_out ): - filter_ = filters.TruncateResponseFilter(entrypoints=['spam'], max_len=24) + filter_ = filters.TruncateResponseFilter(entrypoints=["spam"], max_len=24) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: constants.Stage.response.value, - constants.ENTRYPOINT_NAME_KEY: 'spam', + constants.ENTRYPOINT_NAME_KEY: "spam", constants.RESPONSE_KEY: response_in, }, } - logger.info('response', extra=extra) + logger.info("response", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) @@ -231,19 +250,19 @@ def test_truncate_response_to_string_casting( def test_truncate_response_ignores_error_response(handler, logger): - filter_ = filters.TruncateResponseFilter(entrypoints=['^spam'], max_len=5) + filter_ = filters.TruncateResponseFilter(entrypoints=["^spam"], max_len=5) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: constants.Stage.response.value, - constants.ENTRYPOINT_NAME_KEY: 'spam', + constants.ENTRYPOINT_NAME_KEY: "spam", constants.RESPONSE_STATUS_KEY: constants.Status.error.value, }, } - logger.info('response', extra=extra) + logger.info("response", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) @@ -255,23 +274,23 @@ def test_truncate_response_ignores_error_response(handler, logger): def test_truncate_request_ignores_response_data(handler, logger): - filter_ = filters.TruncateCallArgsFilter(entrypoints=['^spam'], max_len=5) + filter_ = filters.TruncateCallArgsFilter(entrypoints=["^spam"], max_len=5) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: constants.Stage.response.value, - constants.ENTRYPOINT_NAME_KEY: 'spam', - constants.RESPONSE_KEY: '123456789', + constants.ENTRYPOINT_NAME_KEY: "spam", + constants.RESPONSE_KEY: "123456789", }, } - logger.info('response', extra=extra) + logger.info("response", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) - assert data[constants.RESPONSE_KEY] == '123456789' + assert data[constants.RESPONSE_KEY] == "123456789" assert constants.REQUEST_TRUNCATED_KEY not in data assert constants.REQUEST_LENGTH_KEY not in data assert constants.RESPONSE_TRUNCATED_KEY not in data @@ -280,23 +299,23 @@ def test_truncate_request_ignores_response_data(handler, logger): def test_truncate_response_ignores_request_data(handler, logger): - filter_ = filters.TruncateResponseFilter(entrypoints=['^spam'], max_len=5) + filter_ = filters.TruncateResponseFilter(entrypoints=["^spam"], max_len=5) logger.addFilter(filter_) extra = { constants.TRACE_KEY: { constants.STAGE_KEY: constants.Stage.request.value, - constants.ENTRYPOINT_NAME_KEY: 'spam', - constants.REQUEST_KEY: '123456789', + constants.ENTRYPOINT_NAME_KEY: "spam", + constants.REQUEST_KEY: "123456789", }, } - logger.info('request', extra=extra) + logger.info("request", extra=extra) data = getattr(handler.log_record, constants.TRACE_KEY) - assert data[constants.REQUEST_KEY] == '123456789' + assert data[constants.REQUEST_KEY] == "123456789" assert constants.RESPONSE_TRUNCATED_KEY not in data assert constants.RESPONSE_LENGTH_KEY not in data assert constants.REQUEST_TRUNCATED_KEY not in data @@ -305,4 +324,22 @@ def test_truncate_response_ignores_request_data(handler, logger): def test_base_truncate_filter_cannot_be_used(handler, logger): with pytest.raises(TypeError): - filters.BaseTruncateFilter(entrypoints=['^spam'], max_len=5) + filters.BaseTruncateFilter(entrypoints=["^spam"], max_len=5) + + +@pytest.mark.parametrize( + ("log_record", "should_log"), + ( + # not an HTTP entrypoint + (object(), True), + # HTTP entrypoint, log any url ... + (Mock(**{"worker_ctx.entrypoint.url": "/some/url"}), True), + # ... except the health check one + (Mock(**{"worker_ctx.entrypoint.url": "/healthcheck"}), False), + (Mock(**{"worker_ctx.entrypoint.url": "/health-check"}), False), + (Mock(**{"worker_ctx.entrypoint.url": "/health_check"}), False), + ), +) +def test_health_check_filter(log_record, should_log): + filter_ = filters.HealthCheckTraceFilter() + assert filter_.filter(log_record) == should_log diff --git a/tests/test_formatters.py b/tests/test_formatters.py index f3226dc..1094ed0 100644 --- a/tests/test_formatters.py +++ b/tests/test_formatters.py @@ -8,53 +8,75 @@ @pytest.mark.parametrize( - ('input_', 'expected_output'), + ("input_", "expected_output"), ( ( - {'datetime': datetime(2017, 7, 7, 12, 0)}, - '{"datetime": "2017-07-07 12:00:00"}' + {"datetime": datetime(2017, 7, 7, 12, 0)}, + '{"datetime": "2017-07-07 12:00:00"}', ), ({None}, '"{None}"'), - ) + ), ) -def test_json_serialiser_will_deal_with_datetime(input_, expected_output): - +def test_json_serialiser(input_, expected_output): log_record = Mock() setattr(log_record, constants.TRACE_KEY, input_) - assert ( - formatters.JSONFormatter().format(log_record) == expected_output) + assert formatters.JSONFormatter().format(log_record) == expected_output @pytest.mark.parametrize( - ('key', 'value_in', 'expected_value_out'), + "formatter", + ( + formatters.JSONFormatter(indent=4, sort_keys=True), + formatters.PrettyJSONFormatter(), + ), +) +def test_pretty_json_serialiser(formatter): + log_record = Mock() + setattr(log_record, constants.TRACE_KEY, {"show": {"this": "pretty"}}) + + expected_output = "\n".join( + ( + "{", + ' "show": {', + ' "this": "pretty"', + " }", + "}", + ) + ) + + assert formatter.format(log_record) == expected_output + + +@pytest.mark.parametrize( + ("key", "value_in", "expected_value_out"), ( ( constants.CONTEXT_DATA_KEY, - {'should': ('be', 'serialised')}, + {"should": ("be", "serialised")}, '{"should": ["be", "serialised"]}', ), ( constants.REQUEST_KEY, - ('should', 'be', 'serialised'), + ("should", "be", "serialised"), '["should", "be", "serialised"]', ), ( constants.RESPONSE_KEY, - {'should': ('be', 'serialised')}, + {"should": ("be", "serialised")}, '{"should": ["be", "serialised"]}', ), ( constants.EXCEPTION_ARGS_KEY, - {'should': ('be', 'serialised')}, + {"should": ("be", "serialised")}, '{"should": ["be", "serialised"]}', ), ( - 'some-other-key', - {'should': ['NOT', 'be', 'serialised']}, - {'should': ['NOT', 'be', 'serialised']}, + "some-other-key", + {"should": ["NOT", "be", "serialised"]}, + {"should": ["NOT", "be", "serialised"]}, ), - ) + ), ) def test_elasticsearch_document_serialiser(key, value_in, expected_value_out):