fix: write-ahead audit entry so calls stop when the audit log stops accepting writes (SEC-03)
This commit is contained in:
1 parent
5b622e64e2
commit
43eebd3089
8 files changed
+134
-15
No files matched your search
@@ -115,8 +115,9 @@ One token verifier accepts either kind. The dispatcher turns the verified token
|
||||
|
||||
## Audit
|
||||
|
||||
Every tool call, including failed and invalid ones, produces exactly one event in the
|
||||
append-only, hash-chained audit log. Only argument names are recorded, never values. Details and
|
||||
Every tool call, including failed and invalid ones, produces exactly one result event in the
|
||||
append-only, hash-chained audit log, after a write-ahead event that makes a call fail closed when
|
||||
the log stops accepting writes. Only argument names are recorded, never values. Details and
|
||||
integrity validation are in [audit-logging.md](audit-logging.md).
|
||||
|
||||
## Request flow
|
||||
@@ -127,7 +128,9 @@ integrity validation are in [audit-logging.md](audit-logging.md).
|
||||
schema, and resolves the identity.
|
||||
4. The executor calls Gitea with the identity's token.
|
||||
5. The response is bounded, redacted and masked, and wrapped in the envelope.
|
||||
6. One audit event is written and the result is returned.
|
||||
6. One audit result event is written and the result is returned. (A write-ahead
|
||||
`tool_call_started` event is written right after the tool lookup in step 3; when it cannot be
|
||||
written the call is refused.)
|
||||
|
||||
## Module map
|
||||
|
||||
|
||||
+13
-9
@@ -1,8 +1,10 @@
|
||||
# Audit logging
|
||||
|
||||
Every tool call produces exactly one event in an append-only, hash-chained JSON-lines log,
|
||||
whether it succeeded, failed at Gitea, failed validation or hit an internal error. Security
|
||||
events are logged in the same chain.
|
||||
Every tool call produces exactly one result event (`tool_invocation`) in an append-only,
|
||||
hash-chained JSON-lines log, whether it succeeded, failed at Gitea, failed validation or hit an
|
||||
internal error. A call to a known tool is preceded by a small write-ahead event
|
||||
(`tool_call_started`, see Location and permissions). Security events are logged in the same
|
||||
chain.
|
||||
|
||||
## What an event contains
|
||||
|
||||
@@ -11,7 +13,7 @@ Each line is one JSON object:
|
||||
| Field | Meaning |
|
||||
|---|---|
|
||||
| `timestamp` | UTC, ISO 8601 |
|
||||
| `event_type` | `tool_invocation` or `security_event` |
|
||||
| `event_type` | `tool_invocation`, `tool_call_started`, `access_denied` or `security_event` |
|
||||
| `request_id` | Correlation id of the request |
|
||||
| `payload` | The event data, see below |
|
||||
| `prev_hash` | `entry_hash` of the previous line (`GENESIS` for the first) |
|
||||
@@ -56,11 +58,13 @@ The log is written to `AUDIT_LOG_PATH`, default `DATA_DIR/audit.log` (`/var/lib/
|
||||
image). Keep it on durable storage, readable and writable only by the service account.
|
||||
|
||||
The server opens the file for append at startup and exits with code 2 (message on stderr) when
|
||||
that fails, so it never runs unaudited. Each call also obtains the audit logger before it runs;
|
||||
if that fails the call is refused with `audit_unavailable` and never reaches Gitea. A write
|
||||
failure after a call has executed is only logged to stderr: the Gitea side effect already
|
||||
happened and the caller must still receive the result. The `correlation_id` of a tool entry is
|
||||
the request id, which is also the entry's `request_id`.
|
||||
that fails, so it never runs unaudited. The check does not stop at startup: each call to a known
|
||||
tool first writes a `tool_call_started` entry (tool name, domain and correlation id), and when
|
||||
that write fails (full disk, revoked mount, closed file) the call is refused with
|
||||
`audit_unavailable` and never reaches Gitea. Calls resume as soon as writes work again. A write
|
||||
failure of the final `tool_invocation` entry after a call has executed is only logged to stderr:
|
||||
the Gitea side effect already happened and the caller must still receive the result. The
|
||||
`correlation_id` of both entries is the request id, which is also the entry's `request_id`.
|
||||
|
||||
## Rotation
|
||||
|
||||
|
||||
+1
-1
@@ -78,7 +78,7 @@ Repudiation
|
||||
|
||||
| Threat | Mitigation | Implemented in |
|
||||
|---|---|---|
|
||||
| Unrecorded tool calls | Exactly one hash-chained audit entry per call; a call is refused when the audit log cannot be opened; startup fails on an unwritable log | `server.py`, `audit.py`, `transports.py` (write failures after startup: SEC-03) |
|
||||
| Unrecorded tool calls | Exactly one hash-chained result entry per call, preceded by a write-ahead `tool_call_started` entry; a call is refused when either the logger or that write fails; startup fails on an unwritable log | `server.py`, `audit.py`, `transports.py` |
|
||||
| Undetected edits of the log | SHA-256 hash chain, `scripts/validate_audit_log.py` | `audit.py` (unkeyed chain: SEC-11) |
|
||||
|
||||
Information disclosure
|
||||
|
||||
@@ -162,6 +162,21 @@ class AuditLogger:
|
||||
payload["error"] = error
|
||||
return self._append_entry("tool_invocation", payload)
|
||||
|
||||
def log_tool_call_started(
|
||||
self, tool_name: str, correlation_id: str, domain: str | None = None
|
||||
) -> str:
|
||||
"""Write the write-ahead entry of a call that is about to run.
|
||||
|
||||
The dispatcher writes it before executing a known tool and refuses the call
|
||||
when it cannot be written, so an audit log that stopped accepting writes
|
||||
after startup (full disk, revoked mount) stops the calls instead of letting
|
||||
them run unrecorded. The final ``tool_invocation`` entry carries the result.
|
||||
"""
|
||||
payload: dict[str, Any] = {"correlation_id": correlation_id, "tool_name": tool_name}
|
||||
if domain is not None:
|
||||
payload["domain"] = domain
|
||||
return self._append_entry("tool_call_started", payload)
|
||||
|
||||
def log_access_denied(
|
||||
self,
|
||||
tool_name: str,
|
||||
|
||||
@@ -430,6 +430,19 @@ class _Dispatcher:
|
||||
record.outcome = "unknown_tool"
|
||||
raise MCPError(types.INVALID_PARAMS, f"Unknown tool: {record.tool}")
|
||||
record.domain = entry.domain
|
||||
# Write-ahead entry: a call whose start cannot be recorded does not run.
|
||||
try:
|
||||
audit.log_tool_call_started(entry.tool.name, request_id, entry.domain)
|
||||
except Exception as exc:
|
||||
logger.error("audit log write failed, refusing the call: %s", type(exc).__name__)
|
||||
record.outcome = "audit_unavailable"
|
||||
return _result(
|
||||
_error_payload(
|
||||
"audit_unavailable",
|
||||
"The audit log is not writable, so the call was not executed",
|
||||
),
|
||||
is_error=True,
|
||||
)
|
||||
try:
|
||||
return await self._dispatch(entry, arguments, record)
|
||||
except Exception as exc:
|
||||
|
||||
@@ -0,0 +1,79 @@
|
||||
"""The audit log is fail closed after startup too (SEC-03) and names the client (SEC-12)."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
from typing import Any
|
||||
|
||||
import pytest
|
||||
from pytest_httpx import HTTPXMock
|
||||
|
||||
from aegis_gitea_mcp.audit import get_audit_logger
|
||||
from tests.test_server_helpers import API, connected, mock_user
|
||||
|
||||
REPO_ARGS = {"owner": "octo", "repo": "demo"}
|
||||
|
||||
|
||||
@pytest.fixture(autouse=True)
|
||||
def _env(mock_env: None) -> None:
|
||||
"""The audit logger reads the process-wide settings."""
|
||||
|
||||
|
||||
class FailingFile:
|
||||
"""Stands in for the open audit file and fails every write like a full disk."""
|
||||
|
||||
def __init__(self) -> None:
|
||||
self.attempts = 0
|
||||
|
||||
def write(self, data: str) -> int:
|
||||
self.attempts += 1
|
||||
raise OSError(28, "No space left on device")
|
||||
|
||||
def flush(self) -> None: # pragma: no cover - never reached
|
||||
raise OSError(28, "No space left on device")
|
||||
|
||||
def close(self) -> None:
|
||||
return None
|
||||
|
||||
|
||||
def payload_of(result: Any) -> dict[str, Any]:
|
||||
decoded: dict[str, Any] = json.loads(result.content[0].text)
|
||||
return decoded
|
||||
|
||||
|
||||
async def test_calls_stop_when_the_audit_log_stops_accepting_writes(
|
||||
httpx_mock: HTTPXMock,
|
||||
) -> None:
|
||||
mock_user(httpx_mock)
|
||||
httpx_mock.add_response(url=f"{API}/repos/octo/demo", json={"name": "demo"}, is_reusable=True)
|
||||
async with connected() as client:
|
||||
first = await client.call_tool("gitea_repo_get", REPO_ARGS)
|
||||
assert not first.is_error
|
||||
sent_before = len(httpx_mock.get_requests())
|
||||
|
||||
audit = get_audit_logger()
|
||||
healthy_file = audit._log_file
|
||||
audit._log_file = FailingFile() # type: ignore[assignment]
|
||||
second = await client.call_tool("gitea_repo_get", REPO_ARGS)
|
||||
mutation = await client.call_tool(
|
||||
"gitea_issue_create_issue", {**REPO_ARGS, "body": {"title": "x"}}
|
||||
)
|
||||
|
||||
assert second.is_error and mutation.is_error
|
||||
assert payload_of(second)["error"]["kind"] == "audit_unavailable"
|
||||
assert payload_of(mutation)["error"]["kind"] == "audit_unavailable"
|
||||
# Gitea was not contacted at all while the log was broken.
|
||||
assert len(httpx_mock.get_requests()) == sent_before
|
||||
|
||||
audit._log_file = healthy_file
|
||||
resumed = await client.call_tool("gitea_repo_get", REPO_ARGS)
|
||||
assert not resumed.is_error
|
||||
|
||||
|
||||
async def test_the_refusal_does_not_leak_the_failure_reason() -> None:
|
||||
async with connected() as client:
|
||||
get_audit_logger()._log_file = FailingFile() # type: ignore[assignment]
|
||||
result = await client.call_tool("gitea_repo_get", REPO_ARGS)
|
||||
|
||||
text = result.content[0].text # type: ignore[union-attr]
|
||||
assert "No space left" not in text and "OSError" not in text
|
||||
@@ -476,6 +476,9 @@ async def test_audit_write_failure_after_execution_does_not_break_the_call(
|
||||
httpx_mock.add_response(url=f"{API}/repos/octo/demo", json={})
|
||||
|
||||
class BrokenAudit:
|
||||
def log_tool_call_started(self, *args: Any, **kwargs: Any) -> str:
|
||||
return "started"
|
||||
|
||||
def log_tool_invocation(self, *args: Any, **kwargs: Any) -> str:
|
||||
raise OSError("disk full: " + GITEA_TOKEN)
|
||||
|
||||
|
||||
@@ -341,8 +341,10 @@ async def test_real_stdio_subprocess_serves_the_catalog(tmp_path: Path) -> None:
|
||||
payload = json.loads(result.content[0].text) # type: ignore[union-attr]
|
||||
assert "error" in payload and GITEA_TOKEN not in json.dumps(payload)
|
||||
audit = (tmp_path / "state" / "audit.log").read_text(encoding="utf-8").splitlines()
|
||||
assert len(audit) == 1
|
||||
assert GITEA_TOKEN not in audit[0]
|
||||
events = [json.loads(line)["event_type"] for line in audit]
|
||||
# A write-ahead entry, then the one tool_invocation entry with the result.
|
||||
assert events == ["tool_call_started", "tool_invocation"]
|
||||
assert all(GITEA_TOKEN not in line for line in audit)
|
||||
|
||||
|
||||
# serve command
|
||||
|
||||
Reference in new issue
Block a user