From e9f3497441784f900478fc8d9b10cb7b9f55deee Mon Sep 17 00:00:00 2001 From: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> Date: Wed, 26 Aug 2026 07:36:39 -0700 Subject: [PATCH] fix: recover from corrupt metadata.json on disk full (ENOSPC) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Problem: Sessions running when the disk filled up logged endless repeating errors (json.decoder.JSONDecodeError on empty metadata.json). Root cause is two bugs: 1. Non-atomic metadata writes. All four metadata writers used Path.write_text(), which truncates the file to 0 bytes THEN writes. When the disk was full (ENOSPC), the truncate succeeded but the content write failed, leaving metadata.json permanently empty. 2. No tolerance for corrupt metadata. _touch_last_event_at reads-then-writes: json.loads('') throws every event before reaching the write that would repair it, so the error repeats forever. _ensure_metadata only recreates *missing* files, not 0-byte ones that still "exist". Solution (logging_handler.py): - Added import os. - New helper _read_metadata() returns None for missing/empty/corrupt/non-dict JSON instead of raising, so callers rebuild from defaults. - New helper _atomic_write_text() writes to a temp file then os.replace(); on failure it leaves the existing file untouched and cleans up the temp file. - Rewrote all four metadata functions to read tolerantly and write atomically. _touch_last_event_at now self-heals: corrupt metadata.json is rebuilt from defaults in-place, stopping the error loop. Testing: 10 new tests in test_logging_handler_metadata_recovery.py covering: - _read_metadata tolerance for all error cases - atomic-write-leaves-original-intact-on-simulated-ENOSPC - end-to-end self-heal of empty/corrupt metadata.json mid-session and after restart All tests pass (639 + 10 new). Dogfooded against 4 real corrupted sessions on this machine — all now valid JSON, 0 zero-byte files remaining. Generated with [Amplifier](https://github.com/microsoft/amplifier) Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- .../handlers/logging_handler.py | 108 ++++++-- .../test_logging_handler_metadata_recovery.py | 232 ++++++++++++++++++ 2 files changed, 323 insertions(+), 17 deletions(-) create mode 100644 modules/hook-context-intelligence/tests/test_logging_handler_metadata_recovery.py diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py index 4f6a574..26c99db 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py @@ -9,6 +9,7 @@ import asyncio import json import logging +import os import random import time from collections import deque @@ -1324,6 +1325,54 @@ async def __call__(self, event: str, data: dict[str, Any]) -> HookResult: return HookResult(action="continue") + # -- metadata read/write primitives ------------------------------------- + @staticmethod + def _read_metadata(meta_path: Path) -> dict[str, Any] | None: + """Read and parse metadata.json, tolerating missing/empty/corrupt files. + + Returns the parsed object, or ``None`` when the file is absent, empty, + or not valid JSON. A ``None`` return signals the caller to rebuild + metadata from defaults rather than raise. + + This is the guard against a file left 0-length by a previously + interrupted write (e.g. an ``ENOSPC`` truncation while the disk was + full): ``meta_path.exists()`` is True for such a file, but its content + is unparseable, so an ``exists()``-only check is not sufficient. + """ + try: + raw = meta_path.read_text() + except OSError: + return None + if not raw.strip(): + return None + try: + parsed = json.loads(raw) + except json.JSONDecodeError: + return None + return parsed if isinstance(parsed, dict) else None + + @staticmethod + def _atomic_write_text(meta_path: Path, text: str) -> None: + """Write ``text`` to ``meta_path`` atomically via temp file + os.replace. + + Guarantees a reader never observes a partially written or truncated + file. On success the rename is atomic; on failure (e.g. ``ENOSPC``) the + existing file at ``meta_path`` is left untouched rather than truncated + to zero bytes -- which is precisely the corruption that a plain + ``write_text`` produced when the disk filled mid-write. The temp file + is best-effort cleaned up on failure. + """ + tmp_path = meta_path.with_name(f"{meta_path.name}.{os.getpid()}.tmp") + try: + tmp_path.write_text(text) + os.replace(tmp_path, meta_path) + except OSError: + try: + tmp_path.unlink() + except OSError: + pass + raise + # -- metadata lifecycle ------------------------------------------------- def _ensure_metadata( self, @@ -1331,9 +1380,15 @@ def _ensure_metadata( session_id: str, data: dict[str, Any], ) -> None: - """Create initial metadata.json on first event for this session.""" + """Create initial metadata.json on first event for this session. + + Treats a missing, empty, or corrupt file as "needs creation" -- a file + left 0-length by a prior interrupted write (e.g. ENOSPC while the disk + was full) is thus repaired here rather than left to error on every + future event. + """ meta_path = session_dir / "metadata.json" - if meta_path.exists(): + if self._read_metadata(meta_path) is not None: return metadata: dict[str, Any] = { @@ -1347,7 +1402,7 @@ def _ensure_metadata( "status": "running", "working_dir": self._resolver.working_dir, } - meta_path.write_text(json.dumps(metadata, separators=(",", ":"))) + self._atomic_write_text(meta_path, json.dumps(metadata, separators=(",", ":"))) def _enrich_metadata_from_session_init( self, @@ -1357,11 +1412,11 @@ def _enrich_metadata_from_session_init( ) -> None: """Enrich metadata with fields only available in session:start/fork.""" meta_path = session_dir / "metadata.json" - if meta_path.exists(): - meta = json.loads(meta_path.read_text()) - else: - # defensive: should already exist from _ensure_metadata; this branch - # is unreachable in normal flow but guards against unexpected race conditions. + meta = self._read_metadata(meta_path) + if meta is None: + # metadata.json is missing, empty, or corrupt (e.g. left 0-length by + # a prior ENOSPC-truncated write). Rebuild from defaults rather than + # raise, then re-apply the authoritative session-init fields below. meta = { "format": _METADATA_FORMAT, "version": _METADATA_VERSION, @@ -1387,16 +1442,16 @@ def _enrich_metadata_from_session_init( if value: meta[field] = value - meta_path.write_text(json.dumps(meta, separators=(",", ":"))) + self._atomic_write_text(meta_path, json.dumps(meta, separators=(",", ":"))) def _finalize_metadata(self, session_dir: Path, data: dict[str, Any]) -> None: """Mark session as completed in metadata.""" meta_path = session_dir / "metadata.json" - if meta_path.exists(): - meta = json.loads(meta_path.read_text()) - else: - # defensive: should already exist from _ensure_metadata; this branch - # is unreachable in normal flow but guards against unexpected race conditions. + meta = self._read_metadata(meta_path) + if meta is None: + # metadata.json is missing, empty, or corrupt (e.g. left 0-length by + # a prior ENOSPC-truncated write). Rebuild from defaults rather than + # raise, so the session is still marked completed below. meta = { "format": _METADATA_FORMAT, "version": _METADATA_VERSION, @@ -1408,7 +1463,7 @@ def _finalize_metadata(self, session_dir: Path, data: dict[str, Any]) -> None: meta["status"] = data.get("status", "completed") meta["ended_at"] = data.get("timestamp", "") - meta_path.write_text(json.dumps(meta, separators=(",", ":"))) + self._atomic_write_text(meta_path, json.dumps(meta, separators=(",", ":"))) # -- lifecycle management ------------------------------------------------ async def close(self) -> None: @@ -1419,14 +1474,33 @@ async def close(self) -> None: def _touch_last_event_at(self, session_dir: Path, timestamp: str) -> None: """Update last_event_at in metadata.json after each event append. + Self-healing: a missing, empty, or corrupt metadata.json (e.g. one left + 0-length by a prior ENOSPC-truncated write while the disk was full) is + rebuilt from best-effort defaults instead of erroring on every event. + Best-effort: catches OSError and json.JSONDecodeError, logs a warning, and never raises. A failure here must never block event capture. """ try: meta_path = session_dir / "metadata.json" - meta = json.loads(meta_path.read_text()) + meta = self._read_metadata(meta_path) + if meta is None: + # metadata.json is missing, empty, or corrupt. Rebuild a minimal + # valid record from what this handler knows so freshness tracking + # recovers; the session_id folder is meta_path's grandparent + # (.../sessions//context-intelligence/metadata.json). + meta = { + "format": _METADATA_FORMAT, + "version": _METADATA_VERSION, + "session_id": session_dir.parent.name, + "workspace": self._workspace or "", + "parent_id": self._parent_id or "", + "started_at": timestamp, + "status": "running", + "working_dir": self._resolver.working_dir, + } meta["last_event_at"] = timestamp - meta_path.write_text(json.dumps(meta, separators=(",", ":"))) + self._atomic_write_text(meta_path, json.dumps(meta, separators=(",", ":"))) except (OSError, json.JSONDecodeError): logger.warning( "LoggingHandler failed to update last_event_at for %s", diff --git a/modules/hook-context-intelligence/tests/test_logging_handler_metadata_recovery.py b/modules/hook-context-intelligence/tests/test_logging_handler_metadata_recovery.py new file mode 100644 index 0000000..e5985c5 --- /dev/null +++ b/modules/hook-context-intelligence/tests/test_logging_handler_metadata_recovery.py @@ -0,0 +1,232 @@ +"""Regression tests for metadata.json corruption recovery. + +Background: a long-running session's ``metadata.json`` is rewritten after every +event. The pre-fix code used a non-atomic ``Path.write_text`` (truncate then +write). When the disk filled mid-write (``ENOSPC``) the truncate succeeded but +the content write did not, leaving ``metadata.json`` permanently 0 bytes. Every +subsequent event then hit ``json.loads("")`` and raised +``JSONDecodeError: Expecting value: line 1 column 1 (char 0)`` -- caught, logged, +and repeated forever, because the read failed before the write that would have +repaired it and ``_ensure_metadata`` only (re)creates a *missing* file. + +These tests verify the two-part fix: +1. reads tolerate a missing/empty/corrupt file and rebuild it (self-heal), and +2. writes are atomic (temp file + os.replace), so a failed write never + truncates the existing file to zero bytes. +""" + +from __future__ import annotations + +import json +from pathlib import Path +from unittest.mock import patch + + +class _FakeResolver: + """Minimal resolver adapter for testing LoggingHandler in isolation.""" + + def __init__( + self, base_path: Path, project_slug: str, workspace: str = "test-workspace" + ) -> None: + self.base_path = base_path + self.project_slug = project_slug + self.workspace = workspace + self.working_dir: str = "/w" + + def session_dir(self, session_id: str) -> Path: + return self.base_path / self.project_slug / "sessions" / session_id / "context-intelligence" + + +def _meta_path(tmp_path: Path, session_id: str = "s1") -> Path: + return tmp_path / "proj" / "sessions" / session_id / "context-intelligence" / "metadata.json" + + +# --------------------------------------------------------------------------- +# _read_metadata: tolerate missing / empty / corrupt +# --------------------------------------------------------------------------- +class TestReadMetadata: + def test_missing_returns_none(self, tmp_path: Path) -> None: + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + assert LoggingHandler._read_metadata(tmp_path / "nope.json") is None + + def test_empty_returns_none(self, tmp_path: Path) -> None: + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + p = tmp_path / "metadata.json" + p.write_text("") # exactly the 0-byte ENOSPC artifact + assert LoggingHandler._read_metadata(p) is None + + def test_corrupt_returns_none(self, tmp_path: Path) -> None: + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + p = tmp_path / "metadata.json" + p.write_text("{not json") + assert LoggingHandler._read_metadata(p) is None + + def test_non_object_returns_none(self, tmp_path: Path) -> None: + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + p = tmp_path / "metadata.json" + p.write_text("[1, 2, 3]") + assert LoggingHandler._read_metadata(p) is None + + def test_valid_returns_dict(self, tmp_path: Path) -> None: + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + p = tmp_path / "metadata.json" + p.write_text(json.dumps({"a": 1})) + assert LoggingHandler._read_metadata(p) == {"a": 1} + + +# --------------------------------------------------------------------------- +# _atomic_write_text: a failed write must not truncate the existing file +# --------------------------------------------------------------------------- +class TestAtomicWrite: + def test_success_writes_content(self, tmp_path: Path) -> None: + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + p = tmp_path / "metadata.json" + LoggingHandler._atomic_write_text(p, '{"ok":true}') + assert json.loads(p.read_text()) == {"ok": True} + + def test_failure_leaves_original_intact(self, tmp_path: Path) -> None: + """If the temp write fails (e.g. ENOSPC), the existing file is untouched. + + This is the core guarantee the old ``write_text`` violated: it would + have left a 0-byte file. The atomic path must leave the last-good + content in place instead. + """ + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + p = tmp_path / "metadata.json" + good = json.dumps({"status": "running", "last_event_at": "t0"}) + p.write_text(good) + + real_write_text = Path.write_text + + def fail_on_tmp(self: Path, *args: object, **kwargs: object): + # Simulate ENOSPC only for the temp file the atomic writer creates. + if self.name.endswith(".tmp"): + raise OSError("No space left on device") + return real_write_text(self, *args, **kwargs) # type: ignore[arg-type] + + with patch.object(Path, "write_text", fail_on_tmp): + try: + LoggingHandler._atomic_write_text(p, json.dumps({"status": "new"})) + except OSError: + pass # the writer re-raises; caller (`_touch`) handles it + + # Original content survives; no truncation to zero bytes. + assert p.read_text() == good + assert p.stat().st_size > 0 + # No leftover temp files in the directory. + assert not list(tmp_path.glob("*.tmp")) + + +# --------------------------------------------------------------------------- +# End-to-end self-heal through the handler event flow +# --------------------------------------------------------------------------- +class TestSelfHeal: + async def test_touch_heals_empty_metadata_mid_session(self, tmp_path: Path) -> None: + """The exact reported scenario: metadata.json goes 0-byte mid-session. + + A subsequent event must self-heal it (not raise, not warn) and restore a + valid file whose last_event_at reflects that event. + """ + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + logger, + ) + + handler = LoggingHandler(_FakeResolver(tmp_path, "proj")) + await handler( + "session:start", + {"session_id": "s1", "timestamp": "2026-01-15T10:00:00Z", "working_dir": "/w"}, + ) + + meta_path = _meta_path(tmp_path) + assert json.loads(meta_path.read_text())["last_event_at"] == "2026-01-15T10:00:00Z" + + # Corrupt exactly as ENOSPC did: truncate to zero bytes. + meta_path.write_text("") + assert meta_path.stat().st_size == 0 + + with patch.object(logger, "warning") as warn: + await handler( + "tool:call", + {"session_id": "s1", "timestamp": "2026-01-15T10:05:00Z", "tool_name": "read_file"}, + ) + + # No warning was emitted -- the error loop is gone. + warn.assert_not_called() + + healed = json.loads(meta_path.read_text()) + assert healed["last_event_at"] == "2026-01-15T10:05:00Z" + assert healed["session_id"] == "s1" + assert healed["status"] == "running" + + async def test_touch_heals_corrupt_metadata_mid_session(self, tmp_path: Path) -> None: + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + logger, + ) + + handler = LoggingHandler(_FakeResolver(tmp_path, "proj")) + await handler( + "session:start", + {"session_id": "s1", "timestamp": "2026-01-15T10:00:00Z", "working_dir": "/w"}, + ) + + _meta_path(tmp_path).write_text("{ truncated garbage") + + with patch.object(logger, "warning") as warn: + await handler( + "tool:call", + {"session_id": "s1", "timestamp": "2026-01-15T10:06:00Z", "tool_name": "grep"}, + ) + + warn.assert_not_called() + assert ( + json.loads(_meta_path(tmp_path).read_text())["last_event_at"] == "2026-01-15T10:06:00Z" + ) + + async def test_ensure_metadata_recreates_empty_file_after_restart(self, tmp_path: Path) -> None: + """A fresh handler (process restart) also heals a pre-existing 0-byte file. + + ``_ensure_metadata`` must treat empty/corrupt as "needs creation", not + skip on ``exists()``. + """ + from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + LoggingHandler, + ) + + # Pre-create the corrupt artifact before any handler sees the session. + meta_path = _meta_path(tmp_path) + meta_path.parent.mkdir(parents=True, exist_ok=True) + meta_path.write_text("") + + handler = LoggingHandler(_FakeResolver(tmp_path, "proj")) + await handler( + "tool:call", + {"session_id": "s1", "timestamp": "2026-01-15T11:00:00Z", "tool_name": "read_file"}, + ) + + meta = json.loads(meta_path.read_text()) + assert meta["session_id"] == "s1" + assert meta["last_event_at"] == "2026-01-15T11:00:00Z" + assert meta["working_dir"] == "/w"