fix: sort out loggging, run boilerplate's md -> html isolated in process

Author: oesteban

fmriprep/cli/run.py

@@ -93,6 +93,9 @@ def main():
         sentry_sdk.capture_message('fMRIPrep started', level='info')
 
     config.loggers.workflow.log(25, 'fMRIPrep started!')
+    config.loggers.workflow.log(15, '\n'.join(
+        ['fMRIPrep config:'] + ['\t\t%s' % s for s in config.dumps().splitlines()])
+    )
     errno = 1  # Default is error exit unless otherwise set
     try:
         fmriprep_wf.run(**config.nipype.get_plugin())
@@ -113,13 +116,20 @@ def main():
         config.loggers.workflow.critical('fMRIPrep failed: %s', e)
         raise
     else:
-
         config.loggers.workflow.log(25, 'fMRIPrep finished successfully!')
         if not config.execution.notrack:
             success_message = 'fMRIPrep finished without errors'
             sentry_sdk.add_breadcrumb(message=success_message, level='info')
             sentry_sdk.capture_message(success_message, level='info')
 
+        # Bother users with the boilerplate only iff the workflow went okay.
+        if (config.execution.output_dir / 'fmriprep' / 'logs' / 'CITATION.md').exists():
+            config.loggers.workflow.log(
+                25, 'Works derived from this fMRIPrep execution should '
+                'include the following boilerplate:\n\n%s',
+                (config.execution.output_dir / 'fmriprep' / 'logs' / 'CITATION.md').read_text()
+            )
+
         if config.workflow.run_reconall:
             from templateflow import api
             from niworkflows.utils.misc import _copy_any
@@ -131,52 +141,7 @@ def main():
         errno = 0
     finally:
         from niworkflows.reports import generate_reports
-        from subprocess import check_call, CalledProcessError, TimeoutExpired
         from pkg_resources import resource_filename as pkgrf
-        from shutil import copyfile
-
-        citation_files = {
-            ext: config.execution.output_dir / 'fmriprep' / 'logs'
-            / ('CITATION.%s' % ext) for ext in ('bib', 'tex', 'md', 'html')
-        }
-
-        if not config.execution.md_only_boilerplate and citation_files['md'].exists():
-            # Generate HTML file resolving citations
-            cmd = ['pandoc', '-s', '--bibliography',
-                   pkgrf('fmriprep', 'data/boilerplate.bib'),
-                   '--filter', 'pandoc-citeproc',
-                   '--metadata', 'pagetitle="fMRIPrep citation boilerplate"',
-                   str(citation_files['md']),
-                   '-o', str(citation_files['html'])]
-
-            config.loggers.cli.info(
-                'Generating an HTML version of the citation boilerplate...')
-            try:
-                check_call(cmd, timeout=10)
-            except (FileNotFoundError, CalledProcessError, TimeoutExpired):
-                config.loggers.cli.warning(
-                    'Could not generate CITATION.html file:\n%s', ' '.join(cmd))
-
-            # Generate LaTex file resolving citations
-            cmd = ['pandoc', '-s', '--bibliography',
-                   pkgrf('fmriprep', 'data/boilerplate.bib'),
-                   '--natbib', str(citation_files['md']),
-                   '-o', str(citation_files['tex'])]
-            config.loggers.cli.info(
-                'Generating a LaTeX version of the citation boilerplate...')
-            try:
-                check_call(cmd, timeout=10)
-            except (FileNotFoundError, CalledProcessError, TimeoutExpired):
-                config.loggers.cli.warning(
-                    'Could not generate CITATION.tex file:\n%s', ' '.join(cmd))
-            else:
-                copyfile(pkgrf('fmriprep', 'data/boilerplate.bib'),
-                         citation_files['bib'])
-        else:
-            config.loggers.cli.warning(
-                'fMRIPrep could not find the markdown version of '
-                'the citation boilerplate (%s). HTML and LaTeX versions'
-                ' of it will not be available', citation_files['md'])
 
         # Generate reports phase
         failed_reports = generate_reports(

fmriprep/cli/workflow.py

@@ -121,8 +121,45 @@ def build_boilerplate(config_file, workflow):
             except FileNotFoundError:
                 pass
 
-        citation_files['md'].write_text(boilerplate)
-        config.loggers.workflow.log(
-            25, 'Works derived from this fMRIPrep execution should '
-            'include the following boilerplate:\n\n%s', boilerplate
-        )
+    citation_files['md'].write_text(boilerplate)
+
+    citation_files = {
+        ext: config.execution.output_dir / 'fmriprep' / 'logs'
+        / ('CITATION.%s' % ext) for ext in ('bib', 'tex', 'md', 'html')
+    }
+
+    if not config.execution.md_only_boilerplate and citation_files['md'].exists():
+        from subprocess import check_call, CalledProcessError, TimeoutExpired
+        from pkg_resources import resource_filename as pkgrf
+        from shutil import copyfile
+        # Generate HTML file resolving citations
+        cmd = ['pandoc', '-s', '--bibliography',
+               pkgrf('fmriprep', 'data/boilerplate.bib'),
+               '--filter', 'pandoc-citeproc',
+               '--metadata', 'pagetitle="fMRIPrep citation boilerplate"',
+               str(citation_files['md']),
+               '-o', str(citation_files['html'])]
+
+        config.loggers.cli.info(
+            'Generating an HTML version of the citation boilerplate...')
+        try:
+            check_call(cmd, timeout=10)
+        except (FileNotFoundError, CalledProcessError, TimeoutExpired):
+            config.loggers.cli.warning(
+                'Could not generate CITATION.html file:\n%s', ' '.join(cmd))
+
+        # Generate LaTex file resolving citations
+        cmd = ['pandoc', '-s', '--bibliography',
+               pkgrf('fmriprep', 'data/boilerplate.bib'),
+               '--natbib', str(citation_files['md']),
+               '-o', str(citation_files['tex'])]
+        config.loggers.cli.info(
+            'Generating a LaTeX version of the citation boilerplate...')
+        try:
+            check_call(cmd, timeout=10)
+        except (FileNotFoundError, CalledProcessError, TimeoutExpired):
+            config.loggers.cli.warning(
+                'Could not generate CITATION.tex file:\n%s', ' '.join(cmd))
+        else:
+            copyfile(pkgrf('fmriprep', 'data/boilerplate.bib'),
+                     citation_files['bib'])

fmriprep/config.py

@@ -412,6 +412,9 @@ class workflow(_Config):
 class loggers(_Config):
     """Configure loggers."""
 
+    _fmt = "%(asctime)s,%(msecs)d %(name)-2s " "%(levelname)-2s:\n\t %(message)s"
+    _datefmt = "%y%m%d-%H:%M:%S"
+
     default = logging.getLogger()
     cli = logging.getLogger('cli')
     workflow = nlogging.getLogger('nipype.workflow')
@@ -485,6 +488,11 @@ def init_layout():
 
 def set_logger_level():
     """Set the current log level to all nipype loggers."""
+    _handler = logging.StreamHandler(stream=sys.stdout)
+    _handler.setFormatter(
+        logging.Formatter(fmt=loggers._fmt, datefmt=loggers._datefmt)
+    )
+    loggers.cli.addHandler(_handler)
     loggers.default.setLevel(execution.log_level)
     loggers.cli.setLevel(execution.log_level)
     loggers.interface.setLevel(execution.log_level)

fmriprep/workflows/bold/base.py

@@ -192,11 +192,11 @@ def init_func_preproc_wf(bold_file):
                 "Multiple single-band reference files found for {}; using "
                 "{}".format(refbase, sbbase))
         else:
-            config.loggers.workflow.log(
-                25, "Using single-band reference file {}".format(sbbase))
+            config.loggers.workflow.info("Using single-band reference file %s.",
+                                         sbbase)
     else:
-        config.loggers.workflow.log(
-            25, "No single-band-reference found for {}".format(refbase))
+        config.loggers.workflow.info("No single-band-reference found for %s.",
+                                     refbase)
 
     metadata = layout.get_metadata(ref_file)