diff --git a/CHANGELOG.md b/CHANGELOG.md index 29f98993..ffe36b39 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/docs/source/api.rst b/docs/source/api.rst index 44cd604d..30a2e92f 100644 --- a/docs/source/api.rst +++ b/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 ********* diff --git a/neo4j/debug.py b/neo4j/debug.py index b1a191ca..275e356c 100644 --- a/neo4j/debug.py +++ b/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 diff --git a/tests/unit/common/test_debug.py b/tests/unit/common/test_debug.py new file mode 100644 index 00000000..245fde64 --- /dev/null +++ b/tests/unit/common/test_debug.py @@ -0,0 +1,184 @@ +# 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( + ("default_level", "level", "expected_level"), + ( + (None, None, logging.DEBUG), + (logging.WARNING, None, logging.WARNING), + (logging.WARNING, logging.DEBUG, logging.DEBUG), + (logging.DEBUG, logging.WARNING, logging.WARNING), + (1, None, 1), + (None, 1, 1), + ) +) +def test_watcher_level(add_handler_mocker, default_level, level, + expected_level): + logger_name = "neo4j" + logger = add_handler_mocker(logger_name)[0] + kwargs = {} + if default_level is not None: + kwargs["default_level"] = default_level + watcher = neo4j_debug.Watcher(logger_name, **kwargs) + 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( + ("default_out", "out", "expected_out"), + ( + (None, None, sys.stderr), + (sys.stdout, None, sys.stdout), + (sys.stdout, sys.stderr, sys.stderr), + (sys.stderr, sys.stdout, sys.stdout), + (custom_log_out, None, custom_log_out), + (None, custom_log_out, custom_log_out), + ) +) +def test_watcher_out(add_handler_mocker, default_out, out, + expected_out): + logger_name = "neo4j" + logger = add_handler_mocker(logger_name)[0] + kwargs = {} + if default_out is not None: + kwargs["default_out"] = default_out + watcher = neo4j_debug.Watcher(logger_name, **kwargs) + 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 + + +@pytest.mark.parametrize("colour", (True, False)) +def test_watcher_colour(add_handler_mocker, colour): + logger_name = "neo4j" + logger = add_handler_mocker(logger_name)[0] + watcher = neo4j_debug.Watcher(logger_name, colour=colour) + watcher.watch() + + (handler,), _ = logger.addHandler.call_args + assert isinstance(handler, logging.Handler) + assert isinstance(handler.formatter, logging.Formatter) + if colour: + assert isinstance(handler.formatter, neo4j_debug.ColourFormatter) + else: + assert not isinstance(handler.formatter, neo4j_debug.ColourFormatter) + + +@pytest.mark.parametrize("colour", (True, False)) +def test_watcher_format(add_handler_mocker, colour): + logger_name = "neo4j" + logger = add_handler_mocker(logger_name)[0] + watcher = neo4j_debug.Watcher(logger_name, colour=colour) + 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 + if colour: + assert format == "%(threadName)s(%(thread)d) %(asctime)s %(message)s" + else: + assert format == "[%(levelname)s] " \ + "%(threadName)s(%(thread)d) %(asctime)s %(message)s"