Merge pull request #285 from ihmeuw/collijk/feature/add-logging-subsy…

…stem

Add logging subsystem

docs/nitpick-exceptions

@@ -7,6 +7,9 @@ py:class pandas.core.frame.DataFrame
 py:class pandas.core.series.Series
 py:class pandas.core.generic.PandasObject
 
+# loguru
+py:class loguru._logger.Logger
+
 # vivarium
 # Type aliases don't play nicely with sphinx when you import them
 # elsewhere.  Works fine for static type checker though.  I think this

docs/source/api_reference/framework/logging/index.rst

@@ -0,0 +1,7 @@
+.. automodule:: vivarium.framework.logging
+
+.. toctree::
+   :maxdepth: 2
+   :glob:
+
+   *

docs/source/api_reference/framework/logging/manager.rst

@@ -0,0 +1 @@
+.. automodule:: vivarium.framework.logging.manager

docs/source/api_reference/framework/logging/utilities.rst

@@ -0,0 +1 @@
+.. automodule:: vivarium.framework.logging.utilities

docs/source/concepts/logging.rst

@@ -0,0 +1,9 @@
+.. _logging_concept:
+
+=================
+Framework Logging
+=================
+
+.. todo::
+
+   Everything here.

src/vivarium/framework/artifact/manager.py

@@ -12,7 +12,6 @@
 from typing import Any, Sequence, Union
 
 import pandas as pd
-from loguru import logger
 
 from vivarium.config_tree import ConfigTree
 from vivarium.framework.artifact.artifact import Artifact
@@ -37,6 +36,7 @@ def name(self):
 
     def setup(self, builder):
         """Performs this component's simulation setup."""
+        self.logger = builder.logging.get_logger(self.name)
         # because not all columns are accessible via artifact filter terms, apply config filters separately
         self.config_filter_term = validate_filter_term(
             builder.configuration.input_data.artifact_filter_term
@@ -63,9 +63,9 @@ def _load_artifact(self, configuration: ConfigTree) -> Union[Artifact, None]:
             return None
         artifact_path = parse_artifact_path_config(configuration)
         base_filter_terms = get_base_filter_terms(configuration)
-        logger.debug(f"Running simulation from artifact located at {artifact_path}.")
-        logger.debug(f"Artifact base filter terms are {base_filter_terms}.")
-        logger.debug(f"Artifact additional filter terms are {self.config_filter_term}.")
+        self.logger.info(f"Running simulation from artifact located at {artifact_path}.")
+        self.logger.info(f"Artifact base filter terms are {base_filter_terms}.")
+        self.logger.info(f"Artifact additional filter terms are {self.config_filter_term}.")
         return Artifact(artifact_path, base_filter_terms)
 
     def load(self, entity_key: str, **column_filters: _Filter) -> Any:

src/vivarium/framework/engine.py

@@ -24,7 +24,6 @@
 
 import numpy as np
 import pandas as pd
-from loguru import logger
 
 from vivarium.config_tree import ConfigTree
 from vivarium.exceptions import VivariumError
@@ -34,6 +33,7 @@
 from .components import ComponentInterface
 from .event import EventInterface
 from .lifecycle import LifeCycleInterface
+from .logging import LoggingInterface
 from .lookup import LookupTableInterface
 from .metrics import Metrics
 from .plugins import PluginManager
@@ -101,8 +101,8 @@ def __init__(
         configuration: Union[Dict, ConfigTree] = None,
         plugin_configuration: Union[Dict, ConfigTree] = None,
         sim_name: str = None,
+        logging_verbosity: int = 1,
     ):
-
         self._name = self._get_context_name(sim_name)
 
         # Bootstrap phase: Parse arguments, make private managers
@@ -120,7 +120,12 @@ def __init__(
 
         self._plugin_manager = PluginManager(model_specification.plugins)
 
-        # TODO: Setup logger here.
+        self._logging = self._plugin_manager.get_plugin("logging")
+        self._logging.configure_logging(
+            simulation_name=self.name,
+            verbosity=logging_verbosity,
+        )
+        self._logger = self._logging.get_logger()
 
         self._builder = Builder(self.configuration, self._plugin_manager)
 
@@ -152,12 +157,13 @@ def __init__(
             setattr(self, f"_{name}", controller)
 
         # The order the managers are added is important.  It represents the
-        # order in which they will be set up.  The clock is required by
-        # several of the other managers, including the lifecycle manager.  The
+        # order in which they will be set up.  The logging manager and the clock are
+        # required by several of the other managers, including the lifecycle manager. The
         # lifecycle manager is also required by most managers. The randomness
         # manager requires the population manager.  The remaining managers need
         # no ordering.
         managers = [
+            self._logging,
             self._clock,
             self._lifecycle,
             self._resource,
@@ -221,7 +227,7 @@ def initialize_simulants(self):
         self._clock.step_forward()
 
     def step(self):
-        logger.debug(self._clock.time)
+        self._logger.debug(self._clock.time)
         for event in self.time_step_events:
             self._lifecycle.set_state(event)
             self.time_step_emitters[event](self._population.get_population(True).index)
@@ -236,7 +242,7 @@ def finalize(self):
         self.end_emitter(self._population.get_population(True).index)
         unused_config_keys = self.configuration.unused_keys()
         if unused_config_keys:
-            logger.debug(
+            self._logger.warning(
                 f"Some configuration keys not used during run: {unused_config_keys}."
             )
 
@@ -246,13 +252,13 @@ def report(self, print_results=True):
             self._population.get_population(True).index
         )
         if print_results:
-            logger.debug("\n" + pformat(metrics))
+            self._logger.info("\n" + pformat(metrics))
             performance_metrics = self.get_performance_metrics()
             performance_metrics = performance_metrics.to_string(
                 index=False,
                 float_format=lambda x: f"{x:.2f}",
             )
-            logger.debug("\n" + performance_metrics)
+            self._logger.info("\n" + performance_metrics)
 
         return metrics
 
@@ -293,6 +299,8 @@ class Builder:
 
     Attributes
     ----------
+    logging: LoggingInterface
+        Provides access to the :ref:`logging<logging_concept>` system.
     lookup: LookupTableInterface
         Provides access to simulant-specific data via the
         :ref:`lookup table<lookup_concept>` abstraction.
@@ -331,6 +339,9 @@ class Builder:
     def __init__(self, configuration, plugin_manager):
         self.configuration = configuration
 
+        self.logging = plugin_manager.get_plugin_interface(
+            "logging"
+        )  # type: LoggingInterface
         self.lookup = plugin_manager.get_plugin_interface(
             "lookup"
         )  # type: LookupTableInterface

src/vivarium/framework/logging/__init__.py

@@ -0,0 +1,12 @@
+"""
+=======
+Logging
+=======
+
+"""
+from vivarium.framework.logging.manager import LoggingInterface, LoggingManager
+from vivarium.framework.logging.utilities import (
+    configure_logging_to_file,
+    configure_logging_to_terminal,
+    list_loggers,
+)

src/vivarium/framework/logging/manager.py

@@ -0,0 +1,56 @@
+"""
+=====================
+The Logging Subsystem
+=====================
+
+"""
+from loguru import logger
+from loguru._logger import Logger
+
+from vivarium.framework.logging.utilities import configure_logging_to_terminal
+
+
+class LoggingManager:
+    def __init__(self):
+        self._simulation_name = None
+
+    def configure_logging(
+        self,
+        simulation_name: str,
+        verbosity: int = 0,
+        long_format: bool = True,
+    ) -> None:
+        self._simulation_name = simulation_name
+        if self._terminal_logging_not_configured():
+            configure_logging_to_terminal(verbosity=verbosity, long_format=long_format)
+
+    @staticmethod
+    def _terminal_logging_not_configured() -> bool:
+        # This hacks into the internals of loguru to see if we've already configured a
+        # terminal sink. Loguru maintains a global increment of the loggers it has generated
+        # and has a default logger configured with id 0. All code paths in this library that
+        # configure logging handlers delete the default handler with id 0, add a terminal
+        # logging handler (with id 1) and potentially have a file logging handler with id 2.
+        # This behavior is based on sequencing of the handle definition. This is a bit
+        # fragile since it depends on a loguru's internals as well as the stability of code
+        # paths in vivarium, but both are quite stable at this point, so I think it's pretty,
+        # low risk.
+        return 1 not in logger._core.handlers
+
+    @property
+    def name(self):
+        return "logging_manager"
+
+    def get_logger(self, component_name: str = None) -> Logger:
+        bind_args = {"simulation": self._simulation_name}
+        if component_name:
+            bind_args["component"] = component_name
+        return logger.bind(**bind_args)
+
+
+class LoggingInterface:
+    def __init__(self, manager: LoggingManager):
+        self._manager = manager
+
+    def get_logger(self, component_name: str = None) -> Logger:
+        return self._manager.get_logger(component_name)

src/vivarium/framework/logging/utilities.py

@@ -0,0 +1,159 @@
+"""
+=================
+Logging Utilities
+=================
+
+This module contains utilities for configuring logging.
+
+"""
+import logging
+import sys
+from pathlib import Path
+
+from loguru import logger
+
+
+def configure_logging_to_terminal(verbosity: int, long_format: bool = True) -> None:
+    """Configure logging to print to the sys.stdout.
+
+    Parameters
+    ----------
+    verbosity
+        The verbosity level of the logging. 0 logs at the WARNING level, 1 logs
+        at the INFO level, and 2 logs at the DEBUG level.
+    long_format
+        Whether to use the long format for logging messages, which includes explicit
+        information about the simulation context and component in the log messages.
+
+    """
+    _clear_default_configuration()
+    _add_logging_sink(
+        sink=sys.stdout,
+        verbosity=verbosity,
+        long_format=long_format,
+        colorize=True,
+        serialize=False,
+    )
+
+
+def configure_logging_to_file(output_directory: Path) -> None:
+    """Configure logging to write to a file in the provided output directory.
+
+    Parameters
+    ----------
+    output_directory
+        The directory to write the log file to.
+
+    """
+    log_file = output_directory / "simulation.log"
+    _add_logging_sink(
+        log_file,
+        verbosity=2,
+        long_format=True,
+        colorize=False,
+        serialize=False,
+    )
+
+
+def _clear_default_configuration():
+    try:
+        logger.remove(0)  # Clear default configuration
+    except ValueError:
+        pass
+
+
+def _add_logging_sink(
+    sink,
+    verbosity: int,
+    long_format: bool,
+    colorize: bool,
+    serialize: bool,
+) -> int:
+    """Add a logging sink to the logger.
+
+    Parameters
+    ----------
+    sink
+        The sink to add.  Can be a file path, a file object, or a callable.
+    verbosity
+        The verbosity level.  0 is the default and will only log warnings and errors.
+        1 will log info messages.  2 will log debug messages.
+    long_format
+        Whether to use the long format for logging messages.  The long format includes
+        the simulation name and component name.  The short format only includes the
+        file name and line number.
+    colorize
+        Whether to colorize the log messages.
+    serialize
+        Whether to serialize log messages.  This is useful when logging to
+        a file or a database.
+
+    """
+    log_formatter = _LogFormatter(long_format)
+    logging_level = _get_log_level(verbosity)
+    return logger.add(
+        sink,
+        colorize=colorize,
+        level=logging_level,
+        format=log_formatter.format,
+        serialize=serialize,
+    )
+
+
+class _LogFormatter:
+    time = "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green>"
+    level = "<level>{level: <8}</level>"
+    simulation = "<cyan>{extra[simulation]}</cyan> - <cyan>{name}</cyan>:<cyan>{line}</cyan>"
+    simulation_and_component = (
+        "<cyan>{extra[simulation]}</cyan>-<cyan>{extra[component]}</cyan>:<cyan>{line}</cyan>"
+    )
+    short_name_and_line = "<cyan>{name}</cyan>:<cyan>{line}</cyan>"
+    message = "<level>{message}</level>"
+
+    def __init__(self, long_format: bool = False):
+        self.long_format = long_format
+
+    def format(self, record):
+        fmt = self.time + " | "
+
+        if self.long_format:
+            fmt += self.level + " | "
+
+        if self.long_format and "simulation" in record["extra"]:
+            if "component" in record["extra"]:
+                fmt += self.simulation_and_component + " - "
+            else:
+                fmt += self.simulation + " - "
+        else:
+            fmt += self.short_name_and_line + " - "
+
+        fmt += self.message + "\n{exception}"
+        return fmt
+
+
+def _get_log_level(verbosity: int):
+    if verbosity == 0:
+        return "WARNING"
+    elif verbosity == 1:
+        return "INFO"
+    elif verbosity >= 2:
+        return "DEBUG"
+
+
+def list_loggers():
+    """Utility function for analyzing the logging environment."""
+    root_logger = logging.getLogger()
+    print("Root logger: ", root_logger)
+    for h in root_logger.handlers:
+        print(f"     %s" % h)
+
+    print("Other loggers")
+    print("=============")
+    for name, logger_ in logging.Logger.manager.loggerDict.items():
+        print("+ [%-20s] %s " % (name, logger_))
+        if not isinstance(logger_, logging.PlaceHolder):
+            handlers = list(logger_.handlers)
+            if not handlers:
+                print("     No handlers")
+            for h in logger_.handlers:
+                print("     %s" % h)