Switch to logging

.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

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`.

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'):

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)

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
 

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)

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)