From 7fcf1bf41b91e4f4ba14c92d82bab23ddd7536c8 Mon Sep 17 00:00:00 2001 From: Jac Fitzgerald Date: Wed, 1 Jul 2026 17:56:52 -0700 Subject: [PATCH 1/2] fix: route INFO logs to stdout so PowerShell doesn't raise NativeCommandError Python's logging.StreamHandler defaults to sys.stderr. PowerShell treats any stderr output from a native command as a NativeCommandError, so a successful tabcmd run would trigger error handling in PS scripts. Now INFO and below goes to stdout (normal output), while WARNING and above stays on stderr (real errors remain distinguishable). Closes #303 Co-Authored-By: Claude Sonnet 4.6 --- tabcmd/execution/logger_config.py | 17 +++++++++++++---- 1 file changed, 13 insertions(+), 4 deletions(-) diff --git a/tabcmd/execution/logger_config.py b/tabcmd/execution/logger_config.py index e20b10a1..c90e4d0c 100644 --- a/tabcmd/execution/logger_config.py +++ b/tabcmd/execution/logger_config.py @@ -1,6 +1,7 @@ import logging import logging.handlers import os +import sys path = os.path.dirname(os.path.abspath(__file__)) @@ -63,10 +64,18 @@ def configure_log(name: str, logging_level_input: str): if not any( isinstance(h, logging.StreamHandler) and not isinstance(h, logging.FileHandler) for h in named_logger.handlers ): - console = logging.StreamHandler() - console.setLevel(logging_level) - console.setFormatter(logging.Formatter(log_format)) - named_logger.addHandler(console) + # INFO and below → stdout so PowerShell doesn't treat normal output as errors. + # WARNING and above → stderr so real errors are still distinguishable. + stdout_handler = logging.StreamHandler(sys.stdout) + stdout_handler.setLevel(logging_level) + stdout_handler.addFilter(lambda r: r.levelno < logging.WARNING) + stdout_handler.setFormatter(logging.Formatter(log_format)) + named_logger.addHandler(stdout_handler) + + stderr_handler = logging.StreamHandler(sys.stderr) + stderr_handler.setLevel(logging.WARNING) + stderr_handler.setFormatter(logging.Formatter(FORMATS[logging.ERROR])) + named_logger.addHandler(stderr_handler) return named_logger From 541debee3473111dd8520bf0fa8336c00d6433a7 Mon Sep 17 00:00:00 2001 From: Jac Fitzgerald Date: Wed, 1 Jul 2026 18:38:41 -0700 Subject: [PATCH 2/2] test: add stdout/stderr split tests; replace lambda filter with named function Co-Authored-By: Claude Sonnet 4.6 --- tabcmd/execution/logger_config.py | 6 +- tests/commands/test_logger_config.py | 97 ++++++++++++++++++++++++++-- 2 files changed, 96 insertions(+), 7 deletions(-) diff --git a/tabcmd/execution/logger_config.py b/tabcmd/execution/logger_config.py index c90e4d0c..1df5c452 100644 --- a/tabcmd/execution/logger_config.py +++ b/tabcmd/execution/logger_config.py @@ -37,6 +37,10 @@ def logToRoot(message, *args, **kwargs): setattr(logging, method_name, logToRoot) +def _below_warning(record: logging.LogRecord) -> bool: + return record.levelno < logging.WARNING + + def add_trace_level(): trace_level: int = logging.DEBUG - 5 add_log_level("TRACE", trace_level) @@ -68,7 +72,7 @@ def configure_log(name: str, logging_level_input: str): # WARNING and above → stderr so real errors are still distinguishable. stdout_handler = logging.StreamHandler(sys.stdout) stdout_handler.setLevel(logging_level) - stdout_handler.addFilter(lambda r: r.levelno < logging.WARNING) + stdout_handler.addFilter(_below_warning) stdout_handler.setFormatter(logging.Formatter(log_format)) named_logger.addHandler(stdout_handler) diff --git a/tests/commands/test_logger_config.py b/tests/commands/test_logger_config.py index 531453a3..4a09d7f3 100644 --- a/tests/commands/test_logger_config.py +++ b/tests/commands/test_logger_config.py @@ -1,16 +1,26 @@ +import io import logging import logging.handlers +import sys import unittest +from unittest import mock from tabcmd.execution.logger_config import configure_log +def _clear_handlers(): + root = logging.getLogger() + for handler in root.handlers[:]: + handler.close() + root.removeHandler(handler) + for name in list(logging.Logger.manager.loggerDict): + if name.startswith("test_"): + logging.getLogger(name).handlers.clear() + + class LoggerConfigTests(unittest.TestCase): def setUp(self): - root = logging.getLogger() - for handler in root.handlers[:]: - handler.close() - root.removeHandler(handler) + _clear_handlers() def test_rotating_file_handler_present(self): configure_log("test_rotate", "DEBUG") @@ -27,17 +37,92 @@ def test_rotating_file_handler_settings(self): self.assertEqual(handler.maxBytes, 1_000_000) self.assertEqual(handler.backupCount, 5) - def test_no_duplicate_handlers_on_repeated_calls(self): + def test_no_duplicate_file_handlers_on_repeated_calls(self): configure_log("test_dup", "DEBUG") configure_log("test_dup", "DEBUG") root_handlers = logging.getLogger().handlers rotating = [h for h in root_handlers if isinstance(h, logging.handlers.RotatingFileHandler)] - self.assertEqual(len(rotating), 1, "Repeated configure_log calls must not add duplicate handlers") + self.assertEqual(len(rotating), 1, "Repeated configure_log calls must not add duplicate file handlers") + + def test_no_duplicate_console_handlers_on_repeated_calls(self): + fake_out, fake_err = io.StringIO(), io.StringIO() + with mock.patch("sys.stdout", fake_out), mock.patch("sys.stderr", fake_err): + configure_log("test_dup_console", "DEBUG") + configure_log("test_dup_console", "DEBUG") + named = logging.getLogger("test_dup_console") + stream_handlers = [ + h for h in named.handlers if isinstance(h, logging.StreamHandler) and not isinstance(h, logging.FileHandler) + ] + self.assertEqual(len(stream_handlers), 2, "Repeated calls must not add more than 2 console handlers") def test_root_logger_level_set(self): configure_log("test_level", "WARNING") self.assertEqual(logging.getLogger().level, logging.WARNING) +class StdoutStderrSplitTests(unittest.TestCase): + """INFO goes to stdout; WARNING+ goes to stderr.""" + + def setUp(self): + _clear_handlers() + + def _make_logger(self, name): + fake_out, fake_err = io.StringIO(), io.StringIO() + with mock.patch("sys.stdout", fake_out), mock.patch("sys.stderr", fake_err): + logger = configure_log(name, "DEBUG") + logger.propagate = False + return logger, fake_out, fake_err + + def test_two_stream_handlers_attached(self): + logger, _, _ = self._make_logger("test_split_two_handlers") + stream_handlers = [ + h + for h in logger.handlers + if isinstance(h, logging.StreamHandler) and not isinstance(h, logging.FileHandler) + ] + self.assertEqual(len(stream_handlers), 2) + + def test_stdout_and_stderr_handlers_bound_to_correct_streams(self): + fake_out, fake_err = io.StringIO(), io.StringIO() + with mock.patch("sys.stdout", fake_out), mock.patch("sys.stderr", fake_err): + logger = configure_log("test_split_streams", "DEBUG") + stream_handlers = [ + h + for h in logger.handlers + if isinstance(h, logging.StreamHandler) and not isinstance(h, logging.FileHandler) + ] + streams = {h.stream for h in stream_handlers} + self.assertIn(fake_out, streams) + self.assertIn(fake_err, streams) + + def test_info_goes_to_stdout_not_stderr(self): + logger, fake_out, fake_err = self._make_logger("test_split_info") + logger.info("hello stdout") + self.assertIn("hello stdout", fake_out.getvalue()) + self.assertNotIn("hello stdout", fake_err.getvalue()) + + def test_warning_goes_to_stderr_not_stdout(self): + logger, fake_out, fake_err = self._make_logger("test_split_warning") + logger.warning("a warning") + self.assertNotIn("a warning", fake_out.getvalue()) + self.assertIn("a warning", fake_err.getvalue()) + + def test_error_goes_to_stderr_not_stdout(self): + logger, fake_out, fake_err = self._make_logger("test_split_error") + logger.error("an error") + self.assertNotIn("an error", fake_out.getvalue()) + self.assertIn("an error", fake_err.getvalue()) + + def test_no_double_print_from_sibling_loggers(self): + """Two distinct leaf loggers sharing the same streams must not double-print.""" + fake_out, fake_err = io.StringIO(), io.StringIO() + with mock.patch("sys.stdout", fake_out), mock.patch("sys.stderr", fake_err): + logger_a = configure_log("test_split_sibling_a", "DEBUG") + configure_log("test_split_sibling_b", "DEBUG") + logger_a.propagate = False + logger_a.info("msg from a") + self.assertEqual(fake_out.getvalue().count("msg from a"), 1, "Message should appear exactly once") + + if __name__ == "__main__": unittest.main()