From c141f3f73270e868822d5bbc6e1a887831d4957e Mon Sep 17 00:00:00 2001 From: mathiasg Date: Mon, 26 Sep 2022 16:31:15 -0400 Subject: [PATCH 1/9] ENH: Add logger creation utility function --- sdcflows/utils/misc.py | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/sdcflows/utils/misc.py b/sdcflows/utils/misc.py index b00c4cc641..ad91affc1e 100644 --- a/sdcflows/utils/misc.py +++ b/sdcflows/utils/misc.py @@ -67,3 +67,17 @@ def get_free_mem(): return round(virtual_memory().free, 1) except Exception: return None + + +def create_logger(name: str, level: int = 40): + import logging + logger = logging.getLogger(name) + logger.setLevel(level) + + if not logger.handlers: + handler = logging.StreamHandler() + handler.setLevel(level) + formatter = logging.Formatter('[%(name)s %(asctime)s] - %(levelname)s: %(message)s') + handler.setFormatter(formatter) + logger.addHandler(handler) + return logger From 39a2296b7cef34efc1c71d53d115cfce71feff79 Mon Sep 17 00:00:00 2001 From: mathiasg Date: Mon, 26 Sep 2022 16:31:43 -0400 Subject: [PATCH 2/9] ENH: Add verbose option when finding estimators --- sdcflows/utils/wrangler.py | 87 +++++++++++++++++++++++++------------- 1 file changed, 58 insertions(+), 29 deletions(-) diff --git a/sdcflows/utils/wrangler.py b/sdcflows/utils/wrangler.py index e31805a515..a026cae2e5 100644 --- a/sdcflows/utils/wrangler.py +++ b/sdcflows/utils/wrangler.py @@ -24,10 +24,20 @@ from itertools import product from contextlib import suppress from pathlib import Path +from typing import Optional, Union +from bids.layout import BIDSLayout from bids.utils import listify -def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmapless=False): + +def find_estimators(*, + layout: BIDSLayout, + subject: str, + sessions: Optional[list[str]] = None, + fmapless: Union[bool, set] = True, + force_fmapless: bool = False, + verbose: bool = False, +): """ Apply basic heuristics to automatically find available data for fieldmap estimation. @@ -53,6 +63,8 @@ def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmap force_fmapless : :obj:`bool` When some other fieldmap estimation methods have been found, fieldmap-less estimation will be skipped except if ``force_fmapless`` is ``True``. + verbose + If enabled, display steps taken to find estimators. Returns ------- @@ -244,9 +256,13 @@ def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmap """ from .. import fieldmaps as fm + from .misc import create_logger from bids.layout import Query from bids.exceptions import BIDSEntityError + # Set up logger (logs only visable if verbose) + logger = create_logger('sdcflows.wrangler', level=10 if verbose else 40) + base_entities = { "subject": subject, "extension": [".nii", ".nii.gz"], @@ -254,36 +270,41 @@ def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmap } subject_root = Path(layout.root) / f"sub-{subject}" - sessions = sessions if sessions else layout.get_sessions(subject=subject) - + sessions = sessions or layout.get_sessions(subject=subject) fmapless = fmapless or {} if fmapless is True: fmapless = {"bold", "dwi"} estimators = [] - b0_ids = tuple() + # Step 1. Use B0FieldIdentifier metadata + has_B0FI = False with suppress(BIDSEntityError): b0_ids = layout.get_B0FieldIdentifiers(**base_entities) + has_B0FI = True - for b0_id in b0_ids: - # Found B0FieldIdentifier metadata entries - entities = base_entities.copy() - entities["B0FieldIdentifier"] = b0_id + if has_B0FI: + logger.debug("Dataset includes B0FieldIdentifier metadata. All `IntendedFor` metadata will be ignored.") + for b0_id in b0_ids: + # Found B0FieldIdentifier metadata entries + b0_entities = base_entities.copy() + b0_entities["B0FieldIdentifier"] = b0_id - _e = fm.FieldmapEstimation([ - fm.FieldmapFile(fmap.path, metadata=fmap.get_metadata()) - for fmap in layout.get(**entities) - ]) - estimators.append(_e) + _e = fm.FieldmapEstimation([ + fm.FieldmapFile(fmap.path, metadata=fmap.get_metadata()) + for fmap in layout.get(**b0_entities) + ]) + logger.debug("Found PEPOLAR estimation %s from sources %s", _e, [x.path for x in _e.sources]) + estimators.append(_e) - # As no B0FieldIdentifier(s) were found, try several heuristics + # Step 2. If no B0FieldIdentifiers were found, try several heuristics if not estimators: # Set up B0 fieldmap strategies: for fmap in layout.get(suffix=["fieldmap", "phasediff", "phase1"], **base_entities): e = fm.FieldmapEstimation( fm.FieldmapFile(fmap.path, metadata=fmap.get_metadata()) ) + logger.debug("Found estimation %s from fmap %s", e, fmap.path) estimators.append(e) # A bunch of heuristics to select EPI fieldmaps @@ -303,18 +324,21 @@ def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmap for fmap in layout.get(direction=dirs, **entities) ] ) + logger.debug("Found PEPOLAR estimation %s from sources %s", e, [x.path for x in e.sources]) estimators.append(e) # At this point, only single-PE _epi files WITH ``IntendedFor`` can # be automatically processed. has_intended = tuple() with suppress(ValueError): - has_intended = layout.get(suffix="epi", IntendedFor=Query.ANY, **base_entities) + has_intended = layout.get(suffix="epi", IntendedFor=Query.REQUIRED, **base_entities) for epi_fmap in has_intended: if epi_fmap.path in fm._estimators.sources: + logger.debug("Single PE fieldmap %s already in use", epi_fmap.path) continue # skip EPI images already considered above + logger.debug("Found single PE fieldmap %s", epi_fmap.path) epi_base_md = epi_fmap.get_metadata() # There are two possible interpretations of an IntendedFor list: @@ -326,19 +350,23 @@ def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmap for intent in listify(epi_base_md["IntendedFor"]): target = layout.get_file(str(subject_root / intent)) if target is None: + logger.debug("Single PE target %s not found", target) continue + logger.debug("Found single PE target %s", target.path) # The new estimator is IntendedFor the individual targets, # even if the EPI file is IntendedFor multiple estimator_md = epi_base_md.copy() estimator_md["IntendedFor"] = [intent] with suppress(ValueError, TypeError, fm.MetadataError): - estimators.append( - fm.FieldmapEstimation( - [fm.FieldmapFile(epi_fmap.path, metadata=estimator_md), - fm.FieldmapFile(target.path, metadata=target.get_metadata())] - ) + e = fm.FieldmapEstimation( + [ + fm.FieldmapFile(epi_fmap.path, metadata=estimator_md), + fm.FieldmapFile(target.path, metadata=target.get_metadata()) + ] ) + logger.debug("Found estimation %s from fmap %s", e, epi_fmap.path) + estimators.append(e) if estimators and not force_fmapless: fmapless = False @@ -347,6 +375,7 @@ def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmap anat_file = layout.get(suffix="T1w", **base_entities) if not fmapless or not anat_file: + logger.debug("Skipping fmap-less estimation") return estimators from .epimanip import get_trt @@ -386,15 +415,15 @@ def find_estimators(*, layout, subject, sessions=None, fmapless=True, force_fmap ] ) ) - estimators.append( - fm.FieldmapEstimation( - [ - fm.FieldmapFile( - anat_file[0], metadata={"IntendedFor": fmpaths} - ), - *fmfiles, - ] - ) + e = fm.FieldmapEstimation( + [ + fm.FieldmapFile( + anat_file[0], metadata={"IntendedFor": fmpaths} + ), + *fmfiles, + ] ) + logger.debug("Fieldmap-less estimation %s with sources %s", e, [x.path for x in e.sources]) + estimators.append(e) return estimators From a392c8589c18b9fd2c1044c7c3426ed2877894a9 Mon Sep 17 00:00:00 2001 From: mathiasg Date: Mon, 26 Sep 2022 16:49:13 -0400 Subject: [PATCH 3/9] ENH: Add verbose to find estimator CLI --- sdcflows/cli/find_estimators.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/sdcflows/cli/find_estimators.py b/sdcflows/cli/find_estimators.py index 9595193983..e43fcb9d66 100644 --- a/sdcflows/cli/find_estimators.py +++ b/sdcflows/cli/find_estimators.py @@ -32,6 +32,12 @@ def _parser(): help="Path to a PyBIDS database folder, for faster indexing (especially " "useful for large datasets). Will be created if not present." ) + parser.add_argument( + "-v", + "--verbose", + action="store_true", + help="Print information while finding estimators (Useful for debugging)", + ) return parser @@ -76,7 +82,7 @@ def main(argv=None): estimators_record = {} for subject in subjects: estimators_record[subject] = find_estimators( - layout=layout, subject=subject, fmapless=pargs.fmapless + layout=layout, subject=subject, fmapless=pargs.fmapless, verbose=pargs.verbose, ) # pretty print results From 90b4c454e22309af323505d5b83832e69cf474f0 Mon Sep 17 00:00:00 2001 From: mathiasg Date: Mon, 26 Sep 2022 17:21:53 -0400 Subject: [PATCH 4/9] FIX: Overwrite existing logger handler --- sdcflows/utils/misc.py | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/sdcflows/utils/misc.py b/sdcflows/utils/misc.py index ad91affc1e..b87f37bac4 100644 --- a/sdcflows/utils/misc.py +++ b/sdcflows/utils/misc.py @@ -21,6 +21,7 @@ # https://www.nipreps.org/community/licensing/ # """Basic miscellaneous utilities.""" +import logging def front(inlist): @@ -69,15 +70,15 @@ def get_free_mem(): return None -def create_logger(name: str, level: int = 40): - import logging +def create_logger(name: str, level: int = 40) -> logging.Logger: logger = logging.getLogger(name) logger.setLevel(level) - - if not logger.handlers: - handler = logging.StreamHandler() - handler.setLevel(level) - formatter = logging.Formatter('[%(name)s %(asctime)s] - %(levelname)s: %(message)s') - handler.setFormatter(formatter) - logger.addHandler(handler) + # clear any existing handlers + logger.handlers.clear() + handler = logging.StreamHandler() + handler.setLevel(level) + # formatter = logging.Formatter('[%(name)s %(asctime)s] - %(levelname)s: %(message)s') + formatter = logging.Formatter('[%(name)s - %(levelname)s]: %(message)s') + handler.setFormatter(formatter) + logger.addHandler(handler) return logger From 67cab9edc51e2667d32a94b053f909b7c5f20fee Mon Sep 17 00:00:00 2001 From: mathiasg Date: Mon, 26 Sep 2022 22:10:32 -0400 Subject: [PATCH 5/9] ENH: Improve logging messages --- sdcflows/utils/wrangler.py | 46 +++++++++++++++++++++++++++++--------- 1 file changed, 36 insertions(+), 10 deletions(-) diff --git a/sdcflows/utils/wrangler.py b/sdcflows/utils/wrangler.py index a026cae2e5..c063d02e3c 100644 --- a/sdcflows/utils/wrangler.py +++ b/sdcflows/utils/wrangler.py @@ -290,12 +290,17 @@ def find_estimators(*, b0_entities = base_entities.copy() b0_entities["B0FieldIdentifier"] = b0_id - _e = fm.FieldmapEstimation([ + e = fm.FieldmapEstimation([ fm.FieldmapFile(fmap.path, metadata=fmap.get_metadata()) for fmap in layout.get(**b0_entities) ]) - logger.debug("Found PEPOLAR estimation %s from sources %s", _e, [x.path for x in _e.sources]) - estimators.append(_e) + logger.debug( + "Found %s estimation from %d sources:\n- %s", + e.method.name, + len(e.sources), + "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), + ) + estimators.append(e) # Step 2. If no B0FieldIdentifiers were found, try several heuristics if not estimators: @@ -304,7 +309,12 @@ def find_estimators(*, e = fm.FieldmapEstimation( fm.FieldmapFile(fmap.path, metadata=fmap.get_metadata()) ) - logger.debug("Found estimation %s from fmap %s", e, fmap.path) + logger.debug( + "Found %s estimation from %d sources:\n- %s", + e.method.name, + len(e.sources), + "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), + ) estimators.append(e) # A bunch of heuristics to select EPI fieldmaps @@ -324,7 +334,12 @@ def find_estimators(*, for fmap in layout.get(direction=dirs, **entities) ] ) - logger.debug("Found PEPOLAR estimation %s from sources %s", e, [x.path for x in e.sources]) + logger.debug( + "Found %s estimation from %d sources:\n- %s", + e.method.name, + len(e.sources), + "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), + ) estimators.append(e) # At this point, only single-PE _epi files WITH ``IntendedFor`` can @@ -335,10 +350,10 @@ def find_estimators(*, for epi_fmap in has_intended: if epi_fmap.path in fm._estimators.sources: - logger.debug("Single PE fieldmap %s already in use", epi_fmap.path) + logger.debug("Skipping fieldmap %s (already in use)", epi_fmap.relpath) continue # skip EPI images already considered above - logger.debug("Found single PE fieldmap %s", epi_fmap.path) + logger.debug("Found single PE fieldmap %s", epi_fmap.relpath) epi_base_md = epi_fmap.get_metadata() # There are two possible interpretations of an IntendedFor list: @@ -353,7 +368,7 @@ def find_estimators(*, logger.debug("Single PE target %s not found", target) continue - logger.debug("Found single PE target %s", target.path) + logger.debug("Found single PE target %s", target.relpath) # The new estimator is IntendedFor the individual targets, # even if the EPI file is IntendedFor multiple estimator_md = epi_base_md.copy() @@ -365,7 +380,12 @@ def find_estimators(*, fm.FieldmapFile(target.path, metadata=target.get_metadata()) ] ) - logger.debug("Found estimation %s from fmap %s", e, epi_fmap.path) + logger.debug( + "Found %s estimation from %d sources:\n- %s", + e.method.name, + len(e.sources), + "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), + ) estimators.append(e) if estimators and not force_fmapless: @@ -378,6 +398,7 @@ def find_estimators(*, logger.debug("Skipping fmap-less estimation") return estimators + logger.debug("Attempting fmap-less estimation") from .epimanip import get_trt for ses, suffix in sorted(product(sessions or (None,), fmapless)): @@ -423,7 +444,12 @@ def find_estimators(*, *fmfiles, ] ) - logger.debug("Fieldmap-less estimation %s with sources %s", e, [x.path for x in e.sources]) + logger.debug( + "Found %s estimation from %d sources:\n- %s", + e.method.name, + len(e.sources), + "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), + ) estimators.append(e) return estimators From e502208646c1cde31695d3fe2f36d3d992112858 Mon Sep 17 00:00:00 2001 From: mathiasg Date: Mon, 26 Sep 2022 22:26:44 -0400 Subject: [PATCH 6/9] FIX: Make Date: Mon, 26 Sep 2022 22:36:58 -0400 Subject: [PATCH 7/9] STY: Satisfy flake8 --- sdcflows/utils/wrangler.py | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/sdcflows/utils/wrangler.py b/sdcflows/utils/wrangler.py index 96fb74b6c3..5ef108a44a 100644 --- a/sdcflows/utils/wrangler.py +++ b/sdcflows/utils/wrangler.py @@ -29,8 +29,8 @@ from bids.utils import listify - -def find_estimators(*, +def find_estimators( + *, layout: BIDSLayout, subject: str, sessions: Optional[List[str]] = None, @@ -284,7 +284,10 @@ def find_estimators(*, has_B0FI = True if has_B0FI: - logger.debug("Dataset includes B0FieldIdentifier metadata. All `IntendedFor` metadata will be ignored.") + logger.debug( + "Dataset includes `B0FieldIdentifier` metadata." + "Any data missing this metadata will be ignored." + ) for b0_id in b0_ids: # Found B0FieldIdentifier metadata entries b0_entities = base_entities.copy() From 54233eb809a96eba27fd86c6ce746c02c17f04d4 Mon Sep 17 00:00:00 2001 From: mathiasg Date: Tue, 27 Sep 2022 10:15:05 -0400 Subject: [PATCH 8/9] RF: Move identical debug logs to helper function --- sdcflows/utils/wrangler.py | 55 ++++++++++++++++---------------------- 1 file changed, 23 insertions(+), 32 deletions(-) diff --git a/sdcflows/utils/wrangler.py b/sdcflows/utils/wrangler.py index 5ef108a44a..4ba42f37c1 100644 --- a/sdcflows/utils/wrangler.py +++ b/sdcflows/utils/wrangler.py @@ -21,6 +21,7 @@ # https://www.nipreps.org/community/licensing/ # """Find fieldmaps on the BIDS inputs for :abbr:`SDC (susceptibility distortion correction)`.""" +import logging from itertools import product from contextlib import suppress from pathlib import Path @@ -28,6 +29,8 @@ from bids.layout import BIDSLayout from bids.utils import listify +from .. import fieldmaps as fm + def find_estimators( *, @@ -37,7 +40,7 @@ def find_estimators( fmapless: Union[bool, set] = True, force_fmapless: bool = False, verbose: bool = False, -): +) -> list: """ Apply basic heuristics to automatically find available data for fieldmap estimation. @@ -255,7 +258,6 @@ def find_estimators( bids_id='auto_00000')] """ - from .. import fieldmaps as fm from .misc import create_logger from bids.layout import Query from bids.exceptions import BIDSEntityError @@ -297,12 +299,7 @@ def find_estimators( fm.FieldmapFile(fmap.path, metadata=fmap.get_metadata()) for fmap in layout.get(**b0_entities) ]) - logger.debug( - "Found %s estimation from %d sources:\n- %s", - e.method.name, - len(e.sources), - "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), - ) + _log_debug_estimation(logger, e, layout.root) estimators.append(e) # Step 2. If no B0FieldIdentifiers were found, try several heuristics @@ -312,12 +309,7 @@ def find_estimators( e = fm.FieldmapEstimation( fm.FieldmapFile(fmap.path, metadata=fmap.get_metadata()) ) - logger.debug( - "Found %s estimation from %d sources:\n- %s", - e.method.name, - len(e.sources), - "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), - ) + _log_debug_estimation(logger, e, layout.root) estimators.append(e) # A bunch of heuristics to select EPI fieldmaps @@ -337,12 +329,7 @@ def find_estimators( for fmap in layout.get(direction=dirs, **entities) ] ) - logger.debug( - "Found %s estimation from %d sources:\n- %s", - e.method.name, - len(e.sources), - "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), - ) + _log_debug_estimation(logger, e, layout.root) estimators.append(e) # At this point, only single-PE _epi files WITH ``IntendedFor`` can @@ -383,12 +370,7 @@ def find_estimators( fm.FieldmapFile(target.path, metadata=target.get_metadata()) ] ) - logger.debug( - "Found %s estimation from %d sources:\n- %s", - e.method.name, - len(e.sources), - "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), - ) + _log_debug_estimation(logger, e, layout.root) estimators.append(e) if estimators and not force_fmapless: @@ -447,12 +429,21 @@ def find_estimators( *fmfiles, ] ) - logger.debug( - "Found %s estimation from %d sources:\n- %s", - e.method.name, - len(e.sources), - "\n- ".join([str(x.path.relative_to(layout.root)) for x in e.sources]), - ) + _log_debug_estimation(logger, e, layout.root) estimators.append(e) return estimators + + +def _log_debug_estimation( + logger: logging.Logger, + estimation: fm.FieldmapEstimation, + bids_root: str, +) -> None: + """A helper function to log estimation information when running with verbosity.""" + logger.debug( + "Found %s estimation from %d sources:\n- %s", + estimation.method.name, + len(estimation.sources), + "\n- ".join([str(s.path.relative_to(bids_root)) for s in estimation.sources]), + ) From 84708af9cf67caab24440d818083a65550b794c7 Mon Sep 17 00:00:00 2001 From: mathiasg Date: Thu, 6 Oct 2022 10:39:40 -0400 Subject: [PATCH 9/9] ENH: Allow external logger --- sdcflows/cli/find_estimators.py | 7 ++++++- sdcflows/utils/wrangler.py | 15 +++++++-------- 2 files changed, 13 insertions(+), 9 deletions(-) diff --git a/sdcflows/cli/find_estimators.py b/sdcflows/cli/find_estimators.py index e43fcb9d66..c0192b442c 100644 --- a/sdcflows/cli/find_estimators.py +++ b/sdcflows/cli/find_estimators.py @@ -73,16 +73,21 @@ def main(argv=None): """ from niworkflows.utils.bids import collect_participants from sdcflows.utils.wrangler import find_estimators + from sdcflows.utils.misc import create_logger pargs = _parser().parse_args(argv) bids_dir = pargs.bids_dir.resolve(strict=True) layout = gen_layout(bids_dir, pargs.bids_database_dir) subjects = collect_participants(layout, pargs.subjects) + logger = create_logger('sdcflow.wrangler', level=10 if pargs.verbose else 40) estimators_record = {} for subject in subjects: estimators_record[subject] = find_estimators( - layout=layout, subject=subject, fmapless=pargs.fmapless, verbose=pargs.verbose, + layout=layout, + subject=subject, + fmapless=pargs.fmapless, + logger=logger, ) # pretty print results diff --git a/sdcflows/utils/wrangler.py b/sdcflows/utils/wrangler.py index 4ba42f37c1..2f1ca7e9d7 100644 --- a/sdcflows/utils/wrangler.py +++ b/sdcflows/utils/wrangler.py @@ -39,7 +39,7 @@ def find_estimators( sessions: Optional[List[str]] = None, fmapless: Union[bool, set] = True, force_fmapless: bool = False, - verbose: bool = False, + logger: Optional[logging.Logger] = None, ) -> list: """ Apply basic heuristics to automatically find available data for fieldmap estimation. @@ -66,8 +66,8 @@ def find_estimators( force_fmapless : :obj:`bool` When some other fieldmap estimation methods have been found, fieldmap-less estimation will be skipped except if ``force_fmapless`` is ``True``. - verbose - If enabled, display steps taken to find estimators. + logger + The logger used to relay messages. If not provided, one will be created. Returns ------- @@ -262,8 +262,8 @@ def find_estimators( from bids.layout import Query from bids.exceptions import BIDSEntityError - # Set up logger (logs only visable if verbose) - logger = create_logger('sdcflows.wrangler', level=10 if verbose else 40) + # The created logger is set to ERROR log level + logger = logger or create_logger('sdcflows.wrangler') base_entities = { "subject": subject, @@ -280,12 +280,11 @@ def find_estimators( estimators = [] # Step 1. Use B0FieldIdentifier metadata - has_B0FI = False + b0_ids = tuple() with suppress(BIDSEntityError): b0_ids = layout.get_B0FieldIdentifiers(**base_entities) - has_B0FI = True - if has_B0FI: + if b0_ids: logger.debug( "Dataset includes `B0FieldIdentifier` metadata." "Any data missing this metadata will be ignored."