Add hiding time in logs on init

nuclear/sublog/logging.py

@@ -12,7 +12,7 @@
 
 from nuclear.sublog.context_error import ContextError
 from nuclear.sublog.exception import extended_exception_details
-from nuclear.utils.collections import filter_not_none
+from nuclear.utils.collections import coalesce2, filter_not_none
 from nuclear.utils.env import is_env_flag_enabled
 from nuclear.utils.strings import strip_ansi_colors
 
@@ -22,16 +22,19 @@
 ISO_DATE_FORMAT = r'%Y-%m-%dT%H:%M:%S.%fZ'
 LOGGING_LOGGER_NAME = 'nuclear.sublog'
 
-log_level: str = os.environ.get('NUCLEAR_LOG_LEVEL', 'debug')
-log_level_show: bool = is_env_flag_enabled('NUCLEAR_LOG_LEVEL_SHOW', 'true')
-log_time_show: bool = is_env_flag_enabled('NUCLEAR_LOG_TIME', 'true')
 simultaneous_print_lock = threading.Lock()
 _logging_logger: logging.Logger = logging.getLogger(LOGGING_LOGGER_NAME)
 _log_state = {'init': False}
 
 
-def init_logs():
-    """Configure loggers: formatters, handlers and log levels"""
+def init_logs(
+    show_time: Optional[bool] = None,
+):
+    """
+    Configure loggers: formatters, handlers and log levels
+    :param show_time: if True, formatted time will be displayed in each log message,
+    None will use default value
+    """
     logging_kwargs: Dict[str, Any] = {
         'stream': sys.stdout,
         'format': LOG_FORMAT,
@@ -46,14 +49,22 @@ def init_logs():
         for handler in logging.getLogger().handlers:
             handler.setFormatter(StructuredFormatter())
     else:
+        log_time_show: bool = coalesce2(show_time, is_env_flag_enabled('NUCLEAR_LOG_TIME', 'true'))
         logging.basicConfig(**logging_kwargs)
         for handler in logging.getLogger().handlers:
-            handler.setFormatter(ColoredFormatter())
+            handler.setFormatter(ColoredFormatter(log_time_show))
 
+    log_level: str = os.environ.get('NUCLEAR_LOG_LEVEL', 'debug')
     level = _get_logging_level(log_level)
     root_logger = logging.getLogger(LOGGING_LOGGER_NAME)
     root_logger.setLevel(level)
     _log_state['init'] = True
+    print('twice')
+
+
+def init_logs_once():
+    if not _log_state['init']:
+        init_logs()
 
 
 def get_logger(logger_name: str) -> logging.Logger:
@@ -150,8 +161,10 @@ def add_context(context_name: str, log: bool = False, **ctx):
 
 
 class ColoredFormatter(logging.Formatter):
-    def __init__(self):
+    def __init__(self, log_time_show: bool):
         logging.Formatter.__init__(self)
+        self.log_level_show: bool = is_env_flag_enabled('NUCLEAR_LOG_LEVEL_SHOW', 'true')
+        self.log_time_show: bool = log_time_show
 
     log_level_templates = {
         'CRITICAL': f'{Style.BRIGHT + Fore.RED}CRIT {Style.RESET_ALL}',
@@ -162,7 +175,7 @@ def __init__(self):
     }
 
     def format(self, record: logging.LogRecord) -> str:
-        part_levelname = self.log_level_templates.get(record.levelname, record.levelname) if log_level_show else None
+        part_levelname = self.log_level_templates.get(record.levelname, record.levelname) if self.log_level_show else None
         part_message = record.msg
         part_time = self.format_time()
         parts: List[str] = filter_not_none([part_time, part_levelname, part_message])
@@ -171,9 +184,8 @@ def format(self, record: logging.LogRecord) -> str:
             line = strip_ansi_colors(line)
         return line
 
-    @staticmethod
-    def format_time() -> Optional[str]:
-        if not log_time_show:
+    def format_time(self) -> Optional[str]:
+        if not self.log_time_show:
             return None
         now_tz = datetime.now().astimezone()
         if time.timezone == 0:

nuclear/utils/collections.py

@@ -46,3 +46,14 @@ def flatten(collection: Iterable[Union[T, List[T]]]) -> List[T]:
 
 def filter_not_none(items: List[Optional[T]]) -> List[T]:
     return [item for item in items if item is not None]
+
+
+def coalesce(*items: Optional[T]) -> Optional[T]:
+    for item in items:
+        if item is not None:
+            return item
+    return None
+
+
+def coalesce2(item: Optional[T], default: T) -> T:
+    return item if item is not None else default

tests/asserts.py

@@ -7,11 +7,11 @@
 import mock
 
 from nuclear.cli.parser.error import CliError
-from nuclear.sublog import init_logs
+from nuclear.sublog.logging import init_logs_once
 from nuclear.utils.strings import strip_ansi_colors
 
 
-def assert_error(action, error_type: Type[Exception] = RuntimeError, expected_msg: str = None):
+def assert_error(action, error_type: Type[Exception] = RuntimeError, expected_msg: str | None = None):
     try:
         action()
         assert False, 'should raise error'
@@ -21,7 +21,7 @@ def assert_error(action, error_type: Type[Exception] = RuntimeError, expected_ms
             assert expected_msg in str(e), 'unexpected error message'
 
 
-def assert_cli_error(action, expected_error: str = None):
+def assert_cli_error(action, expected_error: str | None = None):
     assert_error(action, CliError, expected_error)
 
 
@@ -36,7 +36,7 @@ def assert_system_exit(action):
 
 class MockIO:
     def __init__(self, *in_args: str):
-        init_logs()
+        init_logs_once()
         logger = logging.getLogger('nuclear.sublog')
         logger.setLevel(logging.DEBUG)
         logger.propagate = False
@@ -113,7 +113,7 @@ def assert_not_match(self, regex: str):
 
 class StdoutCap:
     def __init__(self):
-        init_logs()
+        init_logs_once()
         logger = logging.getLogger('nuclear.sublog')
         logger.setLevel(logging.DEBUG)
         logger.propagate = False

tests/sublog/test_context_logger.py

@@ -1,11 +1,15 @@
 import os
+from time import tzset
 
-from nuclear.sublog import logger, error_handler
+from nuclear.sublog import logger, error_handler, init_logs
 from tests.asserts import MockIO
 
 
 def test_context_logger():
     os.environ['TZ'] = 'Europe/Warsaw'
+    tzset()
+    init_logs()
+    logger.debug('42')
     with MockIO() as mockio:
         with logger.contextualize(request_id=0xdeaddead) as logger2:
             logger2.debug('got request')
@@ -51,7 +55,7 @@ def test_root_context_logger():
         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$')
+            ' I\'m a pickle, cause=RuntimeError traceback=.+:47$')
         mockio.assert_match_uncolor(' logged out, request_id=3735936685$')
         mockio.assert_match_uncolor(' exited$')
 
@@ -64,3 +68,13 @@ def test_child_logger():
     with MockIO() as mockio:
         logger.warning('beware of Python loggers')
         mockio.assert_match_uncolor('] WARN  beware of Python loggers$')
+
+
+def test_hidden_log_time():
+    try:
+        init_logs(show_time=False)
+        with MockIO() as mockio:
+            logger.debug('logged in')
+        mockio.assert_match('^DEBUG logged in$')
+    finally:
+        init_logs()

tests/sublog/test_wrap_error.py

@@ -1,8 +1,9 @@
-from nuclear.sublog import add_context, ContextError, logger, error_handler, exception_details
+from nuclear.sublog import add_context, ContextError, logger, error_handler, exception_details, init_logs
 from tests.asserts import MockIO
 
 
 def test_sublog_wrapping():
+    init_logs()
     with MockIO() as mockio:
         with error_handler():
             with add_context('initializing', request_id=42):
@@ -21,11 +22,11 @@ def test_sublog_wrapping():
 
         mockio.assert_match_uncolor('ERROR initializing: liftoff: dupa, '
                                     'request_id=42 speed=zero '
-                                    'cause=RuntimeError traceback=(.*)/test_wrap_error.py:10$')
+                                    'cause=RuntimeError traceback=(.*)/test_wrap_error.py:11$')
         mockio.assert_match_uncolor('ERROR dupa2, a=5 z=fifteen '
-                                    'cause=ContextError traceback=(.*)/test_wrap_error.py:13$')
+                                    'cause=ContextError traceback=(.*)/test_wrap_error.py:14$')
         mockio.assert_match_uncolor('ERROR dupa3, '
-                                    'cause=RuntimeError traceback=(.*)/test_wrap_error.py:16$')
+                                    'cause=RuntimeError traceback=(.*)/test_wrap_error.py:17$')
         mockio.assert_match_uncolor('INFO  success, param=with_param$')
         mockio.assert_match_uncolor('WARN  attention$')
         mockio.assert_match_uncolor('DEBUG trace$')