diff --git a/.codecov.yml b/.codecov.yml index 214fccccbe..ef7afc0241 100644 --- a/.codecov.yml +++ b/.codecov.yml @@ -12,3 +12,6 @@ coverage: threshold: 1% github_checks: annotations: false +exclude_lines: + - except ImportError: colorama = None + - except curses: curses = None diff --git a/src/ophyd_async/core/device.py b/src/ophyd_async/core/device.py index 07145ae8f2..0e86675fd5 100644 --- a/src/ophyd_async/core/device.py +++ b/src/ophyd_async/core/device.py @@ -3,6 +3,7 @@ from __future__ import annotations import sys +from logging import LoggerAdapter, getLogger from typing import ( Any, Coroutine, @@ -33,6 +34,9 @@ class Device(HasName): def __init__(self, name: str = "") -> None: self.set_name(name) + self.log = LoggerAdapter( + getLogger("ophyd_async.devices"), {"ophyd_async_device_name": self.name} + ) @property def name(self) -> str: @@ -190,3 +194,4 @@ def __exit__(self, type_, value, traceback): "user/explanations/event-loop-choice.html for more info." ) return fut + return fut diff --git a/src/ophyd_async/core/log.py b/src/ophyd_async/core/log.py new file mode 100644 index 0000000000..9ca452c9d9 --- /dev/null +++ b/src/ophyd_async/core/log.py @@ -0,0 +1,250 @@ +# The LogFormatter is adapted light from tornado, which is licensed unders +# Apache 2.0. See other_licenses/ in the repository directory. + +import logging +import sys + +try: + import colorama + + colorama.init() +except ImportError: + colorama = None +try: + import curses +except ImportError: + curses = None + +__all__ = ( + "config_ophyd_async_logging", + "logger", + "set_handler", +) + + +def _stderr_supports_color(): + try: + if hasattr(sys.stderr, "isatty") and sys.stderr.isatty(): + if "curses" in sys.modules: + curses.setupterm() + if curses.tigetnum("colors") > 0: + return True + elif colorama: + if sys.stderr is getattr( + colorama.initialise, "wrapped_stderr", object() + ): + return True + except Exception: + # Very broad exception handling because it's always better to + # fall back to non-colored logs than to break at startup. + pass + return False + + +class LogFormatter(logging.Formatter): + """Log formatter used in Tornado, modified for Python3-only ophyd, then + reused for ophyd-async + + Key features of this formatter are: + + * Color support when logging to a terminal that supports it. + * Timestamps on every log line. + * Robust against str/bytes encoding problems. + + This formatter is enabled automatically by + ``tornado.options.parse_command_line`` or ``tornado.options.parse_config_file`` + (unless ``--logging=none`` is used). + Color support on Windows versions that do not support ANSI color codes is + enabled by use of the colorama__ library. Applications that wish to use + this must first initialize colorama with a call to ``colorama.init``. + See the colorama documentation for details. + + __ https://pypi.python.org/pypi/colorama + + .. versionchanged:: 4.5 + + Added support for ``colorama``. Changed the constructor + signature to be compatible with `logging.config.dictConfig`. + """ + + DEFAULT_FORMAT = "%(color)s[%(levelname)1.1s %(asctime)s %(module)s:\ + %(lineno)d]%(end_color)s %(message)s" + + DEFAULT_DATE_FORMAT = "%y%m%d %H:%M:%S" + DEFAULT_COLORS = { + logging.DEBUG: 4, # Blue + logging.INFO: 2, # Green + logging.WARNING: 3, # Yellow + logging.ERROR: 1, # Red + } + + def __init__( + self, + fmt=DEFAULT_FORMAT, + datefmt=DEFAULT_DATE_FORMAT, + style="%", + color=True, + colors=DEFAULT_COLORS, + ): + r""" + :arg bool color: Enables color support. + :arg str fmt: Log message format. + It will be applied to the attributes dict of log records. The + text between ``%(color)s`` and ``%(end_color)s`` will be colored + depending on the level if color support is on. + :arg dict colors: color mappings from logging level to terminal color + code + :arg str datefmt: Datetime format. + Used for formatting ``(asctime)`` placeholder in ``prefix_fmt``. + + .. versionchanged:: 3.2 + + Added ``fmt`` and ``datefmt`` arguments. + """ + super().__init__(datefmt=datefmt) + self._fmt = fmt + + self._colors = {} + if color and _stderr_supports_color(): + if "curses" in sys.modules: + # The curses module has some str/bytes confusion in + # python3. Until version 3.2.3, most methods return + # bytes, but only accept strings. In addition, we want to + # output these strings with the logging module, which + # works with unicode strings. The explicit calls to + # unicode() below are harmless in python2 but will do the + # right conversion in python 3. + fg_color = curses.tigetstr("setaf") or curses.tigetstr("setf") or "" + + for levelno, code in colors.items(): + self._colors[levelno] = str(curses.tparm(fg_color, code), "ascii") + self._normal = str(curses.tigetstr("sgr0"), "ascii") + else: + # If curses is not present (currently we'll only get here for + # colorama on windows), assume hard-coded ANSI color codes. + for levelno, code in colors.items(): + self._colors[levelno] = "\033[2;3%dm" % code + self._normal = "\033[0m" + else: + self._normal = "" + + def format(self, record): + message = [] + if hasattr(record, "ophyd_async_device_name"): + message.append(f"[{record.ophyd_async_device_name}]") + + message.append(record.getMessage()) + record.message = " ".join(message) + record.asctime = self.formatTime(record, self.datefmt) + + try: + record.color = self._colors[record.levelno] + record.end_color = self._normal + except KeyError: + record.color = "" + record.end_color = "" + + formatted = self._fmt % record.__dict__ + + if record.exc_info and not record.exc_text: + record.exc_text = self.formatException(record.exc_info) + if record.exc_text: + formatted = "{}\n{}".format(formatted.rstrip(), record.exc_text) + return formatted.replace("\n", "\n ") + + +plain_log_format = ( + "[%(levelname)1.1s %(asctime)s.%(msecs)03d %(module)s:%(lineno)d] %(message)s" +) +color_log_format = ( + "%(color)s[%(levelname)1.1s %(asctime)s.%(msecs)03d " + "%(module)s:%(lineno)d]%(end_color)s %(message)s" +) + + +def validate_level(level) -> int: + """ + Return an int for level comparison + """ + if isinstance(level, int): + levelno = level + elif isinstance(level, str): + levelno = logging.getLevelName(level) + + if isinstance(levelno, int): + return levelno + else: + raise ValueError( + "Your level is illegal, please use " + "'CRITICAL', 'FATAL', 'ERROR', 'WARNING', 'INFO', or 'DEBUG'." + ) + + +logger = logging.getLogger("ophyd_async") + +current_handler = None # overwritten below + + +def config_ophyd_async_logging( + file=sys.stdout, datefmt="%H:%M:%S", color=True, level="WARNING" +): + """ + Set a new handler on the ``logging.getLogger('ophyd_async')`` logger. + If this is called more than once, the handler from the previous invocation + is removed (if still present) and replaced. + + Parameters + ---------- + file : object with ``write`` method or filename string + Default is ``sys.stdout``. + datefmt : string + Date format. Default is ``'%H:%M:%S'``. + color : boolean + Use ANSI color codes. True by default. + level : str or int + Python logging level, given as string or corresponding integer. + Default is 'WARNING'. + Returns + ------- + handler : logging.Handler + The handler, which has already been added to the 'ophyd_async' logger. + Examples + -------- + Log to a file. + config_ophyd_async_logging(file='/tmp/what_is_happening.txt') + Include the date along with the time. (The log messages will always include + microseconds, which are configured separately, not as part of 'datefmt'.) + config_ophyd_async_logging(datefmt="%Y-%m-%d %H:%M:%S") + Turn off ANSI color codes. + config_ophyd_async_logging(color=False) + Increase verbosity: show level DEBUG or higher. + config_ophyd_async_logging(level='DEBUG') + """ + global current_handler + if isinstance(file, str): + handler = logging.FileHandler(file) + else: + handler = logging.StreamHandler(file) + levelno = validate_level(level) + handler.setLevel(levelno) + if color: + log_format = color_log_format + else: + log_format = plain_log_format + handler.setFormatter(LogFormatter(log_format, datefmt=datefmt)) + + if current_handler in logger.handlers: + logger.removeHandler(current_handler) + logger.addHandler(handler) + + current_handler = handler + + if logger.getEffectiveLevel() > levelno: + logger.setLevel(levelno) + try: + return handler + finally: + handler.close() + + +set_handler = config_ophyd_async_logging # for back-compat diff --git a/src/ophyd_async/core/signal.py b/src/ophyd_async/core/signal.py index 927faaf402..3321a4ec3f 100644 --- a/src/ophyd_async/core/signal.py +++ b/src/ophyd_async/core/signal.py @@ -45,11 +45,15 @@ class Signal(Device, Generic[T]): """A Device with the concept of a value, with R, RW, W and X flavours""" def __init__( - self, backend: SignalBackend[T], timeout: Optional[float] = DEFAULT_TIMEOUT + self, + backend: SignalBackend[T], + timeout: Optional[float] = DEFAULT_TIMEOUT, + name: str = "", ) -> None: self._name = "" self._timeout = timeout self._init_backend = self._backend = backend + super().__init__(name) @property def name(self) -> str: @@ -67,6 +71,7 @@ async def connect(self, sim=False, timeout=DEFAULT_TIMEOUT): else: self._backend = self._init_backend _sim_backends.pop(self, None) + self.log.debug(f"Connecting to {self.source}") await self._backend.connect(timeout=timeout) @property @@ -91,10 +96,12 @@ def __init__(self, backend: SignalBackend[T], signal: Signal): self._value: Optional[T] = None self.backend = backend + signal.log.debug(f"Making subscription on source {signal.source}") backend.set_callback(self._callback) def close(self): self.backend.set_callback(None) + self._signal.log.debug(f"Closing subscription on source {self._signal.source}") async def get_reading(self) -> Reading: await self._valid.wait() @@ -107,6 +114,10 @@ async def get_value(self) -> T: return self._value def _callback(self, reading: Reading, value: T): + self._signal.log.debug( + f"Updated subscription: reading of source {self._signal.source} changed\ + from {self._reading} to {reading}" + ) self._reading = reading self._value = value self._valid.set() @@ -173,7 +184,9 @@ async def describe(self) -> Dict[str, Descriptor]: @_add_timeout async def get_value(self, cached: Optional[bool] = None) -> T: """The current value""" - return await self._backend_or_cache(cached).get_value() + value = await self._backend_or_cache(cached).get_value() + self.log.debug(f"get_value() on source {self.source} returned {value}") + return value def subscribe_value(self, function: Callback[T]): """Subscribe to updates in value of a device""" @@ -208,8 +221,15 @@ def set(self, value: T, wait=True, timeout=USE_DEFAULT_TIMEOUT) -> AsyncStatus: """Set the value and return a status saying when it's done""" if timeout is USE_DEFAULT_TIMEOUT: timeout = self._timeout - coro = self._backend.put(value, wait=wait, timeout=timeout) - return AsyncStatus(coro) + + async def do_set(): + self.log.debug(f"Putting value {value} to backend at source {self.source}") + await self._backend.put(value, wait=wait, timeout=timeout) + self.log.debug( + f"Successfully put value {value} to backend at source {self.source}" + ) + + return AsyncStatus(do_set()) class SignalRW(SignalR[T], SignalW[T], Locatable): diff --git a/tests/core/test_log.py b/tests/core/test_log.py new file mode 100644 index 0000000000..c50ac00b28 --- /dev/null +++ b/tests/core/test_log.py @@ -0,0 +1,96 @@ +import io +import logging +import logging.handlers +import sys +from unittest.mock import patch + +import colorama +import pytest + +from ophyd_async.core import Device, log +from ophyd_async.core.log import _stderr_supports_color + + +def test_validate_level(): + assert log.validate_level("CRITICAL") == 50 + assert log.validate_level("ERROR") == 40 + assert log.validate_level("WARNING") == 30 + assert log.validate_level("INFO") == 20 + assert log.validate_level("DEBUG") == 10 + assert log.validate_level("NOTSET") == 0 + assert log.validate_level(123) == 123 + with pytest.raises(ValueError): + log.validate_level("MYSTERY") + + +def test_default_config_ophyd_async_logging(): + log.config_ophyd_async_logging() + assert isinstance(log.current_handler, logging.StreamHandler) + assert log.logger.getEffectiveLevel() <= logging.WARNING + + +def test_logger_adapter_ophyd_async_device(): + log_buffer = io.StringIO() + log_stream = logging.StreamHandler(stream=log_buffer) + log_stream.setFormatter(log.LogFormatter()) + log.logger.addHandler(log_stream) + + device = Device(name="test_device") + device.log.warning("here is a warning") + assert log_buffer.getvalue().endswith("[test_device] here is a warning\n") + assert log_buffer.getvalue().endswith("[test_device] here is a warning\n") + assert log_buffer.getvalue().endswith("[test_device] here is a warning\n") + assert log_buffer.getvalue().endswith("[test_device] here is a warning\n") + + +def test_formatter_with_colour(): + log_buffer = io.StringIO() + log_stream = logging.StreamHandler(stream=log_buffer) + with ( + patch("ophyd_async.core.log._stderr_supports_color", return_value=True), + patch("curses.tigetstr", return_value=bytes(4)), + patch("curses.tparm", return_value=bytes(4)), + ): + log_stream.setFormatter(log.LogFormatter()) + + +def test_formatter_with_colour_no_curses(monkeypatch): + log_buffer = io.StringIO() + log_stream = logging.StreamHandler(stream=log_buffer) + with ( + patch("ophyd_async.core.log._stderr_supports_color", return_value=True), + patch("curses.tigetstr", return_value=bytes(4)), + patch("curses.tparm", return_value=bytes(4)), + ): + monkeypatch.delitem(sys.modules, "curses", raising=False) + log_stream.setFormatter(log.LogFormatter()) + + +def test_stderr_supports_color_not_atty(): + with patch("sys.stderr.isatty", return_value=False): + assert not _stderr_supports_color() + + +def test_stderr_supports_color_curses_available(): + with patch("sys.stderr.isatty", return_value=True), patch("curses.setupterm"): + with patch("curses.tigetnum", return_value=8): + assert _stderr_supports_color() + + +def test_stderr_supports_color_colorama_available(monkeypatch): + monkeypatch.delitem(sys.modules, "curses", raising=False) + with ( + patch("sys.stderr.isatty", return_value=True), + patch("colorama.initialise"), + ): + colorama.initialise.wrapped_stderr = sys.stderr + assert _stderr_supports_color() + + +def test_stderr_supports_color_no_curses_no_colorama(): + with ( + patch("sys.stderr.isatty", return_value=True), + patch("curses.setupterm"), + patch("colorama.initialise"), + ): + assert not _stderr_supports_color() diff --git a/tests/core/test_signal.py b/tests/core/test_signal.py index 5393cb1a78..62395bad23 100644 --- a/tests/core/test_signal.py +++ b/tests/core/test_signal.py @@ -1,11 +1,13 @@ import asyncio import re import time +from unittest.mock import AsyncMock import pytest from ophyd_async.core import ( Signal, + SignalBackend, SignalRW, SimSignalBackend, set_and_wait_for_value, @@ -13,6 +15,8 @@ set_sim_value, wait_for_value, ) +from ophyd_async.core.log import config_ophyd_async_logging +from ophyd_async.core.signal import _SignalCache from ophyd_async.core.utils import DEFAULT_TIMEOUT @@ -25,6 +29,20 @@ async def connect(self, sim=False, timeout=DEFAULT_TIMEOUT): pass +class MockSignalRW(SignalRW): + def __init__(self, backend, timeout, name): + super().__init__(backend, timeout, name) + self._backend = AsyncMock() + + async def connect(self): + pass + + +@pytest.fixture +def mock_signal_rw(): + return + + def test_signals_equality_raises(): sim_backend = SimSignalBackend(str, "test") @@ -119,3 +137,31 @@ async def test_set_and_wait_for_value(): assert not st.done set_sim_put_proceeds(sim_signal, True) assert await time_taken_by(st) < 0.1 + + +async def test_signal_connect_logs(caplog): + config_ophyd_async_logging(level="DEBUG") + sim_signal = Signal(SimSignalBackend(str, "test"), timeout=1, name="test_signal") + await sim_signal.connect(sim=True) + assert caplog.text.endswith("Connecting to sim://test\n") + + +async def test_signal_get_and_set_logging(caplog, mock_signal_rw): + config_ophyd_async_logging(level="DEBUG") + mock_signal_rw = MockSignalRW(SignalBackend, timeout=1, name="mock_signal") + await mock_signal_rw.set(value=0) + assert "Putting value 0 to backend at source" in caplog.text + assert "Successfully put value 0 to backend at source" in caplog.text + await mock_signal_rw.get_value() + assert "get_value() on source" in caplog.text + + +def test_subscription_logs(caplog): + config_ophyd_async_logging(level="DEBUG") + cache = _SignalCache( + SignalBackend(), + signal=MockSignalRW(SignalBackend, timeout=1, name="mock_signal"), + ) + assert "Making subscription" in caplog.text + cache.close() + assert "Closing subscription on source" in caplog.text diff --git a/tests/core/test_utils.py b/tests/core/test_utils.py index 6a02bff77f..8fb4179ed5 100644 --- a/tests/core/test_utils.py +++ b/tests/core/test_utils.py @@ -1,3 +1,5 @@ +from unittest.mock import patch + import pytest from ophyd_async.core import ( @@ -123,9 +125,9 @@ async def test_error_handling_connection_timeout(caplog): assert str(e.value) == str(ONE_WORKING_ONE_TIMEOUT_OUTPUT) logs = caplog.get_records("call") - assert len(logs) == 1 - assert "signal ca://A_NON_EXISTENT_SIGNAL timed out" == logs[0].message - assert logs[0].levelname == "DEBUG" + assert len(logs) == 3 + assert "signal ca://A_NON_EXISTENT_SIGNAL timed out" == logs[-1].message + assert logs[-1].levelname == "DEBUG" async def test_error_handling_value_errors(caplog): @@ -147,7 +149,11 @@ async def test_error_handling_value_errors(caplog): assert str(e.value) == str(TWO_WORKING_TWO_TIMEOUT_TWO_VALUE_ERROR_OUTPUT) logs = caplog.get_records("call") - logs = [log for log in logs if "ophyd_async" in log.pathname] + logs = [ + log + for log in logs + if "ophyd_async" in log.pathname and "signal" not in log.pathname + ] assert len(logs) == 4 for i in range(0, 2): @@ -184,7 +190,11 @@ async def test_error_handling_device_collector(caplog): assert str(expected_output) == str(e.value) logs = caplog.get_records("call") - logs = [log for log in logs if "ophyd_async" in log.pathname] + logs = [ + log + for log in logs + if "ophyd_async" in log.pathname and "signal" not in log.pathname + ] assert len(logs) == 5 assert ( logs[0].message diff --git a/tests/epics/demo/test_demo.py b/tests/epics/demo/test_demo.py index 832143de99..988f4d1fa2 100644 --- a/tests/epics/demo/test_demo.py +++ b/tests/epics/demo/test_demo.py @@ -185,6 +185,7 @@ async def test_sensor_disconnected(caplog): async with DeviceCollector(timeout=0.1): s = demo.Sensor("ca://PRE:", name="sensor") logs = caplog.get_records("call") + logs = [log for log in logs if "signal" not in log.pathname] assert len(logs) == 2 assert logs[0].message == ("signal ca://PRE:Value timed out")