diff --git a/doc/dev/logging.md b/doc/dev/logging.md index 997dfa1..4c7f051 100644 --- a/doc/dev/logging.md +++ b/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 `ibex_bluesky_core.log` 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") +``` diff --git a/src/ibex_bluesky_core/__init__.py b/src/ibex_bluesky_core/__init__.py index 5e9bb24..f6df106 100644 --- a/src/ibex_bluesky_core/__init__.py +++ b/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() diff --git a/src/ibex_bluesky_core/callbacks/__init__.py b/src/ibex_bluesky_core/callbacks/__init__.py index 913b6dc..43c6dcb 100644 --- a/src/ibex_bluesky_core/callbacks/__init__.py +++ b/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.""" diff --git a/src/ibex_bluesky_core/callbacks/file_logger.py b/src/ibex_bluesky_core/callbacks/file_logger.py index da1f617..c0b2c6f 100644 --- a/src/ibex_bluesky_core/callbacks/file_logger.py +++ b/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) diff --git a/src/ibex_bluesky_core/callbacks/fitting/__init__.py b/src/ibex_bluesky_core/callbacks/fitting/__init__.py index 6ef3bd9..af489f9 100644 --- a/src/ibex_bluesky_core/callbacks/fitting/__init__.py +++ b/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() diff --git a/src/ibex_bluesky_core/callbacks/plotting.py b/src/ibex_bluesky_core/callbacks/plotting.py index 4299b27..2aec29d 100644 --- a/src/ibex_bluesky_core/callbacks/plotting.py +++ b/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: diff --git a/src/ibex_bluesky_core/devices/block.py b/src/ibex_bluesky_core/devices/block.py index cf77639..93261cc 100644 --- a/src/ibex_bluesky_core/devices/block.py +++ b/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. diff --git a/src/ibex_bluesky_core/devices/dae/dae.py b/src/ibex_bluesky_core/devices/dae/dae.py index 0fa9efc..d2a7032 100644 --- a/src/ibex_bluesky_core/devices/dae/dae.py +++ b/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})" diff --git a/src/ibex_bluesky_core/devices/dae/dae_controls.py b/src/ibex_bluesky_core/devices/dae/dae_controls.py index 80d216b..0c0cb58 100644 --- a/src/ibex_bluesky_core/devices/dae/dae_controls.py +++ b/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") diff --git a/src/ibex_bluesky_core/devices/dae/dae_period_settings.py b/src/ibex_bluesky_core/devices/dae/dae_period_settings.py index 28f37c4..66ec95e 100644 --- a/src/ibex_bluesky_core/devices/dae/dae_period_settings.py +++ b/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,6 +126,7 @@ 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 @@ -130,4 +134,5 @@ 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) diff --git a/src/ibex_bluesky_core/devices/dae/dae_settings.py b/src/ibex_bluesky_core/devices/dae/dae_settings.py index 64e3d07..c948574 100644 --- a/src/ibex_bluesky_core/devices/dae/dae_settings.py +++ b/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,6 +167,7 @@ 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 @@ -171,4 +175,5 @@ 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) diff --git a/src/ibex_bluesky_core/devices/dae/dae_spectra.py b/src/ibex_bluesky_core/devices/dae/dae_spectra.py index 0c90469..1b4ba6d 100644 --- a/src/ibex_bluesky_core/devices/dae/dae_spectra.py +++ b/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(), diff --git a/src/ibex_bluesky_core/devices/dae/dae_tcb_settings.py b/src/ibex_bluesky_core/devices/dae/dae_tcb_settings.py index d8b37ff..b272fa4 100644 --- a/src/ibex_bluesky_core/devices/dae/dae_tcb_settings.py +++ b/src/ibex_bluesky_core/devices/dae/dae_tcb_settings.py @@ -1,5 +1,6 @@ """ophyd-async devices and utilities for the DAE time channel settings.""" +import logging import xml.etree.ElementTree as ET from dataclasses import dataclass from enum import Enum @@ -20,6 +21,8 @@ set_value_in_dae_xml, ) +logger = logging.getLogger(__name__) + TIME_UNIT = "Time Unit" CALCULATION_METHOD = "Calculation Method" TIME_CHANNEL_FILE = "Time Channel File" @@ -136,6 +139,7 @@ async def locate(self) -> Location[DaeTCBSettingsData]: value = await self._raw_tcb_settings.get_value() value_dehexed = dehex_and_decompress(value.encode()).decode() tcb_settings = _convert_xml_to_tcb_settings(value_dehexed) + logger.info("locate tcb settings: %s", tcb_settings) return {"setpoint": tcb_settings, "readback": tcb_settings} @AsyncStatus.wrap @@ -145,4 +149,5 @@ async def set(self, value: DaeTCBSettingsData) -> None: current_xml_dehexed = dehex_and_decompress(current_xml.encode()).decode() xml = _convert_tcb_settings_to_xml(current_xml_dehexed, value) the_value_to_write = compress_and_hex(xml).decode() + logger.info("set tcb settings: %s", the_value_to_write) await self._raw_tcb_settings.set(the_value_to_write, wait=True, timeout=None) diff --git a/src/ibex_bluesky_core/devices/simpledae/__init__.py b/src/ibex_bluesky_core/devices/simpledae/__init__.py index a6b16fc..e99e118 100644 --- a/src/ibex_bluesky_core/devices/simpledae/__init__.py +++ b/src/ibex_bluesky_core/devices/simpledae/__init__.py @@ -1,5 +1,6 @@ """A simple interface to the DAE for bluesky.""" +import logging import typing from bluesky.protocols import Triggerable @@ -16,6 +17,9 @@ from ibex_bluesky_core.devices.simpledae.waiters import Waiter +logger = logging.getLogger(__name__) + + class SimpleDae(Dae, Triggerable, AsyncStageable): """Configurable DAE with pluggable strategies for data collection, waiting, and reduction. @@ -51,6 +55,14 @@ def __init__( self.waiter: "Waiter" = waiter self.reducer: "Reducer" = reducer + logger.info( + "created simpledae with prefix=%s, controller=%s, waiter=%s, reducer=%s", + prefix, + controller, + waiter, + reducer, + ) + # controller, waiter and reducer may be Devices (but don't necessarily have to be), # so can define their own signals. Do __init__ after defining those, so that the signals # are connected/named and usable. @@ -62,7 +74,7 @@ def __init__( for strategy in [self.controller, self.waiter, self.reducer]: for sig in strategy.additional_readable_signals(self): extra_readables.add(sig) - + logger.info("extra readables: %s", list(extra_readables)) self.add_readables(devices=list(extra_readables)) @AsyncStatus.wrap diff --git a/src/ibex_bluesky_core/devices/simpledae/controllers.py b/src/ibex_bluesky_core/devices/simpledae/controllers.py index fc847f6..771fe80 100644 --- a/src/ibex_bluesky_core/devices/simpledae/controllers.py +++ b/src/ibex_bluesky_core/devices/simpledae/controllers.py @@ -1,5 +1,6 @@ """DAE control strategies.""" +import logging import typing from ophyd_async.core import ( @@ -13,15 +14,21 @@ from ibex_bluesky_core.devices.dae.dae_controls import BeginRunExBits from ibex_bluesky_core.devices.simpledae.strategies import Controller +logger = logging.getLogger(__name__) + if typing.TYPE_CHECKING: from ibex_bluesky_core.devices.simpledae import SimpleDae async def _end_or_abort_run(dae: "SimpleDae", save: bool) -> None: if save: + logger.info("ending run") await dae.controls.end_run.trigger(wait=True, timeout=None) + logger.info("run ended") else: + logger.info("aborting run") await dae.controls.abort_run.trigger(wait=True, timeout=None) + logger.info("run aborted") class PeriodPerPointController(Controller): @@ -46,14 +53,17 @@ def __init__(self, save_run: bool) -> None: async def setup(self, dae: "SimpleDae") -> None: """Pre-scan setup (begin a new run in paused mode).""" self._current_period = 0 + logger.info("setting up new run") await dae.controls.begin_run_ex.set(BeginRunExBits.BEGIN_PAUSED) await wait_for_value(dae.run_state, RunstateEnum.PAUSED, timeout=10) + logger.info("setup complete") async def start_counting(self, dae: "SimpleDae") -> None: """Start counting a scan point. Increments the period by 1, then unpauses the run. """ + logger.info("start counting") self._current_period += 1 await dae.period_num.set(self._current_period, wait=True, timeout=None) @@ -65,9 +75,11 @@ async def start_counting(self, dae: "SimpleDae") -> None: ) # Ensure frame counters have reset to zero for the new period. + logger.info("waiting for frame counters to be zero") await wait_for_value(dae.period.good_frames, 0, timeout=10) await wait_for_value(dae.period.raw_frames, 0, timeout=10) + logger.info("resuming run") await dae.controls.resume_run.trigger(wait=True, timeout=None) await wait_for_value( dae.run_state, @@ -77,6 +89,7 @@ async def start_counting(self, dae: "SimpleDae") -> None: async def stop_counting(self, dae: "SimpleDae") -> None: """Stop counting a scan point, by pausing the run.""" + logger.info("stop counting") await dae.controls.pause_run.trigger(wait=True, timeout=None) await wait_for_value(dae.run_state, RunstateEnum.PAUSED, timeout=10) @@ -113,6 +126,7 @@ def __init__(self, save_run: bool) -> None: async def start_counting(self, dae: "SimpleDae") -> None: """Start counting a scan point, by starting a DAE run.""" + logger.info("start counting") await dae.controls.begin_run.trigger(wait=True, timeout=None) await wait_for_value( dae.run_state, @@ -122,6 +136,7 @@ async def start_counting(self, dae: "SimpleDae") -> None: # Take care to read this after we've started a run, but before ending it, so that it # accurately reflects the run number we're actually counting into. + logger.info("saving current run number") run_number = await dae.current_or_next_run_number.get_value() self._run_number_setter(run_number) diff --git a/src/ibex_bluesky_core/devices/simpledae/reducers.py b/src/ibex_bluesky_core/devices/simpledae/reducers.py index 4abe0a8..cc2e883 100644 --- a/src/ibex_bluesky_core/devices/simpledae/reducers.py +++ b/src/ibex_bluesky_core/devices/simpledae/reducers.py @@ -1,6 +1,7 @@ """DAE data reduction strategies.""" import asyncio +import logging import math from abc import ABCMeta, abstractmethod from typing import TYPE_CHECKING, Collection, Sequence @@ -17,6 +18,8 @@ from ibex_bluesky_core.devices.dae.dae_spectra import DaeSpectra from ibex_bluesky_core.devices.simpledae.strategies import Reducer +logger = logging.getLogger(__name__) + if TYPE_CHECKING: from ibex_bluesky_core.devices.simpledae import SimpleDae @@ -30,9 +33,11 @@ async def sum_spectra(spectra: Collection[DaeSpectra]) -> sc.Variable | sc.DataA Returns a scipp scalar, which has .value and .variance properties for accessing the sum and variance respectively of the summed counts. """ + logger.info("Summing %d spectra using scipp", len(spectra)) summed_counts = sc.scalar(value=0, unit=sc.units.counts, dtype="float64") for spec in asyncio.as_completed([s.read_spectrum_dataarray() for s in spectra]): summed_counts += (await spec).sum() + logger.debug("Summed counts: %s", summed_counts) return summed_counts @@ -74,6 +79,7 @@ def denominator(self, dae: "SimpleDae") -> SignalR[int] | SignalR[float]: async def reduce_data(self, dae: "SimpleDae") -> None: """Apply the normalization.""" + logger.info("starting reduction") summed_counts, denominator = await asyncio.gather( sum_spectra(self.detectors.values()), self.denominator(dae).get_value() ) @@ -92,6 +98,7 @@ async def reduce_data(self, dae: "SimpleDae") -> None: self._det_counts_stddev_setter(math.sqrt(detector_counts_var)) self._intensity_stddev_setter(math.sqrt(intensity_var)) + logger.info("reduction complete") def additional_readable_signals(self, dae: "SimpleDae") -> list[Device]: """Publish interesting signals derived or used by this reducer.""" @@ -162,6 +169,7 @@ def __init__( async def reduce_data(self, dae: "SimpleDae") -> None: """Apply the normalization.""" + logger.info("starting reduction") detector_counts, monitor_counts = await asyncio.gather( sum_spectra(self.detectors.values()), sum_spectra(self.monitors.values()) ) @@ -185,6 +193,7 @@ async def reduce_data(self, dae: "SimpleDae") -> None: self._det_counts_stddev_setter(math.sqrt(detector_counts_var)) self._mon_counts_stddev_setter(math.sqrt(monitor_counts_var)) + logger.info("reduction complete") def additional_readable_signals(self, dae: "SimpleDae") -> list[Device]: """Publish interesting signals derived or used by this reducer.""" diff --git a/src/ibex_bluesky_core/devices/simpledae/waiters.py b/src/ibex_bluesky_core/devices/simpledae/waiters.py index 14b3ade..1c034a7 100644 --- a/src/ibex_bluesky_core/devices/simpledae/waiters.py +++ b/src/ibex_bluesky_core/devices/simpledae/waiters.py @@ -1,6 +1,7 @@ """DAE waiting strategies.""" import asyncio +import logging from abc import ABCMeta, abstractmethod from typing import TYPE_CHECKING, Generic, TypeVar @@ -12,6 +13,8 @@ from ibex_bluesky_core.devices.simpledae.strategies import Waiter +logger = logging.getLogger(__name__) + if TYPE_CHECKING: from ibex_bluesky_core.devices.simpledae import SimpleDae @@ -33,7 +36,10 @@ def __init__(self, value: T) -> None: async def wait(self, dae: "SimpleDae") -> None: """Wait for signal to reach the user-specified value.""" - await wait_for_value(self.get_signal(dae), lambda v: v >= self._value, timeout=None) + signal = self.get_signal(dae) + logger.info("starting wait for signal %s", signal.source) + await wait_for_value(signal, lambda v: v >= self._value, timeout=None) + logger.info("completed wait for signal %s", signal.source) def additional_readable_signals(self, dae: "SimpleDae") -> list[Device]: """Publish the signal we're waiting on as an interesting signal.""" @@ -90,4 +96,6 @@ def __init__(self, *, seconds: float) -> None: async def wait(self, dae: "SimpleDae") -> None: """Wait for the specified time duration.""" + logger.info("starting wait for %f seconds", self._secs) await asyncio.sleep(self._secs) + logger.info("completed wait") diff --git a/src/ibex_bluesky_core/log.py b/src/ibex_bluesky_core/log.py new file mode 100644 index 0000000..ab9b330 --- /dev/null +++ b/src/ibex_bluesky_core/log.py @@ -0,0 +1,64 @@ +"""Bluesky specific logging configuration. + +Note: logging.config.fileconfig sets the global, application-level, logging policies. We are a +library so should not set application-level policies. Instead just quietly add handlers for our own +logger and the bluesky logger. +""" + +import logging.config +import os +import sys +from logging import Formatter +from logging.handlers import TimedRotatingFileHandler + +__all__ = ["setup_logging", "set_bluesky_log_levels", "LOG_HANDLER"] + +DEFAULT_LOG_FOLDER = os.path.join("C:\\", "instrument", "var", "logs", "bluesky") + +# Find the log directory, if already set in the environment, else use the default +log_location = os.environ.get("IBEX_BLUESKY_CORE_LOGS", DEFAULT_LOG_FOLDER) + +INTERESTING_LOGGER_NAMES = ["ibex_bluesky_core", "bluesky", "ophyd_async"] + +LOG_HANDLER = TimedRotatingFileHandler(os.path.join(log_location, "bluesky.log"), "midnight") + +LOG_HANDLER.setFormatter( + Formatter( + "%(asctime)s (%(process)d) %(name)s %(filename)s " + "[line:%(lineno)d] %(levelname)s %(message)s" + ), +) + + +def setup_logging() -> None: + """Set up logging.""" + # Create the log directory if it doesn't already exist + try: + os.makedirs(log_location, exist_ok=True) + except OSError: + print("unable to create ibex_bluesky_core log directory", file=sys.stderr) + else: + # We only want messages from bluesky, ophyd_async, and ibex_bluesky_core in our logs, not + # messages from the root logger or other libraries. + for name in INTERESTING_LOGGER_NAMES: + logging.getLogger(name).addHandler(LOG_HANDLER) + + set_bluesky_log_levels() + + +def set_bluesky_log_levels(level: str | int | None = None) -> None: + """Set log level of bluesky-related loggers: ibex_bluesky_core, bluesky & ophyd_async. + + Args: + level: a log level string or integer, or None. If None, will set INFO level by default for + loggers which have not previously been configured, but will not change log levels for + already-configured loggers. + + """ + for name in INTERESTING_LOGGER_NAMES: + logger = logging.getLogger(name) + if level is None and logger.level == logging.NOTSET: + level = "INFO" + + if level is not None: + logger.setLevel(level) diff --git a/src/ibex_bluesky_core/logger/logger.py b/src/ibex_bluesky_core/logger/logger.py deleted file mode 100644 index 4f75461..0000000 --- a/src/ibex_bluesky_core/logger/logger.py +++ /dev/null @@ -1,27 +0,0 @@ -"""Bluesky specific logging utility.""" - -import logging -import logging.config -import os -from pathlib import Path - -"""Logger for bluesky. Loads the configured log handler and also attaches to default bluesky logger -To use me -1. you need to import me --> from ibex_bluesky_core.logger import logger -2. Use me at the level you want --> logger.blueskylogger.info("Some useful message") -3. To change the log level check the logging.conf file""" - -BLUESKY_LOGGER = "bluesky" -DEFAULT_LOGGER = "blueskylogs.log" -LOG_FOLDER = os.path.join("C:\\", "instrument", "var", "logs", BLUESKY_LOGGER) - -# Find the log directory, if already set in the environment, else use the default -log_location = os.environ.get("BLUESKY_LOGS", LOG_FOLDER) -# Create the log directory if it doesn't already exist -os.makedirs(log_location, exist_ok=True) - -filepath = Path(__file__).resolve().parent -# disable_existing_loggers ensures all loggers have same configuration as below -logging.config.fileConfig(os.path.join(filepath, "logging.conf"), disable_existing_loggers=False) - -blueskylogger = logging.getLogger("blueskycore") diff --git a/src/ibex_bluesky_core/logger/logging.conf b/src/ibex_bluesky_core/logger/logging.conf deleted file mode 100644 index af33c17..0000000 --- a/src/ibex_bluesky_core/logger/logging.conf +++ /dev/null @@ -1,31 +0,0 @@ -[loggers] -keys=root,blueskycore - -[handlers] -keys=timedRotatingFileHandler - -[formatters] -keys=simpleFormatter,debugFormatter - -[logger_root] -level=INFO -handlers=timedRotatingFileHandler - -[logger_blueskycore] -level=INFO -qualname=blueskycore -propagate=0 -handlers=timedRotatingFileHandler - -[handler_timedRotatingFileHandler] -class=logging.handlers.TimedRotatingFileHandler -level=INFO -formatter=debugFormatter -#args=set the file name to blueskylogs.log and the log folder as set in the environment variable; if not set, set to default - \instrument\var\logs\bluesky -args=(os.path.join(os.environ.get("BLUESKY_LOGS", os.path.join("C:\\", "instrument", "var", "logs", "bluesky")),'blueskylogs.log'), "midnight") - -[formatter_simpleFormatter] -format=%(asctime)s - %(name)s - %(levelname)s - %(message)s - -[formatter_debugFormatter] -format=%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s diff --git a/src/ibex_bluesky_core/preprocessors.py b/src/ibex_bluesky_core/preprocessors.py index c1cf68a..29b3c56 100644 --- a/src/ibex_bluesky_core/preprocessors.py +++ b/src/ibex_bluesky_core/preprocessors.py @@ -1,5 +1,6 @@ """Bluesky plan preprocessors specific to ISIS.""" +import logging from typing import Generator from bluesky import plan_stubs as bps @@ -11,6 +12,8 @@ from ibex_bluesky_core.devices import get_pv_prefix +logger = logging.getLogger(__name__) + def _get_rb_number_signal() -> SignalR[str]: return epics_signal_r(str, f"{get_pv_prefix()}ED:RBNUMBER", name="rb_number") @@ -19,6 +22,7 @@ def _get_rb_number_signal() -> SignalR[str]: def add_rb_number_processor(msg: Msg) -> tuple[Generator[Msg, None, None] | None, None]: """Preprocessor for adding the current RB number to the plan's metadata.""" if msg.command == "open_run" and "rb_number" not in msg.kwargs: + logger.info("open_run without RB number, mutating to include RB number.") def _before() -> Generator[Msg, None, None]: rb_number: SignalR[str] = _get_rb_number_signal() @@ -34,6 +38,7 @@ def _cant_read_rb(_: Exception) -> Generator[Msg, None, str]: rb = yield from bpp.contingency_wrapper( _read_rb(), except_plan=_cant_read_rb, auto_raise=False ) + logger.debug("Injected RB number: %s", rb) return (yield from bpp.inject_md_wrapper(single_gen(msg), md={"rb_number": rb})) return _before(), None diff --git a/src/ibex_bluesky_core/run_engine.py b/src/ibex_bluesky_core/run_engine.py index 06ac056..6f73db0 100644 --- a/src/ibex_bluesky_core/run_engine.py +++ b/src/ibex_bluesky_core/run_engine.py @@ -2,6 +2,7 @@ import asyncio import functools +import logging from functools import cache from threading import Event @@ -11,10 +12,12 @@ from bluesky.utils import DuringTask from ibex_bluesky_core.callbacks.document_logger import DocLoggingCallback +from ibex_bluesky_core.preprocessors import add_rb_number_processor __all__ = ["get_run_engine"] -from ibex_bluesky_core.preprocessors import add_rb_number_processor + +logger = logging.getLogger(__name__) class _DuringTask(DuringTask): @@ -69,6 +72,7 @@ def get_run_engine() -> RunEngine: - https://nsls-ii.github.io/bluesky/tutorial.html#the-runengine - https://nsls-ii.github.io/bluesky/run_engine_api.html """ + logger.info("Creating new bluesky RunEngine") loop = asyncio.new_event_loop() # Only log *very* slow callbacks (in asyncio debug mode) diff --git a/tests/devices/test_block.py b/tests/devices/test_block.py index 8bd0b5f..f7e2c39 100644 --- a/tests/devices/test_block.py +++ b/tests/devices/test_block.py @@ -287,3 +287,10 @@ def test_plan_mv_block(RE, writable_block): set_mock_value(writable_block.setpoint, 123.0) RE(bps.mv(writable_block, 456.0)) get_mock_put(writable_block.setpoint).assert_called_once_with(456.0, wait=True, timeout=None) + + +def test_block_reprs(): + assert repr(BlockR(float, block_name="foo", prefix="")) == "BlockR(name=foo)" + assert repr(BlockRw(float, block_name="bar", prefix="")) == "BlockRw(name=bar)" + assert repr(BlockRwRbv(float, block_name="baz", prefix="")) == "BlockRwRbv(name=baz)" + assert repr(BlockMot(block_name="qux", prefix="")) == "BlockMot(name=qux)" diff --git a/tests/devices/test_dae.py b/tests/devices/test_dae.py index 4a4bc7d..a2a9f6c 100644 --- a/tests/devices/test_dae.py +++ b/tests/devices/test_dae.py @@ -1015,3 +1015,7 @@ async def test_if_tof_edges_has_no_units_then_read_spec_dataarray_gives_error( with pytest.raises(ValueError, match="Could not determine engineering units"): await spectrum.read_spectrum_dataarray() + + +def test_dae_repr(): + assert repr(Dae(prefix="foo", name="bar")) == "Dae(name=bar, prefix=foo)" diff --git a/tests/logger/test_logger.py b/tests/logger/test_logger.py deleted file mode 100644 index f4772fa..0000000 --- a/tests/logger/test_logger.py +++ /dev/null @@ -1,25 +0,0 @@ -import sys -from logging.handlers import TimedRotatingFileHandler - -from ibex_bluesky_core.logger import logger - -LOG_MESSAGE = "Logging something to " -LOG_FILE_NAME = "blueskylogs.log" - - -def test_GIVEN_logging_is_requested_THEN_handler_is_added(): - this_function_name = sys._getframe().f_code.co_name - message = LOG_MESSAGE + this_function_name - # Log invocation. - logger.blueskylogger.info(message) - - loghandler = None - for handler in logger.blueskylogger.handlers: - if isinstance(handler, TimedRotatingFileHandler): - loghandler = handler - - assert isinstance(loghandler, TimedRotatingFileHandler) - assert loghandler is not None - assert loghandler.name == "timedRotatingFileHandler" - assert loghandler.baseFilename.endswith(LOG_FILE_NAME) - assert loghandler is not None diff --git a/tests/test_log.py b/tests/test_log.py new file mode 100644 index 0000000..04b556b --- /dev/null +++ b/tests/test_log.py @@ -0,0 +1,61 @@ +import logging +from unittest.mock import patch + +import pytest + +from ibex_bluesky_core.log import LOG_HANDLER, set_bluesky_log_levels, setup_logging + + +@pytest.mark.parametrize("name", ["ibex_bluesky_core", "ophyd_async", "bluesky"]) +def test_setup_logging(name: str): + logging.getLogger(name).handlers.clear() + setup_logging() + assert any(handler == LOG_HANDLER for handler in logging.getLogger(name).handlers) + + +def test_setup_logging_does_not_add_handler_to_root_logger(): + setup_logging() + assert not any(handler == LOG_HANDLER for handler in logging.getLogger().handlers) + + +def test_setup_logging_does_not_crash_if_directory_cannot_be_created( + capfd: pytest.CaptureFixture[str], +): + with patch("ibex_bluesky_core.log.os.makedirs") as mock_makedirs: + mock_makedirs.side_effect = OSError + setup_logging() + + stdout, stderr = capfd.readouterr() + assert stderr == "unable to create ibex_bluesky_core log directory\n" + + +@pytest.mark.parametrize("level", ["DEBUG", "INFO", "WARNING", "ERROR"]) +def test_set_bluesky_log_levels_explicit(level: str): + set_bluesky_log_levels(level) + for name in ["ibex_bluesky_core", "ophyd_async", "bluesky"]: + assert logging.getLevelName(logging.getLogger(name).level) == level + + +def test_set_bluesky_log_levels_default_previously_unset(): + # Setup, pretend log levels have never been set + set_bluesky_log_levels(logging.NOTSET) + + # If the levels weren't previously set, override them to INFO + set_bluesky_log_levels() + + for name in ["ibex_bluesky_core", "ophyd_async", "bluesky"]: + assert logging.getLogger(name).level == logging.INFO + + +def test_set_bluesky_log_levels_default_previously_set(): + # Setup, set some explicit log levels on various loggers. + logging.getLogger("ibex_bluesky_core").setLevel(logging.WARN) + logging.getLogger("bluesky").setLevel(logging.INFO) + logging.getLogger("ophyd_async").setLevel(logging.DEBUG) + + set_bluesky_log_levels() + + # Assert we didn't override the previously explicitly-set levels + assert logging.getLogger("ibex_bluesky_core").level == logging.WARN + assert logging.getLogger("bluesky").level == logging.INFO + assert logging.getLogger("ophyd_async").level == logging.DEBUG