From 67596a8aecfcd92ad87044a00e963a54c7af2ae3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?David=20N=C3=BA=C3=B1ez?= Date: Fri, 30 Oct 2020 21:53:14 +0100 Subject: [PATCH] Change NuCypherLogger behavior to always escape curly braces. The rationale is that it's unclear how to justify the previous behavior with some edge cases like `{{}`, which was `{}`. Also unit tests are improved even further. --- nucypher/utilities/logging.py | 13 ++------- tests/unit/test_logging.py | 51 +++++++++++++++++++++++++---------- 2 files changed, 39 insertions(+), 25 deletions(-) diff --git a/nucypher/utilities/logging.py b/nucypher/utilities/logging.py index e4d866f94..9300f9508 100644 --- a/nucypher/utilities/logging.py +++ b/nucypher/utilities/logging.py @@ -196,21 +196,12 @@ class Logger(TwistedLogger): See Issue #724 and, particularly, https://github.com/nucypher/nucypher/issues/724#issuecomment-600190455""" - CURLY_BRACES_REGEX = re.compile('{+|}+') - @classmethod def escape_format_string(cls, string): """ - Escapes curly braces from a PEP-3101's format string when there's a sequence of odd length + Escapes all curly braces from a PEP-3101's format string. """ - - def escape_group_of_curly_braces(match): - curlies = match.group() - if len(curlies) % 2 == 1: - curlies += curlies - return curlies - - escaped_string = cls.CURLY_BRACES_REGEX.sub(escape_group_of_curly_braces, string) + escaped_string = string.replace("{", "{{").replace("}", "}}") return escaped_string def emit(self, level, format=None, **kwargs): diff --git a/tests/unit/test_logging.py b/tests/unit/test_logging.py index d9674d98a..5dfd7a2a4 100644 --- a/tests/unit/test_logging.py +++ b/tests/unit/test_logging.py @@ -35,50 +35,66 @@ def get_json_observer_for_file(logfile): return json_observer -ordinary_string = "And you're boring, and you're totally ordinary, and you know it" -quirky_but_ok_strings = ( +# Any string without curly braces won't have any problem +ordinary_strings = ( + "Because there's nothing worse in life than being ordinary.", +) + +# Strings that have curly braces but that appear in groups of even length are considered safe too, +# as curly braces are escaped. Twisted will eat these just fine, but since they have curly braces, +# we will process them in our Logger. +quirky_strings = ( "{{}}", "{{hola}}", "{{{{}}}}", "foo{{}}", ) -normal_strings = (ordinary_string, *quirky_but_ok_strings) +# These are strings that are definitely going to cause trouble for Twisted Logger freaky_format_strings = ( # Including the expected exception and error message ("{", ValueError, "Single '{' encountered in format string"), ("}", ValueError, "Single '}' encountered in format string"), ("foo}", ValueError, "Single '}' encountered in format string"), ("bar{", ValueError, "Single '{' encountered in format string"), ("}{", ValueError, "Single '}' encountered in format string"), + ("{{}", ValueError, "Single '}' encountered in format string"), + ("}}{", ValueError, "Single '{' encountered in format string"), (f"{b'{'}", ValueError, "expected '}' before end of string"), (f"{b'}'}", ValueError, "Single '}' encountered in format string"), ("{}", KeyError, ""), + ("{}{", KeyError, ""), + ("{}}", KeyError, ""), ("{{{}}}", KeyError, ""), ("{{{{{}}}}}", KeyError, ""), ("{bananas}", KeyError, "bananas"), (str({'bananas': '🍌🍌🍌'}), KeyError, "bananas"), ) +# Embrace the quirky! +acceptable_strings = (*ordinary_strings, *quirky_strings) + def test_twisted_logger_doesnt_like_curly_braces(capsys): twisted_logger = TwistedLogger('twisted', observer=naive_print_observer) # Normal strings are logged normally - for string in normal_strings: + for string in acceptable_strings: twisted_logger.info(string) captured = capsys.readouterr() assert string.format() == captured.out + assert not captured.err # But curly braces are not - for string, exception, exception_message in freaky_format_strings: + for string, _exception, exception_message in freaky_format_strings: twisted_logger.info(string) captured = capsys.readouterr() assert string != captured.out assert "Unable to format event" in captured.out + assert exception_message in captured.out -def test_twisted_json_logger_doesnt_like_curly_braces(): +def test_twisted_json_logger_doesnt_like_curly_braces_either(): twisted_logger = TwistedLogger('twisted-json') # Normal strings are logged normally - for string in normal_strings: + for string in acceptable_strings: file = StringIO() twisted_logger.observer = get_json_observer_for_file(file) twisted_logger.info(string) @@ -98,30 +114,38 @@ def test_but_nucypher_logger_is_cool_with_that(capsys): nucypher_logger = Logger('nucypher-logger', observer=naive_print_observer) # Normal strings are logged normally - for string in normal_strings: + for string in acceptable_strings: nucypher_logger.info(string) captured = capsys.readouterr() - assert string.format() == captured.out + assert string == captured.out + assert not captured.err # And curly braces too! - for string, exception, exception_message in freaky_format_strings: + for string, _exception, _exception_message in freaky_format_strings: nucypher_logger.info(string) captured = capsys.readouterr() assert "Unable to format event" not in captured.out + assert not captured.err assert string == captured.out def test_even_nucypher_json_logger_is_cool(): + + def expected_processing(string_with_curly_braces): + ascii_string = py_encode_basestring_ascii(string_with_curly_braces)[1:-1] + expected_output = Logger.escape_format_string(ascii_string) + return expected_output + nucypher_logger = Logger('nucypher-logger-json') # Normal strings are logged normally - for string in normal_strings: + for string in acceptable_strings: file = StringIO() nucypher_logger.observer = get_json_observer_for_file(file) nucypher_logger.info(string) logged_event = file.getvalue() assert '"log_level": {"name": "info"' in logged_event - assert f'"log_format": "{string}"' in logged_event + assert f'"log_format": "{expected_processing(string)}"' in logged_event # And curly braces too! for string, _exception, _exception_message in freaky_format_strings: @@ -130,5 +154,4 @@ def test_even_nucypher_json_logger_is_cool(): nucypher_logger.info(string) logged_event = file.getvalue() assert '"log_level": {"name": "info"' in logged_event - ascii_string = py_encode_basestring_ascii(string)[1:-1] - assert f'"log_format": "{Logger.escape_format_string(ascii_string)}"' in logged_event + assert f'"log_format": "{expected_processing(string)}"' in logged_event