From 73d49357070b3f53d7b87619d79c6bfedb52238d Mon Sep 17 00:00:00 2001 From: Jon Palmer Date: Tue, 10 Mar 2026 22:07:59 -0700 Subject: [PATCH] Silence default predict memory log chatter Agent-Id: agent-bea35971-4f1b-4957-99f4-e25b0114a72a --- funannotate2/predict.py | 25 ---------- funannotate2/utilities.py | 21 +------- tests/unit/test_predict.py | 47 ++++++++++++++++++ tests/unit/test_utilities.py | 94 ++++++++++++++++++++++++++++++++++++ 4 files changed, 143 insertions(+), 44 deletions(-) diff --git a/funannotate2/predict.py b/funannotate2/predict.py index a4db332..ba2e341 100755 --- a/funannotate2/predict.py +++ b/funannotate2/predict.py @@ -1386,19 +1386,6 @@ def abinitio_wrapper( contig_length = get_contig_length(contig) - # Log contig processing message (debug only) - log_message = ( - f"Processing contig {contig_name} (length: {contig_length:,} bp)" - ) - try: - if hasattr(logger, "debug"): - logger.debug(log_message) - elif callable(logger): - logger(log_message + "\n") - else: - print(log_message) - except Exception: - print(log_message) except ImportError: warning_message = ( "Memory monitoring requested but memory module not available" @@ -1483,18 +1470,6 @@ def run_tool_with_error_tracking(tool_name, run_func, *args, **kwargs): ) logger.warning(warning_msg) - # Log prediction (debug only) - log_message = f"{tool_name} memory prediction for {contig_name}: {predicted_mb:.1f} MB" - try: - if hasattr(logger, "debug"): - logger.debug(log_message) - elif callable(logger): - logger(log_message + "\n") - else: - print(log_message) - except Exception: - print(log_message) - # Run the tool run_func(*args, **kwargs) return True, None diff --git a/funannotate2/utilities.py b/funannotate2/utilities.py index 081d481..9d4361b 100755 --- a/funannotate2/utilities.py +++ b/funannotate2/utilities.py @@ -832,26 +832,9 @@ def logoutput(logname, process_result): elif callable(logfile): # For function-based loggers, skip detailed output logging pass - # Log memory stats if available (debug only) + # Keep detailed memory stats out of the normal logger path. + # Structured records are still written to the dedicated JSONL file below. if memory_stats: - from .memory import format_memory_report - - memory_report = f"Memory usage for {process_name or 'subprocess'}:\n{format_memory_report(memory_stats)}" - - # Try different logging methods with error handling - use debug level - try: - if hasattr(logfile, "debug"): - logfile.debug(memory_report) - elif callable(logfile): - # Handle function-based loggers like sys.stderr.write - logfile(memory_report + "\n") - else: - # Fallback to print - print(memory_report) - except Exception: - # If all else fails, just print it - print(memory_report) - # Also write to dedicated memory monitoring file try: import os diff --git a/tests/unit/test_predict.py b/tests/unit/test_predict.py index e01ff34..0e132bc 100644 --- a/tests/unit/test_predict.py +++ b/tests/unit/test_predict.py @@ -270,3 +270,50 @@ def mock_predict(args): finally: # Restore the original function funannotate2.predict.predict = original_predict + + @patch("funannotate2.predict.run_snap") + @patch("funannotate2.memory.get_system_memory_info") + @patch("funannotate2.memory.predict_memory_usage") + @patch("funannotate2.memory.get_contig_length") + def test_abinitio_wrapper_suppresses_memory_chatter_but_keeps_tool_logging( + self, + mock_get_contig_length, + mock_predict_memory_usage, + mock_get_system_memory_info, + mock_run_snap, + tmp_path, + ): + """Per-contig memory details should not leak into ordinary predict logs.""" + contig = tmp_path / "scaffold_1.fasta" + contig.write_text(">scaffold_1\nATGC\n") + + mock_get_contig_length.return_value = 4 + mock_predict_memory_usage.return_value = { + "predicted_peak_with_margin_mb": 64.0 + } + mock_get_system_memory_info.return_value = {"available_gb": 8.0} + + def fake_run_snap(*args, **kwargs): + kwargs["log"]("snap tool output\n") + return 0 + + mock_run_snap.side_effect = fake_run_snap + + logger = MagicMock() + params = {"abinitio": {"snap": {"location": "snap-trained.hmm"}}} + + stats = funannotate2.predict.abinitio_wrapper( + str(contig), params, logger, monitor_memory=True + ) + + info_messages = [call.args[0] for call in logger.info.call_args_list] + debug_messages = [call.args[0] for call in logger.debug.call_args_list] + + assert "snap tool output" in info_messages + assert "Successfully ran tools for scaffold_1.fasta: snap" in info_messages + assert not any("Processing contig" in message for message in info_messages) + assert not any("memory prediction for scaffold_1.fasta" in message for message in info_messages) + assert not any("Processing contig" in message for message in debug_messages) + assert not any("memory prediction for scaffold_1.fasta" in message for message in debug_messages) + assert stats["tools_run"] == ["snap"] + assert stats["contig_length"] == 4 diff --git a/tests/unit/test_utilities.py b/tests/unit/test_utilities.py index 43548dd..e928978 100644 --- a/tests/unit/test_utilities.py +++ b/tests/unit/test_utilities.py @@ -2,13 +2,16 @@ Unit tests for the utilities module. """ +import json import os +from unittest.mock import MagicMock, patch from funannotate2.utilities import ( create_tmpdir, merge_coordinates, naming_slug, readBlocks, + runSubprocess, ) @@ -134,3 +137,94 @@ def test_read_blocks_no_pattern(self): blocks = list(readBlocks(source, "#")) assert len(blocks) == 1 assert blocks[0] == ["Line 1", "Line 2", "Line 3"] + + +class TestRunSubprocess: + """Regression tests for subprocess logging behavior.""" + + @patch("funannotate2.utilities.subprocess.Popen") + @patch("funannotate2.memory.MemoryMonitor") + def test_monitoring_keeps_memory_report_out_of_callable_logs( + self, mock_monitor_cls, mock_popen, tmp_path, monkeypatch + ): + """Memory monitoring should not emit formatted reports via callable logs.""" + process = MagicMock() + process.pid = 12345 + process.returncode = 0 + process.stdout = "" + process.stderr = "" + mock_popen.return_value = process + + mock_monitor = mock_monitor_cls.return_value + mock_monitor.monitor_process.return_value = { + "process_name": "snap-scaffold_1.fasta", + "duration_seconds": 1.5, + "peak_rss_mb": 10.0, + "peak_vms_mb": 20.0, + "avg_rss_mb": 9.0, + "avg_vms_mb": 19.0, + "sample_count": 2, + "samples": [], + } + + messages = [] + monkeypatch.setenv("FUNANNOTATE2_OUTPUT_DIR", str(tmp_path)) + + runSubprocess( + ["snap", "input.fasta"], + messages.append, + cwd=str(tmp_path), + monitor_memory=True, + process_name="snap-scaffold_1.fasta", + ) + + assert messages == [] + + memory_log = tmp_path / "logfiles" / "predict-abinitio-memory-monitoring.jsonl" + assert memory_log.exists() + + records = [json.loads(line) for line in memory_log.read_text().splitlines()] + assert len(records) == 1 + assert records[0]["process_name"] == "snap-scaffold_1.fasta" + assert records[0]["tool_name"] == "snap" + assert records[0]["memory_stats"]["peak_rss_mb"] == 10.0 + + @patch("funannotate2.utilities.subprocess.Popen") + @patch("funannotate2.memory.MemoryMonitor") + def test_monitoring_does_not_debug_log_formatted_memory_report( + self, mock_monitor_cls, mock_popen, tmp_path, monkeypatch + ): + """Detailed memory reports should stay out of the normal logfile path.""" + process = MagicMock() + process.pid = 12345 + process.returncode = 0 + process.stdout = "" + process.stderr = "" + mock_popen.return_value = process + + mock_monitor = mock_monitor_cls.return_value + mock_monitor.monitor_process.return_value = { + "process_name": "snap-scaffold_1.fasta", + "duration_seconds": 1.5, + "peak_rss_mb": 10.0, + "peak_vms_mb": 20.0, + "avg_rss_mb": 9.0, + "avg_vms_mb": 19.0, + "sample_count": 2, + "samples": [], + } + + logger = MagicMock() + monkeypatch.setenv("FUNANNOTATE2_OUTPUT_DIR", str(tmp_path)) + + runSubprocess( + ["snap", "input.fasta"], + logger, + cwd=str(tmp_path), + monitor_memory=True, + process_name="snap-scaffold_1.fasta", + ) + + debug_messages = [call.args[0] for call in logger.debug.call_args_list] + assert "snap input.fasta" in debug_messages + assert not any("Memory usage for" in message for message in debug_messages)