Improve logging helper neo4j.debug.watch() (#1032)

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 #946

Author: robsdedude

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."""

tests/unit/test_debug.py

@@ -26,47 +26,55 @@
 
 
 @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()
     watcher.watch()
     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()