Merge branch '756-update-debug-mode' into 'v3'

Debug flag

Closes #756

See merge request openflexure/openflexure-microscope-server!615

README.md

@@ -25,7 +25,7 @@ More information is also available in the [handbook](https://gitlab.com/openflex
 
 ## Running directly
 
-The Python package provides a command `ofm-microscope-server` that runs the server. This is what is used by `systemd` to run the service. You will need to provide some command-line arguments, see the output of `--help` for an up to date list. See `/etc/systemd/system/openflexure-microscope-server.service` for the command line used to run the server by default on the  Raspberry Pi. In general, you are likely to want to specify a configuration file with `-c`, a host (`--host 0.0.0.0` to serve on all addresses) and a port (`--port 5000`). The `--fallback` option will allow the server to start *even if the hardware specified in the configuration file can't load*. This serves an error page, rather than have the server fail. In the future, it should redirect users to a way to fix their configuration.
+The Python package provides a command `ofm-microscope-server` that runs the server. This is what is used by `systemd` to run the service. You will need to provide some command-line arguments, see the output of `--help` for an up to date list. See `/etc/systemd/system/openflexure-microscope-server.service` for the command line used to run the server by default on the  Raspberry Pi. In general, you are likely to want to specify a configuration file with `-c`, a host (`--host 0.0.0.0` to serve on all addresses) and a port (`--port 5000`). The `--fallback` option will allow the server to start *even if the hardware specified in the configuration file can't load*. This serves an error page, rather than have the server fail. In the future, it should redirect users to a way to fix their configuration. The `--debug` option spins up both the OpenFlexure Microscope server and the LabThings server in `DEBUG` mode, providing more verbose logging information.
 
 It is also possible to run the server in simulation mode. See Developer guidelines below.
 

apidocs/dev/README.md

@@ -71,6 +71,8 @@ sudo -u openflexure-ws application/openflexure-microscope-server/.venv/bin/openf
 
 ```
 
+> Note: If you would like more detailed logging information from both the OpenFlexure Microscope server and the LabThings server, you can add the `--debug` argument to the end of the above command to activate `DEBUG` level logs.
+
 ### Running the simulation server on other platforms
 
 To start the simulation server:
@@ -81,6 +83,8 @@ To start the simulation server:
 
 `openflexure-microscope-server --fallback -c ./ofm_config_simulation.json`
 
+> Note: If you would like more detailed logging information from both the OpenFlexure Microscope server and the LabThings server, you can add the `--debug` argument to the end of the above command to activate `DEBUG` level logs.
+
 * Open the address displayed in the terminal in any browser.
 * To close the simulation server, return to the terminal and press `ctrl + c`.
 

apidocs/dev/simulation_guide.md

@@ -27,6 +27,8 @@ The simulation server GUI is a copy of the GUI you would find on the hardware wi
 
 This can fail with an error that the chosen port is already in use. In that case, append `--port 8081`
 
+> Note: If you would like more detailed logging information from both the OpenFlexure Microscope server and the LabThings server, you can add the `--debug` argument to the end of the above command to activate `DEBUG` level logs.
+
 ---
 
 ## Video Walkthrough

src/openflexure_microscope_server/logging.py

@@ -23,17 +23,26 @@ LOGGER = logging.getLogger(__name__)
 OFM_LOG_FILE: Optional[str] = None
 
 
-def configure_logging(log_folder: str) -> None:
+def configure_logging(log_folder: str, debug: bool = False) -> None:
     """Configure logging for the server while it is running.
 
-    This modifies the root logger to have a rotating file handler and
+    Params:
+    - log_folder: This modifies the root logger to have a rotating file handler and
     adds a custom handler that prints and stores all records except
     ``uvicorn.access`` logs.
+    - debug: This modifies the root logger to change its logging level. It is
+    set to True by starting the server with the cli argument ``--debug``.
 
     It is important not to let Uvicorn override these settings.
+
     """
     root_logger = logging.getLogger()
-    root_logger.setLevel(logging.INFO)
+
+    if debug:
+        root_logger.setLevel(logging.DEBUG)
+    else:
+        root_logger.setLevel(logging.INFO)
+
     # Explicitly make OFM_LOG_FILE a global so it can be updated based on log settings
     # This requires silencing PLW0603 which disallows globals.
     global OFM_LOG_FILE  # noqa: PLW0603
@@ -44,6 +53,7 @@ def configure_logging(log_folder: str) -> None:
     ofm_format_str = "[%(asctime)s] [%(levelname)s] %(message)s"
     OFM_HANDLER.setFormatter(logging.Formatter(ofm_format_str))
     OFM_HANDLER.addFilter(UvicornAccessFilter())
+    OFM_HANDLER.level = root_logger.level
     root_logger.addHandler(OFM_HANDLER)
 
     try:
@@ -63,7 +73,10 @@ def configure_logging(log_folder: str) -> None:
     except PermissionError as e:
         LOGGER.error(f"Cannot create log file at {OFM_LOG_FILE}: {e}")
 
-    LOGGER.info("OFM server root logger has been set up at INFO level")
+    LOGGER.info(
+        "OFM server root logger has been set up at %s level",
+        logging.getLevelName(root_logger.level),
+    )
 
 
 def retrieve_log() -> PlainTextResponse:

src/openflexure_microscope_server/server/__init__.py

@@ -72,7 +72,7 @@ def set_shutdown_function(shutdown_function: Callable[[], None]) -> None:
 
 
 def customise_server(
-    server: lt.ThingServer, application_config: OFMApplicationData, debug: bool = False
+    server: lt.ThingServer, application_config: OFMApplicationData
 ) -> None:
     """Customise the server with additional endpoints, debug mode etc."""
     if DEVELOPER_MODE:
@@ -88,10 +88,6 @@ def customise_server(
     add_v2_endpoints(server)
     add_static_files(server, application_config.data_folder)
 
-    # Configure logging to DEBUG if requested in CLI args.
-    if debug:
-        lt.logs.configure_thing_logger(logging.DEBUG)
-
     # Add an endpoint to get the logs - (directly calling the FastAPI decorator)
     server.app.get(str(server.api_prefix.rstrip("/")) + "/log/")(retrieve_log)
     server.app.get(str(server.api_prefix.rstrip("/")) + "/logfile/")(
@@ -113,15 +109,15 @@ def serve_from_cli(argv: Optional[list[str]] = None) -> None:
     server = None
     try:
         lt_config = _full_config_from_args(args)
+        debug = bool(args.debug)
         # Validate our application data
         if lt_config.application_config is None:
             raise ValueError("No application configuration was supplied.")
         application_config = OFMApplicationData(**lt_config.application_config)
-        configure_logging(application_config.log_folder)
+        configure_logging(application_config.log_folder, debug)
 
-        server = lt.ThingServer.from_config(lt_config)
+        server = lt.ThingServer.from_config(lt_config, debug)
-        debug = bool(args.debug)
+        customise_server(server, application_config)
-        customise_server(server, application_config, debug)
 
         def shutdown_call() -> None:
             try:

tests/unit_tests/test_logging.py

@@ -206,3 +206,31 @@ def test_uvicorn_error_only_says_error_on_error(
             assert name in log_txt
         for name in names_not_in_log:
             assert name not in log_txt
+
+
+@pytest.mark.parametrize(
+    ("debug_flag", "expected_level"),
+    [
+        (False, logging.INFO),
+        (True, logging.DEBUG),
+    ],
+)
+def test_configure_logging_debug_mode(debug_flag, expected_level):
+    """Check that debug flag sets the correct root and handler logging levels."""
+    # Reset handler at start of test
+    ofm_logging.OFM_HANDLER = ofm_logging.OFMHandler()
+
+    with tmp_logging_dir() as tmpdir:
+        # Run configuration with the parameterised debug flag
+        ofm_logging.configure_logging(tmpdir, debug=debug_flag)
+
+        root_logger = logging.getLogger()
+
+        # Assert the root logger level was set correctly
+        assert root_logger.level == expected_level
+        # Assert the custom OFM handler level was synced to the root logger
+        assert ofm_logging.OFM_HANDLER.level == expected_level
+
+        # Cleanup: Remove the OFM_HANDLER from the root logger so it doesn't
+        # interfere with other tests in the suite.
+        root_logger.removeHandler(ofm_logging.OFM_HANDLER)

tests/unit_tests/test_server_cli.py

@@ -112,35 +112,35 @@ def test_failed_customise(mocker):
 
 def test_debug_mode(mocker):
     """Test that --debug flag triggers lt.logs.configure_thing_logger."""
-    # Mock the LabThings function that returns the server
+    # Mock the LabThings server creation so we can inspect its arguments
-    mocker.patch(
+    mock_from_config = mocker.patch(
         "openflexure_microscope_server.server.lt.ThingServer.from_config",
         return_value=mocker.Mock(),
     )
-    # Mock customisation dependencies to avoid side effects
-    mocker.patch.object(ofm_server, "add_v2_endpoints")
-    mocker.patch.object(ofm_server, "add_static_files")
-    # Mock logging to avoid side effects and allow checking calls
-    mocker.patch.object(ofm_server, "configure_logging")
-    mocker.patch.object(ofm_server, "retrieve_log")
-    mocker.patch.object(ofm_server, "retrieve_log_from_file")
-    # Mock uvicorn.run to avoid starting a server
-    mocker.patch("openflexure_microscope_server.server.uvicorn.run")
 
-    # Mock the target function
+    # Mock configure_logging to inspect its arguments and prevent side effects
-    mock_configure_thing_logger = mocker.patch(
+    mock_configure_logging = mocker.patch.object(ofm_server, "configure_logging")
-        "openflexure_microscope_server.server.lt.logs.configure_thing_logger"
+
-    )
+    # Mock other dependencies to avoid side effects (file writing, server starting)
+    mocker.patch.object(ofm_server, "customise_server")
+    mocker.patch("openflexure_microscope_server.server.uvicorn.run")
 
     # 1. Run with --debug
     ofm_server.serve_from_cli(["-c", SIM_CONFIG, "--debug"])
 
-    # Verify it was called with DEBUG level
+    # Verify configure_logging was called with debug=True (the second argument)
-    mock_configure_thing_logger.assert_called_once_with(logging.DEBUG)
+    assert mock_configure_logging.call_args.args[1] is True
+    # Verify ThingServer.from_config was called with debug=True (the second argument)
+    assert mock_from_config.call_args.args[1] is True
+
+    # Reset the mocks for the next run
+    mock_configure_logging.reset_mock()
+    mock_from_config.reset_mock()
 
     # 2. Run without --debug
-    mock_configure_thing_logger.reset_mock()
     ofm_server.serve_from_cli(["-c", SIM_CONFIG])
 
-    # Verify it was NOT called
+    # Verify configure_logging was called with debug=False
-    mock_configure_thing_logger.assert_not_called()
+    assert mock_configure_logging.call_args.args[1] is False
+    # Verify ThingServer.from_config was called with debug=False
+    assert mock_from_config.call_args.args[1] is False

webapp/src/components/tabContentComponents/loggingContent.vue

@@ -121,7 +121,7 @@ export default {
     ...mapState(useSettingsStore, ["baseUri"]),
     filteredLevels: function () {
       let cutoffIndex = this.allLevels.indexOf(this.filterLevel);
-      return this.allLevels.slice(cutoffIndex, -1);
+      return this.allLevels.slice(cutoffIndex);
     },
     filteredItems: function () {
       var items = [];