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
This commit is contained in:
teknium1 2026-03-13 22:14:00 -07:00
parent af8791a49d
commit b59da08730
4 changed files with 74 additions and 6 deletions

View file

@ -1,8 +1,10 @@
"""Tests for tools/checkpoint_manager.py — CheckpointManager.""" """Tests for tools/checkpoint_manager.py — CheckpointManager."""
import logging
import os import os
import json import json
import shutil import shutil
import subprocess
import pytest import pytest
from pathlib import Path from pathlib import Path
from unittest.mock import patch from unittest.mock import patch
@ -143,6 +145,12 @@ class TestTakeCheckpoint:
result = mgr.ensure_checkpoint(str(work_dir), "initial") result = mgr.ensure_checkpoint(str(work_dir), "initial")
assert result is True 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): def test_dedup_same_turn(self, mgr, work_dir):
r1 = mgr.ensure_checkpoint(str(work_dir), "first") r1 = mgr.ensure_checkpoint(str(work_dir), "first")
r2 = mgr.ensure_checkpoint(str(work_dir), "second") r2 = mgr.ensure_checkpoint(str(work_dir), "second")
@ -375,6 +383,26 @@ class TestErrorResilience:
result = mgr.ensure_checkpoint(str(work_dir), "test") result = mgr.ensure_checkpoint(str(work_dir), "test")
assert result is False 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): def test_checkpoint_failure_does_not_raise(self, mgr, work_dir, monkeypatch):
"""Checkpoint failures should never raise — they're silently logged.""" """Checkpoint failures should never raise — they're silently logged."""
def broken_run_git(*args, **kwargs): def broken_run_git(*args, **kwargs):

View file

@ -5,6 +5,7 @@ handling without requiring a running terminal environment.
""" """
import json import json
import logging
from unittest.mock import MagicMock, patch from unittest.mock import MagicMock, patch
from tools.file_tools import ( 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") mock_ops.write_file.assert_called_once_with("/tmp/out.txt", "hello world!\n")
@patch("tools.file_tools._get_file_ops") @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") mock_get.side_effect = PermissionError("read-only filesystem")
from tools.file_tools import write_file_tool 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 "error" in result
assert "read-only" in result["error"] 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: class TestPatchHandler:

View file

@ -92,10 +92,17 @@ def _run_git(
shadow_repo: Path, shadow_repo: Path,
working_dir: str, working_dir: str,
timeout: int = _GIT_TIMEOUT, timeout: int = _GIT_TIMEOUT,
allowed_returncodes: Optional[Set[int]] = None,
) -> tuple: ) -> 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) env = _git_env(shadow_repo, working_dir)
cmd = ["git"] + list(args) cmd = ["git"] + list(args)
allowed_returncodes = allowed_returncodes or set()
try: try:
result = subprocess.run( result = subprocess.run(
cmd, cmd,
@ -108,7 +115,7 @@ def _run_git(
ok = result.returncode == 0 ok = result.returncode == 0
stdout = result.stdout.strip() stdout = result.stdout.strip()
stderr = result.stderr.strip() stderr = result.stderr.strip()
if not ok: if not ok and result.returncode not in allowed_returncodes:
logger.error( logger.error(
"Git command failed: %s (rc=%d) stderr=%s", "Git command failed: %s (rc=%d) stderr=%s",
" ".join(cmd), result.returncode, stderr, " ".join(cmd), result.returncode, stderr,
@ -381,7 +388,10 @@ class CheckpointManager:
# Check if there's anything to commit # Check if there's anything to commit
ok_diff, diff_out, _ = _run_git( ok_diff, diff_out, _ = _run_git(
["diff", "--cached", "--quiet"], shadow, working_dir, ["diff", "--cached", "--quiet"],
shadow,
working_dir,
allowed_returncodes={1},
) )
if ok_diff: if ok_diff:
# No changes to commit # No changes to commit

View file

@ -1,6 +1,7 @@
#!/usr/bin/env python3 #!/usr/bin/env python3
"""File Tools Module - LLM agent file manipulation tools.""" """File Tools Module - LLM agent file manipulation tools."""
import errno
import json import json
import logging import logging
import os import os
@ -11,6 +12,18 @@ from agent.redact import redact_sensitive_text
logger = logging.getLogger(__name__) 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_lock = threading.Lock()
_file_ops_cache: dict = {} _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) result = file_ops.write_file(path, content)
return json.dumps(result.to_dict(), ensure_ascii=False) return json.dumps(result.to_dict(), ensure_ascii=False)
except Exception as e: 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) return json.dumps({"error": str(e)}, ensure_ascii=False)