Add logging messages to signals

src/ophyd_async/core/device.py

@@ -3,6 +3,8 @@
 from __future__ import annotations
 
 import sys
+from functools import cached_property
+from logging import LoggerAdapter, getLogger
 from typing import (
     Any,
     Coroutine,
@@ -39,6 +41,12 @@ def name(self) -> str:
         """Return the name of the Device"""
         return self._name
 
+    @cached_property
+    def log(self):
+        return LoggerAdapter(
+            getLogger("ophyd_async.devices"), {"ophyd_async_device_name": self.name}
+        )
+
     def children(self) -> Iterator[Tuple[str, Device]]:
         for attr_name, attr in self.__dict__.items():
             if attr_name != "parent" and isinstance(attr, Device):
@@ -52,6 +60,11 @@ def set_name(self, name: str):
         name:
             New name to set
         """
+
+        # Ensure self.log is recreated after a name change
+        if hasattr(self, "log"):
+            del self.log
+
         self._name = name
         for attr_name, child in self.children():
             child_name = f"{name}-{attr_name.rstrip('_')}" if name else ""

src/ophyd_async/core/signal.py

@@ -61,9 +61,9 @@ def __init__(
         timeout: Optional[float] = DEFAULT_TIMEOUT,
         name: str = "",
     ) -> None:
-        super().__init__(name)
         self._timeout = timeout
         self._init_backend = self._backend = backend
+        super().__init__(name)
 
     async def connect(self, sim=False, timeout=DEFAULT_TIMEOUT):
         if sim:
@@ -72,6 +72,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
@@ -96,10 +97,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()
@@ -112,6 +115,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"
+            f"from {self._reading} to {reading}"
+        )
         self._reading = reading
         self._value = value
         self._valid.set()
@@ -178,7 +185,9 @@ async def describe(self) -> Dict[str, DataKey]:
     @_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"""
@@ -213,8 +222,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):

src/ophyd_async/epics/_backend/_p4p.py

@@ -244,7 +244,6 @@ def __init__(self, datatype: Optional[Type[T]], read_pv: str, write_pv: str):
         self.converter: PvaConverter = DisconnectedPvaConverter()
         self.subscription: Optional[Subscription] = None
 
-    @property
     def source(self, name: str):
         return f"pva://{self.read_pv}"
 

tests/core/test_device.py

@@ -110,3 +110,10 @@ async def test_wait_for_connection_propagates_error(
     with pytest.raises(NotConnected) as e:
         await wait_for_connection(**failing_coros)
         assert traceback.extract_tb(e.__traceback__)[-1].name == "failing_coroutine"
+
+
+async def test_device_log_has_correct_name():
+    device = DummyBaseDevice()
+    assert device.log.extra["ophyd_async_device_name"] == ""
+    device.set_name("device")
+    assert device.log.extra["ophyd_async_device_name"] == "device"

tests/core/test_signal.py

@@ -1,7 +1,8 @@
 import asyncio
+import logging
 import re
 import time
-from unittest.mock import ANY
+from unittest.mock import ANY, AsyncMock
 
 import numpy
 import pytest
@@ -12,6 +13,7 @@
     DeviceCollector,
     HintedSignal,
     Signal,
+    SignalBackend,
     SignalR,
     SignalRW,
     SimSignalBackend,
@@ -26,6 +28,7 @@
     soft_signal_rw,
     wait_for_value,
 )
+from ophyd_async.core.signal import _SignalCache
 from ophyd_async.core.utils import DEFAULT_TIMEOUT
 from ophyd_async.epics.signal import epics_signal_r, epics_signal_rw
 
@@ -39,6 +42,19 @@ 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()
+
+    @property
+    def source(self) -> str:
+        return "source"
+
+    async def connect(self):
+        pass
+
+
 def test_signals_equality_raises():
     sim_backend = SimSignalBackend(str)
 
@@ -228,3 +244,31 @@ async def test_assert_configuration(sim_readable: DummyReadable):
         },
     }
     await assert_configuration(sim_readable, dummy_config_reading)
+
+
+async def test_signal_connect_logs(caplog):
+    caplog.set_level(logging.DEBUG)
+    sim_signal = Signal(SimSignalBackend(str, "test"), timeout=1, name="test_signal")
+    await sim_signal.connect(sim=True)
+    assert caplog.text.endswith("Connecting to soft://test_signal\n")
+
+
+async def test_signal_get_and_set_logging(caplog):
+    caplog.set_level(logging.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):
+    caplog.set_level(logging.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

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):
@@ -134,7 +136,7 @@ async def test_error_handling_value_errors(caplog):
     caplog.set_level(10)
 
     dummy_device_two_working_one_timeout_two_value_error = (
-        DummyDeviceTwoWorkingTwoTimeOutTwoValueError()
+        DummyDeviceTwoWorkingTwoTimeOutTwoValueError("dsf")
     )
 
     # This should fail since the error is a ValueError
@@ -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

tests/epics/demo/test_demo.py

@@ -192,6 +192,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")