diff --git a/flepimop/gempyor_pkg/src/gempyor/logging.py b/flepimop/gempyor_pkg/src/gempyor/logging.py new file mode 100644 index 000000000..cf31bafc3 --- /dev/null +++ b/flepimop/gempyor_pkg/src/gempyor/logging.py @@ -0,0 +1,169 @@ +""" +Logging utilities for consistent script output. + +This module provides functionality for creating consistent outputs from CLI tools +provided by this package. Currently exported are: +- `ClickHandler`: Custom logging handler specifically designed for CLI output using + click. +- `get_script_logger`: Factory for creating a logger instance with a consistent style + across CLI tools. +""" + +__all__ = ["ClickHandler", "get_script_logger"] + + +import logging +import os +import sys +from typing import Any, IO + +import click + + +DEFAULT_LOG_FORMAT = "%(asctime)s:%(levelname)s:%(name)s> %(message)s" + + +class ClickHandler(logging.Handler): + """ + Custom logging handler specifically for click based CLI tools. + """ + + _punctuation = (".", ",", "?", "!", ":") + + def __init__( + self, + level: int | str = 0, + file: IO[Any] | None = None, + nl: bool = True, + err: bool = False, + color: bool | None = None, + punctuate: bool = True, + ) -> None: + """ + Initialize an instance of the click handler. + + Args: + level: The logging level to use for this handler. + file: The file to write to. Defaults to stdout. + nl: Print a newline after the message. Enabled by default. + err: Write to stderr instead of stdout. + color: Force showing or hiding colors and other styles. By default click + will remove color if the output does not look like an interactive + terminal. + punctuate: A boolean indicating if punctuation should be added to the end + of a log message provided if missing. + + Notes: + For more details on the `file`, `nl`, `err`, and `color` args please refer + to [`click.echo`](https://click.palletsprojects.com/en/8.1.x/api/#click.echo). + """ + super().__init__(level) + self._file = file + self._nl = nl + self._err = err + self._color = color + self._punctuate = punctuate + + def emit(self, record: logging.LogRecord) -> None: + """ + Emit a given log record via `click.echo` + + Args: + record: The log record to output. + + See Also: + [`logging.Handler.emit`](https://docs.python.org/3/library/logging.html#logging.Handler.emit) + """ + msg = self.format(record) + msg = f"{msg}." if self._punctuate and not msg.endswith(self._punctuation) else msg + click.echo( + message=msg, file=self._file, nl=self._nl, err=self._err, color=self._color + ) + + +def get_script_logger( + name: str, + verbosity: int, + handler: logging.Handler | None = None, + log_format: str = DEFAULT_LOG_FORMAT, +) -> logging.Logger: + """ + Create a logger for use in scripts. + + Args: + name: The name to display in the log message, useful for locating the source + of logging messages. Almost always `__name__`. + verbosity: A non-negative integer for the verbosity level. + handler: An optional logging handler to use in creating the logger returned, or + `None` to just use the `ClickHandler`. + log_format: The format to use for logged messages. Passed directly to the `fmt` + argument of [logging.Formatter](https://docs.python.org/3/library/logging.html#logging.Formatter). + + Returns: + An instance of `logging.Logger` that has the appropriate level set based on + `verbosity` and a custom handler for outputting for CLI tools. + + Examples: + >>> from gempyor.logging import get_script_logger + >>> logger = get_script_logger(__name__, 3) + >>> logger.info("This is a log info message") + 2024-10-29 16:07:20,272:INFO:__main__> This is a log info message. + """ + logger = logging.getLogger(name) + logger.setLevel(_get_logging_level(verbosity)) + handler = ClickHandler() if handler is None else handler + log_formatter = logging.Formatter(log_format) + for old_handler in logger.handlers: + logger.removeHandler(old_handler) + handler.setFormatter(log_formatter) + logger.addHandler(handler) + # pytest-dev/pytest#3697 + logger.propagate = os.path.basename(sys.argv[0]) == "pytest" if sys.argv else False + return logger + + +def _get_logging_level(verbosity: int) -> int: + """ + An internal method to convert verbosity to a logging level. + + Args: + verbosity: A non-negative integer for the verbosity level or level from + `logging` that will be returned as is. + + Examples: + >>> _get_logging_level(0) + 40 + >>> _get_logging_level(1) + 30 + >>> _get_logging_level(2) + 20 + >>> _get_logging_level(3) + 10 + >>> _get_logging_level(4) + 10 + >>> import logging + >>> _get_logging_level(logging.ERROR) == logging.ERROR + True + + Raises: + ValueError: If `verbosity` is less than zero. + + Returns: + The log level from the `logging` module corresponding to the given `verbosity`. + """ + if verbosity < 0: + raise ValueError(f"`verbosity` must be non-negative, was given '{verbosity}'.") + if verbosity in ( + logging.DEBUG, + logging.INFO, + logging.WARNING, + logging.ERROR, + logging.CRITICAL, + ): + return verbosity + verbosity_to_logging_level = { + 0: logging.ERROR, + 1: logging.WARNING, + 2: logging.INFO, + } + return verbosity_to_logging_level.get(verbosity, logging.DEBUG) diff --git a/flepimop/gempyor_pkg/src/gempyor/parameters.py b/flepimop/gempyor_pkg/src/gempyor/parameters.py index 7ab0de151..ce312c9a3 100644 --- a/flepimop/gempyor_pkg/src/gempyor/parameters.py +++ b/flepimop/gempyor_pkg/src/gempyor/parameters.py @@ -84,7 +84,8 @@ def __init__( self.npar = len(self.pnames) if self.npar != len(set([name.lower() for name in self.pnames])): raise ValueError( - "Parameters of the SEIR model have the same name (remember that case is not sufficient!)" + "Parameters of the SEIR model have the same " + "name (remember that case is not sufficient!)" ) # Attributes of dictionary @@ -128,16 +129,18 @@ def __init__( print("loaded dates:", df.index) raise ValueError( f"Issue loading file '{fn_name}' for parameter '{pn}': " - f"Provided file dates span '{str(df.index[0])}' to '{str(df.index[-1])}', " - f"but the config dates span '{ti}' to '{tf}'." + f"Provided file dates span '{str(df.index[0])}' to " + f"'{str(df.index[-1])}', but the config dates " + f"span '{ti}' to '{tf}'." ) if not (pd.date_range(ti, tf) == df.index).all(): print("config dates:", pd.date_range(ti, tf)) print("loaded dates:", df.index) raise ValueError( f"Issue loading file '{fn_name}' for parameter '{pn}': " - f"Provided file dates span '{str(df.index[0])}' to '{str(df.index[-1])}', " - f"but the config dates span '{ti}' to '{tf}'." + f"Provided file dates span '{str(df.index[0])}' to " + f"'{str(df.index[-1])}', but the config dates " + f"span '{ti}' to '{tf}'." ) self.pdata[pn]["ts"] = df @@ -148,7 +151,8 @@ def __init__( else: self.pdata[pn]["stacked_modifier_method"] = "product" logging.debug( - f"No 'stacked_modifier_method' for parameter {pn}, assuming multiplicative NPIs" + f"No 'stacked_modifier_method' for parameter {pn}, " + "assuming multiplicative NPIs." ) if self.pconfig[pn]["rolling_mean_windows"].exists(): @@ -165,32 +169,6 @@ def __init__( logging.debug(f"Index in arrays are: {self.pnames2pindex}") logging.debug(f"NPI overlap operation is {self.stacked_modifier_method} ") - def picklable_lamda_alpha(self): - """ - Read the `alpha_val` attribute. - - This defunct method returns the `alpha_val` attribute of this class which is - never set by this class. If this method is called and the `alpha_val` attribute - is not set an AttributeError will be raised. - - Returns: - The `alpha_val` attribute. - """ - return self.alpha_val - - def picklable_lamda_sigma(self): - """ - Read the `sigma_val` attribute. - - This defunct method returns the `sigma_val` attribute of this class which is - never set by this class. If this method is called and the `sigma_val` attribute - is not set an AttributeError will be raised. - - Returns: - The `sigma_val` attribute. - """ - return self.sigma_val - def get_pnames2pindex(self) -> dict: """ Read the `pnames2pindex` attribute. @@ -235,7 +213,8 @@ class via `subpop_names`. else: param_arr[idx] = self.pdata[pn]["ts"].values - return param_arr # we don't store it as a member because this object needs to be small to be pickable + # we don't store it as a member because this object needs to be small to be pickable + return param_arr def parameters_load( self, param_df: pd.DataFrame, n_days: int, nsubpops: int @@ -275,7 +254,8 @@ def parameters_load( param_arr[idx] = self.pdata[pn]["ts"].values else: print( - f"PARAM: parameter {pn} NOT found in loadID file. Drawing from config distribution" + f"PARAM: parameter {pn} NOT found in loadID file. " + "Drawing from config distribution" ) pval = self.pdata[pn]["dist"]() param_arr[idx] = np.full((n_days, nsubpops), pval) diff --git a/flepimop/gempyor_pkg/src/gempyor/shared_cli.py b/flepimop/gempyor_pkg/src/gempyor/shared_cli.py index ef278b6c9..a8554fc01 100644 --- a/flepimop/gempyor_pkg/src/gempyor/shared_cli.py +++ b/flepimop/gempyor_pkg/src/gempyor/shared_cli.py @@ -9,13 +9,14 @@ import multiprocessing import pathlib -from typing import Any, Callable, Literal +from typing import Any, Callable import warnings import click import confuse -from .utils import as_list, config +from .logging import get_script_logger +from .utils import config, as_list @click.group() @@ -277,3 +278,51 @@ def _parse_option(param: click.Parameter, value: Any) -> Any: cfg[option] = _parse_option(config_file_options[option], value) return cfg + + +def log_cli_inputs(kwargs: dict[str, Any], verbosity: int | None = None) -> None: + """ + Log CLI inputs for user debugging. + + This function only logs debug messages so the verbosity has to be set quite high + to see the output of this function. + + Args: + kwargs: The CLI arguments given as a dictionary of key word arguments. + verbosity: The verbosity level of the CLI tool being used or `None` to infer + from the given `kwargs`. + + Examples: + >>> from gempyor.shared_cli import log_cli_inputs + >>> log_cli_inputs({"abc": 123, "def": True}, 3) + 2024-11-05 09:27:58,884:DEBUG:gempyor.shared_cli> CLI was given 2 arguments: + 2024-11-05 09:27:58,885:DEBUG:gempyor.shared_cli> abc = 123. + 2024-11-05 09:27:58,885:DEBUG:gempyor.shared_cli> def = True. + >>> log_cli_inputs({"abc": 123, "def": True}, 2) + >>> from pathlib import Path + >>> kwargs = { + ... "input_file": Path("config.in"), + ... "stochastic": True, + ... "cluster": "longleaf", + ... "verbosity": 3, + ... } + >>> log_cli_inputs(kwargs) + 2024-11-05 09:29:21,666:DEBUG:gempyor.shared_cli> CLI was given 4 arguments: + 2024-11-05 09:29:21,667:DEBUG:gempyor.shared_cli> input_file = /Users/twillard/Desktop/GitHub/HopkinsIDD/flepiMoP/flepimop/gempyor_pkg/config.in. + 2024-11-05 09:29:21,667:DEBUG:gempyor.shared_cli> stochastic = True. + 2024-11-05 09:29:21,668:DEBUG:gempyor.shared_cli> cluster = longleaf. + 2024-11-05 09:29:21,668:DEBUG:gempyor.shared_cli> verbosity = 3. + """ + verbosity = kwargs.get("verbosity") if verbosity is None else verbosity + if verbosity is None: + return + logger = get_script_logger(__name__, verbosity) + longest_key = -1 + total_keys = 0 + for k, _ in kwargs.items(): + longest_key = len(k) if len(k) > longest_key else longest_key + total_keys += 1 + logger.debug("CLI was given %u arguments:", total_keys) + for k, v in kwargs.items(): + v = v.absolute() if isinstance(v, pathlib.Path) else v + logger.debug("%s = %s", k.ljust(longest_key, " "), v) diff --git a/flepimop/gempyor_pkg/tests/logging/test__get_logging_level.py b/flepimop/gempyor_pkg/tests/logging/test__get_logging_level.py new file mode 100644 index 000000000..67480442c --- /dev/null +++ b/flepimop/gempyor_pkg/tests/logging/test__get_logging_level.py @@ -0,0 +1,32 @@ +import logging + +import pytest + +from gempyor.logging import _get_logging_level + + +@pytest.mark.parametrize("verbosity", (-1, -100)) +def test__get_logging_level_negative_verbosity_value_error(verbosity: int) -> None: + with pytest.raises( + ValueError, match=f"`verbosity` must be non-negative, was given '{verbosity}'." + ): + _get_logging_level(verbosity) + + +@pytest.mark.parametrize( + ("verbosity", "expected_level"), + ( + (logging.ERROR, logging.ERROR), + (logging.WARNING, logging.WARNING), + (logging.INFO, logging.INFO), + (logging.DEBUG, logging.DEBUG), + (0, logging.ERROR), + (1, logging.WARNING), + (2, logging.INFO), + (3, logging.DEBUG), + (4, logging.DEBUG), + (5, logging.DEBUG), + ), +) +def test__get_logging_level_output_validation(verbosity: int, expected_level: int) -> None: + assert _get_logging_level(verbosity) == expected_level diff --git a/flepimop/gempyor_pkg/tests/logging/test_click_handler_class.py b/flepimop/gempyor_pkg/tests/logging/test_click_handler_class.py new file mode 100644 index 000000000..983acba8a --- /dev/null +++ b/flepimop/gempyor_pkg/tests/logging/test_click_handler_class.py @@ -0,0 +1,71 @@ +import io +import logging +from typing import Any, IO + +import pytest + +from gempyor.logging import ClickHandler + + +@pytest.mark.parametrize( + "level", + (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL), +) +@pytest.mark.parametrize("file", (None, io.StringIO)) +@pytest.mark.parametrize("nl", (True, False)) +@pytest.mark.parametrize("err", (False, True)) +@pytest.mark.parametrize("color", (None, False)) +@pytest.mark.parametrize("punctuate", (True, False)) +def test_click_handler_init( + level: int | str, + file: IO[Any] | None, + nl: bool, + err: bool, + color: bool | None, + punctuate: bool, +) -> None: + handler = ClickHandler( + level=level, file=file, nl=nl, err=err, color=color, punctuate=punctuate + ) + assert handler.level == level + assert handler._file == file + assert handler._nl == nl + assert handler._err == err + assert handler._color == color + assert handler._punctuate == punctuate + + +@pytest.mark.parametrize("punctuate", (True, False)) +@pytest.mark.parametrize( + "msg", + ( + "This is a message", + "Another message.", + "Start to a list:", + "Middle of a sentence,", + "Oh-no!", + "Question?", + ), +) +def test_click_handler_punctuation_formatting(punctuate: bool, msg: str) -> None: + buffer = io.StringIO() + handler = ClickHandler(level=logging.DEBUG, file=buffer, punctuate=punctuate) + log_record = logging.LogRecord( + name="", + level=logging.DEBUG, + pathname="", + lineno=1, + msg=msg, + args=None, + exc_info=None, + ) + handler.emit(log_record) + buffer.seek(0) + handler_msg = buffer.getvalue() + if not punctuate: + assert handler_msg == msg + "\n" + else: + assert ( + handler_msg + == (msg if msg.endswith(ClickHandler._punctuation) else f"{msg}.") + "\n" + ) diff --git a/flepimop/gempyor_pkg/tests/logging/test_get_script_logger.py b/flepimop/gempyor_pkg/tests/logging/test_get_script_logger.py new file mode 100644 index 000000000..b96e69cb7 --- /dev/null +++ b/flepimop/gempyor_pkg/tests/logging/test_get_script_logger.py @@ -0,0 +1,67 @@ +import logging +import random +import string + +import pytest + +from gempyor.logging import _get_logging_level, get_script_logger, DEFAULT_LOG_FORMAT + + +@pytest.mark.parametrize("name", ("foobar", "fizzbuzz")) +@pytest.mark.parametrize( + "verbosity", + ( + 0, + 1, + 2, + 3, + 4, + logging.CRITICAL, + logging.ERROR, + logging.WARNING, + logging.INFO, + logging.DEBUG, + ), +) +@pytest.mark.parametrize("handler", (None, logging.StreamHandler())) +@pytest.mark.parametrize("log_format", (None, "%(message)s")) +def test_get_script_logger( + caplog: pytest.LogCaptureFixture, + name: str, + verbosity: int, + handler: logging.Handler | None, + log_format: str | None, +) -> None: + caplog.set_level(logging.DEBUG, logger=name) + + if log_format is None: + logger = get_script_logger(name, verbosity, handler=handler) + else: + logger = get_script_logger(name, verbosity, handler=handler, log_format=log_format) + + assert isinstance(logger, logging.Logger) + assert logger.name == name + assert logger.level == _get_logging_level(verbosity) + if handler is not None: + assert len(logger.handlers) == 1 + assert logger.handlers[0] == handler + assert logger.handlers[0].formatter._fmt == ( + log_format if log_format else DEFAULT_LOG_FORMAT + ) + + i = 0 + for val, lvl in [ + (10, "debug"), + (20, "info"), + (30, "warning"), + (40, "error"), + (50, "critical"), + ]: + msg = "".join(random.choice(string.ascii_letters) for _ in range(20)) + getattr(logger, lvl)(msg) + if val < _get_logging_level(verbosity): + assert len(caplog.records) == i + continue + assert caplog.records[i].levelno == val + assert caplog.records[i].message == msg + i += 1 diff --git a/flepimop/gempyor_pkg/tests/parameters/test_parameters_class.py b/flepimop/gempyor_pkg/tests/parameters/test_parameters_class.py index 9801a6193..a7fd6c3b0 100644 --- a/flepimop/gempyor_pkg/tests/parameters/test_parameters_class.py +++ b/flepimop/gempyor_pkg/tests/parameters/test_parameters_class.py @@ -8,7 +8,6 @@ import numpy as np import pandas as pd import pytest -from tempfile import NamedTemporaryFile from gempyor.parameters import Parameters from gempyor.testing import ( @@ -238,7 +237,8 @@ def test_timeseries_parameter_has_insufficient_columns_value_error( ValueError, match=( rf"^Issue loading file '{tmp_file}' for parameter 'sigma': " - rf"the number of non-'date' columns is '{actual_columns}', expected '{mock_inputs.number_of_subpops()}' " + rf"the number of non-'date' columns is '{actual_columns}', expected " + rf"'{mock_inputs.number_of_subpops()}' " rf"\(number of subpopulations\) or one\.$" ), ): @@ -283,7 +283,8 @@ def test_timeseries_parameter_has_insufficient_dates_value_error( ValueError, match=( f"Issue loading file '{tmp_file}' for parameter 'sigma': " - f"Provided file dates span '{timeseries_start_date}( 00:00:00)?' to '{timeseries_end_date}( 00:00:00)?', " + f"Provided file dates span '{timeseries_start_date}( 00:00:00)?' to " + rf"'{timeseries_end_date}( 00:00:00)?', " f"but the config dates span '{mock_inputs.ti}' to '{mock_inputs.tf}'.$" ), ): @@ -374,58 +375,6 @@ def test_parameters_instance_attributes( expected_stacked_modifier_method[modifier_type].append(param_name.lower()) assert params.stacked_modifier_method == expected_stacked_modifier_method - @pytest.mark.parametrize( - "factory,alpha_val", - [ - (fixed_three_valid_parameter_factory, None), - (fixed_three_valid_parameter_factory, 123), - (valid_parameters_factory, "abc"), - ], - ) - def test_picklable_lamda_alpha( - self, - tmp_path: pathlib.Path, - factory: Callable[[pathlib.Path], MockParametersInput], - alpha_val: Any, - ) -> None: - # Setup - mock_inputs = factory(tmp_path) - params = mock_inputs.create_parameters_instance() - - # Attribute error if `alpha_val` is not set - with pytest.raises(AttributeError): - params.picklable_lamda_alpha() - - # We get the expected value when `alpha_val` is set - params.alpha_val = alpha_val - assert params.picklable_lamda_alpha() == alpha_val - - @pytest.mark.parametrize( - "factory,sigma_val", - [ - (fixed_three_valid_parameter_factory, None), - (fixed_three_valid_parameter_factory, 123), - (valid_parameters_factory, "abc"), - ], - ) - def test_picklable_lamda_sigma( - self, - tmp_path: pathlib.Path, - factory: Callable[[pathlib.Path], MockParametersInput], - sigma_val: Any, - ) -> None: - # Setup - mock_inputs = factory(tmp_path) - params = mock_inputs.create_parameters_instance() - - # Attribute error if `sigma_val` is not set - with pytest.raises(AttributeError): - params.picklable_lamda_sigma() - - # We get the expected value when `sigma_val` is set - params.sigma_val = sigma_val - assert params.picklable_lamda_sigma() == sigma_val - @pytest.mark.parametrize( "factory", [ diff --git a/flepimop/gempyor_pkg/tests/shared_cli/test_log_cli_inputs.py b/flepimop/gempyor_pkg/tests/shared_cli/test_log_cli_inputs.py new file mode 100644 index 000000000..1693a5733 --- /dev/null +++ b/flepimop/gempyor_pkg/tests/shared_cli/test_log_cli_inputs.py @@ -0,0 +1,34 @@ +import logging +from pathlib import Path +from typing import Any + +import pytest + +from gempyor.logging import _get_logging_level +from gempyor.shared_cli import log_cli_inputs + + +@pytest.mark.parametrize( + "kwargs", + ( + {"abc": 123}, + {"abc": 123, "verbosity": 3}, + {"str": "foobar", "int": 123, "float": 3.14, "bool": True}, + {"str": "foobar", "int": 123, "float": 3.14, "bool": True, "verbosity": 3}, + {"file_path": Path("fizzbuzz.log")}, + {"file_path": Path("fizzbuzz.log"), "verbosity": 3}, + ), +) +@pytest.mark.parametrize("verbosity", (None, 0, 1, 2, 3, logging.DEBUG, logging.INFO)) +def test_number_of_messages( + caplog: pytest.LogCaptureFixture, kwargs: dict[str, Any], verbosity: int | None +) -> None: + log_cli_inputs(kwargs, verbosity=verbosity) + assert len(caplog.records) == ( + len(kwargs) + 1 + if _get_logging_level( + kwargs.get("verbosity", 0) if verbosity is None else verbosity + ) + <= logging.DEBUG + else 0 + )