[REF] Move logger management to new functions (#750)

* First attempt.

* Hm.

* Fix stream formatter.

* Replace file-specific loggers with a general one.

* Try fixing it.

* Apply to t2smap too.

* Remove ContextFilter.

It's unnecessary now that we're using a single LGR for general logging.

* Add check in CI.

* Remove check.

The issue is that pytest's handler is different from our own.

tedana/combine.py

@@ -5,7 +5,7 @@
 import numpy as np
 from tedana.due import due, Doi
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/decay.py

@@ -8,7 +8,7 @@
 
 from tedana import utils
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/decomposition/_utils.py

@@ -6,7 +6,7 @@
 import numpy as np
 from scipy import stats
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/decomposition/ica.py

@@ -8,7 +8,7 @@
 from scipy import stats
 from sklearn.decomposition import FastICA
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/decomposition/pca.py

@@ -14,7 +14,7 @@
 from tedana.stats import computefeats2
 from tedana.selection import kundu_tedpca
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/gscontrol.py

@@ -11,7 +11,7 @@
 from tedana import utils
 from tedana.due import due, Doi
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger("REPORT")
 RefLGR = logging.getLogger("REFERENCES")
 

tedana/io.py

@@ -20,7 +20,7 @@
 from tedana.stats import computefeats2, get_coeffs
 
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/metrics/_utils.py

@@ -4,7 +4,7 @@
 import numpy as np
 from scipy import stats
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 
 
 def dependency_resolver(dict_, requested_metrics, base_inputs):

tedana/metrics/collect.py

@@ -13,7 +13,7 @@
 from tedana.stats import getfbounds
 
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger("REPORT")
 RefLGR = logging.getLogger("REFERENCES")
 

tedana/metrics/dependence.py

@@ -8,7 +8,7 @@
 from tedana.stats import computefeats2, get_coeffs, t_to_z
 
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger("REPORT")
 RefLGR = logging.getLogger("REFERENCES")
 

tedana/reporting/static_figures.py

@@ -12,7 +12,7 @@
 
 from tedana import io, stats, utils
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 MPL_LGR = logging.getLogger('matplotlib')
 MPL_LGR.setLevel(logging.WARNING)
 RepLGR = logging.getLogger('REPORT')

tedana/selection/_utils.py

@@ -5,7 +5,7 @@
 
 import numpy as np
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/selection/tedica.py

@@ -9,7 +9,7 @@
 from tedana.selection._utils import getelbow, clean_dataframe
 from tedana.metrics import collect
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/selection/tedpca.py

@@ -9,7 +9,7 @@
 from tedana.metrics import collect
 from tedana.selection._utils import (getelbow_cons, getelbow, clean_dataframe)
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/stats.py

@@ -9,7 +9,7 @@
 from tedana import utils
 from tedana.due import due, BibTeX, Doi
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 

tedana/utils.py

@@ -12,7 +12,7 @@
 
 from tedana.due import due, BibTeX
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 
@@ -377,6 +377,55 @@ def millisec2sec(arr):
     return arr / 1000.
 
 
+def setup_loggers(logname=None, repname=None, refname=None, quiet=False, debug=False):
+    # Set up the general logger
+    log_formatter = logging.Formatter(
+        '%(asctime)s\t%(module)s.%(funcName)-12s\t%(levelname)-8s\t%(message)s',
+        datefmt='%Y-%m-%dT%H:%M:%S')
+    stream_formatter = logging.Formatter(
+        "%(levelname)-8s %(module)s:%(funcName)s:%(lineno)d %(message)s"
+    )
+    # set up general logging file and open it for writing
+    if logname:
+        log_handler = logging.FileHandler(logname)
+        log_handler.setFormatter(log_formatter)
+        LGR.addHandler(log_handler)
+
+    stream_handler = logging.StreamHandler()
+    stream_handler.setFormatter(stream_formatter)
+    LGR.addHandler(stream_handler)
+
+    if quiet:
+        LGR.setLevel(logging.WARNING)
+    elif debug:
+        LGR.setLevel(logging.DEBUG)
+    else:
+        LGR.setLevel(logging.INFO)
+
+    # Loggers for report and references
+    text_formatter = logging.Formatter('%(message)s')
+    if repname:
+        rep_handler = logging.FileHandler(repname)
+        rep_handler.setFormatter(text_formatter)
+        RepLGR.setLevel(logging.INFO)
+        RepLGR.addHandler(rep_handler)
+        RepLGR.propagate = False
+
+    if refname:
+        ref_handler = logging.FileHandler(refname)
+        ref_handler.setFormatter(text_formatter)
+        RefLGR.setLevel(logging.INFO)
+        RefLGR.addHandler(ref_handler)
+        RefLGR.propagate = False
+
+
+def teardown_loggers():
+    for local_logger in (RefLGR, RepLGR, LGR):
+        for handler in local_logger.handlers[:]:
+            handler.close()
+            local_logger.removeHandler(handler)
+
+
 def get_resource_path():
     """Return the path to general resources, terminated with separator.
 

tedana/workflows/parser_utils.py

@@ -2,7 +2,6 @@
 Functions for parsers.
 """
 import os.path as op
-import logging
 
 import argparse
 
@@ -35,16 +34,3 @@ def is_valid_file(parser, arg):
         parser.error('The file {0} does not exist!'.format(arg))
 
     return arg
-
-
-class ContextFilter(logging.Filter):
-    """
-    A filter to allow specific logging handlers to ignore specific loggers.
-    We use this to prevent our report-generation and reference-compiling
-    loggers from printing to the general log file or to stdout.
-    """
-    NAMES = ['REPORT', 'REFERENCES']
-
-    def filter(self, record):
-        if not any([n in record.name for n in self.NAMES]):
-            return True

tedana/workflows/t2smap.py

@@ -13,7 +13,7 @@
 from tedana import (combine, decay, io, utils, __version__)
 from tedana.workflows.parser_utils import is_valid_file
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 
@@ -191,12 +191,7 @@ def t2smap_workflow(data, tes, out_dir='.', mask=None,
     if not op.isdir(out_dir):
         os.mkdir(out_dir)
 
-    if debug and not quiet:
-        logging.basicConfig(level=logging.DEBUG)
-    elif quiet:
-        logging.basicConfig(level=logging.WARNING)
-    else:
-        logging.basicConfig(level=logging.INFO)
+    utils.setup_loggers(quiet=quiet, debug=debug)
 
     LGR.info('Using output directory: {}'.format(out_dir))
 
@@ -291,6 +286,9 @@ def t2smap_workflow(data, tes, out_dir='.', mask=None,
     }
     io_generator.save_file(derivative_metadata, 'data description json')
 
+    LGR.info("Workflow completed")
+    utils.teardown_loggers()
+
 
 def _main(argv=None):
     """T2smap entry point"""

tedana/workflows/tedana.py

@@ -21,9 +21,9 @@
                     reporting, selection, utils, __version__)
 import tedana.gscontrol as gsc
 from tedana.stats import computefeats2
-from tedana.workflows.parser_utils import is_valid_file, check_tedpca_value, ContextFilter
+from tedana.workflows.parser_utils import is_valid_file, check_tedpca_value
 
-LGR = logging.getLogger(__name__)
+LGR = logging.getLogger("GENERAL")
 RepLGR = logging.getLogger('REPORT')
 RefLGR = logging.getLogger('REFERENCES')
 
@@ -369,40 +369,7 @@ def tedana_workflow(data, tes, out_dir='.', mask=None,
     extension = 'tsv'
     start_time = datetime.datetime.now().strftime('%Y-%m-%dT%H%M%S')
     logname = op.join(out_dir, (basename + start_time + '.' + extension))
-
-    # set logging format
-    log_formatter = logging.Formatter(
-        '%(asctime)s\t%(name)-12s\t%(levelname)-8s\t%(message)s',
-        datefmt='%Y-%m-%dT%H:%M:%S')
-    text_formatter = logging.Formatter('%(message)s')
-
-    # set up logging file and open it for writing
-    log_handler = logging.FileHandler(logname)
-    log_handler.setFormatter(log_formatter)
-    # Removing handlers after basicConfig doesn't work, so we use filters
-    # for the relevant handlers themselves.
-    log_handler.addFilter(ContextFilter())
-    logging.root.addHandler(log_handler)
-    sh = logging.StreamHandler()
-    sh.addFilter(ContextFilter())
-    logging.root.addHandler(sh)
-
-    if quiet:
-        logging.root.setLevel(logging.WARNING)
-    elif debug:
-        logging.root.setLevel(logging.DEBUG)
-    else:
-        logging.root.setLevel(logging.INFO)
-
-    # Loggers for report and references
-    rep_handler = logging.FileHandler(repname)
-    rep_handler.setFormatter(text_formatter)
-    ref_handler = logging.FileHandler(refname)
-    ref_handler.setFormatter(text_formatter)
-    RepLGR.setLevel(logging.INFO)
-    RepLGR.addHandler(rep_handler)
-    RefLGR.setLevel(logging.INFO)
-    RefLGR.addHandler(ref_handler)
+    utils.setup_loggers(logname, repname, refname, quiet=quiet, debug=debug)
 
     LGR.info('Using output directory: {}'.format(out_dir))
 
@@ -706,8 +673,6 @@ def tedana_workflow(data, tes, out_dir='.', mask=None,
     with open(io_generator.get_name("data description json"), "w") as fo:
         json.dump(derivative_metadata, fo, sort_keys=True, indent=4)
 
-    LGR.info('Workflow completed')
-
     RepLGR.info("This workflow used numpy (Van Der Walt, Colbert, & "
                 "Varoquaux, 2011), scipy (Jones et al., 2001), pandas "
                 "(McKinney, 2010), scikit-learn (Pedregosa et al., 2011), "
@@ -778,17 +743,9 @@ def tedana_workflow(data, tes, out_dir='.', mask=None,
             LGR.info('Generating dynamic report')
             reporting.generate_report(io_generator, tr=img_t_r)
 
-    log_handler.close()
-    logging.root.removeHandler(log_handler)
-    sh.close()
-    logging.root.removeHandler(sh)
-    for local_logger in (RefLGR, RepLGR):
-        for handler in local_logger.handlers[:]:
-            handler.close()
-            local_logger.removeHandler(handler)
-    os.remove(refname)
-
     LGR.info('Workflow completed')
+    utils.teardown_loggers()
+    os.remove(refname)
 
 
 def _main(argv=None):