Repository: databio/pypiper (language: python)

Issue:
`logger_kwargs` isn't used in one branch of the pipeline manager setup
In the pipeline manager constructor, it looks like `logger_kwargs` isn't used when `args` is non-empty or non-null. Is this intended? There's also no docstring for `logger_kwargs`, where it could be noted if this is indeed intended behavior, or at least describing what these values are to be used for.

https://github.com/databio/pypiper/blob/3a8465a900f15a023afc2dd0b73e30cbf2e7eb24/pypiper/manager.py#L216-L232

Possibly related to #210 
Pipeline log file could collide with filepath given to logmuse
From consideration of #210 , it becomes apparent that a user could specify a path to a logfile for a pipeline manager's logger to write to that would collide with the path the manager will generate for its own log file. This would almost surely be inadvertent and would lead to unexpected behavior like log file overwrites, duplicate messages, and possibly a race condition on file writes.

To protect against this, I think that in any pipeline manager constructor, we should...
1. check that there's not this collision
2. if there is a collision, it should be an __exception__

It should be an exception rather than a warning because...
a) It's truly exceptional
b) It's almost surely unintended
c) It would lead to undesirable behavior
d) it would be at the _start_ of almost any pipeline, so raising an exception wouldn't risk wasting a lot of compute progress
e) it's unrecoverable -- there's not really a suitable automatic adjustment to make; the hypothetical filepaths in question (logmuse logfile and pypiper log file) may be expected to be present with _particular_ values, e.g. for consumption by other tools, and so doing something like injecting some distinguishing identifier into the filename suffix doesn't seem suitable

@nsheff would you accept (in principle, code review TBD ;) ) a pull request to this effect?


Discussion / hints:
Perhaps `**logger_kwargs` should be passed to `logmuse.init_logger`?
^^ controlling, perhaps, for possibility of collision w/ `level` (i.e., either remove `level` from the keyword args mapping if it's there--noting difference w/ `DEBUG` if that's the case--or not passing `level='DEBUG'` if level's already in the kwargs mapping.
Hmm, I never understood what logmuse was doing with `init_logger` and I still don't :).

you taught me everything I know about the logging package 
Where `logmuse` opens the file in (over)write mode: https://github.com/databio/logmuse/blob/00f8e9f5fd769f7b10fc51dd0ee514f851707eb5/logmuse/est.py#L260-L261

Where a pipeline manager would pass a logfile to `logmuse`: https://github.com/databio/pypiper/blob/master/pypiper/manager.py#L213-L232 (currently only in the `if not args` branch of code, but should be in both -- see #211 )

Where a manager sets its own log file path: https://github.com/databio/pypiper/blob/master/pypiper/manager.py#L281

Where a manager opens its own log file path for appending: https://github.com/databio/pypiper/blob/3a8465a900f15a023afc2dd0b73e30cbf2e7eb24/pypiper/manager.py#L527-L531
yes, I agree with everything you state. I think basically nobody uses the logmuse to set the logfile path, so it hasn't been a problem. But you're right it could be. 


Fix patch:
diff --git a/pypiper/const.py b/pypiper/const.py
index 2749529..0bfbdb6 100644
--- a/pypiper/const.py
+++ b/pypiper/const.py
@@ -1,6 +1,5 @@
 """ Pypiper constants. """
 
-
 CHECKPOINT_EXTENSION = ".checkpoint"
 DEFAULT_SAMPLE_NAME = "DEFAULT_SAMPLE_NAME"
 PIPELINE_CHECKPOINT_DELIMITER = "_"
diff --git a/pypiper/manager.py b/pypiper/manager.py
index 67441d6..df661b3 100644
--- a/pypiper/manager.py
+++ b/pypiper/manager.py
@@ -58,6 +58,7 @@
 
 
 LOCK_PREFIX = "lock."
+LOGFILE_SUFFIX = "_log.md"
 
 
 class Unbuffered(object):
@@ -193,10 +194,7 @@ def __init__(
         # If no starting point was specified, assume that the pipeline's
         # execution is to begin right away and set the internal flag so that
         # run() is let loose to execute instructions given.
-        if not self.start_point:
-            self._active = True
-        else:
-            self._active = False
+        self._active = not self.start_point
 
         # Pipeline-level variables to track global state and pipeline stats
         # Pipeline settings
@@ -210,26 +208,37 @@ def __init__(
         self.output_parent = params["output_parent"]
         self.testmode = params["testmode"]
 
+        # Establish the log file to check safety with logging keyword arguments.
+        # Establish the output folder since it's required for the log file.
+        self.outfolder = os.path.join(outfolder, "")  # trailing slash
+        self.pipeline_log_file = pipeline_filepath(self, suffix=LOGFILE_SUFFIX)
+
         # Set up logger
         logger_kwargs = logger_kwargs or {}
+        if logger_kwargs.get("logfile") == self.pipeline_log_file:
+            raise ValueError(
+                f"The logfile given for the pipeline manager's logger matches that which will be used by the manager itself: {self.pipeline_log_file}"
+            )
         default_logname = ".".join([__name__, self.__class__.__name__, self.name])
-        if not args:
+        self._logger = None
+        if args:
+            logger_builder_method = "logger_via_cli"
+            try:
+                self._logger = logger_via_cli(args, **logger_kwargs)
+            except logmuse.est.AbsentOptionException as e:
+                # Defer logger construction to init_logger.
+                self.debug(f"logger_via_cli failed: {e}")
+        if self._logger is None:
+            logger_builder_method = "init_logger"
+            # covers cases of bool(args) being False, or failure of logger_via_cli.
             # strict is only for logger_via_cli.
-            kwds = {k: v for k, v in logger_kwargs.items() if k != "strict"}
+            logger_kwargs = {k: v for k, v in logger_kwargs.items() if k != "strict"}
             try:
-                name = kwds.pop("name")
+                name = logger_kwargs.pop("name")
             except KeyError:
                 name = default_logname
-            self._logger = logmuse.init_logger(name, **kwds)
-            self.debug("Logger set with logmuse.init_logger")
-        else:
-            logger_kwargs.setdefault("name", default_logname)
-            try:
-                self._logger = logmuse.logger_via_cli(args)
-                self.debug("Logger set with logmuse.logger_via_cli")
-            except logmuse.est.AbsentOptionException:
-                self._logger = logmuse.init_logger("pypiper", level="DEBUG")
-                self.debug("logger_via_cli failed; Logger set with logmuse.init_logger")
+            self._logger = logmuse.init_logger(name, **logger_kwargs)
+        self.debug(f"Logger set with {logger_builder_method}")
 
         # Keep track of an ID for the number of processes attempted
         self.proc_count = 0
@@ -276,10 +285,7 @@ def __init__(
         #   self.output_parent = os.path.join(os.getcwd(), self.output_parent)
 
         # File paths:
-        self.outfolder = os.path.join(outfolder, "")  # trailing slash
         self.make_sure_path_exists(self.outfolder)
-        self.pipeline_log_file = pipeline_filepath(self, suffix="_log.md")
-
         self.pipeline_profile_file = pipeline_filepath(self, suffix="_profile.tsv")
 
         # Stats and figures are general and so lack the pipeline name.
diff --git a/pypiper/ngstk.py b/pypiper/ngstk.py
index 329b321..b607913 100755
--- a/pypiper/ngstk.py
+++ b/pypiper/ngstk.py
@@ -153,8 +153,7 @@ def get_file_size(self, filenames):
             return sum([self.get_file_size(filename) for filename in filenames])
 
         return round(
-            sum([float(os.stat(f).st_size) for f in filenames.split(" ")])
-            / (1024**2),
+            sum([float(os.stat(f).st_size) for f in filenames.split(" ")]) / (1024**2),
             4,
         )
 
diff --git a/pypiper/utils.py b/pypiper/utils.py
index 8973466..1c65f59 100644
--- a/pypiper/utils.py
+++ b/pypiper/utils.py
@@ -785,12 +785,10 @@ def pipeline_filepath(pm, filename=None, suffix=None):
         filename as given or determined by the pipeline name, and suffix
         appended if given.
     """
-
     if filename is None and suffix is None:
         raise TypeError(
-            "Provide filename and/or suffix to create " "path to a pipeline file."
+            "Provide filename and/or suffix to create path to a pipeline file."
         )
-
     filename = (filename or pm.name) + (suffix or "")
 
     # Note that Pipeline and PipelineManager define the same outfolder.


Test patch:
diff --git a/tests/pipeline_manager/test_manager_constructor.py b/tests/pipeline_manager/test_manager_constructor.py
index 0792bf1..b327fb2 100644
--- a/tests/pipeline_manager/test_manager_constructor.py
+++ b/tests/pipeline_manager/test_manager_constructor.py
@@ -1,10 +1,11 @@
 """ Test effects of construction of a pipeline manager. """
 
 import argparse
+import os
 
 import pytest
 
-from pypiper.manager import CHECKPOINT_SPECIFICATIONS
+from pypiper.manager import CHECKPOINT_SPECIFICATIONS, LOGFILE_SUFFIX
 from tests.helpers import named_param
 
 __author__ = "Vince Reuter"
@@ -24,6 +25,22 @@ def test_manager_starts_in_null_checkpoint_state(get_pipe_manager, checkpoint_ty
     assert getattr(pm, checkpoint_type) is None
 
 
+def test_logger_logfile_collision_with_manager_logfile_is_expected_error__issue_212(
+    get_pipe_manager, tmpdir
+):
+    pipe_name = "test_issue212"
+    with pytest.raises(ValueError) as err_ctx:
+        get_pipe_manager(
+            name=pipe_name,
+            logger_kwargs={
+                "logfile": os.path.join(tmpdir.strpath, pipe_name + LOGFILE_SUFFIX)
+            },
+        )
+    assert str(err_ctx.value).startswith(
+        f"The logfile given for the pipeline manager's logger matches that which will be used by the manager itself"
+    )
+
+
 class ManagerConstructorCheckpointSpecificationTests:
     """Tests for manager's constructor's ability to parse and set
     checkpoint specifications, which can determine aspects of control flow."""