RF+ENH: output messages to stderr not stdout + move printing out of "…

…controllers/models"

Most of the tools which operate over some other tool/streams (e.g. pv, datalad
run, etc) strive to not interfer with stdout so then they could be used
within pipe constructs.  If such wrapper tool outputs to stdout, then it could
not be used within a pipe, e.g. in

   duct my_amportant_compute | grep "a"

construct.  The same goes for git and git-annex, datalad, etc, unless it is
explicitly a command intended to display something (e.g. "datalad wtf").

That is why important to not just "print" to stdout but use e.g. stderr which
is not piped through.  Relates also to issue on logging which should default to
stderr not stdout.

README.md

@@ -65,7 +65,7 @@ options:
                         Reports Written: {num_reports} )
   --clobber             Replace log files if they already exist. (default:
                         False)
-  -q, --quiet           Suppress duct output. (default: False)
+  -q, --quiet           Suppress duct output (to stderr). (default: False)
   --sample-interval SAMPLE_INTERVAL, --s-i SAMPLE_INTERVAL
                         Interval in seconds between status checks of the
                         running process. Sample interval must be less than or

src/con_duct/__main__.py

@@ -169,9 +169,7 @@ class Averages:
     num_samples: int = 0
 
     def update(self: Averages, other: Sample) -> None:
-        assert_num(
-            other.total_rss, other.total_vsz, other.total_pmem, other.total_pcpu
-        )
+        assert_num(other.total_rss, other.total_vsz, other.total_pmem, other.total_pcpu)
         self.num_samples += 1
         self.rss += (other.total_rss - self.rss) / self.num_samples
         self.vsz += (other.total_vsz - self.vsz) / self.num_samples
@@ -330,7 +328,9 @@ def collect_sample(self) -> Sample:
             )
             for line in output.splitlines()[1:]:
                 if line:
-                    pid, pcpu, pmem, rss_kib, vsz_kib, etime, cmd = line.split(maxsplit=6)
+                    pid, pcpu, pmem, rss_kib, vsz_kib, etime, cmd = line.split(
+                        maxsplit=6
+                    )
                     sample.add_pid(
                         int(pid),
                         ProcessStats(
@@ -401,8 +401,9 @@ def dump_json(self) -> str:
             }
         )
 
-    def print_summary(self) -> None:
-        print(self.summary_format.format_map(self.execution_summary))
+    @cached_property
+    def execution_summary_formatted(self) -> str:
+        return self.summary_format.format_map(self.execution_summary)
 
 
 @dataclass
@@ -471,7 +472,7 @@ def from_argv(cls) -> Arguments:  # pragma: no cover
             "-q",
             "--quiet",
             action="store_true",
-            help="Suppress duct output.",
+            help="Suppress duct output (to stderr).",
         )
         parser.add_argument(
             "--sample-interval",
@@ -647,6 +648,10 @@ def safe_close_files(file_list: Iterable[Any]) -> None:
             pass
 
 
+def duct_print(msg: str) -> None:
+    print(msg, file=sys.stderr)
+
+
 def main() -> None:
     args = Arguments.from_argv()
     sys.exit(execute(args))
@@ -673,8 +678,8 @@ def execute(args: Arguments) -> int:
 
     full_command = " ".join([str(args.command)] + args.command_args)
     if not args.quiet:
-        print(f"duct is executing {full_command}...")
-        print(f"Log files will be written to {log_paths.prefix}")
+        duct_print(f"duct is executing {full_command}...")
+        duct_print(f"Log files will be written to {log_paths.prefix}")
     process = subprocess.Popen(
         [str(args.command)] + args.command_args,
         stdout=stdout_file,
@@ -730,7 +735,7 @@ def execute(args: Arguments) -> int:
             report.get_system_info()
             system_logs.write(report.dump_json())
     if not args.quiet:
-        report.print_summary()
+        duct_print(report.execution_summary_formatted)
     safe_close_files([stdout_file, stdout, stderr_file, stderr])
 
     return report.process.returncode

test/test_execution.py

@@ -55,9 +55,9 @@ def test_sanity_red(exit_code: int, temp_output_dir: str) -> None:
         summary_format=EXECUTION_SUMMARY_FORMAT,
         quiet=False,
     )
-    with mock.patch("sys.stdout", new_callable=mock.MagicMock) as mock_stdout:
+    with mock.patch("sys.stderr", new_callable=mock.MagicMock) as mock_stderr:
         assert execute(args) == exit_code
-        call_args = [call.args for call in mock_stdout.write.call_args_list]
+        call_args = [call.args for call in mock_stderr.write.call_args_list]
         assert any(f"Exit Code: {exit_code}" in call_arg[0] for call_arg in call_args)
 
     # We still should execute normally
@@ -179,9 +179,9 @@ def test_outputs_none_quiet(temp_output_dir: str) -> None:
         summary_format="",
         quiet=True,
     )
-    with mock.patch("sys.stdout", new_callable=mock.MagicMock) as mock_stdout:
+    with mock.patch("sys.stderr", new_callable=mock.MagicMock) as mock_stderr:
         assert execute(args) == 0
-        mock_stdout.write.assert_not_called()
+        mock_stderr.write.assert_not_called()
 
 
 def test_exit_before_first_sample(temp_output_dir: str) -> None: