diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index f4dc853..1d92564 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -16,7 +16,7 @@ on: pull_request: types: [opened, synchronize, reopened] paths: - - moldrug/** + - src/moldrug/** - .github/workflows/tests.yml - tests/** - pyproject.toml diff --git a/docs/source/CHANGELOG.md b/docs/source/CHANGELOG.md index 77f5929..30ee014 100644 --- a/docs/source/CHANGELOG.md +++ b/docs/source/CHANGELOG.md @@ -13,6 +13,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed +- Use logging instead of print. - Move from `.rst` to `.md` on the documentation. - Update installation instructions. - Versioning: `Major.Minor.Patch` --> `Major.Minnor.Patch.postX` it helps to distinguish commits that are not yet included on the `Patch`. diff --git a/src/moldrug/cli.py b/src/moldrug/cli.py index 2f78623..fed9ddc 100644 --- a/src/moldrug/cli.py +++ b/src/moldrug/cli.py @@ -7,8 +7,8 @@ """ import argparse import datetime -import inspect import importlib +import inspect import os import sys from typing import Union @@ -17,6 +17,7 @@ from rdkit import Chem from moldrug import __version__, constraintconf, utils +from moldrug.logging_utils import log class CommandLineHelper: @@ -131,7 +132,8 @@ def _translate_config(self): if 'type' not in MainConfig['cluster'] or 'kwargs' not in MainConfig['cluster']: raise ValueError("The cluster configuration must contain 'type' and 'kwargs'.") - from moldrug.runner import Runner, RunnerMode # terminates with a message if dask is not installed + from moldrug.runner import ( # terminates with a message if dask is not installed + Runner, RunnerMode) try: cluster_class = getattr(importlib.import_module("dask_jobqueue"), MainConfig['cluster']['type']) @@ -321,10 +323,9 @@ def __moldrug_cmd(): ) UserArgs = CommandLineHelper(parser) - print( - f"Started at {datetime.datetime.now().strftime('%c')}\n" - f"You are using moldrug: {__version__}.\n\n" - f"{UserArgs}\n\n") + log(f"Started at {datetime.datetime.now().strftime('%c')}") + log(f"You are using moldrug: {__version__}\n") + log(f"{UserArgs}\n\n") # Call the class UserArgs.run_moldrugClass() @@ -336,7 +337,7 @@ def __moldrug_cmd(): if UserArgs.FollowConfig: MutableArgs = UserArgs.MutableArgs.copy() for job in UserArgs.FollowConfig: - print(f"The follow job {job} started.") + log(f"The follow job {job} started.") # Updating arguments MutableArgs.update(UserArgs.FollowConfig[job]) @@ -350,7 +351,7 @@ def __moldrug_cmd(): UserArgs.run_moldrugClass() # Saving data UserArgs.save_data() - print(f'The job {job} finished!') + log(f'The job {job} finished!') # Clean checkpoint on normal end if os.path.isfile('cpt.pbz2'): diff --git a/src/moldrug/constraintconf.py b/src/moldrug/constraintconf.py index 527d675..c0d6347 100644 --- a/src/moldrug/constraintconf.py +++ b/src/moldrug/constraintconf.py @@ -28,7 +28,7 @@ # import warnings from tqdm import tqdm -from moldrug import verbose +from moldrug.logging_utils import LogLevel, log from moldrug.utils import compressed_pickle @@ -190,10 +190,9 @@ def generate_conformers(mol: Chem.rdchem.Mol, try: AllChem.ConstrainedEmbed(temp_mol, core1, randomseed=i) except Exception as e: - if verbose: - print(f"AllChem.ConstrainedEmbed fails with: {e}. \n" - f"On the molecules:\n current mol: {Chem.MolToSmiles(temp_mol)}\n" - f"core: {Chem.MolToSmiles(core1)}\nTrying with gen_aligned_conf") + log(f"AllChem.ConstrainedEmbed fails with: {e}. \n" + f"On the molecule:\n current mol: {Chem.MolToSmiles(temp_mol)}\n" + f"core: {Chem.MolToSmiles(core1)}\nTrying with gen_aligned_conf", LogLevel.DEBUG) temp_mol = gen_aligned_conf(temp_mol, ref_mol, ref_smi, randomseed=randomseed) # Remove the explicit Hs temp_mol = Chem.RemoveHs(temp_mol) diff --git a/src/moldrug/fitness.py b/src/moldrug/fitness.py index ee0a00f..bd6c55c 100644 --- a/src/moldrug/fitness.py +++ b/src/moldrug/fitness.py @@ -11,7 +11,8 @@ from rdkit import Chem from rdkit.Chem import QED, Descriptors -from moldrug import constraintconf, utils, verbose +from moldrug import constraintconf, utils +from moldrug.logging_utils import log, LogLevel def __get_default_desirability(multireceptor: bool = False) -> dict: @@ -352,8 +353,7 @@ def _vinadock( minimum_conf_rms=constraint_minimum_conf_rms, randomseed=vina_seed) except Exception as e: - if verbose: - print(f"constraintconf.generate_conformers fails inside moldrug.fitness._vinadock with {e}") + log(f"constraintconf.generate_conformers fails inside moldrug.fitness._vinadock with {e}", LogLevel.DEBUG) vina_score_pdbqt = (np.inf, "NonValidConformer") return vina_score_pdbqt # Remove conformers that clash with the protein in case of score_only, @@ -450,9 +450,8 @@ def _vinadock( } utils.compressed_pickle(f'error/{Individual.idx}_error', error) # warn(f"\nVina failed! Check: {Individual.idx}_error.pbz2 file in error.\n") - if verbose: - for key in error: - print(f"{key}: {error[key]}") + for key in error: + log(f"{key}: {error[key]}", LogLevel.DEBUG) vina_score_pdbqt = (np.inf, 'VinaFailed') return vina_score_pdbqt diff --git a/src/moldrug/logging_utils.py b/src/moldrug/logging_utils.py new file mode 100644 index 0000000..4bdac76 --- /dev/null +++ b/src/moldrug/logging_utils.py @@ -0,0 +1,31 @@ +import logging +from enum import Enum +from moldrug import verbose + + +class LogLevel(Enum): + DEBUG = logging.DEBUG + INFO = logging.INFO + WARNING = logging.WARNING + ERROR = logging.ERROR + CRITICAL = logging.CRITICAL + + +# Create a logger +logger = logging.getLogger("moldrug") + +# Only configure if no handlers are set (prevents messing with user config) +if not logger.hasHandlers(): + handler = logging.StreamHandler() + formatter = logging.Formatter( + "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + ) + handler.setFormatter(formatter) + logger.addHandler(handler) + # Set default level depending on verbose + logger.setLevel(logging.DEBUG if verbose else logging.INFO) + + +def log(msg: str, level: LogLevel = LogLevel.INFO): + """Unified logging function for the library.""" + logger.log(level.value, msg) diff --git a/src/moldrug/utils.py b/src/moldrug/utils.py index f8f6437..f3a6532 100644 --- a/src/moldrug/utils.py +++ b/src/moldrug/utils.py @@ -12,7 +12,6 @@ from copy import deepcopy from inspect import signature from typing import Callable, Dict, Iterable, List, Optional, Union -from warnings import warn import dill as pickle import numpy as np @@ -24,7 +23,8 @@ from rdkit.Chem import AllChem, DataStructs, Descriptors, Lipinski, rdFMCS from moldrug import __version__ -from moldrug.runner import Runner, RunnerMode, parallel_execution_multiprocessing +from moldrug.logging_utils import log, LogLevel +from moldrug.runner import Runner, RunnerMode RDLogger.DisableLog('rdApp.*') # # in order to pickle the isotope properties of the molecule @@ -930,8 +930,11 @@ def make_sdf(individuals: List[Individual], sdf_name: str = 'out'): w.write(mol) except Exception: # Should be that the pdbqt is not valid - print(f"{individual} does not have a valid pdbqt: {individual.pdbqt}.") - print(f" File {sdf_name}_{i+1}.sdf was created!") + log( + f"{individual} does not have a valid pdbqt: {individual.pdbqt}.", + LogLevel.ERROR + ) + log(f"File {sdf_name}_{i+1}.sdf was created!") else: with Chem.SDWriter(f"{sdf_name}.sdf") as w: for individual in individuals: @@ -949,8 +952,11 @@ def make_sdf(individuals: List[Individual], sdf_name: str = 'out'): w.write(mol) except Exception: # Should be that the pdbqt is not valid - print(f"{individual} does not have a valid pdbqt: {individual.pdbqt}.") - print(f"File {sdf_name}.sdf was createad!") + log( + f"{individual} does not have a valid pdbqt: {individual.pdbqt}.", + LogLevel.ERROR + ) + log(f"File {sdf_name}.sdf was createad!") def _make_kwargs_copy(costfunc, costfunc_kwargs,): @@ -982,9 +988,10 @@ def tar_errors(error_path: str = 'error'): if os.path.isdir(error_path): if os.listdir(error_path): shutil.make_archive('error', 'gztar', error_path) - print(f"\n{50*'=+'}") - print("Note: Check the running warnings and erorrs in error.tar.gz file!") - print(f"{50*'=+'}\n") + + log(f"\t\t{20*'=+'}") + log("Check the running warnings and erorrs in error.tar.gz file!", LogLevel.WARNING) + log(f"\t\t{20*'=+'}") shutil.rmtree(error_path) ###################### @@ -1147,8 +1154,8 @@ def __call__(self, njobs: int = 1, pick: int = None, runner: Optional[Runner] = # Check version of moldrug if self.__moldrug_version != __version__: - warn(f"{self.__class__.__name__} was initilized with moldrug-{self.__moldrug_version} " - f"but was called with moldrug-{__version__}") + log(f"{self.__class__.__name__} was initilized with moldrug-{self.__moldrug_version} " + f"but was called with moldrug-{__version__}", LogLevel.ERROR) self.grow_crem_kwargs.update({'return_mol': True}) new_mols = list(grow_mol(self._seed_mol, self.crem_db_path, **self.grow_crem_kwargs)) if pick: @@ -1171,7 +1178,7 @@ def __call__(self, njobs: int = 1, pick: int = None, runner: Optional[Runner] = for individual in self.pop: args_list.append((individual, kwargs_copy)) - print('Calculating cost function...') + log('Calculating cost function...') self.pop = runner.run(self.__costfunc__, args_list) # Clean directory @@ -1180,7 +1187,7 @@ def __call__(self, njobs: int = 1, pick: int = None, runner: Optional[Runner] = tar_errors('error') # Printing how long was the simulation - print(f"Finished at {datetime.datetime.now().strftime('%c')}.\n") + log(f"Finished at {datetime.datetime.now().strftime('%c')}.\n") def __costfunc__(self, args_list): Individual, kwargs = args_list @@ -1442,8 +1449,8 @@ def __call__(self, njobs: int = 1, runner: Optional[Runner] = None): # Check version of moldrug if self.__moldrug_version__ != __version__: - warn(f"{self.__class__.__name__} was initialized with moldrug-{self.__moldrug_version__} " - f"but was called with moldrug-{__version__}") + log(f"{self.__class__.__name__} was initialized with moldrug-{self.__moldrug_version__} " + f"but was called with moldrug-{__version__}", LogLevel.ERROR) # Here we will update if needed some parameters for # the crem operations that could change between different calls. @@ -1466,7 +1473,7 @@ def __call__(self, njobs: int = 1, runner: Optional[Runner] = None): "generate any new molecule during the initialization of the population. " "Check the provided crem parameters!") if len(GenInitStructs) < (self.popsize - len(self._seed_mol)): - print('The initial population has repeated elements') + log('The initial population has repeated elements', LogLevel.WARNING) # temporal solution GenInitStructs += random.choices(GenInitStructs, k=self.popsize - len(GenInitStructs) - len(self._seed_mol)) @@ -1506,7 +1513,7 @@ def __call__(self, njobs: int = 1, runner: Optional[Runner] = None): for individual in self.pop: args_list.append((individual, kwargs_copy)) - print(f'\n\nCreating the first population with {len(self.pop)} members:') + log(f'Creating the first population with {len(self.pop)} members:') self.pop = runner.run(self.__costfunc__, entries=args_list) # Clean directory @@ -1527,8 +1534,8 @@ def __call__(self, njobs: int = 1, runner: Optional[Runner] = None): self.pop = sorted(self.pop, key=lambda x: x.idx) self.pop = sorted(self.pop) # Print some information of the initial population - print(f"Initial Population: Best Individual: {self.pop[0]}") - print(f"Accepted rate: {self.acceptance[self.NumGens]['accepted']} / {self.acceptance[self.NumGens]['generated']}\n") + log(f"Initial Population: Best Individual: {self.pop[0]}") + log(f"Acceptance rate: {self.acceptance[self.NumGens]['accepted']} / {self.acceptance[self.NumGens]['generated']}\n") # Updating the info of the first individual (parent) # to print at the end how well performed the method (cost function) # Because How the population was initialized and because we are using pool.imap (ordered). @@ -1606,7 +1613,7 @@ def __call__(self, njobs: int = 1, runner: Optional[Runner] = None): individual.idx = i + NumbOfSawIndividuals # The problem here is that we are not being general for other possible Cost functions. args_list.append((individual, kwargs_copy)) - print(f'Evaluating generation {self.NumGens} / {self.maxiter + number_of_previous_generations}:') + log(f'Evaluating generation {self.NumGens} / {self.maxiter + number_of_previous_generations}:') # Calculating cost function in parallel popc = runner.run(self.__costfunc__, args_list) @@ -1650,24 +1657,24 @@ def __call__(self, njobs: int = 1, runner: Optional[Runner] = None): compressed_pickle('cpt', self) # Show Iteration Information - print(f"Generation {self.NumGens}: Best Individual: {self.pop[0]}.") - print(f"Accepted rate: {self.acceptance[self.NumGens]['accepted']} / {self.acceptance[self.NumGens]['generated']}\n") + log(f"Generation {self.NumGens}: Best Individual: {self.pop[0]}") + log(f"Acceptance rate: {self.acceptance[self.NumGens]['accepted']} / {self.acceptance[self.NumGens]['generated']}\n") # Printing summary information - print(f"\n{50*'=+'}\n") - print(f"The simulation finished successfully after {self.NumGens} generations with" - f"a population of {self.popsize} individuals. " - f"A total number of {len(self.SawIndividuals)} Individuals were seen during the simulation.") - print(f"Initial Individual: {self.InitIndividual}") - print(f"Final Individual: {self.pop[0]}") - print(f"The cost function dropped in {self.InitIndividual - self.pop[0]} units.") - print(f"\n{50*'=+'}\n") + log(f"\t\t{20*'=+'}\n") + log(f"The simulation finished successfully after {self.NumGens} generations with" + f"a population of {self.popsize} individuals. " + f"A total number of {len(self.SawIndividuals)} Individuals were seen during the simulation.") + log(f"Initial Individual: {self.InitIndividual}") + log(f"Final Individual: {self.pop[0]}") + log(f"The cost function dropped in {self.InitIndividual - self.pop[0]} units.") + log(f"\t\t{20*'=+'}\n") # Tar errors tar_errors('error') # Printing how long was the simulation - print(f"Total time ({self.maxiter} generations): {time.time() - ts:>5.2f} (s).\n" + log(f"Total time ({self.maxiter} generations): {time.time() - ts:>5.2f} (s).\n" f"Finished at {datetime.datetime.now().strftime('%c')}.\n") def __costfunc__(self, args_list): @@ -1712,7 +1719,7 @@ def mutate(self, individual: Individual): else: _, mol = random.choice(mutants) # nosec except Exception: - print(f'Note: The mutation on {individual} did not work, it will be returned the same individual') + log(f'The mutation on {individual} did not work, it will be returned the same individual', LogLevel.WARNING) mol = individual.mol if self.AddHs: mol = Chem.AddHs(mol)