From 29815f0e607a38669c1c47d52d3cedd3c1e7448c Mon Sep 17 00:00:00 2001
From: Peter Van Dyken <pvandyk2@uwo.ca>
Date: Thu, 28 Jul 2022 16:46:22 -0400
Subject: [PATCH] Add minimal fixes to get logging working

There was previously no central initializing of handlers for logging, so
only WARNING and higher was getting logged and without a modicum of
formatting.

Add a centralized _logging module to initialize the base logger. This
gets called at the two app entrypoints: snakebids.admin:main and upon
initialization of SnakebidsApp
---
 snakebids/_logging.py | 12 ++++++++++++
 snakebids/admin.py    |  8 ++++++--
 snakebids/app.py      | 20 +++++++++++++++-----
 snakebids/cli.py      |  2 +-
 4 files changed, 34 insertions(+), 8 deletions(-)
 create mode 100644 snakebids/_logging.py

diff --git a/snakebids/_logging.py b/snakebids/_logging.py
new file mode 100644
index 00000000..b0a137de
--- /dev/null
+++ b/snakebids/_logging.py
@@ -0,0 +1,12 @@
+import logging
+from typing import Union
+
+
+def setup_logging(level: Union[str, int] = logging.DEBUG):
+    logger = logging.getLogger("snakebids")
+    stream_handler = logging.StreamHandler()
+    formatter = logging.Formatter("%(levelname)-8s %(message)s")
+    stream_handler.setFormatter(formatter)
+
+    logger.addHandler(stream_handler)
+    logger.setLevel(level)
diff --git a/snakebids/admin.py b/snakebids/admin.py
index 6b8bb153..f929cef7 100644
--- a/snakebids/admin.py
+++ b/snakebids/admin.py
@@ -1,15 +1,19 @@
 """Script to generate a Snakebids project."""
 
 import argparse
+import logging
 import os
 from pathlib import Path
 
 from cookiecutter.main import cookiecutter
 
 import snakebids
+from snakebids._logging import setup_logging
 from snakebids.app import SnakeBidsApp
 from snakebids.cli import add_dynamic_args
 
+logger = logging.getLogger(__name__)
+
 
 def create_app(_):
     cookiecutter(os.path.join(snakebids.__path__[0], "project_template"))
@@ -20,7 +24,7 @@ def create_descriptor(args):
     app = SnakeBidsApp(args.app_dir.resolve())
     add_dynamic_args(app.parser, app.config["parse_args"], app.config["pybids_inputs"])
     app.create_descriptor(args.out_path)
-    print(f"Boutiques descriptor created at {args.out_path}")
+    logger.info("Boutiques descriptor created at %s", args.out_path)
 
 
 def gen_parser():
@@ -53,7 +57,7 @@ def gen_parser():
 
 def main():
     """Invoke Cookiecutter on the Snakebids project template."""
-
+    setup_logging()
     parser = gen_parser()
     args = parser.parse_args()
     args.func(args)
diff --git a/snakebids/app.py b/snakebids/app.py
index b1f16a3e..1996f6e3 100644
--- a/snakebids/app.py
+++ b/snakebids/app.py
@@ -11,6 +11,7 @@
 import snakemake
 from snakemake.io import load_configfile
 
+from snakebids._logging import setup_logging
 from snakebids.cli import (
     SnakebidsArgs,
     add_dynamic_args,
@@ -24,7 +25,7 @@
     write_output_mode,
 )
 
-logger = logging.Logger(__name__)
+_logger = logging.getLogger(__name__)
 
 
 SNAKEFILE_CHOICES = [
@@ -61,7 +62,8 @@ def wrapper(self: "SnakeBidsApp"):
                 return Path(self.snakemake_dir, path)
 
         raise ConfigError(
-            f"Error: no {file_name} file found, tried {', '.join(choices)}."
+            f"Error: no {file_name} file found under {self.snakemake_dir}, tried "
+            f"{', '.join(choices)}."
         )
 
     return wrapper
@@ -112,6 +114,14 @@ class SnakeBidsApp:
     )
     args: Optional[SnakebidsArgs] = None
 
+    # pylint: disable=no-self-use
+    def __attrs_post_init__(self):
+        setup_logging()
+
+    @property
+    def logger(self):
+        return _logger
+
     def run_snakemake(self):
         """Run snakemake with that config.
 
@@ -165,10 +175,10 @@ def run_snakemake(self):
                 self.config["output_dir"] /= "results"
                 self.config["root"] = "results"
                 # Print a friendly warning that the output directory will change
-                logger.info(
+                _logger.info(
                     "You specified your output to be in the snakebids directory, so "
                     "we're automatically putting your outputs in the results "
-                    "subdirectory.\nYou'll find your results in `%s`",
+                    "subdirectory. You'll find your results in `%s`",
                     (self.snakemake_dir / "results").resolve(),
                 )
             else:
@@ -181,7 +191,7 @@ def run_snakemake(self):
             try:
                 prepare_bidsapp_output(args.outputdir, args.force)
             except RunError as err:
-                print(err.msg)
+                _logger.error(err.msg)
                 sys.exit(1)
             cwd = args.outputdir
             new_config_file = args.outputdir / self.configfile_path
diff --git a/snakebids/cli.py b/snakebids/cli.py
index 7278fe6a..db36b9bb 100644
--- a/snakebids/cli.py
+++ b/snakebids/cli.py
@@ -13,7 +13,7 @@
 # either Path or pathlib.Path
 Path = pathlib.Path
 
-logger = logging.Logger(__name__)
+logger = logging.getLogger(__name__)
 
 
 # pylint: disable=too-few-public-methods,