Feature: Add option to handle developer logs separately

octue/__init__.py

@@ -1,6 +1,9 @@
+import logging
+
 from .cli import octue_cli
 from .logging_handlers import LOG_FORMAT
 from .runner import Runner
 
 
 __all__ = "LOG_FORMAT", "octue_cli", "Runner"
+package_logger = logging.getLogger(__name__)

octue/cli.py

@@ -35,6 +35,13 @@
     show_default=True,
     help="Log level used for the analysis.",
 )
+@click.option(
+    "--show-twined-logs",
+    is_flag=True,
+    default=False,
+    show_default=True,
+    help="Show logs from the whole package in addition to logs just from your app.",
+)
 @click.option(
     "--force-reset/--no-force-reset",
     default=True,
@@ -43,7 +50,7 @@
     help="Forces a reset of analysis cache and outputs [For future use, currently not implemented]",
 )
 @click.version_option(version=pkg_resources.get_distribution("octue").version)
-def octue_cli(id, skip_checks, logger_uri, log_level, force_reset):
+def octue_cli(id, skip_checks, logger_uri, log_level, show_twined_logs, force_reset):
     """ Octue CLI, enabling a data service / digital twin to be run like a command line application.
 
     When acting in CLI mode, results are read from and written to disk (see
@@ -53,9 +60,16 @@ def octue_cli(id, skip_checks, logger_uri, log_level, force_reset):
     global_cli_context["analysis_id"] = id
     global_cli_context["skip_checks"] = skip_checks
     global_cli_context["logger_uri"] = logger_uri
+    global_cli_context["log_handler"] = None
     global_cli_context["log_level"] = log_level.upper()
+    global_cli_context["show_twined_logs"] = show_twined_logs
     global_cli_context["force_reset"] = force_reset
 
+    if global_cli_context["logger_uri"]:
+        global_cli_context["log_handler"] = get_remote_handler(
+            logger_uri=global_cli_context["logger_uri"], log_level=global_cli_context["log_level"]
+        )
+
 
 @octue_cli.command()
 @click.option(
@@ -105,19 +119,13 @@ def run(app_dir, data_dir, config_dir, input_dir, output_dir, twine):
         configuration_values=os.path.join(config_dir, VALUES_FILENAME),
         configuration_manifest=os.path.join(config_dir, MANIFEST_FILENAME),
         log_level=global_cli_context["log_level"],
+        handler=global_cli_context["log_handler"],
+        show_twined_logs=global_cli_context["show_twined_logs"],
     )
 
-    if global_cli_context["logger_uri"]:
-        handler = get_remote_handler(
-            logger_uri=global_cli_context["logger_uri"], log_level=global_cli_context["log_level"]
-        )
-    else:
-        handler = None
-
     analysis = runner.run(
         app_src=app_dir,
         analysis_id=global_cli_context["analysis_id"],
-        handler=handler,
         input_values=os.path.join(input_dir, VALUES_FILENAME),
         input_manifest=os.path.join(input_dir, MANIFEST_FILENAME),
         output_manifest_path=os.path.join(output_dir, MANIFEST_FILENAME),

octue/logging_handlers.py

@@ -4,12 +4,36 @@
 
 
 # Logging format for analysis runs. All handlers should use this logging format, to make logs consistently parseable
-LOG_FORMAT = "%(name)s %(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s"
+LOGGING_METADATA = " | ".join(("%(name)s", "%(levelname)s", "%(asctime)s", "%(module)s", "%(process)d", "%(thread)d"))
+LOG_FORMAT = "[" + LOGGING_METADATA + "]" + " %(message)s"
 
 
-def get_default_handler(log_level):
-    """ Gets a basic console handler set up for logging analyses
+def apply_log_handler(logger, handler=None, log_level=logging.INFO):
+    """ Create a logger specific to the analysis
+
+    :parameter analysis_id: The id of the analysis to get the log for. Should be unique to the analysis
+    :type analysis_id: str
+
+    :parameter handler: The handler to use. If None, default console handler will be attached.
+
+    :return: logger named in the pattern `analysis-{analysis_id}`
+    :rtype logging.Logger
     """
+    handler = handler or get_default_handler(log_level=log_level)
+    logger.addHandler(handler)
+    logger.setLevel(log_level)
+    logger.info("Using local logger.")
+
+    # Log locally that a remote logger will be used from now on.
+    if type(logger.handlers[0]).__name__ == "SocketHandler":
+        local_logger = logging.getLogger(__name__)
+        local_logger.addHandler(get_default_handler(log_level=log_level))
+        local_logger.setLevel(log_level)
+        local_logger.info(f"Logs streaming to {logger.handlers[0].host + ':' + str(logger.handlers[0].port)}")
+
+
+def get_default_handler(log_level):
+    """ Gets a basic console handler set up for logging analyses. """
     console_handler = logging.StreamHandler()
     console_handler.setLevel(log_level)
     formatter = logging.Formatter(LOG_FORMAT)
@@ -18,7 +42,7 @@ def get_default_handler(log_level):
 
 
 def get_remote_handler(logger_uri, log_level):
-    """Get a log handler for streaming logs to a remote URI accessed via HTTP or HTTPS."""
+    """ Get a log handler for streaming logs to a remote URI accessed via HTTP or HTTPS. """
     parsed_uri = urlparse(logger_uri)
 
     if parsed_uri.scheme not in {"ws", "wss"}:

octue/runner.py

@@ -3,12 +3,13 @@
 import os
 import sys
 
-from octue.logging_handlers import get_default_handler
+from octue.logging_handlers import apply_log_handler
 from octue.resources.analysis import CLASS_MAP, Analysis
 from octue.utils import gen_uuid
 from twined import Twine
 
 
+package_logger = logging.getLogger("octue")
 module_logger = logging.getLogger(__name__)
 
 
@@ -38,7 +39,13 @@ class Runner:
     """
 
     def __init__(
-        self, twine="twine.json", configuration_values=None, configuration_manifest=None, log_level=logging.INFO,
+        self,
+        twine="twine.json",
+        configuration_values=None,
+        configuration_manifest=None,
+        log_level=logging.INFO,
+        handler=None,
+        show_twined_logs=False,
     ):
         """ Constructor for the Runner class. """
 
@@ -64,33 +71,15 @@ def __init__(
 
         # Store the log level (same log level used for all analyses)
         self._log_level = log_level
+        self.handler = handler
 
-    def _get_analysis_logger(self, analysis_id, handler=None):
-        """ Create a logger specific to the analysis
-
-        :parameter analysis_id: The id of the analysis to get the log for. Should be unique to the analysis
-        :type analysis_id: str
-
-        :parameter handler: The handler to use. If None, default console handler will be attached.
-
-        :return: logger named in the pattern `analysis-{analysis_id}`
-        :rtype logging.Logger
-        """
-        handler = handler or get_default_handler(log_level=self._log_level)
-        analysis_logger = logging.getLogger(f"analysis-{analysis_id}")
-        analysis_logger.addHandler(handler)
-        analysis_logger.setLevel(self._log_level)
-
-        if type(analysis_logger.handlers[0]).__name__ == "SocketHandler":
-            local_logger = logging.getLogger(__name__)
-            local_logger.addHandler(get_default_handler(log_level=self._log_level))
-            local_logger.setLevel(self._log_level)
-            local_logger.info(
-                f"Logs streaming to {analysis_logger.handlers[0].host + ':' + str(analysis_logger.handlers[0].port)}"
+        if show_twined_logs:
+            apply_log_handler(logger=package_logger, handler=self.handler, log_level=self._log_level)
+            package_logger.info(
+                "Showing package logs as well as analysis logs (the package logs are recommended for software "
+                "engineers but may still be useful to app development by scientists."
             )
 
-        return analysis_logger
-
     @staticmethod
     def _update_manifest_path(manifest, pathname):
         """ A Quick hack to stitch the new Pathable functionality in the 0.1.4 release into the CLI and runner.
@@ -116,7 +105,6 @@ def run(
         self,
         app_src,
         analysis_id=None,
-        handler=None,
         input_values=None,
         input_manifest=None,
         credentials=None,
@@ -185,7 +173,8 @@ def run(
         )
 
         analysis_id = str(analysis_id) if analysis_id else gen_uuid()
-        analysis_logger = self._get_analysis_logger(analysis_id, handler)
+        analysis_logger = logging.getLogger(f"analysis-{analysis_id}")
+        apply_log_handler(logger=analysis_logger, handler=self.handler, log_level=self._log_level)
 
         analysis = Analysis(
             id=analysis_id,

tests/test_cli.py

@@ -59,8 +59,59 @@ def test_run_command_works_with_data_dir(self):
 
         assert CUSTOM_APP_RUN_MESSAGE in result.output
 
+    def test_package_logs_are_streamed_if_asked_For(self):
+        """ Test that logs from the main part of the package are sent to stderr if the CLI option is enabled. """
+        with tempfile.TemporaryDirectory() as temporary_directory:
+            with mock.patch("logging.StreamHandler.emit") as mock_log_handler_emit:
+                CliRunner().invoke(
+                    octue_cli,
+                    [
+                        "--show-twined-logs",
+                        "run",
+                        f"--app-dir={TESTS_DIR}",
+                        f"--twine={self.TWINE_FILE_PATH}",
+                        f'--data-dir={os.path.join(TESTS_DIR, "data", "data_dir_with_no_manifests")}',
+                        f"--output-dir={temporary_directory}",
+                    ],
+                )
+
+            mock_log_handler_emit.assert_called()
+
+            self.assertTrue(
+                any(
+                    "Showing package logs as well as analysis logs (the package logs are recommended for software "
+                    "engineers but may still be useful to app development by scientists." in arg[0][0].msg
+                    for arg in mock_log_handler_emit.call_args_list
+                )
+            )
+
+    def test_package_logs_are_not_streamed_if_not_asked_for(self):
+        """ Test that logs from the main part of the package aren't sent to stderr if the CLI option is not enabled. """
+        with tempfile.TemporaryDirectory() as temporary_directory:
+            with mock.patch("logging.StreamHandler.emit") as mock_log_handler_emit:
+                CliRunner().invoke(
+                    octue_cli,
+                    [
+                        "run",
+                        f"--app-dir={TESTS_DIR}",
+                        f"--twine={self.TWINE_FILE_PATH}",
+                        f'--data-dir={os.path.join(TESTS_DIR, "data", "data_dir_with_no_manifests")}',
+                        f"--output-dir={temporary_directory}",
+                    ],
+                )
+
+            mock_log_handler_emit.assert_called()
+
+            self.assertFalse(
+                any(
+                    "Showing package logs as well as analysis logs (the package logs are recommended for software "
+                    "engineers but may still be useful to app development by scientists." in arg[0][0].msg
+                    for arg in mock_log_handler_emit.call_args_list
+                )
+            )
+
     def test_remote_logger_uri_can_be_set(self):
-        """Test that remote logger URI can be set via the CLI and that this is logged locally."""
+        """ Test that remote logger URI can be set via the CLI and that this is logged locally. """
         with tempfile.TemporaryDirectory() as temporary_directory:
             with mock.patch("logging.StreamHandler.emit") as mock_local_logger_emit:
                 CliRunner().invoke(