Merge pull request #183 from pph-collective/develop

Logging

.github/workflows/unit-tests.yml

@@ -112,9 +112,17 @@ jobs:
     - name: Install dependencies
       run: poetry install
     - name: Integration Test with pytest
+      continue-on-error: true
+      run: poetry run pytest -m integration_stochastic --cov=titan --cov-report=xml
+    - name: Re-run integration tests if failed
+      continue-on-error: true
+      if: ${{ failure() }}
+      run: poetry run pytest -m integration_stochastic --cov=titan --cov-report=xml
+    - name: Re-run integration tests if failed (x2)
+      if: ${{ failure() }}
       run: poetry run pytest -m integration_stochastic --cov=titan --cov-report=xml
     - name: Upload coverage to Codecov
-      if: always()
+      if: ${{ always() }}
       uses: codecov/codecov-action@v1
       with:
         token: ${{ secrets.CODECOV_TOKEN }}

.gitignore

@@ -29,6 +29,7 @@ ipynb/.ipynb_checkpoints/
 results/
 results/*.txt
 results/*/*.txt
+*log*.txt
 
 profile.prof
 site/

pyproject.toml

@@ -1,6 +1,6 @@
 [tool.poetry]
 name = "titan-model"
-version = "2.4.0"
+version = "2.5.0"
 description = "TITAN Agent Based Model"
 license = "GPL-3.0-only"
 authors = ["Sam Bessey <[email protected]>", "Mary McGrath <[email protected]>"]

tests/population_io_test.py

@@ -80,6 +80,9 @@ def test_read_pop(tmpdir, make_population, params):
     attrs = agent.__dict__.keys()
 
     for attr in attrs:
+        if attr == "component":
+            continue
+
         orig_attr = getattr(agent, attr)
         new_attr = getattr(new_agent, attr)
         if isinstance(orig_attr, BaseFeature):

titan/agent.py

@@ -89,7 +89,7 @@ def __str__(self) -> str:
         """
         return (
             f"\t{self.id}\t{self.age}\t{self.sex_type}\t{self.drug_type}\t"  # type: ignore[attr-defined]
-            f"{self.race}\t{self.hiv.active}"
+            f"{self.race}\t{self.hiv.active}"  # type: ignore[attr-defined]
         )
 
     def __repr__(self) -> str:
@@ -460,22 +460,25 @@ def iter_subset(self) -> Iterator["AgentSet"]:
         for subset in list(self.subset.values()):
             yield subset
 
-    def print_subsets(self):
+    def print_subsets(self, printer=print):
         """
         Pretty print the subsets of this agent set
         """
-        print(f"\t__________ {self.id} __________")
-        print("\tID\t\tN\t\t%")
+        lines = []
+
+        lines.append(f"\t__________ {self.id} __________")
+        # lines.append("\tID\t\tN\t\t%")
+        lines.append("\t{:^6}\t\t{:^5}\t\t{:^4}".format("ID", "N", "%"))
         for set in self.iter_subset():
-            print(
-                "\t{:6}\t\t{:5}\t\t{:.2}".format(
+            lines.append(
+                "\t{:^6}\t\t{:^5}\t\t{:.2}".format(
                     set.id,
                     set.num_members(),
                     safe_divide(set.num_members(), set.parent_set.num_members()),
                 )
             )
             for subset in set.iter_subset():
-                print(
+                lines.append(
                     "\t{:4}\t\t{:5}\t\t{:.2}".format(
                         subset.id,
                         subset.num_members(),
@@ -484,4 +487,5 @@ def print_subsets(self):
                         ),
                     )
                 )
-        print("\t______________ END ______________")
+        lines.append("\t______________ END ______________")
+        printer("\n".join(lines))

titan/features/random_trial.py

@@ -1,4 +1,5 @@
 from typing import Dict
+import logging
 
 from . import base_feature
 from .. import utils
@@ -51,7 +52,7 @@ def update_pop(cls, model: "model.TITAN"):
             model.params.model.network.enable
         ), "Network must be enabled for random trial"
 
-        print(f"Starting random trial ({rt_params.choice})")
+        logging.info(f"Starting random trial ({rt_params.choice})")
         components = model.pop.connected_components()
 
         # set up helper methods based on params
@@ -69,9 +70,8 @@ def update_pop(cls, model: "model.TITAN"):
             suitable = suitable_knowledge
 
         total_nodes = 0
-        print(
-            "Number of components",
-            len([1 for comp in components if comp.number_of_nodes()]),
+        logging.info(
+            f"Number of components {len([1 for comp in components if comp.number_of_nodes()])}",
         )
         for comp in components:
             total_nodes += comp.number_of_nodes()
@@ -152,7 +152,7 @@ def update_pop(cls, model: "model.TITAN"):
                     chosen_agent.random_trial.treated = True  # type: ignore[attr-defined]
                     treat(chosen_agent, model)
 
-        print(("Total agents in trial: ", total_nodes))
+        logging.info(f"Total agents in trial: {total_nodes}")
 
     def set_stats(self, stats: Dict[str, int], time: int):
         if self.active:

titan/features/syringe_services.py

@@ -1,3 +1,5 @@
+import logging
+
 from . import base_feature
 from .. import model as hiv_model
 from .. import utils
@@ -34,7 +36,7 @@ def update_pop(cls, model: "hiv_model.TITAN"):
         args:
             model: the instance of TITAN currently being run
         """
-        print(("\n\n!!!!Engaging syringe services program"))
+        logging.info(("\n\n!!!!Engaging syringe services program"))
         ssp_num_slots = 0
         ssp_agents = {
             agent for agent in model.pop.pwid_agents if agent.syringe_services.active  # type: ignore[attr-defined]
@@ -82,7 +84,7 @@ def update_pop(cls, model: "hiv_model.TITAN"):
             else:
                 break
 
-        print(
+        logging.info(
             f"SSP has {ssp_num_slots} target slots with "
             f"{len(ssp_agents)} slots filled"
         )

titan/model.py

@@ -2,6 +2,7 @@
 from typing import Dict, List, Optional
 from copy import copy
 import os
+import logging
 
 import numpy as np  # type: ignore
 import nanoid  # type: ignore
@@ -34,22 +35,25 @@ def __init__(
             params: the parameter object for this model
             pop: an initialized population to run the model on
         """
+        self.id = nanoid.generate(size=8)
 
         self.params = params
         # pre-fetch commonly used param sub-sets for performance
         self.calibration = params.calibration
 
-        print("=== Begin Initialization Protocol ===\n")
+        utils.set_up_logging(params)
+
+        logging.info(f"Model ID: {self.id}")
+        logging.info("=== Begin Initialization Protocol ===\n")
 
         if pop is None:
-            print("\tGenerating new population")
+            logging.info("  Generating new population")
             self.pop = population.Population(params)
         else:
-            print("\tUsing provided population")
+            logging.info("  Using provided population")
             self.pop = pop
 
         self.time = -1 * self.params.model.time.burn_steps  # burn is negative time
-        self.id = nanoid.generate(size=8)
 
         self.features = [
             feature
@@ -71,16 +75,16 @@ def __init__(
 
         # Set seed format. 0: pure random, else: fixed value
         self.run_seed = utils.get_check_rand_int(params.model.seed.run)
-        print(f"\tRun seed was set to: {self.run_seed}")
+        logging.info(f"  Run seed was set to: {self.run_seed}")
         self.run_random = random.Random(self.run_seed)
         self.np_random = np.random.default_rng(self.run_seed)
         random.seed(self.run_seed)
-        print(("\tFIRST RANDOM CALL {}".format(random.randint(0, 100))))
+        logging.info(("  FIRST RANDOM CALL {}".format(random.randint(0, 100))))
 
-        print("\tResetting death count")
+        logging.info("  Resetting death count")
         self.deaths: List["ag.Agent"] = []  # Number of death
 
-        print("\n === Initialization Protocol Finished ===")
+        logging.info("\n=== Initialization Protocol Finished ===")
 
     def print_stats(self, stat: Dict[str, Dict[str, int]], outdir: str):
         """
@@ -150,20 +154,20 @@ def run(self, outdir: str):
         self.print_stats(stats, outdir)
 
         if self.params.model.time.burn_steps > 0:
-            print("\t===! Start Burn Loop !===")
+            logging.info("  ===! Start Burn Loop !===")
 
         # time starts at negative burn steps, model run starts at t = 1
         while self.time < self.params.model.time.num_steps:
             if self.time == 0:
                 if self.params.model.time.burn_steps > 0:
-                    print("\t===! Burn Loop Complete !===")
-                print("\t===! Start Main Loop !===")
+                    logging.info("  ===! Burn Loop Complete !===")
+                logging.info("  ===! Start Main Loop !===")
 
             self.time += 1
             self.step(outdir)
             self.reset_trackers()
 
-        print("\t===! Main Loop Complete !===")
+        logging.info("  ===! Main Loop Complete !===")
 
     def step(self, outdir: str):
         """
@@ -176,9 +180,11 @@ def step(self, outdir: str):
         args:
             outdir: path to directory where reports should be saved
         """
-        print(f"\n\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t.: TIME {self.time}")
-        print(
-            "\tSTARTING HIV count:{}\tTotal Incarcerated:{}\tHR+:{}\t"
+        logging.info(
+            f"\n                                                  .: TIME {self.time}"
+        )
+        logging.info(
+            "  STARTING HIV count:{}  Total Incarcerated:{}  HR+:{}  "
             "PrEP:{}".format(
                 len(exposures.HIV.agents),
                 sum([1 for a in self.pop.all_agents if a.incar.active]),  # type: ignore[attr-defined]
@@ -201,8 +207,8 @@ def step(self, outdir: str):
         )
         self.print_stats(stats, outdir)
 
-        print(f"Number of relationships: {len(self.pop.relationships)}")
-        self.pop.all_agents.print_subsets()
+        logging.info(f"Number of relationships: {len(self.pop.relationships)}")
+        self.pop.all_agents.print_subsets(logging.info)
 
     def update_all_agents(self):
         """
@@ -318,10 +324,10 @@ def timeline_scaling(self):
                 param = defn.parameter
                 if param != "ts_default":
                     if defn.start_time == self.time:
-                        print(f"timeline scaling - {param}")
+                        logging.info(f"timeline scaling - {param}")
                         utils.scale_param(params, param, defn.scalar)
                     elif defn.stop_time == self.time:
-                        print(f"timeline un-scaling - {param}")
+                        logging.info(f"timeline un-scaling - {param}")
                         utils.scale_param(params, param, 1 / defn.scalar)
 
     def agents_interact(self, rel: "ag.Relationship"):

titan/params/outputs.yml

@@ -36,3 +36,24 @@ outputs:
       - drug_types
       - locations
       - components
+  logging:
+    destination:
+      default: stdout
+      type: enum
+      description: Whether to log to a file or the console (default)
+      values:
+        - stdout
+        - file
+    filepath:
+      default: '__cwd__'
+      description: The directory path where the logs will be printed to if `destination` is `file`.  The logs will be named `titan_log_<date/time>.txt`.  The default is your current working directory.
+      type: any
+    level:
+      default: 'INFO'
+      type: enum
+      description: What is the minimum log level to record? See https://docs.python.org/3/howto/logging.html#when-to-use-logging for details on what the levels mean.
+      values:
+        - 'DEBUG'
+        - 'INFO'
+        - 'WARNING'
+        - 'ERROR'

titan/parse_params.py

@@ -23,7 +23,7 @@ def __init__(self, d: Dict):
     def __getattribute__(self, k):
         try:
             return self[k]
-        except:
+        except KeyError:
             return object.__getattribute__(self, k)
 
     def __setattr__(self, k, v):

titan/population.py

@@ -6,6 +6,7 @@
 from copy import copy
 from math import ceil
 from typing import List, Dict, Set, Optional, Tuple
+import logging
 
 import numpy as np  # type: ignore
 import networkx as nx  # type: ignore
@@ -34,6 +35,10 @@ def __init__(self, params: "parse_params.ObjMap", id: Optional[str] = None):
         else:
             self.id = id
 
+        utils.set_up_logging(params)
+
+        logging.info(f"Population ID: {self.id}")
+
         self.pop_seed = utils.get_check_rand_int(params.model.seed.ppl)
 
         # Init RNG for population creation to pop_seed
@@ -96,7 +101,7 @@ def __init__(self, params: "parse_params.ObjMap", id: Optional[str] = None):
             self.params
         )
 
-        print("\tCreating agents")
+        logging.info("  Creating agents")
         # for each location in the population, create agents per that location's demographics
         init_time = -1 * self.params.model.time.burn_steps
         for loc in self.geography.locations.values():
@@ -109,15 +114,15 @@ def __init__(self, params: "parse_params.ObjMap", id: Optional[str] = None):
                     )
                 ):
                     if self.all_agents.num_members() >= self.params.model.num_pop:
-                        print(
+                        logging.warning(
                             "WARNING: not adding agent to population - too many agents"
                         )
                         break
                     agent = self.create_agent(loc, race, init_time)
                     self.add_agent(agent)
 
         # initialize relationships
-        print("\tCreating Relationships")
+        logging.info("  Creating Relationships")
         self.update_partner_assignments(0)
 
     def create_agent(
@@ -486,10 +491,10 @@ def trim_component(component, max_size):
                     comp.number_of_nodes()
                     > self.params.model.network.component_size.max
                 ):
-                    print("TOO BIG", comp, comp.number_of_nodes())
+                    logging.info("TOO BIG", comp, comp.number_of_nodes())
                     trim_component(comp, self.params.model.network.component_size.max)
 
-        print("\tTotal agents in graph: ", self.graph.number_of_nodes())
+        logging.info(f"  Total agents in graph: {self.graph.number_of_nodes()}")
 
     def connected_components(self) -> List:
         """