Make common MX bluesky logging (#580)

* Move hyperion logs to somewhere common and generalise get_logging_dir
* Add toggle to integrate all logs

helmchart/templates/deployment.yaml

@@ -106,7 +106,7 @@ spec:
             containerPort: {{ .Values.hyperion.containerPort }}
             protocol: TCP
         env:
-          - name: HYPERION_LOG_DIR
+          - name: LOG_DIR
             value: /var/log/bluesky
           - name: BEAMLINE
             value: "{{ .Values.hyperion.beamline }}"

run_hyperion.sh

@@ -99,21 +99,19 @@ if [[ $START == 1 ]]; then
     module unload controls_dev
     module load dials
 
-    RELATIVE_SCRIPT_DIR=$( dirname -- "$0"; )
-    cd ${RELATIVE_SCRIPT_DIR}
 
-    if [ -z "$HYPERION_LOG_DIR" ]; then
+    if [ -z "$LOG_DIR" ]; then
         if [ $IN_DEV == true ]; then
-            HYPERION_LOG_DIR=$RELATIVE_SCRIPT_DIR/tmp/dev
+            LOG_DIR=$RELATIVE_SCRIPT_DIR/tmp/dev
         else
-            HYPERION_LOG_DIR=/dls_sw/$BEAMLINE/logs/bluesky
+            LOG_DIR=/dls_sw/$BEAMLINE/logs/bluesky
         fi
     fi
-    echo "$(date) Logging to $HYPERION_LOG_DIR"
-    export HYPERION_LOG_DIR
-    mkdir -p $HYPERION_LOG_DIR
-    start_log_path=$HYPERION_LOG_DIR/start_log.log
-    callback_start_log_path=$HYPERION_LOG_DIR/callback_start_log.log
+    echo "$(date) Logging to $LOG_DIR"
+    export LOG_DIR
+    mkdir -p $LOG_DIR
+    start_log_path=$LOG_DIR/start_log.log
+    callback_start_log_path=$LOG_DIR/callback_start_log.log
 
     source .venv/bin/activate
 

src/mx_bluesky/common/utils/log.py

@@ -0,0 +1,116 @@
+import logging
+from logging.handlers import TimedRotatingFileHandler
+from os import environ
+from pathlib import Path
+
+from dodal.log import (
+    ERROR_LOG_BUFFER_LINES,
+    CircularMemoryHandler,
+    DodalLogHandlers,
+    integrate_bluesky_and_ophyd_logging,
+    set_up_all_logging_handlers,
+)
+from dodal.log import LOGGER as dodal_logger
+
+__logger_handlers: DodalLogHandlers | None = None
+
+
+class ExperimentMetadataTagFilter(logging.Filter):
+    """When an instance of this custom filter is added to a logging handler, dc_group_id
+    and run_id will be tagged in that handlers' log messages."""
+
+    dc_group_id: str | None = None
+    run_uid: str | None = None
+
+    def filter(self, record):
+        if self.dc_group_id:
+            record.dc_group_id = self.dc_group_id
+        if self.run_uid:
+            record.run_uid = self.run_uid
+        return True
+
+
+tag_filter = ExperimentMetadataTagFilter()
+
+
+def set_dcgid_tag(dcgid):
+    """Set the datacollection group id as a tag on all subsequent log messages.
+    Setting to None will remove the tag."""
+    tag_filter.dc_group_id = dcgid
+
+
+def set_uid_tag(uid):
+    """Set the unique id as a tag on all subsequent log messages.
+    Setting to None will remove the tag."""
+    tag_filter.run_uid = uid
+
+
+def do_default_logging_setup(
+    file_name: str,
+    graylog_port: int,
+    dev_mode: bool = False,
+    integrate_all_logs: bool = True,
+):
+    """Configures dodal logger so that separate debug and info log files are created,
+    info logs are sent to Graylog, info logs are streamed to sys.sterr, and logs from ophyd
+    and bluesky and ophyd-async are optionally included."""
+
+    handlers = set_up_all_logging_handlers(
+        dodal_logger,
+        _get_logging_dir(),
+        file_name,
+        dev_mode,
+        ERROR_LOG_BUFFER_LINES,
+        graylog_port,
+    )
+
+    if integrate_all_logs:
+        integrate_bluesky_and_ophyd_logging(dodal_logger)
+
+    handlers["graylog_handler"].addFilter(tag_filter)
+
+    global __logger_handlers
+    __logger_handlers = handlers
+
+
+def _get_debug_handler() -> CircularMemoryHandler:
+    assert (
+        __logger_handlers is not None
+    ), "You can only use this after running the default logging setup"
+    return __logger_handlers["debug_memory_handler"]
+
+
+def flush_debug_handler() -> str:
+    """Writes the contents of the circular debug log buffer to disk and returns the written filename"""
+    handler = _get_debug_handler()
+    assert isinstance(
+        handler.target, TimedRotatingFileHandler
+    ), "Circular memory handler doesn't have an appropriate fileHandler target"
+    handler.flush()
+    return handler.target.baseFilename
+
+
+def _get_logging_dir() -> Path:
+    """Get the path to write the mx_bluesky log files to.
+
+    Log location can be specified in the LOG_DIR environment variable, otherwise MX bluesky logs are written to 'dls_sw/ixx/logs/bluesky'.
+    This directory will be created if it is not found
+
+    Logs are written to ./tmp/logs/bluesky if BEAMLINE environment variable is not found
+
+    Returns:
+        logging_path (Path): Path to the log file for the file handler to write to.
+    """
+
+    logging_str = environ.get("LOG_DIR")
+    if logging_str:
+        logging_path = Path(logging_str)
+    else:
+        beamline = environ.get("BEAMLINE")
+        logging_path = (
+            Path(f"/dls_sw/{beamline}/logs/bluesky/")
+            if beamline
+            else Path("/tmp/logs/bluesky")
+        )
+    Path.mkdir(logging_path, exist_ok=True, parents=True)
+    return logging_path

src/mx_bluesky/hyperion/__main__.py

@@ -14,6 +14,7 @@
 from flask_restful import Api, Resource
 from pydantic.dataclasses import dataclass
 
+from mx_bluesky.common.utils.log import do_default_logging_setup, flush_debug_handler
 from mx_bluesky.hyperion.exceptions import WarningException
 from mx_bluesky.hyperion.experiment_plans.experiment_registry import (
     PLAN_REGISTRY,
@@ -36,8 +37,6 @@
 )
 from mx_bluesky.hyperion.log import (
     LOGGER,
-    do_default_logging_setup,
-    flush_debug_handler,
 )
 from mx_bluesky.hyperion.parameters.cli import parse_cli_args
 from mx_bluesky.hyperion.parameters.components import HyperionParameters
@@ -345,7 +344,9 @@ def create_app(
 def create_targets():
     hyperion_port = 5005
     args = parse_cli_args()
-    do_default_logging_setup(dev_mode=args.dev_mode)
+    do_default_logging_setup(
+        CONST.LOG_FILE_NAME, CONST.GRAYLOG_PORT, dev_mode=args.dev_mode
+    )
     if not args.use_external_callbacks:
         setup_callback_logging(args.dev_mode)
     app, runner = create_app(

src/mx_bluesky/hyperion/external_interaction/callbacks/__main__.py

@@ -7,6 +7,7 @@
 from dodal.log import LOGGER as dodal_logger
 from dodal.log import set_up_all_logging_handlers
 
+from mx_bluesky.common.utils.log import _get_logging_dir, tag_filter
 from mx_bluesky.hyperion.external_interaction.callbacks.log_uid_tag_callback import (
     LogUidTaggingCallback,
 )
@@ -31,8 +32,6 @@
 from mx_bluesky.hyperion.log import (
     ISPYB_LOGGER,
     NEXUS_LOGGER,
-    _get_logging_dir,
-    tag_filter,
 )
 from mx_bluesky.hyperion.parameters.cli import parse_callback_dev_mode_arg
 from mx_bluesky.hyperion.parameters.constants import CONST

src/mx_bluesky/hyperion/external_interaction/callbacks/ispyb_callback_base.py

@@ -9,6 +9,7 @@
 from dodal.devices.detector.det_resolution import resolution
 from dodal.devices.synchrotron import SynchrotronMode
 
+from mx_bluesky.common.utils.log import set_dcgid_tag
 from mx_bluesky.hyperion.external_interaction.callbacks.plan_reactive_callback import (
     PlanReactiveCallback,
 )
@@ -22,7 +23,7 @@
     StoreInIspyb,
 )
 from mx_bluesky.hyperion.external_interaction.ispyb.ispyb_utils import get_ispyb_config
-from mx_bluesky.hyperion.log import ISPYB_LOGGER, set_dcgid_tag
+from mx_bluesky.hyperion.log import ISPYB_LOGGER
 from mx_bluesky.hyperion.parameters.components import DiffractionExperimentWithSample
 from mx_bluesky.hyperion.parameters.constants import CONST
 from mx_bluesky.hyperion.utils.utils import convert_eV_to_angstrom

src/mx_bluesky/hyperion/external_interaction/callbacks/log_uid_tag_callback.py

@@ -1,7 +1,7 @@
 from bluesky.callbacks import CallbackBase
 from event_model import RunStart, RunStop
 
-from mx_bluesky.hyperion.log import set_uid_tag
+from mx_bluesky.common.utils.log import set_uid_tag
 
 
 class LogUidTaggingCallback(CallbackBase):

src/mx_bluesky/hyperion/external_interaction/callbacks/rotation/ispyb_callback.py

@@ -3,6 +3,7 @@
 from collections.abc import Callable, Sequence
 from typing import TYPE_CHECKING, Any, cast
 
+from mx_bluesky.common.utils.log import set_dcgid_tag
 from mx_bluesky.hyperion.external_interaction.callbacks.common.ispyb_mapping import (
     populate_data_collection_group,
     populate_remaining_data_collection_info,
@@ -22,7 +23,7 @@
     IspybIds,
     StoreInIspyb,
 )
-from mx_bluesky.hyperion.log import ISPYB_LOGGER, set_dcgid_tag
+from mx_bluesky.hyperion.log import ISPYB_LOGGER
 from mx_bluesky.hyperion.parameters.components import IspybExperimentType
 from mx_bluesky.hyperion.parameters.constants import CONST
 from mx_bluesky.hyperion.parameters.rotation import RotationScan

src/mx_bluesky/hyperion/external_interaction/callbacks/xray_centre/ispyb_callback.py

@@ -9,6 +9,7 @@
 from bluesky import preprocessors as bpp
 from dodal.devices.zocalo.zocalo_results import ZOCALO_READING_PLAN_NAME
 
+from mx_bluesky.common.utils.log import set_dcgid_tag
 from mx_bluesky.hyperion.external_interaction.callbacks.common.ispyb_mapping import (
     populate_data_collection_group,
     populate_remaining_data_collection_info,
@@ -36,7 +37,7 @@
     IspybIds,
     StoreInIspyb,
 )
-from mx_bluesky.hyperion.log import ISPYB_LOGGER, set_dcgid_tag
+from mx_bluesky.hyperion.log import ISPYB_LOGGER
 from mx_bluesky.hyperion.parameters.components import DiffractionExperimentWithSample
 from mx_bluesky.hyperion.parameters.constants import CONST
 from mx_bluesky.hyperion.parameters.gridscan import (

src/mx_bluesky/hyperion/log.py

@@ -1,23 +1,10 @@
 import logging
-from logging.handlers import TimedRotatingFileHandler
-from os import environ
-from pathlib import Path
 
-from dodal.log import (
-    ERROR_LOG_BUFFER_LINES,
-    CircularMemoryHandler,
-    DodalLogHandlers,
-    integrate_bluesky_and_ophyd_logging,
-    set_up_all_logging_handlers,
-)
 from dodal.log import LOGGER as dodal_logger
 
-from mx_bluesky.hyperion.parameters.constants import CONST
-
 LOGGER = logging.getLogger("Hyperion")
 LOGGER.setLevel("DEBUG")
 LOGGER.parent = dodal_logger
-__logger_handlers: DodalLogHandlers | None = None
 
 ISPYB_LOGGER = logging.getLogger("Hyperion ISPyB and Zocalo callbacks")
 ISPYB_LOGGER.setLevel(logging.DEBUG)
@@ -26,74 +13,3 @@
 NEXUS_LOGGER.setLevel(logging.DEBUG)
 
 ALL_LOGGERS = [LOGGER, ISPYB_LOGGER, NEXUS_LOGGER]
-
-
-class ExperimentMetadataTagFilter(logging.Filter):
-    dc_group_id: str | None = None
-    run_uid: str | None = None
-
-    def filter(self, record):
-        if self.dc_group_id:
-            record.dc_group_id = self.dc_group_id
-        if self.run_uid:
-            record.run_uid = self.run_uid
-        return True
-
-
-tag_filter = ExperimentMetadataTagFilter()
-
-
-def set_dcgid_tag(dcgid):
-    """Set the datacollection group id as a tag on all subsequent log messages.
-    Setting to None will remove the tag."""
-    tag_filter.dc_group_id = dcgid
-
-
-def set_uid_tag(uid):
-    tag_filter.run_uid = uid
-
-
-def do_default_logging_setup(dev_mode=False):
-    handlers = set_up_all_logging_handlers(
-        dodal_logger,
-        _get_logging_dir(),
-        "hyperion.log",
-        dev_mode,
-        ERROR_LOG_BUFFER_LINES,
-        CONST.GRAYLOG_PORT,
-    )
-    integrate_bluesky_and_ophyd_logging(dodal_logger)
-    handlers["graylog_handler"].addFilter(tag_filter)
-
-    global __logger_handlers
-    __logger_handlers = handlers
-
-
-def _get_debug_handler() -> CircularMemoryHandler:
-    assert (
-        __logger_handlers is not None
-    ), "You can only use this after running the default logging setup"
-    return __logger_handlers["debug_memory_handler"]
-
-
-def flush_debug_handler() -> str:
-    """Writes the contents of the circular debug log buffer to disk and returns the written filename"""
-    handler = _get_debug_handler()
-    assert isinstance(
-        handler.target, TimedRotatingFileHandler
-    ), "Circular memory handler doesn't have an appropriate fileHandler target"
-    handler.flush()
-    return handler.target.baseFilename
-
-
-def _get_logging_dir() -> Path:
-    """Get the path to write the hyperion log files to.
-
-    If the HYPERION_LOG_DIR environment variable exists then logs will be put in here.
-    If no environment variable is found it will default it to the ./tmp/dev directory.
-
-    Returns:
-        logging_path (Path): Path to the log file for the file handler to write to.
-    """
-    logging_path = Path(environ.get("HYPERION_LOG_DIR") or "./tmp/dev/")
-    return logging_path

src/mx_bluesky/hyperion/parameters/constants.py

@@ -139,6 +139,7 @@ class HyperionConstants:
     GRAYLOG_PORT = 12232
     PARAMETER_SCHEMA_DIRECTORY = "src/hyperion/parameters/schemas/"
     ZOCALO_ENV = "dev_artemis" if TEST_MODE else "artemis"
+    LOG_FILE_NAME = "hyperion.log"
 
 
 CONST = HyperionConstants()