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

@@ -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.
         """
-
+        escaped_string = string.replace("{", "{{").replace("}", "}}")
-        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)
         return escaped_string
 
     def emit(self, level, format=None, **kwargs):

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"
+# Any string without curly braces won't have any problem
-quirky_but_ok_strings = (
+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": "{expected_processing(string)}"' in logged_event
-        assert f'"log_format": "{Logger.escape_format_string(ascii_string)}"' in logged_event