Merge pull request #45 from nextgenusfs/clean-memory-log-output

Quiet predict memory-monitoring log output

Author: nextgenusfs

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

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

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

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)