Merge pull request #1209 from DiamondLightSource/1201_dump_debug_logs…

…_endpoint

Add an endpoint to write `DEBUG` level logs

README.md

@@ -24,20 +24,17 @@ Controlling the Gridscan Externally (e.g. from GDA)
 
 Starting the bluesky runner
 -------------------------
-You can start the bluesky runner by running `run_hyperion.sh`. Note that this will fail on a developer machine unless you have a simulated beamline running, instead you should do `run_hyperion.sh --skip-startup-connection`, which will give you a running instance (note that without hardware trying to run a plan on this will fail).
+You can start the bluesky runner by running `run_hyperion.sh`. Note that this will fail on a developer machine unless you have a simulated beamline running, instead you should do `run_hyperion.sh --dev --skip-startup-connection`, which will give you a running instance (note that without hardware trying to run a plan on this will fail). The `--dev` flag ensures that logging will not be sent to the production Graylog.
 
-This script will determine whether you are on a beamline or a production machine based on the `BEAMLINE` environment variable.  If on a beamline Hyperion will run with `INFO` level logging, sending its logs to both production graylog and to the beamline/log/bluesky/hyperion.txt on the shared file system.
+This script will determine whether you are on a beamline or a production machine based on the `BEAMLINE` environment variable.  If on a beamline Hyperion will run with `INFO` level logging, sending its logs to both production graylog and to the beamline/log/bluesky/hyperion.log on the shared file system.
 
-If in a dev environment Hyperion will log to a local graylog instance instead and into a file at `./tmp/dev/hyperion.txt`. A local instance of graylog will need to be running for this to work correctly. To set this up and run up the containers on your local machine run the `setup_graylog.sh` script.
+If in a dev environment Hyperion will log to a local graylog instance instead and into a file at `./tmp/dev/hyperion.log`. A local instance of graylog will need to be running for this to work correctly. To set this up and run up the containers on your local machine run the `setup_graylog.sh` script.
 
 This uses the generic defaults for a local graylog instance. It can be accessed on `localhost:9000` where the username and password for the graylog portal are both admin.
 
-The logging level of hyperion can be selected with the flag
-```
-python -m hyperion --dev --logging-level DEBUG
-```
+The hyperion python module can also be run directly without the startup script. It takes the same command line options, including:
 
-Additionally, `INFO` level logging of the Bluesky event documents can be enabled with the flag
+`INFO` level logging of the Bluesky event documents can be enabled with the flag
 ```
 python -m hyperion --dev --verbose-event-logging
 ```
@@ -86,3 +83,10 @@ curl -X PUT http://127.0.0.1:5005/stop
 
 ```
 
+Writing out `DEBUG` logs
+------------------------
+To make the app write the `DEBUG` level logs stored in the `CircularMemoryHandler`:
+```
+curl -X PUT http://127.0.0.1:5005/flush_debug_log
+
+```

src/hyperion/__main__.py

@@ -32,7 +32,7 @@
 from hyperion.external_interaction.callbacks.logging_callback import (
     VerbosePlanExecutionLoggingCallback,
 )
-from hyperion.log import LOGGER, do_default_logging_setup
+from hyperion.log import LOGGER, do_default_logging_setup, flush_debug_handler
 from hyperion.parameters.cli import parse_cli_args
 from hyperion.parameters.constants import CONST, Actions, Status
 from hyperion.parameters.internal_parameters import InternalParameters
@@ -284,6 +284,19 @@ def get(self, **kwargs):
         return asdict(status_and_message)
 
 
+class FlushLogs(Resource):
+    def put(self, **kwargs):
+        try:
+            status_and_message = StatusAndMessage(
+                Status.SUCCESS, f"Flushed debug log to {flush_debug_handler()}"
+            )
+        except Exception as e:
+            status_and_message = StatusAndMessage(
+                Status.FAILED, f"Failed to flush debug log: {e}"
+            )
+        return asdict(status_and_message)
+
+
 def create_app(
     test_config=None,
     RE: RunEngine = RunEngine({}),
@@ -308,6 +321,10 @@ def create_app(
         "/<string:plan_name>/<string:action>",
         resource_class_args=[runner, context],
     )
+    api.add_resource(
+        FlushLogs,
+        "/flush_debug_log",
+    )
     api.add_resource(
         StopOrStatus,
         "/<string:action>",

src/hyperion/external_interaction/callbacks/__main__.py

@@ -51,8 +51,8 @@ def setup_callbacks():
 
 def setup_logging(dev_mode: bool):
     for logger, filename in [
-        (ISPYB_LOGGER, "hyperion_ispyb_callback.txt"),
-        (NEXUS_LOGGER, "hyperion_nexus_callback.txt"),
+        (ISPYB_LOGGER, "hyperion_ispyb_callback.log"),
+        (NEXUS_LOGGER, "hyperion_nexus_callback.log"),
     ]:
         if logger.handlers == []:
             handlers = set_up_all_logging_handlers(

src/hyperion/log.py

@@ -1,10 +1,13 @@
 import logging
+from logging.handlers import TimedRotatingFileHandler
 from os import environ
 from pathlib import Path
 from typing import Optional
 
 from dodal.log import (
     ERROR_LOG_BUFFER_LINES,
+    CircularMemoryHandler,
+    DodalLogHandlers,
     integrate_bluesky_and_ophyd_logging,
     set_up_all_logging_handlers,
 )
@@ -13,6 +16,7 @@
 LOGGER = logging.getLogger("Hyperion")
 LOGGER.setLevel("DEBUG")
 LOGGER.parent = dodal_logger
+__logger_handlers: Optional[DodalLogHandlers] = None
 
 ISPYB_LOGGER = logging.getLogger("Hyperion ISPyB and Zocalo callbacks")
 ISPYB_LOGGER.setLevel(logging.DEBUG)
@@ -59,6 +63,26 @@ def do_default_logging_setup(dev_mode=False):
     integrate_bluesky_and_ophyd_logging(dodal_logger, handlers)
     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.

tests/system_tests/external_interaction/callbacks/test_external_callbacks.py

@@ -251,9 +251,9 @@ def test_remote_callbacks_write_to_dev_ispyb_for_rotation(
         )
 
     sleep(1)
-    assert isfile("tmp/dev/hyperion_ispyb_callback.txt")
+    assert isfile("tmp/dev/hyperion_ispyb_callback.log")
     ispyb_log_tail = subprocess.run(
-        ["tail", "tmp/dev/hyperion_ispyb_callback.txt"],
+        ["tail", "tmp/dev/hyperion_ispyb_callback.log"],
         timeout=1,
         stdout=subprocess.PIPE,
     ).stdout.decode("utf-8")