Show trailing colon in log messages with context

nuclear/sublog/exception.py

@@ -1,6 +1,6 @@
 import os
 import traceback
-from typing import Collection, Iterable, Dict, Tuple
+from typing import Collection, Iterable, Dict, Optional, Tuple
 
 from nuclear.sublog.context_error import ContextError
 
@@ -17,7 +17,7 @@ def exception_details(e: BaseException) -> str:
     traceback_str = ', '.join(traceback_lines)
     cause = _root_cause_type(e)
     error_msg = _error_message(e)
-    return f'{error_msg}, cause={cause}, traceback={traceback_str}'
+    return f'{error_msg}: cause={cause}, traceback={traceback_str}'
 
 
 def extended_exception_details(e: BaseException) -> Tuple[str, Dict]:
@@ -71,20 +71,21 @@ def _include_traceback_frame(frame: traceback.FrameSummary) -> bool:
     return True
 
 
-def _root_cause_type(e: Exception) -> str:
+def _root_cause_type(e: BaseException) -> str:
     while e.__cause__ is not None:
         e = e.__cause__
     return type(e).__name__
 
 
-def _error_message(e: Exception, context_name: str = ''):
+def _error_message(e: BaseException, context_name: str = ''):
     layers = []
     if context_name:
         layers.append(context_name)
-    while e is not None:
-        if isinstance(e, ContextError):
-            layers.append(e.context_message.strip())
+    e_step: Optional[BaseException] = e
+    while e_step is not None:
+        if isinstance(e_step, ContextError):
+            layers.append(e_step.context_message.strip())
         else:
-            layers.append(str(e).strip())
-        e = e.__cause__
+            layers.append(str(e_step).strip())
+        e_step = e_step.__cause__
     return ': '.join(layers)

nuclear/sublog/logging.py

@@ -94,14 +94,16 @@ def _print_log(self, message: str, ctx: Dict[str, Any], logger_func: Callable):
             self.first_use = False
 
         merged_context = {**self.ctx, **ctx}
-        if not self.structured_logging:
+        if self.structured_logging:
+            logger_func(message, extra={'extra': merged_context})
+        else:
             display_context = _display_context(merged_context)
             if display_context:
-                logger_func(f'{message} {display_context}')
+                if message.endswith(':'):
+                    message = message[:-1]
+                logger_func(f'{message}: {display_context}')
             else:
                 logger_func(message)
-        else:
-            logger_func(message, extra={'extra': merged_context})
 
     def exception(self, e: BaseException):
         log_exception(e)

nuclear/version.py

@@ -1 +1 @@
-__version__ = "2.1.0"
+__version__ = "2.1.1"

tests/sublog/test_catch.py

@@ -11,7 +11,7 @@ def test_sublog_traceback():
                 with add_context('liftoff', speed='zero'):
                     disaster()
 
-        mockio.assert_match_uncolor('ERROR initializing: liftoff: disaster request_id=42 speed=zero '
+        mockio.assert_match_uncolor('ERROR initializing: liftoff: disaster: request_id=42 speed=zero '
                                     'cause=RuntimeError '
                                     'traceback="(.+)/test_catch.py:12, '
                                     '(.+)/test_catch.py:22, '
@@ -43,7 +43,7 @@ def test_catch_with_context_name():
         with error_handler('hacking time'):
             raise RuntimeError('nope')
 
-        mockio.assert_match_uncolor('ERROR hacking time: nope '
+        mockio.assert_match_uncolor('ERROR hacking time: nope: '
                                     'cause=RuntimeError '
                                     'traceback=(.+)/test_catch.py:44"?$')
 
@@ -56,7 +56,7 @@ def test_catch_chained_exception_cause():
             except AttributeError as e:
                 raise RuntimeError('wrapper') from e
 
-        mockio.assert_match_uncolor('ERROR hacking time: wrapper: real cause '
+        mockio.assert_match_uncolor('ERROR hacking time: wrapper: real cause: '
                                     'cause=AttributeError '
                                     'traceback=(.+)/test_catch.py:55"?$')
 
@@ -71,7 +71,7 @@ def test_recover_from_dynamically_imported_module():
             assert loader is not None, 'no module loader'
             loader.exec_module(ext_module)
 
-        mockio.assert_match_uncolor(r'ERROR hacking time: Fire! '
+        mockio.assert_match_uncolor(r'ERROR hacking time: Fire!: '
                                     r'cause=RuntimeError '
                                     r'traceback="(.+)/test_catch.py:72, '
                                     r'<frozen importlib._bootstrap_external>:\d+, '
@@ -87,7 +87,7 @@ def doit():
         cli = CliBuilder(log_error=True, run=doit)
         cli.run()
 
-        mockio.assert_match_uncolor('ERROR fail '
+        mockio.assert_match_uncolor('ERROR fail: '
                                     'cause=RuntimeError '
                                     'traceback=(.+)/test_catch.py:85"?$')
 
@@ -99,6 +99,6 @@ def test_log_exception():
         except Exception as e:
             log_exception(e)
 
-        mockio.assert_match_uncolor('ERROR fail '
+        mockio.assert_match_uncolor('ERROR fail: '
                                     'cause=RuntimeError '
                                     'traceback=(.+)/test_catch.py:98"?$')

tests/sublog/test_context_logger.py

@@ -18,11 +18,11 @@ def test_context_logger():
         # log level
         mockio.assert_match(' DEBUG ')
         # message with context
-        mockio.assert_match(' got request request_id=3735936685$')
+        mockio.assert_match(' got request: request_id=3735936685$')
 
-        mockio.assert_match_uncolor('INFO  logged in request_id=3735936685 user=igrek page="sweet home"$')
+        mockio.assert_match_uncolor('INFO  logged in: request_id=3735936685 user=igrek page="sweet home"$')
         mockio.assert_match_uncolor('WARN  im a root$')
-        mockio.assert_match_uncolor('DEBUG logged out request_id=3735936685$')
+        mockio.assert_match_uncolor('DEBUG logged out: request_id=3735936685$')
         mockio.assert_match_uncolor('DEBUG 42$')
 
 
@@ -43,13 +43,13 @@ def test_root_context_logger():
 
         logger.debug('exited')
 
-        mockio.assert_match_uncolor(' outside context a=4$')
-        mockio.assert_match_uncolor(' got request request_id=3735936685$')
-        mockio.assert_match_uncolor(' logged in request_id=3735936685 user=igrek page=home$')
-        mockio.assert_match_uncolor(' im a root request_id=3735936685 user=igrek$')
+        mockio.assert_match_uncolor(' outside context: a=4$')
+        mockio.assert_match_uncolor(' got request: request_id=3735936685$')
+        mockio.assert_match_uncolor(' logged in: request_id=3735936685 user=igrek page=home$')
+        mockio.assert_match_uncolor(' im a root: request_id=3735936685 user=igrek$')
         mockio.assert_match_uncolor(
-            ' I\'m a pickle cause=RuntimeError traceback=.+:40$')
-        mockio.assert_match_uncolor(' logged out request_id=3735936685$')
+            ' I\'m a pickle: cause=RuntimeError traceback=.+:40$')
+        mockio.assert_match_uncolor(' logged out: request_id=3735936685$')
         mockio.assert_match_uncolor(' exited$')
 
 

tests/sublog/test_wrap_error.py

@@ -19,14 +19,14 @@ def test_sublog_wrapping():
         logger.warn('attention')
         logger.debug('trace')
 
-        mockio.assert_match_uncolor('ERROR initializing: liftoff: dupa '
+        mockio.assert_match_uncolor('ERROR initializing: liftoff: dupa: '
                                     'request_id=42 speed=zero '
                                     'cause=RuntimeError traceback=(.*)/test_wrap_error.py:10$')
-        mockio.assert_match_uncolor('ERROR dupa2 a=5 z=fifteen '
+        mockio.assert_match_uncolor('ERROR dupa2: a=5 z=fifteen '
                                     'cause=ContextError traceback=(.*)/test_wrap_error.py:13$')
-        mockio.assert_match_uncolor('ERROR dupa3 '
+        mockio.assert_match_uncolor('ERROR dupa3: '
                                     'cause=RuntimeError traceback=(.*)/test_wrap_error.py:16$')
-        mockio.assert_match_uncolor('INFO  success param=with_param$')
+        mockio.assert_match_uncolor('INFO  success: param=with_param$')
         mockio.assert_match_uncolor('WARN  attention$')
         mockio.assert_match_uncolor('DEBUG trace$')
 
@@ -41,7 +41,7 @@ def test_sublog_wrapping_try_string():
                     raise RuntimeError('parent') from e
     except Exception as e:
         assert str(e) == 'initializing: liftoff: parent: dupa'
-        assert exception_details(e).startswith('initializing: liftoff: parent: dupa, cause=ValueError, traceback=')
+        assert exception_details(e).startswith('initializing: liftoff: parent: dupa: cause=ValueError, traceback='), exception_details(e)
 
 
     try: