From 9bbefdbcd36538e5746be4ca233837710fbfac37 Mon Sep 17 00:00:00 2001 From: Chadwick Boulay Date: Thu, 3 Sep 2026 19:16:35 -0400 Subject: [PATCH] Stop warning about a profiler header mismatch on an empty log file _setup_logger treated an empty first line as a header mismatch, so it warned and unlinked the file on every process start. Because the header is only written at DEBUG level while FileHandler created the file eagerly, a run with profiling off left a zero-byte log behind, making the condition self-perpetuating. Guard the comparison with `if not first_line` (matching ezmsg/util/profiler.py) and construct the handler with delay=True so no empty file is created when nobody asked for profiling. Fixes #12 Co-Authored-By: Claude Opus 5 (1M context) --- src/ezmsg/baseproc/util/profile.py | 10 +++++--- tests/test_profile.py | 41 ++++++++++++++++++++++++++++++ 2 files changed, 48 insertions(+), 3 deletions(-) diff --git a/src/ezmsg/baseproc/util/profile.py b/src/ezmsg/baseproc/util/profile.py index ff78cdf..a5dc6fa 100644 --- a/src/ezmsg/baseproc/util/profile.py +++ b/src/ezmsg/baseproc/util/profile.py @@ -34,7 +34,10 @@ def _setup_logger(append: bool = False) -> logging.Logger: try: with open(logpath) as f: first_line = f.readline().rstrip() - if first_line == HEADER: + if not first_line: + # Empty file; nothing to mismatch against, write the header ourselves. + pass + elif first_line == HEADER: write_header = False else: # Remove the file if appending, but headers do not match @@ -61,8 +64,9 @@ def _setup_logger(append: bool = False) -> logging.Logger: # Set the logger's level to EZMSG_LOGLEVEL env var value if it exists, otherwise INFO _logger.setLevel(os.environ.get("EZMSG_LOGLEVEL", "INFO").upper()) - # Create a file handler to write log messages to the log file - fh = logging.FileHandler(logpath) + # Create a file handler to write log messages to the log file. + # delay=True so a run with profiling disabled doesn't leave a zero-byte file behind. + fh = logging.FileHandler(logpath, delay=True) fh.setLevel(logging.DEBUG) # Set the file handler log level to DEBUG # Add the file handler to the logger diff --git a/tests/test_profile.py b/tests/test_profile.py index 7c52d71..79366ae 100644 --- a/tests/test_profile.py +++ b/tests/test_profile.py @@ -135,6 +135,47 @@ def test_logger_append_header_match(mock_logger_path): handler.close() +def test_logger_append_empty_file(mock_logger_path, caplog): + """An existing but empty log file is not a header mismatch and must not warn.""" + test_logpath = mock_logger_path + with open(test_logpath, "w") as f: + f.truncate(0) + + with caplog.at_level(logging.WARNING, logger="ezmsg"): + logger = _setup_logger(append=True) + + assert "header mismatch" not in caplog.text.lower() + + # The header is still written to the empty file. + with open(test_logpath, "r") as f: + first_line = f.readline().strip() + assert first_line == HEADER + + for handler in list(logger.handlers): + logger.removeHandler(handler) + handler.close() + + +def test_no_empty_file_when_profiling_disabled(mock_logger_path): + """With profiling off (level > DEBUG) no zero-byte log file is left behind.""" + test_logpath = mock_logger_path + test_logpath.unlink(missing_ok=True) + + # _setup_logger mutates the shared "ezprofile" logger; restore its level afterwards. + prev_level = logging.getLogger("ezprofile").level + try: + with patch.dict(os.environ, {"EZMSG_LOGLEVEL": "INFO"}): + logger = _setup_logger(append=True) + + assert not test_logpath.exists() + + for handler in list(logger.handlers): + logger.removeHandler(handler) + handler.close() + finally: + logging.getLogger("ezprofile").setLevel(prev_level) + + def test_profile_method_decorator(): """Test the profile_method decorator."""