diff --git a/.github/workflows/unit-tests.yml b/.github/workflows/unit-tests.yml index 154f2da4..6557830d 100644 --- a/.github/workflows/unit-tests.yml +++ b/.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 }} diff --git a/.gitignore b/.gitignore index ba9aedd4..b2ed88bb 100644 --- a/.gitignore +++ b/.gitignore @@ -29,6 +29,7 @@ ipynb/.ipynb_checkpoints/ results/ results/*.txt results/*/*.txt +*log*.txt profile.prof site/ diff --git a/pyproject.toml b/pyproject.toml index 01219833..fdfa72f4 100644 --- a/pyproject.toml +++ b/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 ", "Mary McGrath "] diff --git a/tests/population_io_test.py b/tests/population_io_test.py index 38a20894..5312620e 100644 --- a/tests/population_io_test.py +++ b/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): diff --git a/titan/agent.py b/titan/agent.py index 4ccbaa90..16b40618 100644 --- a/titan/agent.py +++ b/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)) diff --git a/titan/features/random_trial.py b/titan/features/random_trial.py index 4a0a9059..7928f10e 100644 --- a/titan/features/random_trial.py +++ b/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: diff --git a/titan/features/syringe_services.py b/titan/features/syringe_services.py index dff718ba..89ca25ea 100644 --- a/titan/features/syringe_services.py +++ b/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" ) diff --git a/titan/model.py b/titan/model.py index 818acdc3..5bb9ae19 100644 --- a/titan/model.py +++ b/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"): diff --git a/titan/params/outputs.yml b/titan/params/outputs.yml index fb86ee9f..3b53ae07 100644 --- a/titan/params/outputs.yml +++ b/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_.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' diff --git a/titan/parse_params.py b/titan/parse_params.py index 72b5f6e5..39ecff0d 100644 --- a/titan/parse_params.py +++ b/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): diff --git a/titan/population.py b/titan/population.py index a299ce08..8ae57edd 100644 --- a/titan/population.py +++ b/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,7 +114,7 @@ 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 @@ -117,7 +122,7 @@ def __init__(self, params: "parse_params.ObjMap", id: Optional[str] = None): 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: """ diff --git a/titan/population_io.py b/titan/population_io.py index 7ca071c5..691d8736 100644 --- a/titan/population_io.py +++ b/titan/population_io.py @@ -5,6 +5,7 @@ from tempfile import mkdtemp import glob import re +import logging from .population import Population from .agent import Agent, Relationship @@ -12,6 +13,7 @@ from .location import Location from . import features from . import exposures +from . import utils agent_feature_attrs = [ feature.name for feature in features.BaseFeature.__subclasses__() @@ -40,6 +42,8 @@ def write(pop: Population, dir: str, compress: bool = True) -> str: """ assert len(pop.relationships) > 0, "Can't write empty population" + utils.set_up_logging(pop.params) + # open agent file agent_file = os.path.join(dir, f"{pop.id}_agents.csv") @@ -86,7 +90,7 @@ def write_extra_class(extra_attrs, extra_type): def write_extra_class_file(file_name, collection, extra, attrs): - print(f"Creating {file_name}") + logging.info(f"Creating {file_name}") with open(file_name, "w", newline="") as f: writer = csv.DictWriter(f, fieldnames=attrs) writer.writeheader() @@ -96,7 +100,7 @@ def write_extra_class_file(file_name, collection, extra, attrs): def write_class_file(file_name, collection, attrs): - print(f"Creating {file_name}") + logging.info(f"Creating {file_name}") with open(file_name, "w", newline="") as f: writer = csv.DictWriter(f, fieldnames=attrs) writer.writeheader() diff --git a/titan/run_titan.py b/titan/run_titan.py index 1c7b45e1..eebd56d9 100755 --- a/titan/run_titan.py +++ b/titan/run_titan.py @@ -10,6 +10,7 @@ import csv import traceback from typing import List, Optional +import logging # allow imports to work if running it as a script for development locally if __name__ == "__main__": @@ -258,6 +259,8 @@ def single_run(sweep, outfile_dir, params, save_pop, pop_path): """ A single run of titan. Dispatched from main using parallel processes. """ + utils.set_up_logging(params) + pid = str(os.getpid()) pid_outfile_dir = os.path.join(outfile_dir, pid) save_pop_dir = ( @@ -285,7 +288,7 @@ def single_run(sweep, outfile_dir, params, save_pop, pop_path): if save_pop_dir is not None: pop_io.write(pop, save_pop_dir) - print(f"Population saved to: {save_pop_dir}") + logging.info(f"Population saved to: {save_pop_dir}") try: model = TITAN(params, pop=pop) diff --git a/titan/utils.py b/titan/utils.py index 9c726c76..55e9c360 100644 --- a/titan/utils.py +++ b/titan/utils.py @@ -2,6 +2,9 @@ from functools import wraps from typing import TypeVar, Collection, Union, Iterable from math import floor +import logging +import os +from datetime import datetime import networkx as nx # type: ignore @@ -209,7 +212,7 @@ def scale_param(params: ObjMap, param_path: str, scalar: float, delimiter="|"): scaling_item, last_key = get_param_from_path(params, param_path, delimiter) old_val = scaling_item[last_key] - print(f"scaling - {param_path}: {old_val} => {old_val * scalar}") + logging.info(f"scaling - {param_path}: {old_val} => {old_val * scalar}") scaling_item[last_key] = old_val * scalar @@ -225,7 +228,7 @@ def override_param(params: ObjMap, param_path: str, value, delimiter="|"): last_key = int(last_key) old_val = override_item[last_key] - print(f"overriding - {param_path}: {old_val} => {value}") + logging.info(f"overriding - {param_path}: {old_val} => {value}") override_item[last_key] = value @@ -303,3 +306,30 @@ def get_cumulative_bin(rand_gen, bin_def: ObjMap) -> int: break return bin + + +def set_up_logging(params): + # set up logging + if params.outputs.logging.destination == "file": + log_msg_format = "{message:<64} [{asctime}][{levelname}][{module}]" + log_dt_format = "%Y%m%d%H%M%S" + path = ( + os.getcwd() + if params.outputs.logging.filepath == "__cwd__" + else params.outputs.logging.filepath + ) + logging.basicConfig( + format=log_msg_format, + style="{", + datefmt=log_dt_format, + filename=os.path.join( + path, f"titan_log_{datetime.now().strftime(log_dt_format)}.txt" + ), + level=params.outputs.logging.level, + ) + else: + log_msg_format = "%(message)s" + logging.basicConfig( + format=log_msg_format, + level=params.outputs.logging.level, + )