[4.4] Add documentation and tests for logging (#738)

* Add documentation for logging
* Add unit tests for logging helper

Author: robsdedude

docs/source/api.rst

@@ -1413,6 +1413,34 @@ following code:
     ...
 
 
+*******
+Logging
+*******
+
+The driver offers logging for debugging purposes. It is not recommended to
+enable logging for anything other than debugging. For instance, if the driver is
+not able to connect to the database server or if undesired behavior is observed.
+
+Logging can be enable like so:
+
+.. code-block:: python
+
+    import logging
+    import sys
+
+    # create a handler, e.g. to log to stdout
+    handler = logging.StreamHandler(sys.stdout)
+    # configure the handler to your liking
+    handler.setFormatter(logging.Formatter(
+        "%(threadName)s(%(thread)d) %(asctime)s  %(message)s"
+    ))
+    # add the handler to the driver's logger
+    logging.getLogger("neo4j").addHandler(handler)
+    # make sure the logger logs on the desired log level
+    logging.getLogger("neo4j").setLevel(logging.DEBUG)
+    # from now on, DEBUG logging to stderr is enabled in the driver
+
+
 ********
 Bookmark
 ********

neo4j/debug.py

@@ -44,16 +44,30 @@ def format(self, record):
 
 
 class Watcher:
-    """ Log watcher for monitoring driver and protocol activity.
-    """
+    """Log watcher for easier logging setup.
+
+    Example::
+
+        from neo4j.debug import Watcher
 
-    handlers = {}
+        with Watcher("neo4j"):
+            # DEBUG logging to stderr enabled within this context
+            ...  # do something
+
+    .. note:: The Watcher class is not thread-safe. Having Watchers in multiple
+        threads can lead to duplicate log messages as the context manager will
+        enable logging for all threads.
+
+    :param logger_names: Names of loggers to watch.
+    :type logger_names: str
+    """
 
     def __init__(self, *logger_names):
         super(Watcher, self).__init__()
         self.logger_names = logger_names
         self.loggers = [getLogger(name) for name in self.logger_names]
         self.formatter = ColourFormatter("%(asctime)s  %(message)s")
+        self.handlers = {}
 
     def __enter__(self):
         self.watch()
@@ -63,6 +77,13 @@ def __exit__(self, exc_type, exc_val, exc_tb):
         self.stop()
 
     def watch(self, level=DEBUG, out=stderr):
+        """Enable logging for all loggers.
+
+        :param level: Minimum log level to show.
+        :type level: int
+        :param out: Output stream for all loggers.
+        :type out: stream or file-like object
+        """
         self.stop()
         handler = StreamHandler(out)
         handler.setFormatter(self.formatter)
@@ -72,20 +93,36 @@ def watch(self, level=DEBUG, out=stderr):
             logger.setLevel(level)
 
     def stop(self):
-        try:
-            for logger in self.loggers:
-                logger.removeHandler(self.handlers[logger.name])
-        except KeyError:
-            pass
+        """Disable logging for all loggers."""
+        for logger in self.loggers:
+            try:
+                logger.removeHandler(self.handlers.pop(logger.name))
+            except KeyError:
+                pass
 
 
 def watch(*logger_names, level=DEBUG, out=stderr):
-    """ Quick wrapper for using the Watcher.
+    """Quick wrapper for using  :class:`.Watcher`.
+
+    Create a Wathcer with the given configuration, enable watching and return
+    it.
+
+    Example::
+
+        from neo4j.debug import watch
+
+        watch("neo4j")
+        # from now on, DEBUG logging to stderr is enabled in the driver
+
+    :param logger_names: name of logger to watch
+    :type logger_names: str
+    :param level: minimum log level to show (default ``logging.DEBUG``)
+    :type level: int
+    :param out: where to send output (default ``sys.stderr``)
+    :type out: stream or file-like object
 
-    :param logger_name: name of logger to watch
-    :param level: minimum log level to show (default DEBUG)
-    :param out: where to send output (default stderr)
     :return: Watcher instance
+    :rtype: :class:`.Watcher`
     """
     watcher = Watcher(*logger_names)
     watcher.watch(level, out)

tests/unit/test_debug.py

@@ -0,0 +1,162 @@
+# Copyright (c) "Neo4j"
+# Neo4j Sweden AB [https://neo4j.com]
+#
+# This file is part of Neo4j.
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     https://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+
+import io
+import logging
+import sys
+
+import pytest
+
+from neo4j import debug as neo4j_debug
+
+
+@pytest.fixture
+def add_handler_mocker(mocker):
+    def setup_mock(*logger_names):
+        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()
+        return loggers
+
+    return setup_mock
+
+
+def test_watch_returns_watcher(add_handler_mocker):
+    logger_name = "neo4j"
+    add_handler_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)
+    neo4j_debug.watch(*logger_names)
+    for logger in loggers:
+        logger.addHandler.assert_called_once()
+
+
+def test_watcher_watch_adds_logger(add_handler_mocker):
+    logger_name = "neo4j"
+    logger = add_handler_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):
+    logger_name = "neo4j"
+    logger = add_handler_mocker(logger_name)[0]
+    watcher = neo4j_debug.Watcher(logger_name)
+
+    watcher.watch()
+    (handler,), _ = logger.addHandler.call_args
+
+    logger.removeHandler.assert_not_called()
+    watcher.stop()
+    logger.removeHandler.assert_called_once_with(handler)
+
+
+def test_watcher_context_manager(mocker):
+    logger_name = "neo4j"
+    watcher = neo4j_debug.Watcher(logger_name)
+    watcher.watch = mocker.Mock()
+    watcher.stop = mocker.Mock()
+
+    with watcher:
+        watcher.watch.assert_called_once()
+        watcher.stop.assert_not_called()
+    watcher.stop.assert_called_once()
+
+
+@pytest.mark.parametrize(
+    ("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]
+    watcher = neo4j_debug.Watcher(logger_name)
+    kwargs = {}
+    if level is not None:
+        kwargs["level"] = level
+    watcher.watch(**kwargs)
+
+    (handler,), _ = logger.addHandler.call_args
+    assert handler.level == logging.NOTSET
+    logger.setLevel.assert_called_once_with(expected_level)
+
+
+custom_log_out = io.StringIO()
+
+@pytest.mark.parametrize(
+    ("out", "expected_out"),
+    (
+        (None, sys.stderr),
+        (sys.stderr, sys.stderr),
+        (sys.stdout, sys.stdout),
+        (custom_log_out, custom_log_out),
+    )
+)
+def test_watcher_out(add_handler_mocker, out, expected_out):
+    logger_name = "neo4j"
+    logger = add_handler_mocker(logger_name)[0]
+    watcher = neo4j_debug.Watcher(logger_name)
+    kwargs = {}
+    if out is not None:
+        kwargs["out"] = out
+    watcher.watch(**kwargs)
+
+    (handler,), _ = logger.addHandler.call_args
+    assert isinstance(handler, logging.StreamHandler)
+    assert handler.stream == expected_out
+
+
+def test_watcher_colour(add_handler_mocker):
+    logger_name = "neo4j"
+    logger = add_handler_mocker(logger_name)[0]
+    watcher = neo4j_debug.Watcher(logger_name)
+    watcher.watch()
+
+    (handler,), _ = logger.addHandler.call_args
+    assert isinstance(handler, logging.Handler)
+    assert isinstance(handler.formatter, neo4j_debug.ColourFormatter)
+
+
+def test_watcher_format(add_handler_mocker):
+    logger_name = "neo4j"
+    logger = add_handler_mocker(logger_name)[0]
+    watcher = neo4j_debug.Watcher(logger_name)
+    watcher.watch()
+
+    (handler,), _ = logger.addHandler.call_args
+    assert isinstance(handler, logging.Handler)
+    assert isinstance(handler.formatter, logging.Formatter)
+    # Don't look at me like that. It's just for testing.
+    format = handler.formatter._fmt
+    assert format == "%(asctime)s  %(message)s"