Reuse log from ophyd v1

.codecov.yml

@@ -12,3 +12,6 @@ coverage:
         threshold: 1%
 github_checks:
   annotations: false
+exclude_lines:
+  - except ImportError: colorama = None
+  - except curses: curses = None

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

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

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):