Merge pull request #3487 from derekpierre/logging-one-more-thing

One more thing: Individual logging observers need to adhere to log levels

newsfragments/3487.misc.rst

@@ -0,0 +1 @@
+Ensure that log observers filter log messages by log level.

nucypher/network/nodes.py

@@ -1133,7 +1133,7 @@ class Teacher:
             if self._staking_provider_is_really_staking(
                 registry=registry, eth_endpoint=eth_endpoint
             ):  # <-- Blockchain CALL
-                self.log.info(f"Verified operator {self}")
+                self.log.debug(f"Verified operator {self}")
                 self.verified_operator = True
             else:
                 raise self.NotStaking(f"{self.checksum_address} is not staking")

nucypher/utilities/logging.py

@@ -2,9 +2,11 @@ import pathlib
 import sys
 from contextlib import contextmanager
 from enum import Enum
+from typing import Callable
 
 from twisted.logger import (
     FileLogObserver,
+    LogEvent,
     LogLevel,
     formatEventAsClassicLogText,
     globalLogPublisher,
@@ -106,8 +108,11 @@ class GlobalLoggerSettings:
             # sentry
             observer = sentry_observer
 
-        cls._observers[logging_type] = observer
-        globalLogPublisher.addObserver(observer)
+        # wrap to adhere to log level since other loggers rely on observer to differentiate
+        wrapped_observer = observer_log_level_wrapper(observer)
+
+        globalLogPublisher.addObserver(wrapped_observer)
+        cls._observers[logging_type] = wrapped_observer
 
     @classmethod
     def start_console_logging(cls):
@@ -224,3 +229,11 @@ class Logger(TwistedLogger):
         if level >= GlobalLoggerSettings.log_level:
             clean_format = self.escape_format_string(str(format))
             super().emit(level=level, format=clean_format, **kwargs)
+
+
+def observer_log_level_wrapper(observer: Callable[[LogEvent], None]):
+    def log_level_wrapper(event: LogEvent):
+        if event["log_level"] >= GlobalLoggerSettings.log_level:
+            observer(event)
+
+    return log_level_wrapper

tests/unit/test_logging.py

@@ -13,7 +13,11 @@ from twisted.logger import (
 )
 
 from nucypher.utilities.emitters import StdoutEmitter
-from nucypher.utilities.logging import GlobalLoggerSettings, Logger
+from nucypher.utilities.logging import (
+    GlobalLoggerSettings,
+    Logger,
+    observer_log_level_wrapper,
+)
 
 
 def naive_print_observer(event):
@@ -169,15 +173,12 @@ def test_pause_all_logging_while():
 
 
 @pytest.mark.parametrize("global_log_level", LogLevel._enumerants.values())
-def test_log_level_adhered_to(global_log_level):
+def test_log_level_adhered_to(global_log_level, mocker):
     old_log_level = GlobalLoggerSettings.log_level.name
     try:
         GlobalLoggerSettings.set_log_level(global_log_level.name)
 
-        received_events = []
-
-        def logger_observer(event):
-            received_events.append(event)
+        logger_observer = mocker.Mock()
 
         logger = Logger("test-logger")
         logger.observer = logger_observer
@@ -193,7 +194,80 @@ def test_log_level_adhered_to(global_log_level):
                 num_logged_events += 1
             # else not logged
 
-            assert len(received_events) == num_logged_events
+            assert logger_observer.call_count == num_logged_events
+    finally:
+        GlobalLoggerSettings.set_log_level(old_log_level)
+
+
+@pytest.mark.parametrize("global_log_level", LogLevel._enumerants.values())
+def test_observer_log_level_wrapper_for_adhering_to_log_levels(
+    global_log_level, mocker
+):
+    old_log_level = GlobalLoggerSettings.log_level.name
+    try:
+        GlobalLoggerSettings.set_log_level(global_log_level.name)
+
+        logger_observer = mocker.Mock()
+
+        logger = TwistedLogger("test-logger")
+        logger.observer = observer_log_level_wrapper(logger_observer)
+
+        message = "People without self-doubt should never put themselves in a position of complete power"  # - Chuck Rhoades (Billions)
+        num_logged_events = 0
+
+        for level in LogLevel._enumerants.values():
+            # call logger.<level>(message)
+            getattr(logger, level.name)(message)
+
+            if level >= global_log_level:
+                num_logged_events += 1
+            # else not logged
+
+            assert logger_observer.call_count == num_logged_events
+    finally:
+        GlobalLoggerSettings.set_log_level(old_log_level)
+
+
+@pytest.mark.parametrize("global_log_level", LogLevel._enumerants.values())
+def test_global_observer_uses_wrapper_for_adhering_to_log_levels(
+    global_log_level, mocker
+):
+    original_method = observer_log_level_wrapper
+
+    logger_observer = mocker.Mock()
+
+    def adjusted_call(observer):
+        # replace observer used with our Mock
+        return original_method(logger_observer)
+
+    old_log_level = GlobalLoggerSettings.log_level.name
+    try:
+        GlobalLoggerSettings.set_log_level(global_log_level.name)
+
+        with GlobalLoggerSettings.pause_all_logging_while():
+            # patch call to wrapper, to replace global observer with our own
+            mocker.patch(
+                "nucypher.utilities.logging.observer_log_level_wrapper",
+                side_effect=adjusted_call,
+            )
+
+            GlobalLoggerSettings.start_console_logging()
+            assert len(GlobalLoggerSettings._observers) == 1
+
+            logger = TwistedLogger("test-logger")
+            message = "People without self-doubt should never put themselves in a position of complete power"  # - Chuck Rhoades (Billions)
+
+            num_logged_events = 0
+
+            for level in LogLevel._enumerants.values():
+                # call logger.<level>(message)
+                getattr(logger, level.name)(message)
+
+                if level >= global_log_level:
+                    num_logged_events += 1
+                # else not logged
+
+                assert logger_observer.call_count == num_logged_events
     finally:
         GlobalLoggerSettings.set_log_level(old_log_level)