From f94217c4099f6e8fa55d2eed32b3aba30958af72 Mon Sep 17 00:00:00 2001 From: Robsdedude Date: Tue, 2 Apr 2024 12:19:56 +0200 Subject: [PATCH] Improve logging helper `neo4j.debug.watch()` The helper did not handle logging level correctly. For example ``` neo4j.debug.watch("neo4j", out=sys.stdout) neo4j.debug.watch("neo4j", out=sys.stderr, level=logging.WARNING) ``` would've caused the logging level of the "neo4j" logger to end up being `WARNING` even though the first call (implicitly) requested `DEBUG`. The fix will make sure to set the logger's level to the most verbose requested level and use a level filter on the Handlers registered for each call to filter on the level accordingly. Backport of https://github.com/neo4j/neo4j-python-driver/pull/946 --- neo4j/debug.py | 4 +- tests/unit/test_debug.py | 125 +++++++++++++++++++++++++++++---------- 2 files changed, 96 insertions(+), 33 deletions(-) diff --git a/neo4j/debug.py b/neo4j/debug.py index 1e1a8e5d5..182f885b4 100644 --- a/neo4j/debug.py +++ b/neo4j/debug.py @@ -87,10 +87,12 @@ def watch(self, level=DEBUG, out=stderr): self.stop() handler = StreamHandler(out) handler.setFormatter(self.formatter) + handler.setLevel(level) for logger in self. loggers: self.handlers[logger.name] = handler logger.addHandler(handler) - logger.setLevel(level) + if logger.getEffectiveLevel() > level: + logger.setLevel(level) def stop(self): """Disable logging for all loggers.""" diff --git a/tests/unit/test_debug.py b/tests/unit/test_debug.py index e03e06826..ef4441cd8 100644 --- a/tests/unit/test_debug.py +++ b/tests/unit/test_debug.py @@ -26,37 +26,45 @@ @pytest.fixture -def add_handler_mocker(mocker): +def logger_mocker(mocker): + original_levels = {} + def setup_mock(*logger_names): + nonlocal original_levels + loggers = [logging.getLogger(name) for name in logger_names] for logger in loggers: - logger.addHandler = mocker.Mock() - logger.removeHandler = mocker.Mock() - logger.setLevel = mocker.Mock() + original_levels[logger] = logger.level + mocker.patch.object(logger, "addHandler") + mocker.patch.object(logger, "removeHandler") + mocker.spy(logger, "setLevel") return loggers - return setup_mock + yield setup_mock + + for logger, level in original_levels.items(): + logger.setLevel(level) -def test_watch_returns_watcher(add_handler_mocker): +def test_watch_returns_watcher(logger_mocker): logger_name = "neo4j" - add_handler_mocker(logger_name) + logger_mocker(logger_name) watcher = neo4j_debug.watch(logger_name) assert isinstance(watcher, neo4j_debug.Watcher) @pytest.mark.parametrize("logger_names", (("neo4j",), ("foobar",), ("neo4j", "foobar"))) -def test_watch_enables_logging(logger_names, add_handler_mocker): - loggers = add_handler_mocker(*logger_names) +def test_watch_enables_logging(logger_names, logger_mocker): + loggers = logger_mocker(*logger_names) neo4j_debug.watch(*logger_names) for logger in loggers: logger.addHandler.assert_called_once() -def test_watcher_watch_adds_logger(add_handler_mocker): +def test_watcher_watch_adds_logger(logger_mocker): logger_name = "neo4j" - logger = add_handler_mocker(logger_name)[0] + logger = logger_mocker(logger_name)[0] watcher = neo4j_debug.Watcher(logger_name) logger.addHandler.assert_not_called() @@ -64,9 +72,9 @@ def test_watcher_watch_adds_logger(add_handler_mocker): logger.addHandler.assert_called_once() -def test_watcher_stop_removes_logger(add_handler_mocker): +def test_watcher_stop_removes_logger(logger_mocker): logger_name = "neo4j" - logger = add_handler_mocker(logger_name)[0] + logger = logger_mocker(logger_name)[0] watcher = neo4j_debug.Watcher(logger_name) watcher.watch() @@ -89,31 +97,84 @@ def test_watcher_context_manager(mocker): watcher.stop.assert_called_once() -@pytest.mark.parametrize( - ("level", "expected_level"), - ( - (None, logging.DEBUG), - (logging.DEBUG, logging.DEBUG), - (logging.WARNING, logging.WARNING), - (1, 1), - ) +WATCH_ARGS = ( + # level, expected_level + (None, logging.DEBUG), + (logging.DEBUG, logging.DEBUG), + (logging.WARNING, logging.WARNING), + (1, 1), ) -def test_watcher_level(add_handler_mocker, level, expected_level): - logger_name = "neo4j" - logger = add_handler_mocker(logger_name)[0] + + +def _setup_watch(logger_name, level): watcher = neo4j_debug.Watcher(logger_name) kwargs = {} if level is not None: kwargs["level"] = level watcher.watch(**kwargs) + +@pytest.mark.parametrize(("level", "expected_level"), WATCH_ARGS) +@pytest.mark.parametrize( + "effective_level", + (logging.DEBUG, logging.WARNING, logging.INFO, logging.ERROR) +) +def test_watcher_level( + logger_mocker, level, expected_level, effective_level, +): + logger_name = "neo4j" + logger = logger_mocker(logger_name)[0] + logger.setLevel(effective_level) + logger.setLevel.reset_mock() + _setup_watch(logger_name, level) + (handler,), _ = logger.addHandler.call_args - assert handler.level == logging.NOTSET - logger.setLevel.assert_called_once_with(expected_level) + assert handler.level == expected_level + if effective_level <= expected_level: + logger.setLevel.assert_not_called() + else: + logger.setLevel.assert_called_once_with(expected_level) + + +@pytest.mark.parametrize(("level1", "expected_level1"), WATCH_ARGS) +@pytest.mark.parametrize(("level2", "expected_level2"), WATCH_ARGS) +@pytest.mark.parametrize( + "effective_level", + (logging.DEBUG, logging.WARNING, logging.INFO, logging.ERROR) +) +def test_watcher_level_multiple_watchers( + logger_mocker, level1, expected_level1, level2, expected_level2, + effective_level, +): + logger_name = "neo4j" + logger = logger_mocker(logger_name)[0] + logger.setLevel(effective_level) + logger.setLevel.reset_mock() + _setup_watch(logger_name, level1) + _setup_watch(logger_name, level2) + + assert logger.addHandler.call_count == 2 + (handler1,), _ = logger.addHandler.call_args_list[0] + (handler2,), _ = logger.addHandler.call_args_list[1] + + assert handler1.level == expected_level1 + assert handler2.level == expected_level2 + + expected_logger_level = min(expected_level1, expected_level2) + if effective_level <= expected_logger_level: + logger.setLevel.assert_not_called() + else: + if effective_level > expected_level1 > expected_level2: + assert logger.setLevel.call_count == 2 + else: + assert logger.setLevel.call_count == 1 + (level,), _ = logger.setLevel.call_args_list[-1] + assert level == expected_logger_level custom_log_out = io.StringIO() + @pytest.mark.parametrize( ("out", "expected_out"), ( @@ -123,9 +184,9 @@ def test_watcher_level(add_handler_mocker, level, expected_level): (custom_log_out, custom_log_out), ) ) -def test_watcher_out(add_handler_mocker, out, expected_out): +def test_watcher_out(logger_mocker, out, expected_out): logger_name = "neo4j" - logger = add_handler_mocker(logger_name)[0] + logger = logger_mocker(logger_name)[0] watcher = neo4j_debug.Watcher(logger_name) kwargs = {} if out is not None: @@ -137,9 +198,9 @@ def test_watcher_out(add_handler_mocker, out, expected_out): assert handler.stream == expected_out -def test_watcher_colour(add_handler_mocker): +def test_watcher_colour(logger_mocker): logger_name = "neo4j" - logger = add_handler_mocker(logger_name)[0] + logger = logger_mocker(logger_name)[0] watcher = neo4j_debug.Watcher(logger_name) watcher.watch() @@ -148,9 +209,9 @@ def test_watcher_colour(add_handler_mocker): assert isinstance(handler.formatter, neo4j_debug.ColourFormatter) -def test_watcher_format(add_handler_mocker): +def test_watcher_format(logger_mocker): logger_name = "neo4j" - logger = add_handler_mocker(logger_name)[0] + logger = logger_mocker(logger_name)[0] watcher = neo4j_debug.Watcher(logger_name) watcher.watch()