Improve logging helper neo4j.debug (#728)

 - no ANSI color codes by default
 - log thread name and id
 - add documentation for logging
 - add unit tests for logging helper

Author: robsdedude

CHANGELOG.md

@@ -6,8 +6,8 @@
 - Python 3.6 support has been dropped.
 - `Result`, `Session`, and `Transaction` can no longer be imported from
   `neo4j.work`. They should've been imported from `neo4j` all along.  
-  Remark: It's recommended to import everything needed directly from `noe4j`,
-  not its submodules or subpackages.
+  Remark: It's recommended to import everything needed directly from `noe4j` if
+  available, not its submodules or subpackages.
 - Experimental pipelines feature has been removed.
 - Experimental async driver has been added.
 - `ResultSummary.server.version_info` has been removed.  
@@ -51,9 +51,9 @@
       Use `hour_minute_second_nanosecond` instead.
     - The property `second` returns an `int` instead of a `float`.  
       Use `nanosecond` to get the sub-second information.
-- Creation of a driver with `bolt[+s[sc]]://` scheme has been deprecated and
-  will raise an error in the Future. The routing context was and will be
-  silently ignored until then.
+- Creation of a driver with `bolt[+s[sc]]://` scheme and a routing context has
+  been deprecated and will raise an error in the Future. The routing context was
+  and will be silently ignored until then.
 - Bookmarks
   - `Session.last_bookmark` was deprecated. Its behaviour is partially incorrect
     and cannot be fixed without breaking its signature.  
@@ -94,6 +94,10 @@
 - `ServerInfo.connection_id` has been deprecated and will be removed in a
   future release. There is no replacement as this is considered internal
   information.
+- Output of logging helper `neo4j.debug.watch` changes
+  - ANSI colour codes for log output are now opt-in
+  - Prepend log format with log-level (if colours are disabled)
+  - Prepend log format with thread name and id
 
 
 ## Version 4.4

docs/source/api.rst

@@ -1352,6 +1352,49 @@ 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.
+
+There are different ways of enabling logging as listed below.
+
+Simple Approach
+===============
+
+.. autofunction:: neo4j.debug.watch(*logger_names, level=logging.DEBUG, out=sys.stderr, colour=False)
+
+Context Manager
+===============
+
+.. autoclass:: neo4j.debug.Watcher(*logger_names, default_level=logging.DEBUG, default_out=sys.stderr, colour=False)
+    :members:
+    :special-members: __enter__, __exit__
+
+Full Controll
+=============
+
+.. 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
+
+
 *********
 Bookmarks
 *********

neo4j/debug.py

@@ -29,6 +29,12 @@
 from sys import stderr
 
 
+__all__ = [
+    "Watcher",
+    "watch"
+]
+
+
 class ColourFormatter(Formatter):
     """ Colour formatter for pretty log output.
     """
@@ -50,49 +56,117 @@ 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
+
+        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
+    :param default_level: Default minimum log level to show.
+        The level can be overridden by setting the level a level when calling
+        :meth:`.watch`.
+    :type default_level: int
+    :param default_out: Default output stream for all loggers.
+        The level can be overridden by setting the level a level when calling
+        :meth:`.watch`.
+    :type default_out: stream or file-like object
+    :param colour: Whether the log levels should be indicated with ANSI colour
+        codes.
+    :type colour: bool
     """
 
-    handlers = {}
-
-    def __init__(self, *logger_names):
+    def __init__(self, *logger_names, default_level=DEBUG, default_out=stderr,
+                 colour=False):
         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._loggers = [getLogger(name) for name in self.logger_names]
+        self.default_level = default_level
+        self.default_out = default_out
+        self._handlers = {}
+
+        format = "%(threadName)s(%(thread)d) %(asctime)s  %(message)s"
+        if not colour:
+            format = "[%(levelname)s] " + format
+
+        formatter_cls = ColourFormatter if colour else Formatter
+        self.formatter = formatter_cls(format)
 
     def __enter__(self):
+        """Enable logging for all loggers."""
         self.watch()
         return self
 
     def __exit__(self, exc_type, exc_val, exc_tb):
+        """Disable logging for all loggers."""
         self.stop()
 
-    def watch(self, level=DEBUG, out=stderr):
+    def watch(self, level=None, out=None):
+        """Enable logging for all loggers.
+
+        :param level: Minimum log level to show.
+            If :const:`None`, the ``default_level`` is used.
+        :type level: int or :const:`None`
+        :param out: Output stream for all loggers.
+            If :const:`None`, the ``default_out`` is used.
+        :type out: stream or file-like object or :const:`None`
+        """
+        if level is None:
+            level = self.default_level
+        if out is None:
+            out = self.default_out
         self.stop()
         handler = StreamHandler(out)
         handler.setFormatter(self.formatter)
-        for logger in self. loggers:
-            self.handlers[logger.name] = handler
+        for logger in self. _loggers:
+            self._handlers[logger.name] = handler
             logger.addHandler(handler)
             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, colour=False):
+    """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
 
-def watch(*logger_names, level=DEBUG, out=stderr):
-    """ Quick wrapper for using the Watcher.
+    :param logger_names: Names of loggers to watch.
+    :type logger_names: str
+    :param level: see ``default_level`` of :class:`.Watcher`.
+    :type level: int
+    :param out: see ``default_out`` of :class:`.Watcher`.
+    :type out: stream or file-like object
+    :param colour: see ``colour`` of :class:`.Watcher`.
+    :type colour: bool
 
-    :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)
+    watcher = Watcher(*logger_names, colour=colour, default_level=level,
+                      default_out=out)
+    watcher.watch()
     return watcher