diff --git a/src/ophyd_async/core/device.py b/src/ophyd_async/core/device.py index 07145ae8f2..ce7beaeecb 100644 --- a/src/ophyd_async/core/device.py +++ b/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 "" diff --git a/src/ophyd_async/core/signal.py b/src/ophyd_async/core/signal.py index d1fe17546a..d0d50c8999 100644 --- a/src/ophyd_async/core/signal.py +++ b/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): diff --git a/src/ophyd_async/epics/_backend/_p4p.py b/src/ophyd_async/epics/_backend/_p4p.py index 807b74e696..816f1f5e68 100644 --- a/src/ophyd_async/epics/_backend/_p4p.py +++ b/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}" diff --git a/tests/core/test_device.py b/tests/core/test_device.py index 482666c18c..97184aed54 100644 --- a/tests/core/test_device.py +++ b/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" diff --git a/tests/core/test_signal.py b/tests/core/test_signal.py index 5b3037f7b7..ccd3540133 100644 --- a/tests/core/test_signal.py +++ b/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 diff --git a/tests/core/test_utils.py b/tests/core/test_utils.py index 74ea8bc787..b2e22a46c0 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): @@ -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 diff --git a/tests/epics/demo/test_demo.py b/tests/epics/demo/test_demo.py index 35ff880191..f6cddb4ad1 100644 --- a/tests/epics/demo/test_demo.py +++ b/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")