Repository: PyFstat/PyFstat

Issue:
better catch lalpulsar executable output
As a followup to #435, lalpulsar (formerly lalapps) executable output still goes straight to stdout, not through logging. Probably needs a fix to `run_commandline`.

Discussion:
dbkeitel: Please rebase to get a clean diff.

Patch:
diff --git a/pyfstat/helper_functions.py b/pyfstat/helper_functions.py
index d07ade4..2e69aeb 100644
--- a/pyfstat/helper_functions.py
+++ b/pyfstat/helper_functions.py
@@ -13,6 +13,7 @@ import shutil
 import subprocess
 from datetime import datetime, timezone
 from functools import wraps
+from typing import Union
 
 import lal
 import lalpulsar
@@ -246,59 +247,59 @@ def get_comb_values(F0, frequencies, twoF, period, N=4):
     return comb_frequencies, twoF[comb_idxs], freq_err * np.ones(len(comb_idxs))
 
 
-def run_commandline(cl, raise_error=True, return_output=True):
-    """Run a string cmd as a subprocess, check for errors and return output.
+def run_commandline(
+    cl: str, raise_error: bool = True, return_output: bool = False
+) -> Union[subprocess.CompletedProcess, None]:
+    """Run a string command as a subprocess.
 
     Parameters
     ----------
-    cl: str
+    cl:
         Command to run
-    log_level: int
-        Sets the logging level for some of this function's messages.
-        See https://docs.python.org/library/logging.html#logging-levels
-        Default is '20' (INFO).
-        FIXME: Not used for all messages.
-    raise_error: bool
+    raise_error:
         If True, raise an error if the subprocess fails.
-        If False, continue and just return `0`.
-    return_output: bool
-        If True, return the captured output of the subprocess (stdout and stderr).
-        If False, return nothing on successful execution.
+        If False, just log the error, continue, and return ``None``.
+    return_output:
+        If True, return the ``subprocess.CompletedProcess`` object.
+        If False, return ``None``.
 
     Returns
     ----------
-    out: str or int, optional
-        The captured output of the subprocess (stdout and stderr)
-        if `return_output=True`.
-        0 on failed execution if `raise_error=False`.
+    out:
+        The ```subprocess.CompletedProcess`` of the subprocess
+        if ``return_output=True``. ``None`` if ``return_output=False``
+        or on  failed execution if ``raise_error=False``.
     """
 
     logger.info("Now executing: " + cl)
     if "|" in cl:
         logger.warning(
-            "Pipe ('|') found in commandline, errors may not be" " properly caught!"
+            "Pipe ('|') found in commandline, errors may not be  properly caught!"
         )
     try:
+        completed_process = subprocess.run(
+            cl,
+            check=True,
+            shell=True,
+            capture_output=True,
+            text=True,
+        )
+        if msg := completed_process.stdout:
+            [logger.info(line) for line in msg.splitlines()]
+        if msg := completed_process.stderr:
+            [logger.error(line) for line in msg.splitlines()]
         if return_output:
-            out = subprocess.check_output(
-                cl,  # what to run
-                stderr=subprocess.STDOUT,  # catch errors
-                shell=True,  # proper environment etc
-                universal_newlines=True,  # properly display linebreaks in error/output printing
-            )
-        else:
-            subprocess.check_call(cl, shell=True)
+            return completed_process
     except subprocess.CalledProcessError as e:
-        logger.error("Execution failed: {}".format(e))
-        if e.output:
-            logger.error(e.output)
+        if msg := getattr(e, "output", None):
+            [logger.info(line) for line in msg.splitlines()]
+        logger.error(f"Execution failed: {e}")
+        if msg := getattr(e, "stderr", None):
+            [logger.error(line) for line in msg.splitlines()]
         if raise_error:
             raise
-        elif return_output:
-            out = 0
-    os.system("\n")
-    if return_output:
-        return out
+
+    return None
 
 
 def convert_array_to_gsl_matrix(array):


Test patch:
diff --git a/tests/test_helper_functions.py b/tests/test_helper_functions.py
index ba1e2ff..3980dc8 100644
--- a/tests/test_helper_functions.py
+++ b/tests/test_helper_functions.py
@@ -1,4 +1,9 @@
+from subprocess import CalledProcessError, CompletedProcess
+
+import pytest
+
 import pyfstat
+from pyfstat.helper_functions import run_commandline
 
 
 def test_gps_to_datestr_utc():
@@ -10,3 +15,82 @@ def test_gps_to_datestr_utc():
     old_str = "Wed Sep 14 01:46:25 GMT 2011"
     new_str = pyfstat.helper_functions.gps_to_datestr_utc(gps)
     assert new_str.rstrip(" UTC") == old_str.replace(" GMT ", " ")
+
+
+def test_run_commandline_noreturn():
+    assert run_commandline("echo 'Testing no return'", return_output=False) is None
+
+
+def test_run_commandline_goodreturn(caplog):
+    return_obj = run_commandline("echo 'Testing return'", return_output=True)
+    _, log_level, log_message = caplog.record_tuples[-1]
+    assert type(return_obj) is CompletedProcess
+    assert log_level == 20
+    assert return_obj.stdout == log_message + "\n"
+
+
+def test_run_commandline_stdout_stderr(caplog):
+    # Test warning for pipes and proper stdout and stderr redirect
+    msg = "This is a simulated error message, do not worry human!"
+    run_commandline(
+        f"echo '{msg}' | tee /dev/stderr"
+    )  # print this to both stdout and stderr
+    # check that the messages came through at the right logging levels
+    # 20 == INFO, 30 == WARNING, 40 == ERROR
+    messages = caplog.record_tuples[-3:]
+    assert (messages[0][1] == 30) and (
+        "Pipe ('|') found in commandline" in messages[0][2]
+    )
+    assert messages[1][1] == 20
+    assert messages[1][2] == msg
+    assert messages[2][1] == 40
+    assert messages[2][2] == msg
+
+
+def test_run_commandline_expected_error_with_raise(caplog):
+    with pytest.raises(CalledProcessError):
+        run_commandline("ls nonexistent-directory 1>&2", raise_error=True)
+    assert caplog.record_tuples[-1][1] == 40
+
+
+def test_run_commandline_expected_error_noraise(caplog):
+    assert run_commandline("ls nonexistent-directory", raise_error=False) is None
+
+
+def test_run_commandline_lal_noerror(caplog):
+    # Basic print should come out as INFO
+    return_obj = run_commandline("lalpulsar_version", return_output=True)
+    assert return_obj.stderr == ""
+    assert return_obj.returncode == 0
+    for return_line, (_, log_level, log_message) in zip(
+        return_obj.stdout.split("\n"), caplog.record_tuples[1:]
+    ):
+        assert log_level == 20
+        assert return_line == log_message
+
+
+def test_run_commandline_lal_expected_error(caplog):
+    # Errors should go through stderr and come out as ERROR
+    with pytest.raises(CalledProcessError):
+        return_obj = run_commandline(
+            "lalpulsar_version --nonexistent-option-for-simulated-error",
+            return_output=True,
+        )
+        _, log_level, log_message = caplog.record_tuples[-1]
+        assert log_level == 40
+        assert return_obj.stderr == log_message
+        assert return_obj.stdout == ""
+        assert return_obj.returncode != 0
+
+
+def test_run_commandline_lal_expected_error_and_stdout(caplog):
+    # this one should print something to stdout *before* the error
+    run_commandline(
+        "lalpulsar_ComputeFstatistic_v2 --DataFiles no_such_file --Alpha 0 --Delta 0",
+        raise_error=False,
+    )
+    for _, log_level, log_message in caplog.record_tuples:
+        if "Now executing:" in log_message or "[normal]" in log_message:
+            assert log_level == 20
+        else:
+            assert log_level == 40