From b59da08730977cb9c584eed5e2d94bb4274d7ec8 Mon Sep 17 00:00:00 2001 From: teknium1 Date: Fri, 13 Mar 2026 22:14:00 -0700 Subject: [PATCH] fix: reduce file tool log noise - treat git diff --cached --quiet rc=1 as an expected checkpoint state instead of logging it as an error - downgrade expected write PermissionError/EROFS/EACCES failures out of error logging while keeping unexpected exceptions at error level - add regression tests for both logging behaviors --- tests/tools/test_checkpoint_manager.py | 28 ++++++++++++++++++++++++++ tests/tools/test_file_tools.py | 18 +++++++++++++++-- tools/checkpoint_manager.py | 16 ++++++++++++--- tools/file_tools.py | 18 ++++++++++++++++- 4 files changed, 74 insertions(+), 6 deletions(-) diff --git a/tests/tools/test_checkpoint_manager.py b/tests/tools/test_checkpoint_manager.py index fc8479aca..ef843465f 100644 --- a/tests/tools/test_checkpoint_manager.py +++ b/tests/tools/test_checkpoint_manager.py @@ -1,8 +1,10 @@ """Tests for tools/checkpoint_manager.py — CheckpointManager.""" +import logging import os import json import shutil +import subprocess import pytest from pathlib import Path from unittest.mock import patch @@ -143,6 +145,12 @@ class TestTakeCheckpoint: result = mgr.ensure_checkpoint(str(work_dir), "initial") assert result is True + def test_successful_checkpoint_does_not_log_expected_diff_exit(self, mgr, work_dir, caplog): + with caplog.at_level(logging.ERROR, logger="tools.checkpoint_manager"): + result = mgr.ensure_checkpoint(str(work_dir), "initial") + assert result is True + assert not any("diff --cached --quiet" in r.getMessage() for r in caplog.records) + def test_dedup_same_turn(self, mgr, work_dir): r1 = mgr.ensure_checkpoint(str(work_dir), "first") r2 = mgr.ensure_checkpoint(str(work_dir), "second") @@ -375,6 +383,26 @@ class TestErrorResilience: result = mgr.ensure_checkpoint(str(work_dir), "test") assert result is False + def test_run_git_allows_expected_nonzero_without_error_log(self, tmp_path, caplog): + completed = subprocess.CompletedProcess( + args=["git", "diff", "--cached", "--quiet"], + returncode=1, + stdout="", + stderr="", + ) + with patch("tools.checkpoint_manager.subprocess.run", return_value=completed): + with caplog.at_level(logging.ERROR, logger="tools.checkpoint_manager"): + ok, stdout, stderr = _run_git( + ["diff", "--cached", "--quiet"], + tmp_path / "shadow", + str(tmp_path / "work"), + allowed_returncodes={1}, + ) + assert ok is False + assert stdout == "" + assert stderr == "" + assert not caplog.records + def test_checkpoint_failure_does_not_raise(self, mgr, work_dir, monkeypatch): """Checkpoint failures should never raise — they're silently logged.""" def broken_run_git(*args, **kwargs): diff --git a/tests/tools/test_file_tools.py b/tests/tools/test_file_tools.py index 27ccf7042..2bf141580 100644 --- a/tests/tools/test_file_tools.py +++ b/tests/tools/test_file_tools.py @@ -5,6 +5,7 @@ handling without requiring a running terminal environment. """ import json +import logging from unittest.mock import MagicMock, patch from tools.file_tools import ( @@ -87,13 +88,26 @@ class TestWriteFileHandler: mock_ops.write_file.assert_called_once_with("/tmp/out.txt", "hello world!\n") @patch("tools.file_tools._get_file_ops") - def test_exception_returns_error_json(self, mock_get): + def test_permission_error_returns_error_json_without_error_log(self, mock_get, caplog): mock_get.side_effect = PermissionError("read-only filesystem") from tools.file_tools import write_file_tool - result = json.loads(write_file_tool("/tmp/out.txt", "data")) + with caplog.at_level(logging.DEBUG, logger="tools.file_tools"): + result = json.loads(write_file_tool("/tmp/out.txt", "data")) assert "error" in result assert "read-only" in result["error"] + assert any("write_file expected denial" in r.getMessage() for r in caplog.records) + assert not any(r.levelno >= logging.ERROR for r in caplog.records) + + @patch("tools.file_tools._get_file_ops") + def test_unexpected_exception_still_logs_error(self, mock_get, caplog): + mock_get.side_effect = RuntimeError("boom") + + from tools.file_tools import write_file_tool + with caplog.at_level(logging.ERROR, logger="tools.file_tools"): + result = json.loads(write_file_tool("/tmp/out.txt", "data")) + assert result["error"] == "boom" + assert any("write_file error" in r.getMessage() for r in caplog.records) class TestPatchHandler: diff --git a/tools/checkpoint_manager.py b/tools/checkpoint_manager.py index 16ef69ead..5315e37b1 100644 --- a/tools/checkpoint_manager.py +++ b/tools/checkpoint_manager.py @@ -92,10 +92,17 @@ def _run_git( shadow_repo: Path, working_dir: str, timeout: int = _GIT_TIMEOUT, + allowed_returncodes: Optional[Set[int]] = None, ) -> tuple: - """Run a git command against the shadow repo. Returns (ok, stdout, stderr).""" + """Run a git command against the shadow repo. Returns (ok, stdout, stderr). + + ``allowed_returncodes`` suppresses error logging for known/expected non-zero + exits while preserving the normal ``ok = (returncode == 0)`` contract. + Example: ``git diff --cached --quiet`` returns 1 when changes exist. + """ env = _git_env(shadow_repo, working_dir) cmd = ["git"] + list(args) + allowed_returncodes = allowed_returncodes or set() try: result = subprocess.run( cmd, @@ -108,7 +115,7 @@ def _run_git( ok = result.returncode == 0 stdout = result.stdout.strip() stderr = result.stderr.strip() - if not ok: + if not ok and result.returncode not in allowed_returncodes: logger.error( "Git command failed: %s (rc=%d) stderr=%s", " ".join(cmd), result.returncode, stderr, @@ -381,7 +388,10 @@ class CheckpointManager: # Check if there's anything to commit ok_diff, diff_out, _ = _run_git( - ["diff", "--cached", "--quiet"], shadow, working_dir, + ["diff", "--cached", "--quiet"], + shadow, + working_dir, + allowed_returncodes={1}, ) if ok_diff: # No changes to commit diff --git a/tools/file_tools.py b/tools/file_tools.py index 8ed019f0a..e2535b06a 100644 --- a/tools/file_tools.py +++ b/tools/file_tools.py @@ -1,6 +1,7 @@ #!/usr/bin/env python3 """File Tools Module - LLM agent file manipulation tools.""" +import errno import json import logging import os @@ -11,6 +12,18 @@ from agent.redact import redact_sensitive_text logger = logging.getLogger(__name__) +_EXPECTED_WRITE_ERRNOS = {errno.EACCES, errno.EPERM, errno.EROFS} + + +def _is_expected_write_exception(exc: Exception) -> bool: + """Return True for expected write denials that should not hit error logs.""" + if isinstance(exc, PermissionError): + return True + if isinstance(exc, OSError) and exc.errno in _EXPECTED_WRITE_ERRNOS: + return True + return False + + _file_ops_lock = threading.Lock() _file_ops_cache: dict = {} @@ -238,7 +251,10 @@ def write_file_tool(path: str, content: str, task_id: str = "default") -> str: result = file_ops.write_file(path, content) return json.dumps(result.to_dict(), ensure_ascii=False) except Exception as e: - logger.error("write_file error: %s: %s", type(e).__name__, e) + if _is_expected_write_exception(e): + logger.debug("write_file expected denial: %s: %s", type(e).__name__, e) + else: + logger.error("write_file error: %s: %s", type(e).__name__, e, exc_info=True) return json.dumps({"error": str(e)}, ensure_ascii=False)