Merge pull request #560 from OpenCOMPES/logging_tests_and_fixes

Logging tests and fixes

Author: rettigl

src/sed/core/logging.py

@@ -11,6 +11,7 @@
 import sys
 from datetime import datetime
 from functools import wraps
+from inspect import signature
 from typing import Callable
 
 # Default log directory
@@ -43,28 +44,33 @@ def setup_logging(
     # Create base logger
     base_logger = logging.getLogger("sed")
     base_logger.setLevel(logging.DEBUG)  # Set the minimum log level for the logger
-    if set_base_handler or not base_logger.hasHandlers():
-        if base_logger.hasHandlers():
+    if set_base_handler or len(base_logger.handlers) == 0:
+        if len(base_logger.handlers):
             base_logger.handlers.clear()
 
         # Determine log file path
         if user_log_path is None:
             user_log_path = DEFAULT_LOG_DIR
-        os.makedirs(user_log_path, exist_ok=True)
-        log_file = os.path.join(user_log_path, f"sed_{datetime.now().strftime('%Y-%m-%d')}.log")
-
-        # Create file handler and set level to debug
-        file_handler = logging.FileHandler(log_file)
-        file_handler.setLevel(FILE_VERBOSITY)
-
-        # Create formatter for file
-        file_formatter = logging.Formatter(
-            "%(asctime)s - %(name)s - %(levelname)s - %(message)s in %(filename)s:%(lineno)d",
-        )
-        file_handler.setFormatter(file_formatter)
-
-        # Add file handler to logger
-        base_logger.addHandler(file_handler)
+        try:
+            os.makedirs(user_log_path, exist_ok=True)
+            log_file = os.path.join(user_log_path, f"sed_{datetime.now().strftime('%Y-%m-%d')}.log")
+
+            # Create file handler and set level to debug
+            file_handler = logging.FileHandler(log_file)
+            file_handler.setLevel(FILE_VERBOSITY)
+
+            # Create formatter for file
+            file_formatter = logging.Formatter(
+                "%(asctime)s - %(name)s - %(levelname)s - %(message)s in %(filename)s:%(lineno)d",
+            )
+            file_handler.setFormatter(file_formatter)
+
+            # Add file handler to logger
+            base_logger.addHandler(file_handler)
+        except PermissionError:
+            logging.warning(f"Cannot create logfile in Folder {user_log_path}, disabling logfile.")
+            base_logger.addHandler(logging.NullHandler())
+            base_logger.propagate = False
 
     # create named logger
     logger = base_logger.getChild(name)
@@ -109,7 +115,11 @@ def log_call(func: Callable):
         def new_func(*args, **kwargs):
             saved_args = locals()
             args_str = ""
-            for arg in saved_args["args"][1:]:
+            for arg in (
+                saved_args["args"][1:]
+                if "self" in signature(func).parameters
+                else saved_args["args"]
+            ):
                 args_str += f"{arg}, "
             for name, arg in saved_args["kwargs"].items():
                 args_str += f"{name}={arg}, "

tests/test_logging.py

@@ -0,0 +1,113 @@
+import io
+import logging
+import os
+from datetime import datetime
+
+import pytest
+
+from sed.core.logging import call_logger
+from sed.core.logging import set_verbosity
+from sed.core.logging import setup_logging
+
+
+@pytest.fixture
+def logger_():
+    logger = setup_logging("test_logger")
+    log_capture_string = io.StringIO()
+    ch = logging.StreamHandler(log_capture_string)
+    ch.setLevel(logging.DEBUG)
+    logger.addHandler(ch)
+    yield logger, log_capture_string
+
+
+def test_debug_logging(logger_):
+    logger, log_capture_string = logger_
+    logger.debug("This is a debug message")
+    assert "This is a debug message" in log_capture_string.getvalue()
+
+
+def test_info_logging(logger_):
+    logger, log_capture_string = logger_
+    logger.info("This is an info message")
+    assert "This is an info message" in log_capture_string.getvalue()
+
+
+def test_warning_logging(logger_):
+    logger, log_capture_string = logger_
+    logger.warning("This is a warning message")
+    assert "This is a warning message" in log_capture_string.getvalue()
+
+
+def test_error_logging(logger_):
+    logger, log_capture_string = logger_
+    logger.error("This is an error message")
+    assert "This is an error message" in log_capture_string.getvalue()
+
+
+def test_critical_logging(logger_):
+    logger, log_capture_string = logger_
+    logger.critical("This is a critical message")
+    assert "This is a critical message" in log_capture_string.getvalue()
+
+
+def test_set_verbosity(logger_):
+    logger, log_capture_string = logger_
+    set_verbosity(logger, verbose=True)
+    assert logger.handlers[0].level == logging.INFO
+    set_verbosity(logger, verbose=False)
+    assert logger.handlers[0].level == logging.WARNING
+
+
+def test_logger_has_base_logger(logger_):
+    logger, log_capture_string = logger_
+    assert logger.name == "sed.test_logger"
+    assert logger.parent.name == "sed"
+    assert logger.parent.parent.name == "root"
+    assert logger.parent.level == logging.DEBUG
+    assert isinstance(logger.parent.handlers[0], logging.FileHandler)
+
+
+def test_logger_creates_logfile(tmp_path):
+    logger = setup_logging("test_logger", set_base_handler=True, user_log_path=tmp_path)
+    log_file = os.path.join(tmp_path, f"sed_{datetime.now().strftime('%Y-%m-%d')}.log")
+    assert os.path.exists(log_file)
+    with open(log_file) as f:
+        assert f.read() == ""
+    logger.debug("This is a debug message")
+    with open(log_file) as f:
+        assert "This is a debug message" in f.read()
+
+
+def test_readonly_path(tmp_path, caplog):
+    os.chmod(tmp_path, 0o444)
+    with caplog.at_level(logging.WARNING):
+        setup_logging("test_logger", set_base_handler=True, user_log_path=tmp_path)
+    assert f"Cannot create logfile in Folder {tmp_path}, disabling logfile." in caplog.messages[0]
+    log_file = os.path.join(tmp_path, f"sed_{datetime.now().strftime('%Y-%m-%d')}.log")
+    assert not os.path.exists(log_file)
+
+
+def test_call_logger(logger_):
+    logger, log_capture_string = logger_
+
+    @call_logger(logger)
+    def test_function(test_param=None):  # noqa: ARG001
+        return
+
+    test_function(test_param=[1, 3, 5])
+    assert "test_function(test_param=[1, 3, 5])" in log_capture_string.getvalue()
+
+    test_function([1, 3, 5])
+    assert "test_function([1, 3, 5])" in log_capture_string.getvalue()
+
+    test_function()
+    assert "test_function()" in log_capture_string.getvalue()
+
+    class TestClass:
+        @call_logger(logger)
+        def test_method(self, test_param=None):  # noqa: ARG002
+            return
+
+    test_instance = TestClass()
+    test_instance.test_method(test_param=[1, 3, 5])
+    assert "test_method(test_param=[1, 3, 5])" in log_capture_string.getvalue()