diff --git a/.github/workflows/Lint-and-test.yml b/.github/workflows/Lint-and-test.yml index d6cf780..5495ede 100644 --- a/.github/workflows/Lint-and-test.yml +++ b/.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 diff --git a/.github/workflows/test-against-main.yml b/.github/workflows/test-against-main.yml new file mode 100644 index 0000000..006a958 --- /dev/null +++ b/.github/workflows/test-against-main.yml @@ -0,0 +1,38 @@ +name: test-against-main +on: + schedule: + - cron: "0 0 * * *" +jobs: + tests: + runs-on: ubuntu-latest + strategy: + matrix: + version: ['3.11', "3.12"] + steps: + - uses: actions/checkout@v4 + - uses: actions/setup-python@v5 + with: + python-version: ${{ matrix.version }} + - name: install requirements + run: pip install -e .[dev] + - name: install latest bluesky and ophyd-async + run: pip install --upgrade --force-reinstall git+https://github.com/bluesky/bluesky.git@main git+https://github.com/bluesky/ophyd-async.git@main + - name: run ruff + run: python -m ruff check + - name: run pyright + run: python -m pyright + - name: run pytest + run: python -m pytest + results: + if: ${{ always() }} + runs-on: ubuntu-latest + name: Final Results + needs: [tests] + steps: + - run: exit 1 + # see https://stackoverflow.com/a/67532120/4907315 + if: >- + ${{ + contains(needs.*.result, 'failure') + || contains(needs.*.result, 'cancelled') + }} diff --git a/doc/architectural_decisions/005-variance-addition.md b/doc/architectural_decisions/005-variance-addition.md new file mode 100644 index 0000000..d9ee84f --- /dev/null +++ b/doc/architectural_decisions/005-variance-addition.md @@ -0,0 +1,58 @@ +# Variance addition to counts data + +## Status + +Current + +## Context + +For counts data, the uncertainty on counts is typically defined by poisson counting statistics, i.e. the standard deviation on `N` counts is `sqrt(N)`. + +This can be problematic in cases where zero counts have been collected, as the standard deviation will then be zero, which will subsequently lead to "infinite" point weightings in downstream fitting routines for example. + +A number of possible approaches were considered: + +| Option | Description | +| --- | --- | +| A | Reject data with zero counts, i.e. explicitly throw an exception if any data with zero counts is seen as part of a scan. | +| B | Use a standard deviation of `NaN` for points with zero counts. | +| C | Define the standard deviation of `N` counts as `1` if counts are zero, otherwise `sqrt(N)`. This is one of the approaches available in mantid for example. | +| D | Define the standard deviation of `N` counts as `sqrt(N+0.5)` unconditionally - on the basis that "half a count" is smaller than the smallest possible actual measurement which can be taken. | +| E | No special handling, calculate std. dev. as `sqrt(N)`. | + +For clarity, the following table shows the value and associated uncertainty for each option: + +| Counts | Std. Dev. (A) | Std. Dev. (B) | Std. Dev. (C) | Std. Dev. (D) | Std. Dev. (E) | +| ------- | ------ | ------- | ------- | ------- | --- | +| 0 | raise exception | NaN | 1 | 0.707 | 0 | +| 1 | 1 | 1 | 1 | 1.224745 | 1 | +| 2 | 1.414214 | 1.414214 | 1.414214 | 1.581139 | 1.414214 | +| 3 | 1.732051 | 1.732051 | 1.732051 | 1.870829 | 1.732051 | +| 4 | 2 | 2 | 2 | 2.12132 | 2 | +| 5 | 2.236068 | 2.236068 | 2.236068 | 2.345208 | 2.236068 | +| 10 | 3.162278 | 3.162278 | 3.162278 | 3.24037 | 3.162278 | +| 50 | 7.071068 | 7.071068 | 7.071068 | 7.106335 | 7.071068 | +| 100 | 10 | 10 | 10 | 10.02497 | 10 | +| 500 | 22.36068 | 22.36068 | 22.36068 | 22.37186 | 22.36068 | +| 1000 | 31.62278 | 31.62278 | 31.62278 | 31.63068 | 31.62278 | +| 5000 | 70.71068 | 70.71068 | 70.71068 | 70.71421 | 70.71068 | +| 10000 | 100 | 100 | 100 | 100.0025 | 100 | + +## Present + +These approaches were discussed in a regular project update meeting including +- TW & FA (Experiment controls) +- CK (Reflectometry) +- JL (Muons) +- RD (SANS) + +## Decision + +The consensus was to go with Option D. + +## Justification + +- Option A will cause real-life scans to crash in low counts regions. +- Option B involves `NaN`s, which have many surprising floating-point characteristics and are highly likely to be a source of future bugs. +- Option D was preferred to option C by scientists present. +- Option E causes surprising results and/or crashes downstream, for example fitting may consider points with zero uncertainty to have "infinite" weight, therefore effectively disregarding all other data. diff --git a/doc/callbacks/plotting.md b/doc/callbacks/plotting.md index 0bca52d..5bfffba 100644 --- a/doc/callbacks/plotting.md +++ b/doc/callbacks/plotting.md @@ -38,9 +38,12 @@ ax = plt.gca() # Set the y-scale to logarithmic ax.set_yscale("log") # Use the above axes in a LivePlot callback -plot_callback = LivePlot(y="y_variable", x="x_variable", ax=ax) +plot_callback = LivePlot(y="y_variable", x="x_variable", ax=ax, yerr="yerr_variable") +# yerr is the uncertanties of each y value, producing error bars ``` +By providing a signal name to the `yerr` argument you can pass uncertainties to LivePlot, by not providing anything for this argument means that no errorbars will be drawn. Errorbars are drawn after each point collected, displaying their standard deviation- uncertainty data is collected from Bluesky event documents and errorbars are updated after every new point added. + The `plot_callback` object can then be subscribed to the run engine, using either: - An explicit callback when calling the run engine: `RE(some_plan(), plot_callback)` - Be subscribed in a plan using `@subs_decorator` from bluesky **(recommended)** diff --git a/doc/conf.py b/doc/conf.py index b05eef8..4d82a6d 100644 --- a/doc/conf.py +++ b/doc/conf.py @@ -16,10 +16,17 @@ author = "ISIS Experiment Controls" release = "0.1" - # -- General configuration --------------------------------------------------- # https://www.sphinx-doc.org/en/master/usage/configuration.html#general-configuration +nitpicky = True +nitpick_ignore_regex = [ + ("py:func", r"^(?!ibex_bluesky_core\.).*$"), + ("py:class", r"^(?!ibex_bluesky_core\.).*$"), + ("py:class", r"^.*\.T$"), + ("py:obj", r"^.*\.T$"), +] + myst_enable_extensions = ["dollarmath"] extensions = [ @@ -45,11 +52,9 @@ # https://www.sphinx-doc.org/en/master/usage/configuration.html#options-for-html-output html_theme = "sphinx_rtd_theme" -html_static_path = ["_static"] html_logo = "logo.png" html_theme_options = { "logo_only": False, - "display_version": False, "style_nav_header_background": "#343131", } html_favicon = "favicon.png" diff --git a/doc/dev/logging.md b/doc/dev/logging.md index 997dfa1..7a2806b 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 `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") +``` diff --git a/doc/fitting/fitting.md b/doc/fitting/fitting.md index f9acbb7..d192b64 100644 --- a/doc/fitting/fitting.md +++ b/doc/fitting/fitting.md @@ -24,14 +24,17 @@ plt.figure() ax = plt.gca() # ax is shared by fit_callback and plot_callback -plot_callback = LivePlot(y="y_variable", x="x_variable", ax=ax) -fit_callback = LiveFit(Gaussian.fit(), y="y_variable", x="x_variable", update_every=0.5) +plot_callback = LivePlot(y="y_signal", x="x_signal", ax=ax, yerr="yerr_signal") +fit_callback = LiveFit(Gaussian.fit(), y="y_signal", x="x_signal", yerr="yerr_signal", update_every=0.5) +# Using the yerr parameter allows you to use error bars. # update_every = in seconds, how often to recompute the fit. If `None`, do not compute until the end. Default is 1. fit_plot_callback = LiveFitPlot(fit_callback, ax=ax, color="r") ``` **Note:** that the `LiveFit` callback doesn't directly do the plotting, it will return function parameters of the model its trying to fit to; a `LiveFit` object must be passed to `LiveFitPlot` which can then be subscribed to the `RunEngine`. See the [Bluesky Documentation](https://blueskyproject.io/bluesky/main/callbacks.html#livefitplot) for information on the various arguments that can be passed to the `LiveFitPlot` class. +Using the `yerr` argument allows you to pass uncertainties via a signal to LiveFit, so that the "weight" of each point influences the fit produced. By not providing a signal name you choose not to use uncertainties/weighting in the fitting calculation. Each weight is computed as `1/(standard deviation at point)` and is taken into account to determine how much a point affects the overall fit of the data. Same as the rest of `LiveFit`, the fit will be updated after every new point collected now taking into account the weights of each point. Uncertainty data is collected from Bluesky event documents after each new point. + The `plot_callback` and `fit_plot_callback` objects can then be subscribed to the `RunEngine`, using the same methods as described in [`LivePlot`](../callbacks/plotting.md). See the following example using `@subs_decorator`: ```py @@ -79,7 +82,7 @@ from bluesky.callbacks import LiveFitPlot from ibex_bluesky_core.callbacks.fitting.fitting_utils import [FIT] # Pass [FIT].fit() to the first parameter of LiveFit -lf = LiveFit([FIT].fit(), y="y_variable", x="x_variable", update_every=0.5) +lf = LiveFit([FIT].fit(), y="y_signal", x="x_signal", update_every=0.5) # Then subscribe to LiveFitPlot(lf, ...) ``` @@ -89,7 +92,7 @@ The `[FIT].fit()` function will pass the `FitMethod` object straight to the `Liv **Note:** that for the fits in the above table that require parameters, you will need to pass value(s) to their `.fit` method. For example Polynomial fitting: ```py -lf = LiveFit(Polynomial.fit(3), y="y_variable", x="x_variable", update_every=0.5) +lf = LiveFit(Polynomial.fit(3), y="y_signal", x="x_signal", update_every=0.5) # For a polynomial of degree 3 ``` @@ -138,7 +141,7 @@ def guess(x: npt.NDArray[np.float64], y: npt.NDArray[np.float64]) -> dict[str, l fit_method = FitMethod(model, guess) #Pass the model and guess function to FitMethod -lf = LiveFit(fit_method, y="y_variable", x="x_variable", update_every=0.5) +lf = LiveFit(fit_method, y="y_signal", x="x_signal", update_every=0.5) # Then subscribe to LiveFitPlot(lf, ...) ``` @@ -163,7 +166,7 @@ def different_model(x: float, c1: float, c0: float) -> float: fit_method = FitMethod(different_model, Linear.guess()) # Uses the user defined model and the standard Guessing. function for linear models -lf = LiveFit(fit_method, y="y_variable", x="x_variable", update_every=0.5) +lf = LiveFit(fit_method, y="y_signal", x="x_signal", update_every=0.5) # Then subscribe to LiveFitPlot(lf, ...) ``` @@ -188,7 +191,7 @@ def different_guess(x: float, c1: float, c0: float) -> float: fit_method = FitMethod(Linear.model(), different_guess) # Uses the standard linear model and the user defined Guessing. function -lf = LiveFit(fit_method, y="y_variable", x="x_variable", update_every=0.5) +lf = LiveFit(fit_method, y="y_signal", x="x_signal", update_every=0.5) # Then subscribe to LiveFitPlot(lf, ...) ``` diff --git a/doc/fitting/images_fits/dampedosc.PNG b/doc/fitting/images_fits/dampedosc.png similarity index 100% rename from doc/fitting/images_fits/dampedosc.PNG rename to doc/fitting/images_fits/dampedosc.png diff --git a/doc/index.rst b/doc/index.rst index 5f6b5d5..2e89d7c 100644 --- a/doc/index.rst +++ b/doc/index.rst @@ -22,58 +22,15 @@ abstraction library, which allows bluesky to communicate with an underlying cont - Bluesky or scanning-related utilities which are useful across multiple beamlines. -Overview -======== +Getting started +=============== -.. note:: - - bluesky is a very flexible data acquisition framework. The following example illustrates a minimal scan, - not the full extent of bluesky's functionality. - -Using ``ibex_bluesky_core``, one can define some simple instrument-specific devices:: - - from ibex_bluesky_core.devices.block import block_r, block_mot - - mot = block_mot("mot") # An IBEX block pointing at a motor - det = block_r(float, "p5") # A readback block - -And define a simple step-scan which uses those devices:: - - import bluesky.plans as bp - from ophyd_async.plan_stubs import ensure_connected - - def my_plan(start: float, stop: float, num: int): - yield from ensure_connected(det, mot, force_reconnect=True) - yield from bp.scan([det], mot, start, stop, num) - -After which, a simple scan can be run by a user:: - - from ibex_bluesky_core.run_engine import get_run_engine - - # A bluesky RunEngine instance, already available if using IBEX GUI - RE = get_run_engine() - - # Scan "mot" from 0 to 10 in 5 steps, reading "my_detector" at each step. - RE(my_plan(0, 10, 5)) - -That plan may then also use: - -- Other `experimental plans `_ or - `plan stubs `_, to build up more complex - plans. -- `Callbacks `_ provided by either - ``ibex_bluesky_core`` or ``bluesky``, which do something with the results of the scan: live - fitting, live plotting, file-writing, ... -- `Simulation facilities `_ provided by - bluesky, to check for problems before the plan is run -- And a range of other functionality! - -See the `manual system tests `_ for -some full runnable examples of complex plans, using a wider range of bluesky functionality. +.. toctree:: + :maxdepth: 2 + :caption: Tutorial + :glob: -The reference documentation below lists the functionality that has been implemented in ``ibex_bluesky_core``, -however the vast majority of `bluesky `_ functionality remains -available, and the advanced user is also encouraged to read that documentation. + tutorial/overview.md Reference documentation ======================= diff --git a/doc/tutorial/overview.md b/doc/tutorial/overview.md new file mode 100644 index 0000000..0fbc1fe --- /dev/null +++ b/doc/tutorial/overview.md @@ -0,0 +1,206 @@ +# Getting started + +`ibex_bluesky_core` is a library which bridges the +[IBEX control system](https://github.com/ISISComputingGroup/ibex_user_manual/wiki/What-Is-IBEX) +and the [bluesky data acquisition framework](https://blueskyproject.io/). + +Bluesky is a highly flexible data acquisition system, which has previously been used at +large-scale research facilities such as [NSLS-II](https://www.bnl.gov/nsls2/) and +[Diamond](https://www.diamond.ac.uk/Home.html), among others. + +While the bluesky framework itself is generic enough to cope with many forms of data acquisition, +one of the core use cases is "scanning" - that is, measuring how some experimental parameter(s) +vary with respect to other parameter(s). Bluesky has extensive mechanisms and helpers for typical +scanning workflows. + +The most important concepts in bluesky are: +- **Plans** tell bluesky what to do next, in the form of **Messages** +- **Devices** encapsulate the details of how some specific device is controlled +- The **RunEngine** executes plans (possibly interacting with devices) +- **Callbacks** do something with data emitted by the scan + +## Plans + +A plan is an _iterable_ of _messages_. A very simple plan, which doesn't do anything, is: + +```python +from bluesky.utils import Msg + +my_plan = [Msg("null")] +``` + +Where `Msg("null")` is an instruction to bluesky (which in this case, does nothing). + +While it's possible to write bluesky plans as any iterable, in practice plans are usually written +using python [generators](https://peps.python.org/pep-0255/), using python's +[`yield from`](https://peps.python.org/pep-0380/) syntax to delegate to other plans as necessary: + +```python +import bluesky.plan_stubs as bps + +def plan(): + yield from bps.null() +``` + +## Devices + +`ibex_bluesky_core` provides built-in support for a number of ISIS-specific devices. For example, +blocks are available as devices: + +```python +from ibex_bluesky_core.devices.block import block_r, block_mot + +mot = block_mot("mot") # An IBEX block pointing at a motor +det = block_r(float, "p5") # A readback block with float datatype +``` + +Block objects provide several mechanisms for configuring write behaviour - see +{py:obj}`ibex_bluesky_core.devices.block.BlockWriteConfig` for detailed options. + +Likewise, the DAE is available as a bluesky device: see [the DAE Documentation](../devices/dae.md) +for full examples including example configurations. + +## Setting and reading values + +Bluesky provides plan stubs for setting & reading values from bluesky devices: `bps.mv()` and +`bps.rd()` respectively. + +```python +from ibex_bluesky_core.devices.block import BlockMot +import bluesky.plan_stubs as bps + +def multiply_motor_pos_by_2(mot: BlockMot): + current_value = yield from bps.rd(mot) + yield from bps.mv(mot, current_value * 2.0) +``` + +```{danger} +Notice that we are using `bps.rd()` and `bps.mv()` here, rather than `g.cget()` or `g.cset()`. +Bare `genie` or `inst` commands **must not** be used in bluesky plans - instead, prefer to use the +bluesky-native functionality - i.e. plans using `yield from`. + +Carefully review [calling external code](../plan_stubs/external_code.md) if you do need to call +external code in a plan. +``` + +For more details about plan stubs (plan fragments like `mv` and `read`), see +[bluesky plan stubs documentation](https://blueskyproject.io/bluesky/main/plans.html#stub-plans) + +## Scanning + +Having created some simple devices, those devices can be used in standard bluesky plans: + +```python +from ophyd_async.plan_stubs import ensure_connected +import bluesky.plans as bp +from ibex_bluesky_core.devices.block import block_r, block_mot + +def my_plan(det_block_name: str, mot_block_name: str, start: float, stop: float, num: int): + mot = block_mot(mot_block_name) + det = block_r(float, det_block_name) + + # Devices connect up-front - this means that plans are generally "fail-fast", and + # will detect problems such as typos in block names before the whole plan runs. + yield from ensure_connected(det, mot, force_reconnect=True) + + # Delegate to bluesky's scan plan. + yield from bp.scan([det], mot, start, stop, num) +``` + +For details about plans which are available directly from `bluesky` - like `bp.scan` above - see +[bluesky's plan documentation](https://blueskyproject.io/bluesky/main/plans.html#pre-assembled-plans). + +## The `RunEngine` + +The `RunEngine` is the central "conductor" in bluesky - it is responsible for reading a plan and +performing the associated actions on the hardware. To get a run engine instance, use: + +```python +from ibex_bluesky_core.run_engine import get_run_engine +RE = get_run_engine() +``` + +```{tip} +In the IBEX GUI, manually getting a runengine is unnecessary - it is done automatically. +``` + +Then execute a plan using the RunEngine: + +``` +RE(my_plan("det", "mot", 0, 10, 5)) +``` + +Noth that typing `my_plan("det", "mot", 0, 10, 5)` does not do anything by itself. +That is because `my_plan` is a python generator - which does nothing until iterated. +To actually execute the plan, it must be passed to the `RunEngine`, which is conventionally +called `RE`. + +For more detail about the RunEngine, see: +- [bluesky RunEngine docs](https://blueskyproject.io/bluesky/main/tutorial.html#the-runengine) +- [bluesky RunEngine API docs](https://blueskyproject.io/bluesky/main/run_engine_api.html) + +## Callbacks + +Callbacks are bluesky's mechanism for listening to data from a scan. Some examples of common callbacks +are: +- [File writing](../callbacks/file_writing.md) +- [Plotting](../callbacks/plotting.md) +- [Fitting](../fitting/fitting.md) +- [Live Tables](https://blueskyproject.io/bluesky/main/callbacks.html#livetable) + +It is possible to use callbacks manually, when executing a plan: + +```python +from bluesky.callbacks import LiveTable + +RE(my_plan("det", "mot", 0, 10, 5), LiveTable(["mot", "det"])) +``` + +However, to save typing out callbacks repeatedly, user-specified plans can add callbacks via +[`subs_decorator`](https://blueskyproject.io/bluesky/main/callbacks.html#through-a-plan): + +```python +from ibex_bluesky_core.devices.block import block_r, block_mot +from ophyd_async.plan_stubs import ensure_connected +from bluesky.preprocessors import subs_decorator +from bluesky.callbacks import LiveTable +import bluesky.plans as bp + +def my_plan(det_block_name: str, mot_block_name: str, start: float, stop: float, num: int): + mot = block_mot(mot_block_name) + det = block_r(float, det_block_name) + + @subs_decorator([ + LiveTable([mot.name, det.name]), + ]) + def _inner(): + yield from ensure_connected(det, mot, force_reconnect=True) + yield from bp.scan([det], mot, start, stop, num) + yield from _inner() +``` + +The above will show a `LiveTable` by default, any time `my_plan` is executed. The same mechanism can +be used for example to always configure a particular scan with plots and a fit with a specific type. + +For more information on callbacks, see +[bluesky callbacks documentation](https://blueskyproject.io/bluesky/main/callbacks.html). + +## See also + +**Plans & plan-stubs** +- Bluesky [experiment plans](https://blueskyproject.io/bluesky/main/plans.html#summary) +- Bluesky [plan stubs](https://blueskyproject.io/bluesky/main/plans.html#stub-plans) +- {py:obj}`ibex_bluesky_core.plan_stubs` + +**Callbacks** +- [Bluesky callbacks](https://blueskyproject.io/bluesky/main/callbacks.html) +- {py:obj}`ibex_bluesky_core.callbacks` +- [Fitting callbacks](../fitting/fitting.md) + +**Full Examples** +- [Manual system tests](https://github.com/ISISComputingGroup/ibex_bluesky_core/tree/main/manual_system_tests) (full, +runnable example plans) + +**External documentation** +- [bluesky](https://blueskyproject.io/bluesky) +- [ophyd-async](https://blueskyproject.io/ophyd-async) \ No newline at end of file diff --git a/manual_system_tests/dae_scan.py b/manual_system_tests/dae_scan.py index f4d12cc..eb9e32a 100644 --- a/manual_system_tests/dae_scan.py +++ b/manual_system_tests/dae_scan.py @@ -8,12 +8,14 @@ import bluesky.plans as bp import matplotlib import matplotlib.pyplot as plt -from bluesky.callbacks import LiveTable +from bluesky.callbacks import LiveFitPlot, LiveTable from bluesky.preprocessors import subs_decorator from bluesky.utils import Msg from ophyd_async.plan_stubs import ensure_connected from ibex_bluesky_core.callbacks.file_logger import HumanReadableFileCallback +from ibex_bluesky_core.callbacks.fitting import LiveFit +from ibex_bluesky_core.callbacks.fitting.fitting_utils import Linear from ibex_bluesky_core.callbacks.plotting import LivePlot from ibex_bluesky_core.devices import get_pv_prefix from ibex_bluesky_core.devices.block import block_rw_rbv @@ -27,6 +29,8 @@ from ibex_bluesky_core.devices.simpledae.waiters import GoodFramesWaiter from ibex_bluesky_core.run_engine import get_run_engine +NUM_POINTS: int = 3 + def dae_scan_plan() -> Generator[Msg, None, None]: """Manual system test which moves a block and reads the DAE. @@ -67,6 +71,11 @@ def dae_scan_plan() -> Generator[Msg, None, None]: controller.run_number.set_name("run number") reducer.intensity.set_name("normalized counts") + _, ax = plt.subplots() + lf = LiveFit( + Linear.fit(), y=reducer.intensity.name, x=block.name, yerr=reducer.intensity_stddev.name + ) + yield from ensure_connected(block, dae, force_reconnect=True) @subs_decorator( @@ -81,7 +90,15 @@ def dae_scan_plan() -> Generator[Msg, None, None]: dae.good_frames.name, ], ), - LivePlot(y=reducer.intensity.name, x=block.name, marker="x", linestyle="none"), + LiveFitPlot(livefit=lf, ax=ax), + LivePlot( + y=reducer.intensity.name, + x=block.name, + marker="x", + linestyle="none", + ax=ax, + yerr=reducer.intensity_stddev.name, + ), LiveTable( [ block.name, @@ -96,9 +113,9 @@ def dae_scan_plan() -> Generator[Msg, None, None]: ] ) def _inner() -> Generator[Msg, None, None]: - num_points = 3 - yield from bps.mv(dae.number_of_periods, num_points) - yield from bp.scan([dae], block, 0, 10, num=num_points) + yield from bps.mv(dae.number_of_periods, NUM_POINTS) # type: ignore + # Pyright does not understand as bluesky isn't typed yet + yield from bp.scan([dae], block, 0, 10, num=NUM_POINTS) yield from _inner() diff --git a/pyproject.toml b/pyproject.toml index 82786a6..03c8b88 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -111,3 +111,6 @@ reportUntypedClassDecorator = true reportUntypedFunctionDecorator = true [tool.setuptools_scm] + +[tool.build_sphinx] + 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..3d18ea3 100644 --- a/src/ibex_bluesky_core/callbacks/fitting/__init__.py +++ b/src/ibex_bluesky_core/callbacks/fitting/__init__.py @@ -1,6 +1,7 @@ """For IBEX Bluesky scan fitting.""" import logging +import warnings from typing import Callable import lmfit @@ -8,6 +9,9 @@ import numpy.typing as npt from bluesky.callbacks import LiveFit as _DefaultLiveFit from bluesky.callbacks.core import make_class_safe +from event_model.documents.event import Event + +logger = logging.getLogger(__name__) class FitMethod: @@ -42,20 +46,12 @@ 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.""" def __init__( - self, - method: FitMethod, - y: str, - x: str, - *, - update_every: int = 1, + self, method: FitMethod, y: str, x: str, *, update_every: int = 1, yerr: str | None = None ) -> None: """Call Bluesky LiveFit with assumption that there is only one independant variable. @@ -63,18 +59,41 @@ def __init__( method (FitMethod): The FitMethod (Model & Guess) to use when fitting. y (str): The name of the dependant variable. x (str): The name of the independant variable. - update_every (int): How often to update the fit. (seconds) + update_every (int, optional): How often to update the fit. (seconds) + yerr (str or None, optional): Name of field in the Event document + that provides standard deviation for each Y value. None meaning + do not use uncertainties in fit. """ self.method = method + self.yerr = yerr + self.weight_data = [] super().__init__( - model=method.model, - y=y, - independent_vars={"x": x}, - update_every=update_every, + model=method.model, y=y, independent_vars={"x": x}, update_every=update_every ) + def event(self, doc: Event) -> None: + """When an event is received, update caches.""" + weight = None + if self.yerr is not None: + try: + weight = 1 / doc["data"][self.yerr] + except ZeroDivisionError: + warnings.warn( + "standard deviation for y is 0, therefore applying weight of 0 on fit", + stacklevel=1, + ) + weight = 0.0 + + self.update_weight(weight) + super().event(doc) + + def update_weight(self, weight: float | None = 0.0) -> None: + """Update uncertainties cache.""" + if self.yerr is not None: + self.weight_data.append(weight) + def update_fit(self) -> None: """Use the provided guess function with the most recent x and y values after every update. @@ -85,10 +104,26 @@ def update_fit(self) -> None: None """ - 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 - ) - - super().update_fit() + n = len(self.model.param_names) + if len(self.ydata) < n: + warnings.warn( + f"LiveFitPlot cannot update fit until there are at least {n} data points", + stacklevel=1, + ) + else: + 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) + + kwargs = {} + kwargs.update(self.independent_vars_data) + kwargs.update(self.init_guess) + self.result = self.model.fit( + self.ydata, weights=None if self.yerr is None else self.weight_data, **kwargs + ) + self.__stale = False diff --git a/src/ibex_bluesky_core/callbacks/fitting/fitting_utils.py b/src/ibex_bluesky_core/callbacks/fitting/fitting_utils.py index d60a7ff..4bacdc7 100644 --- a/src/ibex_bluesky_core/callbacks/fitting/fitting_utils.py +++ b/src/ibex_bluesky_core/callbacks/fitting/fitting_utils.py @@ -190,7 +190,6 @@ def guess( ) -> Callable[[npt.NDArray[np.float64], npt.NDArray[np.float64]], dict[str, lmfit.Parameter]]: """Linear Guessing.""" return Polynomial.guess(1) - # Uses polynomial guessing with a degree of 1 class Polynomial(Fit): @@ -332,14 +331,17 @@ def guess( # Guessing. gradient of linear-slope part of function dy = np.gradient(y) # Return array of differences in y max_dy = np.max(dy) # Return max y difference, this will always be on the upwards slope - dx = x[1] - x[0] # Find x step + dx = abs(x[1] - x[0]) # Find x step gradient = max_dy / dx d2y = np.diff(dy) # Double differentiate y to find how gradients change inflection0 = x[np.argmax(d2y)] # Where there is positive gradient change background = min(y) # The lowest y value is the background - inflections_diff = -(background - y[np.argmax(y)]) / gradient + if gradient != 0.0: + inflections_diff = -(background - y[np.argmax(y)]) / gradient + else: + inflections_diff = dx # Fallback case, guess one x step # As linear, using y - y1 = m(x - x1) -> x = (y - y1) / gradient - x1 # The highest y value + slightly more to account for further convergence diff --git a/src/ibex_bluesky_core/callbacks/plotting.py b/src/ibex_bluesky_core/callbacks/plotting.py index 4299b27..5547346 100644 --- a/src/ibex_bluesky_core/callbacks/plotting.py +++ b/src/ibex_bluesky_core/callbacks/plotting.py @@ -1,11 +1,12 @@ """IBEX plotting callbacks.""" import logging +from typing import Any import matplotlib import matplotlib.pyplot as plt from bluesky.callbacks import LivePlot as _DefaultLivePlot -from bluesky.callbacks.core import make_class_safe +from bluesky.callbacks.core import get_obj_fields, make_class_safe from event_model.documents import Event, RunStart logger = logging.getLogger(__name__) @@ -15,18 +16,60 @@ class LivePlot(_DefaultLivePlot): """Live plot, customized for IBEX.""" + def __init__( + self, + y: str, + x: str | None = None, + yerr: str | None = None, + *args: Any, # noqa: ANN401 + **kwargs: Any, # noqa: ANN401 + ) -> None: + """Initialise LivePlot. + + Args: + y (str): The name of the dependant variable. + x (str or None, optional): The name of the independant variable. + yerr (str or None, optional): Name of uncertainties signal. + Providing None means do not plot uncertainties. + *args: As per mpl_plotting.py + **kwargs: As per mpl_plotting.py + + """ + super().__init__(y=y, x=x, *args, **kwargs) # noqa: B026 + if yerr is not None: + self.yerr, *others = get_obj_fields([yerr]) + else: + self.yerr = None + self.yerr_data = [] + def _show_plot(self) -> None: - # Play nicely with the "normal" backends too - only force show if we're - # actually using our custom backend. + """Call plt.show(). + + 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: - """Process an start document (delegate to superclass, then show the plot).""" - super().start(doc) - self._show_plot() - def event(self, doc: Event) -> None: """Process an event document (delegate to superclass, then show the plot).""" + new_yerr = None if self.yerr is None else doc["data"][self.yerr] + self.update_yerr(new_yerr) super().event(doc) self._show_plot() + + def update_plot(self) -> None: + """Create error bars if needed, then update plot.""" + if self.yerr is not None: + self.ax.errorbar(x=self.x_data, y=self.y_data, yerr=self.yerr_data, fmt="none") # type: ignore + super().update_plot() + + def update_yerr(self, yerr: float | None) -> None: + """Update uncertainties data.""" + self.yerr_data.append(yerr) + + def start(self, doc: RunStart) -> None: + """Process an start document (delegate to superclass, then show the plot).""" + super().start(doc) + self._show_plot() diff --git a/src/ibex_bluesky_core/devices/block.py b/src/ibex_bluesky_core/devices/block.py index cf77639..3ab87e8 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,7 +19,9 @@ from ibex_bluesky_core.devices import get_pv_prefix -"""Block data type""" +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 901df1e..35a4b83 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,9 @@ from ophyd_async.core import SignalR, StandardReadable from ophyd_async.epics.signal import epics_signal_r +VARIANCE_ADDITION = 0.5 +logger = logging.getLogger(__name__) + class DaeSpectra(StandardReadable): """Subdevice for a single DAE spectra.""" @@ -89,6 +93,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(), @@ -107,7 +116,21 @@ async def read_spectrum_dataarray(self) -> sc.DataArray: if unit is None: raise ValueError("Could not determine engineering units of tof edges.") + # See doc\architectural_decisions\005-variance-addition.md + # for justfication of the VARIANCE_ADDITION to variances + return sc.DataArray( - data=sc.Variable(dims=["tof"], values=counts, variances=counts, unit=sc.units.counts, dtype="float64"), - coords={"tof": sc.array(dims=["tof"], values=tof_edges, unit=sc.Unit(unit), dtype="float64")}, + data=sc.Variable( + dims=["tof"], + values=counts, + variances=counts + VARIANCE_ADDITION, + unit=sc.units.counts, + dtype="float64", + ), + coords={ + "tof": sc.array(dims=["tof"], + values=tof_edges, + unit=sc.Unit(unit), + dtype="float64") + }, ) 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 f5b0edd..18a089b 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 @@ -19,6 +20,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 @@ -32,9 +35,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 @@ -130,6 +135,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( self.summer(self.detectors.values()), self.denominator(dae).get_value() ) @@ -148,6 +154,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.""" @@ -229,6 +236,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( self.detector_summer(self.detectors.values()), self.monitor_summer(self.monitors.values()), @@ -253,6 +261,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..258e870 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 @@ -19,7 +22,7 @@ T = TypeVar("T", int, float) -class _SimpleWaiter(Waiter, Generic[T], metaclass=ABCMeta): +class SimpleWaiter(Waiter, Generic[T], metaclass=ABCMeta): """Wait for a single DAE variable to be greater or equal to a specified numeric value.""" def __init__(self, value: T) -> None: @@ -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.""" @@ -41,10 +47,10 @@ def additional_readable_signals(self, dae: "SimpleDae") -> list[Device]: @abstractmethod def get_signal(self, dae: "SimpleDae") -> SignalR[T]: - pass + """Get the numeric signal to wait for.""" -class PeriodGoodFramesWaiter(_SimpleWaiter[int]): +class PeriodGoodFramesWaiter(SimpleWaiter[int]): """Wait for period good frames to reach a user-specified value.""" def get_signal(self, dae: "SimpleDae") -> SignalR[int]: @@ -52,7 +58,7 @@ def get_signal(self, dae: "SimpleDae") -> SignalR[int]: return dae.period.good_frames -class GoodFramesWaiter(_SimpleWaiter[int]): +class GoodFramesWaiter(SimpleWaiter[int]): """Wait for good frames to reach a user-specified value.""" def get_signal(self, dae: "SimpleDae") -> SignalR[int]: @@ -60,7 +66,7 @@ def get_signal(self, dae: "SimpleDae") -> SignalR[int]: return dae.good_frames -class GoodUahWaiter(_SimpleWaiter[float]): +class GoodUahWaiter(SimpleWaiter[float]): """Wait for good microamp-hours to reach a user-specified value.""" def get_signal(self, dae: "SimpleDae") -> SignalR[float]: @@ -68,7 +74,7 @@ def get_signal(self, dae: "SimpleDae") -> SignalR[float]: return dae.good_uah -class MEventsWaiter(_SimpleWaiter[float]): +class MEventsWaiter(SimpleWaiter[float]): """Wait for a user-specified number of millions of events.""" def get_signal(self, dae: "SimpleDae") -> SignalR[float]: @@ -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..19f0f4f --- /dev/null +++ b/src/ibex_bluesky_core/log.py @@ -0,0 +1,75 @@ +"""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 functools import cache +from logging import Formatter +from logging.handlers import TimedRotatingFileHandler + +__all__ = ["setup_logging", "set_bluesky_log_levels", "file_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"] + + +@cache +def file_handler() -> TimedRotatingFileHandler: + """Get the file handler for ibex_bluesky_core and related loggers. + + Cached so that this function does not run on import, but multiple invocations always return the + same handler object. + """ + handler = TimedRotatingFileHandler(os.path.join(log_location, "bluesky.log"), "midnight") + + handler.setFormatter( + Formatter( + "%(asctime)s (%(process)d) %(name)s %(filename)s " + "[line:%(lineno)d] %(levelname)s %(message)s" + ), + ) + return handler + + +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) + return + + # 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(file_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/__init__.py b/src/ibex_bluesky_core/run_engine/__init__.py index a0a64e8..f6d9344 100644 --- a/src/ibex_bluesky_core/run_engine/__init__.py +++ b/src/ibex_bluesky_core/run_engine/__init__.py @@ -2,6 +2,7 @@ import asyncio import functools +import logging from functools import cache from threading import Event @@ -11,13 +12,16 @@ 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.plan_stubs import CALL_SYNC_MSG_KEY -from ibex_bluesky_core.preprocessors import add_rb_number_processor from ibex_bluesky_core.run_engine._msg_handlers import call_sync_handler +logger = logging.getLogger(__name__) + class _DuringTask(DuringTask): def block(self, blocking_event: Event) -> None: @@ -71,6 +75,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/callbacks/fitting/test_fitting_callback.py b/tests/callbacks/fitting/test_fitting_callback.py index a59da49..05d2d31 100644 --- a/tests/callbacks/fitting/test_fitting_callback.py +++ b/tests/callbacks/fitting/test_fitting_callback.py @@ -1,10 +1,13 @@ +import warnings from unittest import mock +from unittest.mock import MagicMock import lmfit import numpy as np import numpy.typing as npt from ibex_bluesky_core.callbacks.fitting import FitMethod, LiveFit +from ibex_bluesky_core.callbacks.fitting.fitting_utils import Linear def test_guess_called(): @@ -92,3 +95,70 @@ def model(x: npt.NDArray[np.float64]) -> npt.NDArray[np.float64]: ) model_mock.assert_called() + + +def test_model_called_with_weights_if_yerr_is_given(): + def guess(x: npt.NDArray[np.float64], y: npt.NDArray[np.float64]) -> dict[str, lmfit.Parameter]: + return {} + + model = lmfit.Model(lambda x: x) + model.fit = MagicMock() + method = FitMethod(model=model, guess=guess) + lf = LiveFit(method, y="y", x="x", yerr="yerr") + + x = 1 + y = 2 + yerr = 3 + + lf.event( + { + "data": { # type: ignore + "y": y, + "x": x, + "yerr": yerr, + } + } + ) + + model.fit.assert_called_with([y], weights=[1 / yerr], x=[1]) + + +def test_warning_given_if_yerr_is_0(): + def guess(x: npt.NDArray[np.float64], y: npt.NDArray[np.float64]) -> dict[str, lmfit.Parameter]: + return {} + + model = lmfit.Model(lambda x: x) + model.fit = MagicMock() + method = FitMethod(model=model, guess=guess) + lf = LiveFit(method, y="y", x="x", yerr="yerr") + + x = 1 + y = 2 + yerr = 0 + + with warnings.catch_warnings(record=True) as w: + lf.event( + { + "data": { # type: ignore + "y": y, + "x": x, + "yerr": yerr, + } + } + ) + + model.fit.assert_called_with([y], weights=[0.0], x=[1]) + + assert len(w) == 1 + assert "standard deviation for y is 0, therefore applying weight of 0 on fit" in str( + w[-1].message + ) + + +def test_warning_if_no_y_data(): + with warnings.catch_warnings(record=True) as w: + lf = LiveFit(Linear.fit(), y="y", x="x", yerr="yerr") + lf.update_fit() + + assert len(w) == 1 + assert "LiveFitPlot cannot update fit until there are at least" in str(w[-1].message) diff --git a/tests/callbacks/fitting/test_fitting_methods.py b/tests/callbacks/fitting/test_fitting_methods.py index e9be85a..c7fbc9d 100644 --- a/tests/callbacks/fitting/test_fitting_methods.py +++ b/tests/callbacks/fitting/test_fitting_methods.py @@ -447,6 +447,13 @@ def test_guess_inflections_diff(self): assert 3.0 == pytest.approx(outp["inflections_diff"].value, rel=1e-2) + def test_guess_inflections_diff_with_all_zero_data(self): + x = np.array([-1.0, 0.0, 1.0, 2.0, 3.0, 4.0]) + y = np.array([0.0, 0.0, 0.0, 0.0, 0.0, 0.0]) + outp = SlitScan.guess()(x, y) + + assert 1.0 == pytest.approx(outp["inflections_diff"].value, rel=1e-2) + def test_guess_height_above_inflection1(self): x = np.array([-1.0, 0.0, 1.0, 2.0, 3.0, 4.0]) y = np.array([1.0, 1.0, 2.0, 3.0, 4.0, 4.0]) diff --git a/tests/callbacks/test_plotting_callback.py b/tests/callbacks/test_plotting_callback.py index e5b486a..c15658c 100644 --- a/tests/callbacks/test_plotting_callback.py +++ b/tests/callbacks/test_plotting_callback.py @@ -1,6 +1,8 @@ from typing import Any from unittest.mock import MagicMock, patch +from matplotlib import pyplot as plt + from ibex_bluesky_core.callbacks.plotting import LivePlot @@ -42,3 +44,54 @@ def test_show_plot_only_shows_if_backend_is_genie(): mock_get_backend.return_value = "simulated_genie_python_backend" lp._show_plot() mock_plt_show.assert_called_once() + + +def test_errorbars_created_if_yerr_is_given(): + _, ax = plt.subplots() + ax.errorbar = MagicMock() + + lp = LivePlot(y="y", x="x", yerr="yerr", ax=ax) + + x = 1 + y = 2 + yerr = 3 + + # Fake just enough of an event document. + lp.start( + { + "time": 0, + "uid": "0", + "scan_id": 0, + } + ) + + # Fake just enough of an event document. + lp.event( + { + "data": { + "y": y, + "x": x, + "yerr": yerr, + } + } # type: ignore + ) + + ax.errorbar.assert_called_with(y=[y], x=[x], yerr=[yerr], fmt="none") + + +def test_errorbars_not_created_if_no_yerr(): + _, ax = plt.subplots() + ax.errorbar = MagicMock() + + lp = LivePlot(y="y", x="x", ax=ax) + + lp.start( + { + "time": 0, + "uid": "0", + "scan_id": 0, + } + ) + + lp.update_plot() + assert not ax.errorbar.called 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 82a716d..6c92b89 100644 --- a/tests/devices/test_dae.py +++ b/tests/devices/test_dae.py @@ -25,7 +25,7 @@ DaeSettingsData, TimingSource, ) -from ibex_bluesky_core.devices.dae.dae_spectra import DaeSpectra +from ibex_bluesky_core.devices.dae.dae_spectra import VARIANCE_ADDITION, DaeSpectra from ibex_bluesky_core.devices.dae.dae_tcb_settings import ( CalculationMethod, DaeTCBSettings, @@ -979,7 +979,11 @@ async def test_read_spectrum_dataarray(spectrum: DaeSpectra): data=sc.Variable( dims=["tof"], values=[1000, 2000, 3000], - variances=[1000, 2000, 3000], + variances=[ + 1000 + VARIANCE_ADDITION, + 2000 + VARIANCE_ADDITION, + 3000 + VARIANCE_ADDITION, + ], unit=sc.units.counts, dtype="float32", ), @@ -1015,3 +1019,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..29c3556 --- /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 file_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 == file_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 == file_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