diff --git a/docs/source/api.rst b/docs/source/api.rst index b1e5c7b19..17a7afe9f 100644 --- a/docs/source/api.rst +++ b/docs/source/api.rst @@ -1374,6 +1374,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 ******** diff --git a/neo4j/debug.py b/neo4j/debug.py index b8872a377..ae176d8b7 100644 --- a/neo4j/debug.py +++ b/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) diff --git a/tests/unit/test_debug.py b/tests/unit/test_debug.py new file mode 100644 index 000000000..e03e06826 --- /dev/null +++ b/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"