diff --git a/octue/__init__.py b/octue/__init__.py index 304b19364..4b9866656 100644 --- a/octue/__init__.py +++ b/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__) diff --git a/octue/cli.py b/octue/cli.py index 2b4e95e78..37faac801 100644 --- a/octue/cli.py +++ b/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), diff --git a/octue/logging_handlers.py b/octue/logging_handlers.py index 96697f3b3..a0c7430f6 100644 --- a/octue/logging_handlers.py +++ b/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"}: diff --git a/octue/runner.py b/octue/runner.py index 1565cdbff..374e72bf3 100644 --- a/octue/runner.py +++ b/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, diff --git a/tests/test_cli.py b/tests/test_cli.py index 1a1fe18e9..d90d1a518 100644 --- a/tests/test_cli.py +++ b/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(