Start richer logging

logging_tutorial.rst

@@ -0,0 +1,99 @@
+Logging tutorial
+================
+
+While running the model, it is sometimes useful to monitor the progress
+of certain characteristics across time. This can be used, for instance,
+when debugging or to verify that a recent change has had the desired behaviour.
+
+This can be achieved by modifying the ``LOGGING`` section of the configuration
+that is passed to the simulation tool.
+
+Logging configuration
+---------------------
+**TODO:** Explain the basic options (directory, prefix, level)
+
+Specifying what to log
+----------------------
+By default, no variables are logged. To control which variables will be included,
+list them under the ``column`` key in the logging configuration.
+
+For example, the following configuration will print the values of the ``age``
+and ``sex`` columns for the whole population at every time step:
+
+.. code-block:: yaml
+   :caption: Basic logging configuration
+
+    LOGGING:
+        log_directory: log
+        logfile_prefix: hivpy
+        log_file_level: DEBUG
+        console_log_level: WARNING
+        columns: [age, sex]
+
+If any of the columns are not recognised (because of a misspelling, for example),
+the log will display a warning at the start of the simulation, but the simulation
+will run as normal (with that column name ignored in the log output).
+
+Selecting a subpopulation
+-------------------------
+Instead of showing values for the whole population, you can select a subset to monitor.
+This can be done with the ``if`` key and by providing the criteria for selecting
+the subset of interest.
+
+For example, this configuration will only log values for female individuals:
+
+.. code-block:: yaml
+   :caption: Selecting by a single variable
+
+    LOGGING:
+        log_directory: log
+        logfile_prefix: hivpy
+        log_file_level: DEBUG
+        console_log_level: WARNING
+        columns: [age, sex]
+        if:
+            sex: female
+
+
+Multiple variables can be specified at the same time by providing more keys to ``if``.
+For instance, to select male, HIV- individuals:
+
+.. code-block:: yaml
+   :caption: Selecting by multiple variable
+
+    LOGGING:
+        log_directory: log
+        logfile_prefix: hivpy
+        log_file_level: DEBUG
+        console_log_level: WARNING
+        columns: [age, sex]
+        if:
+            sex: male
+            hiv: False
+
+
+The examples so far have been matching on exact values (such as ``female`` or ``False``),
+but often we want to match a range of values, particularly for numerical variables.
+To do this, use one of these special keys:
+
+* ``eq``: equal to the value provided
+* ``lt``: less than the value provided
+* ``gt``: greater than the value provided
+* ``lte``, ``gte``: as above but also allowing equality
+
+
+The configuration below selects female, HIV+ individuals between 23 and 30 years old
+(both inclusive):
+
+.. code-block:: yaml
+   :caption: More complex criteria
+
+    LOGGING:
+        # (the other configuration keys are omitted for brevity) 
+        if:
+            sex: female
+            hiv: True
+            age:
+                gte: 23
+                lte: 30
+

src/hivpy/config.py

@@ -1,19 +1,9 @@
-import logging
 from dataclasses import dataclass
 from datetime import date, timedelta
-from os import path
 from pathlib import Path
 
 from .exceptions import SimulationException
 
-LEVELS = {
-    'DEBUG': logging.DEBUG,
-    'INFO': logging.INFO,
-    'WARNING': logging.WARNING,
-    'ERROR': logging.ERROR,
-    'CRITICAL': logging.CRITICAL
-}
-
 
 @dataclass
 class LoggingConfig:
@@ -24,25 +14,6 @@ class LoggingConfig:
     fileLogging: bool = True
     fileLogLevel: str = 'DEBUG'
 
-    def start_logging(self):
-        # file logging
-        file = path.join(self.log_dir, self.logfile)
-        logging.root.setLevel(logging.DEBUG)
-        file_logger = logging.FileHandler(file, 'w')
-        file_formatter = logging.Formatter('%(asctime)s %(name)-15s %(levelname)-10s %(message)s',
-                                           datefmt='%y-%d-%m %H:%M:%S')
-        file_logger.setFormatter(file_formatter)
-        file_logger.setLevel(self.fileLogLevel)
-        logging.getLogger(name=None).addHandler(file_logger)
-        # console logging
-        console_logger = logging.StreamHandler()
-        console_formatter = logging.Formatter('%(name)-15s %(levelname)-10s %(message)s')
-        console_logger.setFormatter(console_formatter)
-        console_logger.setLevel(self.consoleLogLevel)
-        logging.getLogger(name=None).addHandler(console_logger)
-
-        print("Starting the simulation. Please, consult the logfile at "+self.logfile)
-
 
 @dataclass
 class SimulationConfig:

src/hivpy/demographics.py

@@ -1,5 +1,4 @@
 import importlib.resources
-import logging
 from math import exp
 
 import numpy as np
@@ -10,6 +9,7 @@
 from hivpy.common import SexType, rng
 from hivpy.demographics_data import DemographicsData
 from hivpy.exceptions import SimulationException
+from hivpy.logging import get_logger
 
 SexDType = pd.CategoricalDtype(iter(SexType))
 
@@ -117,9 +117,9 @@ def __init__(self, min_age, max_age, modelParams):
         self.min_age = min_age
         model_age_limit = -modelParams[1]/modelParams[0]
         if (max_age > model_age_limit):
-            logging.getLogger("Demographics").warning(f"Max age exceeds the maximum age limit for "
-                                                      f"this model (negative probability). "
-                                                      f"Adjusting max age to {model_age_limit}")
+            get_logger("Demographics").warning(f"Max age exceeds the maximum age limit for "
+                                               f"this model (negative probability). "
+                                               f"Adjusting max age to {model_age_limit}")
             self.max_age = model_age_limit
         else:
             self.max_age = max_age

src/hivpy/experiment.py

@@ -7,6 +7,7 @@
 
 from .config import ExperimentConfig, LoggingConfig, SimulationConfig
 from .exceptions import OutputException
+from .logging import start_logging
 from .simulation import SimulationHandler
 
 
@@ -88,13 +89,13 @@ def create_experiment(all_params):
     return ExperimentConfig(simulation_config, logging_config)
 
 
-def run_experiment(experiment_config):
+def run_experiment(experiment_config: ExperimentConfig):
     """Run an entire experiment.
 
     An experiment can consist of one or more simulation runs,
     as well as processing steps after those are completed.
     """
-    experiment_config.logging_config.start_logging()
+    start_logging(experiment_config.logging_config)
     simulation_handler = SimulationHandler(experiment_config.simulation_config)
     simulation_handler.run()
     return (simulation_handler.population)

src/hivpy/logging.py

@@ -0,0 +1,50 @@
+import logging
+from os import path
+
+from .config import LoggingConfig
+
+LEVELS = {
+    'DEBUG': logging.DEBUG,
+    'INFO': logging.INFO,
+    'WARNING': logging.WARNING,
+    'ERROR': logging.ERROR,
+    'CRITICAL': logging.CRITICAL
+}
+
+_ROOT_NAME = "hivpy"
+
+
+def start_logging(config: LoggingConfig):
+    root_logger = logging.getLogger(name=_ROOT_NAME)
+
+    # file logging
+    file = path.join(config.log_dir, config.logfile)
+    root_logger.setLevel(logging.DEBUG)
+    file_logger = logging.FileHandler(file, 'w')
+    file_formatter = logging.Formatter('%(asctime)s %(name)-15s %(levelname)-10s %(message)s',
+                                       datefmt='%y-%d-%m %H:%M:%S')
+    file_logger.setFormatter(file_formatter)
+    file_logger.setLevel(config.fileLogLevel)
+    root_logger.addHandler(file_logger)
+    # console logging
+    console_logger = logging.StreamHandler()
+    console_formatter = logging.Formatter('%(name)-15s %(levelname)-10s %(message)s')
+    console_logger.setFormatter(console_formatter)
+    console_logger.setLevel(config.consoleLogLevel)
+    root_logger.addHandler(console_logger)
+
+    print("Starting the simulation. Please, consult the logfile at "+config.logfile)
+
+
+def get_logger(name=None):
+    qualified_logger_name = _ROOT_NAME + (f".{name.lower()}" if name else "")
+    return logging.getLogger(qualified_logger_name)
+
+
+class HIVpyLogger:
+    def __init__(self, base_logger=None):
+        self._logger = base_logger if base_logger is not None else get_logger()
+
+    def write_population(self, population):
+        population  # stand-in to satisfy linter
+        self._logger.info("This is where the population will go.")

src/hivpy/simulation.py

@@ -1,4 +1,3 @@
-import logging
 import operator
 from datetime import datetime
 
@@ -7,6 +6,7 @@
 
 from .common import SexType, selector
 from .config import SimulationConfig
+from .logging import HIVpyLogger, get_logger
 from .population import Population
 
 
@@ -100,16 +100,19 @@ def _initialise_population(self):
         self.population = Population(self.simulation_config.population_size,
                                      self.simulation_config.start_date)
 
-    def run(self):
+    def run(self, pop_logger: HIVpyLogger = None):
+        logger = get_logger()
         # Start the simulation
         date = self.simulation_config.start_date
         assert date == self.population.date
         time_step = self.simulation_config.time_step
         while date <= self.simulation_config.stop_date:
-            logging.info("Timestep %s\n", date)
+            logger.info("Timestep %s\n", date)
             # Advance the population
             self.population = self.population.evolve(time_step)
+            if pop_logger:
+                pop_logger.write_population(self.population)
             self.output.update_summary_stats(date, self.population.data)
             date = date + time_step
-        logging.info("finished")
+        logger.info("finished")
         self.output.write_output(self.output_path)

src/tests/test_logging.py

@@ -1,15 +1,15 @@
-import logging
 import os.path as path
 
 from hivpy.config import LoggingConfig
+from hivpy.logging import get_logger, start_logging
 
 
 def test_logging_levels(tmp_path, capsys):
     d = tmp_path / "log"
     d.mkdir()
     log_cfg = LoggingConfig(log_dir=d, logfile="hivpy.log")
-    log_cfg.start_logging()
-    logger = logging.getLogger("Testing")
+    start_logging(log_cfg)
+    logger = get_logger("Testing")
     TEST_DEBUG = "Test debug."
     TEST_INFO = "Test info."
     TEST_WARNING = "Test warning."