caching of checks for whether to log at DEBUG2 levels

eth_utils/logging.py

@@ -1,19 +1,43 @@
 import contextlib
+import functools
 import logging
-from typing import Any, Iterator, Type, TypeVar
+from typing import Any, Callable, Iterator, Optional, Type, TypeVar
 
 from .toolz import assoc
 
 DEBUG2_LEVEL_NUM = 8
 
 
+class cached_show_debug2_property:
+    def __init__(self, func: Callable[[logging.Logger], bool]):
+        functools.update_wrapper(self, func)
+        self._func = func
+
+    def __get__(self, obj: Optional[logging.Logger], cls: Type[logging.Logger]) -> bool:
+        if obj is None:
+            return self
+
+        result = self._func(obj)
+        obj.__dict__[self._func.__name__] = result
+        return result
+
+
 class ExtendedDebugLogger(logging.Logger):
     """
     Logging class that can be used for lower level debug logging.
     """
+    @cached_show_debug2_property
+    def show_debug2(self) -> bool:
+        return self.isEnabledFor(DEBUG2_LEVEL_NUM)
 
     def debug2(self, message: str, *args: Any, **kwargs: Any) -> None:
-        self.log(DEBUG2_LEVEL_NUM, message, *args, **kwargs)
+        if self.show_debug2:
+            self.log(DEBUG2_LEVEL_NUM, message, *args, **kwargs)
+        else:
+            # When we find that `DEBUG2` isn't enabled we completely replace
+            # the `debug2` function in this instance of the logger with a noop
+            # lambda to further speed up
+            self.__dict__['debug2'] = lambda message, *args, **kwargs: None
 
 
 def setup_DEBUG2_logging() -> None:

tests/logging-utils/test_DEBUG2_logging.py

@@ -1,4 +1,5 @@
 import logging
+import uuid
 
 import pytest
 
@@ -7,7 +8,7 @@
 
 
 @pytest.fixture
-def DEBUG2_enabled():
+def DEBUG2_installed():
     # caplog only works on loggers retrieved from `logging.getLogger` so we
     # have to use that mechanism to instantiate our logger.
     original_logger = logging.getLoggerClass()
@@ -19,7 +20,7 @@ def DEBUG2_enabled():
         logging.setLoggerClass(original_logger)
 
 
-def test_extended_debug_logger(caplog, DEBUG2_enabled):
+def test_extended_debug_logger(caplog, DEBUG2_installed):
     caplog.set_level(DEBUG2_LEVEL_NUM, "testing")
 
     logger = logging.getLogger("testing")
@@ -32,3 +33,47 @@ def test_extended_debug_logger(caplog, DEBUG2_enabled):
     assert record.levelno == 8
     assert record.args == (1,)
     assert record.message == "message 1"
+
+
+def test_caching_of_debug2_when_disabled(DEBUG2_installed):
+    # we need a unique logger because loggers are cached
+    logger = logging.getLogger(f"testing-{uuid.uuid4()}")
+
+    assert logger.isEnabledFor(DEBUG2_LEVEL_NUM) is False
+
+    assert 'show_debug2' not in logger.__dict__
+    assert logger.show_debug2 is False
+    # cached property should have inserted it into the dict
+    assert 'show_debug2' in logger.__dict__
+
+    assert 'debug2' not in logger.__dict__
+    assert logger.debug2('this should actually call the function') is None
+    assert 'debug2' in logger.__dict__
+    assert logger.debug2('should not do anything but hit the lambda') is None
+
+    # now see that it always returns the value from `__dict__`
+    logger.__dict__['show_debug2'] = 100
+    assert logger.show_debug2 == 100
+
+
+def test_caching_of_debug2_when_enabled(DEBUG2_installed):
+    # we need a unique logger because loggers are cached
+    logger = logging.getLogger(f"testing-{uuid.uuid4()}")
+
+    assert logger.isEnabledFor(DEBUG2_LEVEL_NUM) is False
+    logger.setLevel(DEBUG2_LEVEL_NUM)
+    assert logger.isEnabledFor(DEBUG2_LEVEL_NUM) is True
+
+    assert 'show_debug2' not in logger.__dict__
+    assert logger.show_debug2 is True
+    # cached property should have inserted it into the dict
+    assert 'show_debug2' in logger.__dict__
+
+    assert 'debug2' not in logger.__dict__
+    assert logger.debug2('this should actually call the function') is None
+    assert 'debug2' not in logger.__dict__
+    assert logger.debug2('this should still call the function') is None
+
+    # now see that it always returns the value from `__dict__`
+    logger.__dict__['show_debug2'] = 100
+    assert logger.show_debug2 == 100