Add logging

.github/workflows/Lint-and-test.yml

@@ -19,7 +19,7 @@ jobs:
       - name: install requirements
         run: pip install -e .[dev]
       - name: run pytest
-        run: python -m pytest
+        run: IBEX_BLUESKY_CORE_LOGS=/tmp/ibex_bluesky_core_logs/ python -m pytest
   results:
     if: ${{ always() }}
     runs-on: ubuntu-latest

doc/dev/logging.md

@@ -1,10 +1,34 @@
 # Logging
+To invoke the `ibex_bluesky_core` logger, create and use a `logger` object in [the standard way](https://docs.python.org/3/library/logging.html):
 
-To invoke the bluesky logger, import and use it at the desired level:
 ```python
-from ibex_bluesky_core.logger import logger
-logger.blueskylogger.warning("Message to be logged")
+import logging
+logger = logging.getLogger(__name__)
+logger.warning("Message to be logged")
 ```
-The logger utilizes a `TimedRotatingFileHandler` defined in the `logging.conf` file that rolls over the log at midnight.
 
-The default logging level is defined at `INFO`. This means that events of lesser severity will not be logged. To change the default level, change level attribute of logger_blueskycore in the `logging.conf`
+The logger utilizes a `TimedRotatingFileHandler` defined in `src/ibex_bluesky_core/log.py` that rolls over the log at midnight.
+
+By default, the log files will be created in `c:\instrument\var\logs\bluesky`. This can be configured by setting
+the `IBEX_BLUESKY_CORE_LOGS` environment variable.
+
+There are 3 primary logger objects which are "interesting" in the context of `ibex_bluesky_core`:
+- `ibex_bluesky_core` itself
+- `bluesky`, for low-level diagnostic logging from the run engine & plans
+- `ophyd_async` for low-level diagnostic logging from ophyd-async devices
+
+The default logging level for bluesky libraries is defined at `INFO`. This means that events of lesser severity will not be logged. 
+To change the logging level for all bluesky libraries simultaneously, call: 
+
+```python
+from ibex_bluesky_core.log import set_bluesky_log_levels
+set_bluesky_log_levels("DEBUG")
+```
+
+To change the logging level of just a single library (for example, just `opyhyd_async`), use the standard
+python `logging` mechanisms:
+
+```python
+import logging
+logging.getLogger("ophyd_async").setLevel("DEBUG")
+```

src/ibex_bluesky_core/__init__.py

@@ -1 +1,7 @@
-"""Common plans and devices for use across beamlines."""
+"""Top-level ibex_bluesky_core module."""
+
+from ibex_bluesky_core.log import setup_logging
+
+__all__ = []
+
+setup_logging()

src/ibex_bluesky_core/callbacks/__init__.py

@@ -1 +1 @@
-"""For callbacks that relate to the BlueSky run engine."""
+"""Bluesky callbacks which may be attached to the RunEngine."""

src/ibex_bluesky_core/callbacks/file_logger.py

@@ -1,6 +1,7 @@
 """Creates a readable .txt file of Bluesky runengine dataset."""
 
 import csv
+import logging
 from datetime import datetime
 from pathlib import Path
 from typing import Optional
@@ -12,6 +13,8 @@
 from event_model.documents.run_stop import RunStop
 from zoneinfo import ZoneInfo
 
+logger = logging.getLogger(__name__)
+
 TIME = "time"
 START_TIME = "start_time"
 NAME = "name"
@@ -49,6 +52,8 @@ def start(self, doc: RunStart) -> None:
         self.current_start_document = doc[UID]
         self.filename = self.output_dir / f"{self.current_start_document}.txt"
 
+        logger.info("starting new file %s", self.filename)
+
         exclude_list = [
             TIME,  # We format this later
         ]
@@ -64,19 +69,26 @@ def start(self, doc: RunStart) -> None:
             for key, value in header_data.items():
                 outfile.write(f"{key}: {value}\n")
 
+        logger.debug("successfully wrote header in %s", self.filename)
+
     def descriptor(self, doc: EventDescriptor) -> None:
         """Add the descriptor data to descriptors."""
-        if NAME not in doc or not doc[NAME] or doc[NAME] != "primary":
+        logger.debug("event descriptor with name=%s", doc.get(NAME))
+        if doc.get(NAME) != "primary":
             return
 
+        logger.debug("saving event descriptor with name=%s, id=%s", doc.get(NAME), doc.get(UID))
         descriptor_id = doc[UID]
         self.descriptors[descriptor_id] = doc
 
     def event(self, doc: Event) -> Event:
         """Append an event's output to the file."""
         if not self.filename:
-            print("File has not been started yet - doing nothing")
+            logger.error("File has not been started yet - doing nothing")
             return doc
+
+        logger.debug("Appending event document %s", doc.get(UID))
+
         formatted_event_data = {}
         descriptor_id = doc[DESCRIPTOR]
         event_data = doc[DATA]
@@ -110,5 +122,6 @@ def event(self, doc: Event) -> Event:
 
     def stop(self, doc: RunStop) -> RunStop | None:
         """Clear descriptors."""
+        logger.info("Stopping run, clearing descriptors, filename=%s", self.filename)
         self.descriptors.clear()
         return super().stop(doc)

src/ibex_bluesky_core/callbacks/fitting/__init__.py

@@ -9,6 +9,8 @@
 from bluesky.callbacks import LiveFit as _DefaultLiveFit
 from bluesky.callbacks.core import make_class_safe
 
+logger = logging.getLogger(__name__)
+
 
 class FitMethod:
     """Tell LiveFit how to fit to a scan. Has a Model function and a Guess function.
@@ -42,9 +44,6 @@ def __init__(
         self.guess = guess
 
 
-logger = logging.getLogger(__name__)
-
-
 @make_class_safe(logger=logger)  # pyright: ignore (pyright doesn't understand this decorator)
 class LiveFit(_DefaultLiveFit):
     """Live fit, customized for IBEX."""
@@ -85,10 +84,12 @@ def update_fit(self) -> None:
             None
 
         """
+        logger.debug("updating guess for %s ", self.method)
         self.init_guess = self.method.guess(
             np.array(next(iter(self.independent_vars_data.values()))),
             np.array(self.ydata),
             # Calls the guess function on the set of data already collected in the run
         )
+        logger.info("new guess for %s: %s", self.method, self.init_guess)
 
         super().update_fit()

src/ibex_bluesky_core/callbacks/plotting.py

@@ -19,6 +19,7 @@ def _show_plot(self) -> None:
         # Play nicely with the "normal" backends too - only force show if we're
         # actually using our custom backend.
         if "genie_python" in matplotlib.get_backend():
+            logger.debug("Explicitly show()ing plot for IBEX")
             plt.show()
 
     def start(self, doc: RunStart) -> None:

src/ibex_bluesky_core/devices/block.py

@@ -1,6 +1,7 @@
 """ophyd-async devices and utilities for communicating with IBEX blocks."""
 
 import asyncio
+import logging
 from dataclasses import dataclass
 from typing import Callable, Generic, Type, TypeVar
 
@@ -18,6 +19,8 @@
 
 from ibex_bluesky_core.devices import get_pv_prefix
 
+logger = logging.getLogger(__name__)
+
 """Block data type"""
 T = TypeVar("T")
 
@@ -140,6 +143,10 @@ async def trigger(self) -> None:
         They do not do anything when triggered.
         """
 
+    def __repr__(self) -> str:
+        """Debug representation of this block."""
+        return f"{self.__class__.__name__}(name={self.name})"
+
 
 class BlockRw(BlockR[T], Movable):
     """Device representing an IBEX read/write block of arbitrary data type."""
@@ -184,14 +191,19 @@ async def set(self, value: T) -> None:
         """Set the setpoint of this block."""
 
         async def do_set(setpoint: T) -> None:
+            logger.info("Setting Block %s to %s", self.name, setpoint)
             await self.setpoint.set(
                 setpoint, wait=self._write_config.use_completion_callback, timeout=None
             )
+            logger.info("Got completion callback from setting block %s to %s", self.name, setpoint)
 
             # Wait for the _set_success_func to return true.
             # This uses an "async for" to loop over items from observe_value, which is an async
             # generator. See documentation on "observe_value" or python "async for" for more details
             if self._write_config.set_success_func is not None:
+                logger.info(
+                    "Waiting for set_success_func on setting block %s to %s", self.name, setpoint
+                )
                 async for actual_value in observe_value(self.readback):
                     if self._write_config.set_success_func(setpoint, actual_value):
                         break
@@ -202,9 +214,15 @@ async def set_and_settle(setpoint: T) -> None:
             else:
                 await do_set(setpoint)
 
+            logger.info(
+                "Waiting for configured settle time (%f seconds) on block %s",
+                self._write_config.settle_time_s,
+                self.name,
+            )
             await asyncio.sleep(self._write_config.settle_time_s)
 
         await set_and_settle(value)
+        logger.info("block set complete %s value=%s", self.name, value)
 
 
 class BlockRwRbv(BlockRw[T], Locatable):
@@ -241,6 +259,7 @@ def __init__(
 
     async def locate(self) -> Location[T]:
         """Get the current 'location' of this block."""
+        logger.info("locating block %s", self.name)
         actual, sp_rbv = await asyncio.gather(
             self.readback.get_value(),
             self.setpoint_readback.get_value(),
@@ -301,6 +320,10 @@ def __init__(
         # CS:SB:blockname here, we avoid a write access exception when moving a motor block.
         super().__init__(f"{prefix}CS:SB:{block_name}:SP:RBV", name=block_name)
 
+    def __repr__(self) -> str:
+        """Debug representation of this block."""
+        return f"{self.__class__.__name__}(name={self.name})"
+
 
 def block_r(datatype: Type[T], block_name: str) -> BlockR[T]:
     """Get a local read-only block for the current instrument.

src/ibex_bluesky_core/devices/dae/dae.py

@@ -48,6 +48,7 @@ class Dae(StandardReadable):
     def __init__(self, prefix: str, name: str = "DAE") -> None:
         """Create a new Dae ophyd-async device."""
         dae_prefix = f"{prefix}DAE:"
+        self._prefix = prefix
         self.good_uah: SignalR[float] = epics_signal_r(float, f"{dae_prefix}GOODUAH")
         self.count_rate: SignalR[float] = epics_signal_r(float, f"{dae_prefix}COUNTRATE")
         self.m_events: SignalR[float] = epics_signal_r(float, f"{dae_prefix}MEVENTS")
@@ -109,3 +110,7 @@ def __init__(self, prefix: str, name: str = "DAE") -> None:
         self.controls: DaeControls = DaeControls(dae_prefix)
 
         super().__init__(name=name)
+
+    def __repr__(self) -> str:
+        """Get string representation of this class for debugging."""
+        return f"{self.__class__.__name__}(name={self.name}, prefix={self._prefix})"

src/ibex_bluesky_core/devices/dae/dae_controls.py

@@ -1,11 +1,14 @@
 """ophyd-async devices and utilities for the DAE run controls."""
 
+import logging
 from enum import IntFlag
 
 from bluesky.protocols import Movable
 from ophyd_async.core import AsyncStatus, SignalW, SignalX, StandardReadable
 from ophyd_async.epics.signal import epics_signal_w, epics_signal_x
 
+logger = logging.getLogger(__name__)
+
 
 class DaeControls(StandardReadable):
     """Subdevice for the DAE run controls."""
@@ -43,4 +46,6 @@ def __init__(self, dae_prefix: str, name: str = "") -> None:
     @AsyncStatus.wrap
     async def set(self, value: BeginRunExBits) -> None:
         """Start a run with the specified bits - See BeginRunExBits."""
+        logger.info("starting run with options %s", value)
         await self._raw_begin_run_ex.set(value, wait=True, timeout=None)
+        logger.info("start run complete")

src/ibex_bluesky_core/devices/dae/dae_period_settings.py

@@ -1,5 +1,6 @@
 """ophyd-async devices and utilities for the DAE hardware period settings."""
 
+import logging
 import xml.etree.ElementTree as ET
 from dataclasses import dataclass
 from enum import Enum
@@ -18,6 +19,8 @@
     set_value_in_dae_xml,
 )
 
+logger = logging.getLogger(__name__)
+
 OUTPUT_DELAY = "Output Delay (us)"
 PERIOD_SEQUENCES = "Hardware Period Sequences"
 PERIOD_FILE = "Period File"
@@ -123,11 +126,13 @@ async def locate(self) -> Location[DaePeriodSettingsData]:
         """Retrieve and convert the current XML to DaePeriodSettingsData."""
         value = await self._raw_period_settings.get_value()
         period_settings = _convert_xml_to_period_settings(value)
+        logger.debug("locate period settings: %s", period_settings)
         return {"setpoint": period_settings, "readback": period_settings}
 
     @AsyncStatus.wrap
     async def set(self, value: DaePeriodSettingsData) -> None:
         """Set any changes in the period settings to the XML."""
         current_xml = await self._raw_period_settings.get_value()
         to_write = _convert_period_settings_to_xml(current_xml, value)
+        logger.info("set period settings: %s", to_write)
         await self._raw_period_settings.set(to_write, wait=True, timeout=None)

src/ibex_bluesky_core/devices/dae/dae_settings.py

@@ -1,5 +1,6 @@
 """ophyd-async devices and utilities for the general DAE settings."""
 
+import logging
 import xml.etree.ElementTree as ET
 from dataclasses import dataclass
 from enum import Enum
@@ -17,6 +18,8 @@
     set_value_in_dae_xml,
 )
 
+logger = logging.getLogger(__name__)
+
 VETO3_NAME = "Veto 3 Name"
 VETO2_NAME = "Veto 2 Name"
 VETO1_NAME = "Veto 1 Name"
@@ -164,11 +167,13 @@ async def locate(self) -> Location[DaeSettingsData]:
         """Retrieve and convert the current XML to DaeSettingsData."""
         value = await self._raw_dae_settings.get_value()
         period_settings = _convert_xml_to_dae_settings(value)
+        logger.info("locate dae settings: %s", period_settings)
         return {"setpoint": period_settings, "readback": period_settings}
 
     @AsyncStatus.wrap
     async def set(self, value: DaeSettingsData) -> None:
         """Set any changes in the DAE settings to the XML."""
         current_xml = await self._raw_dae_settings.get_value()
         to_write = _convert_dae_settings_to_xml(current_xml, value)
+        logger.info("set dae settings: %s", to_write)
         await self._raw_dae_settings.set(to_write, wait=True, timeout=None)

src/ibex_bluesky_core/devices/dae/dae_spectra.py

@@ -1,6 +1,7 @@
 """ophyd-async devices and utilities for a single DAE spectra."""
 
 import asyncio
+import logging
 
 import scipp as sc
 from event_model.documents.event_descriptor import DataKey
@@ -9,6 +10,8 @@
 from ophyd_async.core import SignalR, StandardReadable
 from ophyd_async.epics.signal import epics_signal_r
 
+logger = logging.getLogger(__name__)
+
 
 class DaeSpectra(StandardReadable):
     """Subdevice for a single DAE spectra."""
@@ -89,6 +92,11 @@ async def read_spectrum_dataarray(self) -> sc.DataArray:
         Data is returned along dimension "tof", which has bin-edge coordinates and units set from
         the units of the underlying PVs.
         """
+        logger.debug(
+            "Reading spectrum dataarray backed by PVs edges=%s, counts=%s",
+            self.tof_edges.source,
+            self.counts.source,
+        )
         tof_edges, tof_edges_descriptor, counts = await asyncio.gather(
             self.read_tof_edges(),
             self.tof_edges.describe(),