set up logging

Author: nebfield

pgscatalog.combineapp/src/pgscatalog/combineapp/cli.py

@@ -15,26 +15,25 @@
 
 
 def run():
-    logging.basicConfig(
-        format="%(asctime)s %(name)s %(levelname)-8s %(message)s",
-        level=logging.WARNING,
-        datefmt="%Y-%m-%d %H:%M:%S",
-    )
-
     args = parse_args()
 
     if args.verbose:
-        logger.setLevel(logging.INFO)
+        logging.getLogger("pgscatalog.corelib").setLevel(logging.DEBUG)
+        logger.setLevel(logging.DEBUG)
+        logger.debug("Verbose logging enabled")
 
     out_path = pathlib.Path(args.outfile)
 
     if out_path.exists():
-        raise FileExistsError(f"{args.outfile}")
+        logger.critical(f"Output file already exists: {args.outfile}")
+        raise FileExistsError
 
     match x := out_path.name:
         case _ if x.endswith("gz"):
+            logger.debug("Compressing output with gzip")
             compress_output = True
         case _:
+            logger.debug("Not compressing output")
             compress_output = False
 
     paths = list(set(args.scorefiles))  # unique paths only
@@ -52,6 +51,7 @@ def run():
     if args.liftover:
         chain_dir = pathlib.Path(args.chain_dir)
         if not chain_dir.exists():
+            logger.critical(f"Chain directory is missing: {chain_dir}")
             raise FileNotFoundError
 
         liftover_kwargs = {
@@ -65,7 +65,7 @@ def run():
     with concurrent.futures.ThreadPoolExecutor() as executor:
         futures = []
         for scorefile in scoring_files:
-            logger.info(f"Submitting {scorefile!r}")
+            logger.info(f"Submitting {scorefile!r} for execution")
             futures.append(
                 executor.submit(
                     normalise,

pgscatalog.corelib/src/pgscatalog/corelib/__init__.py

@@ -1,3 +1,5 @@
+import logging
+
 from ._config import Config
 from .catalogapi import ScoreQueryResult, CatalogQuery, CatalogCategory
 from .scorefiles import ScoringFiles, ScoringFile, NormalisedScoringFile
@@ -24,6 +26,9 @@
     SamplesheetFormatError,
 )
 
+log_fmt = "%(name)s: %(asctime)s %(levelname)-8s %(message)s"
+logging.basicConfig(format=log_fmt, datefmt="%Y-%m-%d %H:%M:%S")
+logger = logging.getLogger(__name__)
 
 __all__ = [
     "BasePGSException",

pgscatalog.corelib/src/pgscatalog/corelib/_download.py

@@ -27,6 +27,8 @@ def score_download_failed(retry_state):
         raise ScoreChecksumError("All checksum retries failed") from e
     except Exception as download_exc:
         raise ScoreDownloadError("All download retries failed") from download_exc
+    finally:
+        logger.critical(f"Score download failed after all retries: {retry_state!r}")
 
 
 @tenacity.retry(
@@ -81,6 +83,7 @@ def ftp_fallback(retry_state):
     else:
         # no exceptions thrown, move the temporary file to the final output path
         os.rename(score_f.name, out_path)
+        logger.info(f"FTP download OK, {out_path} checksum validation passed")
 
 
 @tenacity.retry(
@@ -124,3 +127,4 @@ def https_download(*, url, out_path, directory, overwrite):
     else:
         # no exceptions thrown, move the temporary file to the final output path
         os.rename(f.name, out_path)
+        logger.info(f"HTTPS download OK, {out_path} checksum validation passed")

pgscatalog.corelib/src/pgscatalog/corelib/_normalise.py

@@ -24,6 +24,10 @@ def normalise(
     2. remap harmonised data, failed harmonisations get None'd
     3. log and optionally drop bad variants
     """
+    logger.info(
+        f"Normalise parameters: {drop_missing=}, {liftover=}, {chain_dir=}, {target_build=}"
+    )
+
     if liftover:
         variants = lift(
             scoring_file=scoring_file,
@@ -169,23 +173,25 @@ def assign_effect_type(variants):
 
     The most common type of effect type is additive:
 
-    >>> variant = ScoreVariant(**{"effect_allele": "A", "effect_weight": 5, "accession": "test", "row_nr": 0, "is_recessive": "FALSE", "is_dominant": "FALSE"})
+    >>> variant = ScoreVariant(**{"effect_allele": "A", "effect_weight": 5, "accession": "test", "row_nr": 0, "is_recessive": "False", "is_dominant": "False"})
     >>> list(assign_effect_type([variant])) # doctest: +ELLIPSIS
     [ScoreVariant(...,effect_type=EffectType.ADDITIVE,...)]
-    >>> variant = ScoreVariant(**{"effect_allele": "A", "effect_weight": 5, "accession": "test", "row_nr": 0, "is_recessive": "TRUE", "is_dominant": "FALSE"})
+    >>> variant = ScoreVariant(**{"effect_allele": "A", "effect_weight": 5, "accession": "test", "row_nr": 0, "is_recessive": "True", "is_dominant": "False"})
     >>> list(assign_effect_type([variant])) # doctest: +ELLIPSIS
     [ScoreVariant(...,effect_type=EffectType.RECESSIVE,...)]
-    >>> variant = ScoreVariant(**{"effect_allele": "A", "effect_weight": 5, "accession": "test", "row_nr": 0, "is_recessive": "FALSE", "is_dominant": "TRUE"})
+    >>> variant = ScoreVariant(**{"effect_allele": "A", "effect_weight": 5, "accession": "test", "row_nr": 0, "is_recessive": "False", "is_dominant": "True"})
     >>> list(assign_effect_type([variant])) # doctest: +ELLIPSIS
     [ScoreVariant(...,effect_type=EffectType.DOMINANT,...)]
+
+    is_recessive and is_dominant fields are parsed from strings to bools during __init__.
     """
     for variant in variants:
         match (variant.is_recessive, variant.is_dominant):
-            case (None, None) | ("FALSE", "FALSE"):
+            case (None, None) | (False, False):
                 pass  # default value is additive, pass to break match and yield
-            case ("FALSE", "TRUE"):
+            case (False, True):
                 variant.effect_type = EffectType.DOMINANT
-            case ("TRUE", "FALSE"):
+            case (True, False):
                 variant.effect_type = EffectType.RECESSIVE
             case _:
                 logger.critical(f"Bad effect type setting: {variant}")

pgscatalog.corelib/src/pgscatalog/corelib/catalogapi.py

@@ -1,5 +1,6 @@
 """ Classes and functions related to the PGS Catalog API """
 import enum
+import logging
 
 import httpx
 import tenacity
@@ -9,6 +10,9 @@
 from ._config import Config
 
 
+logger = logging.getLogger(__name__)
+
+
 class CatalogCategory(enum.Enum):
     """The three main categories in the PGS Catalog
 
@@ -121,6 +125,7 @@ def infer_category(self):
             case _:
                 raise InvalidAccessionError(f"Invalid accession: {accession!r}")
 
+        logger.debug(f"{accession=} {category=}")
         return category
 
     def get_query_url(self):
@@ -153,14 +158,14 @@ def get_query_url(self):
 
         Child traits terms aren't included by default. Only traits can have children.
         """
+        urls: list[str] | str = []
         match (self.category, self.accession):
             case CatalogCategory.TRAIT, str():
                 child_flag: int = int(self.include_children)
-                return f"{self._rest_url_root}/trait/{self.accession}?include_children={child_flag}"
+                urls = f"{self._rest_url_root}/trait/{self.accession}?include_children={child_flag}"
             case CatalogCategory.SCORE, str():
-                return [f"{self._rest_url_root}/score/search?pgs_ids={self.accession}"]
+                urls = [f"{self._rest_url_root}/score/search?pgs_ids={self.accession}"]
             case CatalogCategory.SCORE, list():
-                urls: list[str] = []
                 for chunk in self._chunk_accessions():
                     chunked_accession = ",".join(chunk)
                     urls.append(
@@ -169,12 +174,14 @@ def get_query_url(self):
                     )
                 return urls
             case CatalogCategory.PUBLICATION, str():
-                return f"{self._rest_url_root}/publication/{self.accession}"
+                urls = f"{self._rest_url_root}/publication/{self.accession}"
             case _:
                 raise ValueError(
                     f"Invalid CatalogCategory and accession type: {self.category!r}, "
                     f"type({self.accession!r})"
                 )
+        logger.debug(f"Resolved API query URL: {urls}")
+        return urls
 
     def _chunk_accessions(self):
         size = 50  # /rest/score/{pgs_id} limit when searching multiple IDs
@@ -323,10 +330,15 @@ def get_download_url(self, genome_build=None):
         """
         match build := genome_build:
             case GenomeBuild() if build == GenomeBuild.GRCh37:
-                return self.ftp_grch37_url
+                url = self.ftp_grch37_url
             case GenomeBuild() if build == GenomeBuild.GRCh38:
-                return self.ftp_grch38_url
+                url = self.ftp_grch38_url
             case None:
-                return self.ftp_url
+                url = self.ftp_url
             case _:
                 raise ValueError(f"Invalid genome build {build!r}")
+
+        logger.debug(
+            f"Scoring file download URL for {self.pgs_id} with {build=}: {url}"
+        )
+        return url

pgscatalog.corelib/src/pgscatalog/corelib/scorefiles.py

@@ -259,6 +259,8 @@ def __init__(self, identifier, target_build=None, query_result=None, **kwargs):
             self._directory = self.local_path.parent
 
     def _init_from_accession(self, accession, target_build):
+        logger.debug(f"Instantiating ScoringFile from accession {accession.pgs_id}")
+
         match self._identifier:
             case ScoreQueryResult():
                 # skip hitting the API unnecessarily
@@ -288,6 +290,8 @@ def _init_from_accession(self, accession, target_build):
         self.local_path = None
 
     def _init_from_path(self, target_build=None):
+        logger.debug(f"Instantiating ScoringFile from {self.local_path=}")
+
         if target_build is not None:
             raise ValueError(
                 "target_build must be None for local files. "
@@ -395,6 +399,7 @@ def download(self, directory, overwrite=False):
         self._directory = pathlib.Path(directory)
         fn = pathlib.Path(self.path).name
         out_path = self._directory / fn
+        logger.debug(f"Downloading {self.path} to {out_path}")
         https_download(
             url=self.path,
             out_path=out_path,
@@ -467,6 +472,19 @@ def normalise(
         ('rs78540526', '11', 69701882)
 
         A :class:`LiftoverError` is only raised when many converted coordinates are missing.
+
+        Normalising converts the is_dominant and is_recessive optional fields in
+        scoring files into an EffectType:
+
+        >>> testpath = Config.ROOT_DIR / "tests" / "PGS000802_hmPOS_GRCh37.txt"
+        >>> variants = ScoringFile(testpath).normalise()
+        >>> for i, x in enumerate(variants): # doctest: +ELLIPSIS
+        ...     (x.is_dominant, x.is_recessive, x.effect_type)
+        ...     if i == 2:
+        ...         break
+        (True, False, EffectType.DOMINANT)
+        (False, True, EffectType.RECESSIVE)
+        (True, False, EffectType.DOMINANT)
         """
         yield from normalise(
             scoring_file=self,
@@ -478,6 +496,7 @@ def normalise(
 
     def get_log(self, drop_missing=False, variant_log=None):
         """Create a JSON log from a ScoringFile's header and variant rows."""
+        logger.debug(f"Creating JSON log for {self!r}")
         log = {}
 
         for attr in self._header.fields:
@@ -630,19 +649,25 @@ def __init__(self, *args, target_build=None, **kwargs):
         for arg in flargs:
             match arg:
                 case ScoringFile() if arg.target_build == target_build:
+                    logger.info("ScoringFile build matches target build")
                     scorefiles.append(arg)
                 case ScoringFile() if arg.target_build != target_build:
                     raise ValueError(
                         f"{arg.target_build=} doesn't match {target_build=}"
                     )
                 case _ if pathlib.Path(arg).is_file() and target_build is None:
+                    logger.info(f"Local path: {arg}, no target build is OK")
                     scorefiles.append(ScoringFile(arg))
                 case _ if pathlib.Path(arg).is_file() and target_build is not None:
+                    logger.critical(f"{arg} is a local file and {target_build=}")
                     raise ValueError(
                         "Can't load local scoring file when target_build is set"
                         "Try .normalise() method to do liftover, or load harmonised scoring files from PGS Catalog"
                     )
                 case str() if arg.startswith("PGP") or "_" in arg:
+                    logger.info(
+                        "Term associated with multiple scores detected (PGP or trait)"
+                    )
                     self.include_children = kwargs.get("include_children", None)
                     traitpub_query = CatalogQuery(
                         accession=arg, include_children=self.include_children
@@ -656,6 +681,7 @@ def __init__(self, *args, target_build=None, **kwargs):
                         ]
                     )
                 case str() if arg.startswith("PGS"):
+                    logger.info("PGS ID detected")
                     pgs_batch.append(arg)
                 case str():
                     raise ValueError(f"{arg!r} is not a valid path or an accession")
@@ -664,6 +690,7 @@ def __init__(self, *args, target_build=None, **kwargs):
 
         # batch PGS IDs to avoid overloading the API
         batched_queries = CatalogQuery(accession=pgs_batch).score_query()
+        logger.debug(f"Batching queries to PGS Catalog API: {pgs_batch}")
         batched_scores = [
             ScoringFile(x, target_build=target_build) for x in batched_queries
         ]

pgscatalog.corelib/src/pgscatalog/corelib/scorevariant.py

@@ -204,8 +204,23 @@ def __init__(
 
         self.hm_inferOtherAllele: Optional[str] = hm_inferOtherAllele
         self.hm_source: Optional[str] = hm_source
-        self.is_dominant: Optional[bool] = is_dominant
-        self.is_recessive: Optional[bool] = is_recessive
+
+        match is_dominant:
+            case True | "True":
+                self.is_dominant = True
+            case None:
+                self.is_dominant = None
+            case _:
+                self.is_dominant = False
+
+        match is_recessive:
+            case True | "True":
+                self.is_recessive = True
+            case None:
+                self.is_recessive = None
+            case _:
+                self.is_recessive = False
+
         self.hm_rsID: Optional[str] = hm_rsID
         self.hm_match_chr: Optional[str] = hm_match_chr
         self.hm_match_pos: Optional[str] = hm_match_pos

pgscatalog.corelib/tests/PGS000802_hmPOS_GRCh37.txt

@@ -0,0 +1,39 @@
+###PGS CATALOG SCORING FILE - see https://www.pgscatalog.org/downloads/#dl_ftp_scoring for additional information
+#format_version=2.0
+##POLYGENIC SCORE (PGS) INFORMATION
+#pgs_id=PGS000802
+#pgs_name=CRC_19
+#trait_reported=Colorectal cancer
+#trait_mapped=colorectal cancer
+#trait_efo=EFO_0005842
+#genome_build=NR
+#variants_number=19
+#weight_type=NR
+##SOURCE INFORMATION
+#pgp_id=PGP000191
+#citation=He CY et al. Genomics (2021). doi:10.1016/j.ygeno.2021.01.025
+##HARMONIZATION DETAILS
+#HmPOS_build=GRCh37
+#HmPOS_date=2022-07-28
+#HmPOS_match_chr={"True": null, "False": null}
+#HmPOS_match_pos={"True": null, "False": null}
+rsID	chr_name	chr_position	effect_allele	other_allele	effect_weight	allelefrequency_effect	is_dominant	is_recessive	locus_name	hm_source	hm_rsID	hm_chr	hm_pos	hm_inferOtherAllele
+rs10936599	3	170974795	T	C	0.123	0.377	True	False	MYNN	ENSEMBL	rs10936599	3	169492101	
+rs6061231	20	60390312	A	C	0.491	0.892	False	True	LOC100128184, RPS21	ENSEMBL	rs6061231	20	60956917	
+rs10774214	12	4238613	C	T	0.122	0.637	True	False	LOC100129645, CCND2	ENSEMBL	rs10774214	12	4368352	
+rs10795668	10	8741225	A	G	0.147	0.61	True	False	LOC338591, LOC389936	ENSEMBL	rs10795668	10	8701219	
+rs11903757	2	192295449	T	C	0.185	0.925	False	True	LOC100132133, hCG_2045843	ENSEMBL	rs11903757	2	192587204	
+rs12603526	17	747343	T	C	0.142	0.695	False	True	NXN	ENSEMBL	rs12603526	17	800593	
+rs1321311	6	36730878	G	T	0.135	0.876	True	False	SFRS3, LOC389386	ENSEMBL	rs1321311	6	36622900	
+rs2423279	20	7760350	T	C	0.193	0.715	False	True	FUSIP1P2	ENSEMBL	rs2423279	20	7812350	
+rs3802842	11	110676919	A	C	0.177	0.663	True	False	LOC120376	ENSEMBL	rs3802842	11	111171709	
+rs4813802	20	6647595	T	G	0.189	0.816	False	True	LOC728383	ENSEMBL	rs4813802	20	6699595	
+rs6469656	8	117716969	G	A	0.204	0.627	False	True	TRPS1, EIF3H	ENSEMBL	rs6469656	8	117647788	
+rs647161	5	134526991	C	A	0.277	0.663	False	True	LOC389328, H2AFY	ENSEMBL	rs647161	5	134499092	
+rs704017	10	80489138	A	G	0.123	0.644	True	False	LOC100132987, ZMIZ1	ENSEMBL	rs704017	10	80819132	
+rs7315438	12	114375786	C	T	0.146	0.388	True	False	TBX3, LOC100129020	ENSEMBL	rs7315438	12	115891403	
+rs10411210	19	38224140	C	T	0.232	0.836	False	False	RHPN2	ENSEMBL	rs10411210	19	33532300	
+rs12953717	18	44707927	T	C	0.157	0.789	False	False	SMAD7	ENSEMBL	rs12953717	18	46453929	
+rs16969681	15	30780403	T	C	0.175	0.583	False	False	C15orf45, GREM1	ENSEMBL	rs16969681	15	32993111	
+rs1801133	1	11778965	A	G	0.16	0.592	False	False	MTHFR	ENSEMBL	rs1801133	1	11856378	
+rs6983267	8	128482487	G	T	0.217	0.376	False	False	FAM84B, POU5F1P1	ENSEMBL	rs6983267	8	128413305