fix: logging so that it doesn't affect the root logger (#154)

CAST-genomics · Dec 29, 2022 · c1dc1ef · c1dc1ef
1 parent a6c32d0
commit c1dc1ef
Show file tree

Hide file tree

Showing 7 changed files with 86 additions and 70 deletions.
diff --git a/docs/project_info/contributing.rst b/docs/project_info/contributing.rst
@@ -131,6 +131,17 @@ Before creating your pull request, please run each of our code checks.
 
         nox --session=tests
 
+---------------------
+Publish a new version
+---------------------
+To publish a new version of haptools:
+
+1. First, merge `the most recent haptools PR <https://github.com/CAST-genomics/haptools/pulls>`_ prefixed "chore(main)" created by our Github actions bot
+2. The bot will automatically create a new version on PyPI and tag a release on Github
+3. A few hours later, bioconda will automatically detect the new release on PyPI and create a PR in `their repository <https://github.com/bioconda/bioconda-recipes/pulls>`_
+4. Check that all of the dependencies in the recipe have been updated properly. If they are, you should comment on the bioconda PR with "@BiocondaBot please add label"
+5. After 1-2 days, someone from the bioconda team will merge our PR and the version will get updated on bioconda. Otherwise, ping them a reminder on `Gitter <https://gitter.im/bioconda/Lobby>`_
+
 -----
 Style
 -----
@@ -146,6 +157,27 @@ Code
         ii. from external, third party packages
         iii. from our own internal code
 
+~~~~~~
+Errors
+~~~~~~
+We use the `Python logging module <https://coralogix.com/blog/python-logging-best-practices-tips/>`_ for all messages, including warnings, debugging info, and otherwise. For example, all classes in the ``data`` module have a ``log`` property that stores a logger object. If you are creating a new command, you can use our custom logging module to retrieve a suitable object.
+
+.. code-block:: python
+
+    from .logging import getLogger
+
+    # the level of verbosity desired by the user
+    # can be: CRITICAL, ERROR, WARNING, INFO, DEBUG, or NOTSET
+    verbosity = "DEBUG"
+
+    # create a new logger object for the transform command
+    log = getLogger(name="transform", level=verbosity)
+
+    # log a warning message to the logger
+    log.warning("This is a warning")
+
+This way, the user can choose their level of verbosity among *CRITICAL*, *ERROR*, *WARNING*, *INFO*, *DEBUG*, and *NOTSET*. However, for critical errors (especially for those in the ``data`` module), our convention is to raise exceptions, usually with a custom ``ValueError``.
+
 ~~~~~~~~~~~~~~~~~~~
 Git commit messages
 ~~~~~~~~~~~~~~~~~~~

diff --git a/haptools/__main__.py b/haptools/__main__.py
@@ -362,17 +362,11 @@ def simphenotype(
 
     Note: GENOTYPES must be the output from the transform subcommand.
     """
-    import logging
-
+    from .logging import getLogger
     from .sim_phenotype import simulate_pt
 
-    log = logging.getLogger("haptools simphenotype")
-    db_time = "|%(asctime)s" if verbosity == "DEBUG" else ""
-    logging.basicConfig(
-        format="[%(levelname)8s" + db_time + "] %(message)s (%(filename)s:%(lineno)s)",
-        level=verbosity,
-        datefmt="%H:%M:%S",
-    )
+    log = getLogger(name="simphenotype", level=verbosity)
+
     # handle samples
     if samples and samples_file:
         raise click.UsageError(
@@ -525,17 +519,11 @@ def transform(
     GENOTYPES must be formatted as a VCF or PGEN and HAPLOTYPES must be formatted
     according to the .hap format spec
     """
-    import logging
-
+    from .logging import getLogger
     from .transform import transform_haps
 
-    log = logging.getLogger("haptools transform")
-    db_time = "|%(asctime)s" if verbosity == "DEBUG" else ""
-    logging.basicConfig(
-        format="[%(levelname)8s" + db_time + "] %(message)s (%(filename)s:%(lineno)s)",
-        level=verbosity,
-        datefmt="%H:%M:%S",
-    )
+    log = getLogger(name="transform", level=verbosity)
+
     # handle samples
     if samples and samples_file:
         raise click.UsageError(
@@ -702,17 +690,11 @@ def ld(
     If TARGET is a variant ID, the ID must appear in GENOTYPES. Otherwise, it must
     be present in the .hap file
     """
-    import logging
-
     from .ld import calc_ld
+    from .logging import getLogger
+
+    log = getLogger(name="ld", level=verbosity)
 
-    log = logging.getLogger("haptools ld")
-    db_time = "|%(asctime)s" if verbosity == "DEBUG" else ""
-    logging.basicConfig(
-        format="[%(levelname)8s" + db_time + "] %(message)s (%(filename)s:%(lineno)s)",
-        level=verbosity,
-        datefmt="%H:%M:%S",
-    )
     # handle samples
     if samples and samples_file:
         raise click.UsageError(
@@ -784,14 +766,10 @@ def index(
     Takes in an unsorted .hap file and outputs it as a .gz and a .tbi file
     """
 
-    import logging
     from .index import index_haps
+    from .logging import getLogger
 
-    log = logging.getLogger("haptools index")
-    logging.basicConfig(
-        format="[%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)",
-        level=verbosity,
-    )
+    log = getLogger(name="index", level=verbosity)
 
     index_haps(haplotypes, sort, output, log)
 

diff --git a/haptools/index.py b/haptools/index.py
@@ -7,6 +7,7 @@
 from pysam import tabix_index
 
 from haptools import data
+from .logging import getLogger
 from haptools.data.haplotypes import Haplotypes
 
 
@@ -49,13 +50,9 @@ def index_haps(
         A logging module to which to write messages about progress and any errors
     """
     if log is None:
-        log = logging.getLogger("haptools index")
-        logging.basicConfig(
-            format="[%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)",
-            level="ERROR",
-        )
-    log.info("Loading haplotypes")
+        log = getLogger(name="index", level="ERROR")
 
+    log.info("Loading haplotypes")
     hp = data.Haplotypes(haplotypes, log=log)
 
     if sort:

diff --git a/haptools/ld.py b/haptools/ld.py
@@ -1,12 +1,12 @@
 from __future__ import annotations
-import logging
 from pathlib import Path
 from dataclasses import dataclass, field
 
 import numpy as np
 import numpy.typing as npt
 
 from haptools import data
+from .logging import getLogger
 from .data import Haplotype as HaplotypeBase
 
 
@@ -98,11 +98,7 @@ def calc_ld(
         A logging module to which to write messages about progress and any errors
     """
     if log is None:
-        log = logging.getLogger("haptools ld")
-        logging.basicConfig(
-            format="[%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)",
-            level="ERROR",
-        )
+        log = getLogger(name="ld", level="ERROR")
 
     # convert IDs to set but save the tuple
     ids_tup, ids = ids, (set(ids) if ids is not None else None)

diff --git a/haptools/logging.py b/haptools/logging.py
@@ -2,22 +2,41 @@
 import logging
 
 
-def getLogger(name: str = None):
+def getLogger(name: str = None, level: str = "ERROR"):
     """
     Retrieve a Logger object
 
     Parameters
     ----------
     name : str, optional
         The name of the logging object
+    level : str, optional
+        The level of verbosity for the logger
     """
     if name is None:
-        pass
+        name = ""
+    else:
+        name = "." + name
 
-    log = logging.getLogger("haptools " + name)
-    db_time = "|%(asctime)s" if verbosity == "DEBUG" else ""
-    logging.basicConfig(
-        format="[%(levelname)8s" + db_time + "] %(message)s (%(filename)s:%(lineno)s)",
-        level=verbosity,
+    # create logger
+    logger = logging.getLogger("haptools" + name)
+    logger.setLevel(level)
+
+    # create console handler and set level to debug
+    ch = logging.StreamHandler()
+    ch.setLevel(level)
+
+    # create formatter
+    db_time = "|%(asctime)s" if level == "DEBUG" else ""
+    formatter = logging.Formatter(
+        fmt="[%(levelname)8s" + db_time + "] %(message)s (%(filename)s:%(lineno)s)",
         datefmt="%H:%M:%S",
     )
+
+    # add formatter to ch
+    ch.setFormatter(formatter)
+
+    # add ch to logger
+    logger.addHandler(ch)
+
+    return logger
diff --git a/haptools/sim_phenotype.py b/haptools/sim_phenotype.py
@@ -1,11 +1,12 @@
 from __future__ import annotations
+import logging
 from pathlib import Path
 from dataclasses import dataclass, field
-from logging import getLogger, Logger, DEBUG
 
 import numpy as np
 import numpy.typing as npt
 
+from .logging import getLogger
 from .data import Haplotype as HaplotypeBase
 from .data import (
     Extra,
@@ -45,7 +46,7 @@ class PhenoSimulator:
         Simulated phenotypes; filled by :py:meth:`~.PhenoSimular.run`
     rng: np.random.Generator, optional
         A numpy random number generator
-    log: Logger
+    log: logging.Logger
         A logging instance for recording debug statements
 
     Examples
@@ -63,7 +64,7 @@ def __init__(
         genotypes: Genotypes,
         output: Path = Path("/dev/stdout"),
         seed: int = None,
-        log: Logger = None,
+        log: logging.Logger = None,
     ):
         """
         Initialize a PhenoSimulator object
@@ -81,15 +82,15 @@ def __init__(
 
             This is useful if you want the generated phenotypes to be the same across
             multiple PhenoSimulator instances. If not provided, it will be random.
-        log: Logger, optional
+        log: logging.Logger, optional
             A logging instance for recording debug statements
         """
         self.gens = genotypes
         self.phens = Phenotypes(fname=output)
         self.phens.data = None
         self.phens.samples = self.gens.samples
         self.rng = np.random.default_rng(seed)
-        self.log = log or getLogger(self.__class__.__name__)
+        self.log = log or logging.getLogger(self.__class__.__name__)
 
     def run(
         self,
@@ -169,7 +170,7 @@ def run(
         self.log.info(f"Adding environmental component {noise} for h^2 {heritability}")
         # finally, add everything together to get the simulated phenotypes
         pt_noise = self.rng.normal(0, np.sqrt(noise), size=pt.shape)
-        if self.log.getEffectiveLevel() == DEBUG:
+        if self.log.getEffectiveLevel() == logging.DEBUG:
             # if we're in debug mode, compute the pearson correlation and report it
             # but don't do this otherwise to keep things fast
             corr = np.corrcoef(pt, pt + pt_noise)[1, 0]
@@ -213,7 +214,7 @@ def simulate_pt(
     haplotype_ids: set[str] = None,
     chunk_size: int = None,
     output: Path = Path("-"),
-    log: Logger = None,
+    log: logging.Logger = None,
 ):
     """
     Haplotype-aware phenotype simulation. Create a set of simulated phenotypes from a
@@ -272,15 +273,11 @@ def simulate_pt(
         not in PGEN format.
     output : Path, optional
         The location to which to write the simulated phenotypes
-    log : Logger, optional
+    log : logging.Logger, optional
         The logging module for this task
     """
     if log is None:
-        log = logging.getLogger("haptools simphenotype")
-        logging.basicConfig(
-            format="[%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)",
-            level="ERROR",
-        )
+        log = getLogger(name="simphenotype", level="ERROR")
 
     log.info("Loading haplotypes")
     hp = Haplotypes(haplotypes, haplotype=Haplotype, log=log)

diff --git a/haptools/transform.py b/haptools/transform.py
@@ -10,6 +10,7 @@
 from pysam import VariantFile
 
 from haptools import data
+from .logging import getLogger
 
 
 @dataclass
@@ -549,11 +550,7 @@ def transform_haps(
         A logging module to which to write messages about progress and any errors
     """
     if log is None:
-        log = logging.getLogger("haptools transform")
-        logging.basicConfig(
-            format="[%(levelname)8s] %(message)s (%(filename)s:%(lineno)s)",
-            level="ERROR",
-        )
+        log = getLogger(name="transform", level="ERROR")
 
     haps_class = HaplotypesAncestry if ancestry else data.Haplotypes
     log.info("Loading haplotypes")