fix(agent): recovery crash-loop on duplicated SignalLog line (session b9b92d89)

A runtime self-update restart (runtime_hash_mismatch, force) killed the agent
mid-append: the final agent_shutting_down line landed byte-identically twice
(FileStream 4096-buffer re-flushed by Dispose after a faulted flush). The next
start's ReducerReplay threw non-monotonic ordinal (27 <= 27) and the uncaught
exception turned one crash artifact into a PERMANENT startup crash-loop.

Three surgical fixes:
- SignalLogWriter.Append: bufferSize 1 -> unbuffered write; Dispose can never
  re-flush the payload (at-most-once physical append)
- SignalLogWriter.ReadAll: skip byte-identical consecutive duplicate lines
  (crash artifact, not tamper); non-identical duplicate ordinals stay visible
- RecoveryCoordinator.Recover: catch InvalidOperationException from replay ->
  quarantine all reducer segments + snapshot, reseed from Initial state
  (mirrors the existing log-head-corrupt path) instead of fatal exit

E2E-verified against the real customer signal-log.jsonl: 29 lines -> 28
distinct signals -> replay OK (LastAppliedOrdinal=27, zero signal loss).
Suites green: Agent.V2.Core 1719, DecisionCore 423.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-07-09 23:22:51 +02:00
parent 7afa03aaf1
commit 57e4334bed
4 changed files with 178 additions and 6 deletions
@@ -292,6 +292,74 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration
Assert.True(new FileInfo(rig.StatePath("signal-log.jsonl")).Length > 0); Assert.True(new FileInfo(rig.StatePath("signal-log.jsonl")).Length > 0);
} }
// ================================================================= Replay failure → quarantine
[Fact]
public void Byte_identical_duplicate_log_line_replays_clean_without_quarantine()
{
// Field case (session b9b92d89, 2026-07-09): the dying process double-flushed
// its final Append → identical JSONL line twice. ReadAll dedupes the artifact,
// so recovery replays the distinct signals and does NOT quarantine anything.
using var rig = new Rig();
var sigs = new[]
{
MakeSignal(0, DecisionSignalKind.SessionStarted),
MakeSignal(1, DecisionSignalKind.AppInstallCompleted),
};
SeedSignalLog(rig, sigs);
var logPath = rig.StatePath("signal-log.jsonl");
var lines = File.ReadAllLines(logPath, Encoding.UTF8);
File.AppendAllText(logPath, lines[lines.Length - 1] + "\n", Encoding.UTF8);
var expected = ReducerReplay.Replay(
new DecisionEngine(), DecisionState.CreateInitial(SessionId, TenantId), sigs);
var result = rig.Recover();
Assert.Equal(expected.StepIndex, result.InitialState.StepIndex);
Assert.Equal(expected.LastAppliedSignalOrdinal, result.InitialState.LastAppliedSignalOrdinal);
Assert.False(Directory.Exists(Path.Combine(rig.StateDir, ".quarantine")));
}
[Fact]
public void Non_monotonic_log_is_quarantined_and_reseeds_fresh_instead_of_throwing()
{
// A duplicate ordinal on a NON-identical line (true corruption) must not escape
// Recover as a fatal exception — pre-fix this produced a permanent startup
// crash-loop (every restart replayed the same corrupt log and died again).
// Contract: quarantine all reducer segments, reseed from Initial.
using var rig = new Rig();
var sigs = new[]
{
MakeSignal(0, DecisionSignalKind.SessionStarted),
MakeSignal(1, DecisionSignalKind.AppInstallCompleted),
};
SeedSignalLog(rig, sigs);
// Same ordinal 1, different kind → different bytes → survives ReadAll dedup.
var rogue = AutopilotMonitor.DecisionCore.Serialization.SignalSerializer.Serialize(
MakeSignal(1, DecisionSignalKind.DesktopArrived));
File.AppendAllText(rig.StatePath("signal-log.jsonl"), rogue + "\n", Encoding.UTF8);
var result = rig.Recover();
Assert.True(result.WasStartupQuarantine);
Assert.Equal(SessionStage.SessionStarted, result.InitialState.Stage);
Assert.Equal(0, result.InitialState.StepIndex);
Assert.Equal(-1, result.InitialState.LastAppliedSignalOrdinal);
// Corrupt stream preserved for forensics; live writers are fresh.
Assert.True(Directory.Exists(Path.Combine(rig.StateDir, ".quarantine")));
var quarantinedLogs = Directory.GetFiles(
Path.Combine(rig.StateDir, ".quarantine"), "signal-log.jsonl", SearchOption.AllDirectories);
Assert.Single(quarantinedLogs);
Assert.Equal(-1, result.SignalLog.LastOrdinal);
Assert.Equal(-1, result.Journal.LastStepIndex);
}
// ================================================================= Journal alignment // ================================================================= Journal alignment
[Fact] [Fact]
@@ -105,6 +105,55 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Persistence
Assert.Equal(2, reread.ReadAll().Count); Assert.Equal(2, reread.ReadAll().Count);
} }
[Fact]
public void ReadAll_skips_byte_identical_duplicate_line_crash_artifact()
{
// Field case (session b9b92d89, 2026-07-09): a process kill during the final
// Append (self-update restart) double-flushed the same buffered line → the
// identical JSONL line landed twice. That is a crash artifact, not tampering —
// ReadAll must dedupe it so recovery replay sees a strictly monotonic stream.
using var tmp = new TempDirectory();
var log = tmp.File("signal-log.jsonl");
var writer = new SignalLogWriter(log);
writer.Append(TestSignals.Raw(0));
writer.Append(TestSignals.Raw(1));
// Duplicate the last line verbatim — simulates the double-flush.
var lines = File.ReadAllLines(log, Encoding.UTF8);
File.AppendAllText(log, lines[lines.Length - 1] + "\n", Encoding.UTF8);
var reread = new SignalLogWriter(log);
Assert.Equal(1, reread.LastOrdinal);
var signals = reread.ReadAll();
Assert.Equal(2, signals.Count);
Assert.Equal(0, signals[0].SessionSignalOrdinal);
Assert.Equal(1, signals[1].SessionSignalOrdinal);
}
[Fact]
public void ReadAll_does_not_dedupe_non_identical_duplicate_ordinal()
{
// A duplicate ordinal carried by a DIFFERENT line (true corruption / tamper)
// must NOT be silently dropped — it stays in the stream so the replay ordinal
// check can reject it and trigger quarantine.
using var tmp = new TempDirectory();
var log = tmp.File("signal-log.jsonl");
var writer = new SignalLogWriter(log);
writer.Append(TestSignals.Raw(0));
writer.Append(TestSignals.Raw(1));
// Re-serialize ordinal 1 with a different kind → same ordinal, different bytes.
var rogue = AutopilotMonitor.DecisionCore.Serialization.SignalSerializer.Serialize(
TestSignals.Raw(1, DecisionSignalKind.DesktopArrived));
File.AppendAllText(log, rogue + "\n", Encoding.UTF8);
var reread = new SignalLogWriter(log);
Assert.Equal(3, reread.ReadAll().Count);
}
[Fact] [Fact]
public void ReadAll_on_missing_file_returns_empty() public void ReadAll_on_missing_file_returns_empty()
{ {
@@ -406,11 +406,47 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
// rematerialises every missing StepIndex. For no-replay branches the callback // rematerialises every missing StepIndex. For no-replay branches the callback
// is simply never invoked; the journal stays aligned from the pre-replay // is simply never invoked; the journal stays aligned from the pre-replay
// truncate step above. // truncate step above.
initialState = ReducerReplay.Replay( try
engine: replayEngine, {
seed: seed, initialState = ReducerReplay.Replay(
signals: signalsToReplay, engine: replayEngine,
onTransition: journal.Append); seed: seed,
signals: signalsToReplay,
onTransition: journal.Append);
}
catch (InvalidOperationException ex)
{
// ReducerReplay (or the Journal backfill callback) rejected the persisted
// stream — non-monotonic ordinal, null signal, or a journal monotonicity
// violation. The exception contract says "caller should quarantine rather
// than trust this stream": do exactly that instead of letting the throw
// escape as a fatal startup failure. Field case (session b9b92d89,
// 2026-07-09): a self-update restart killed the agent mid-append and left a
// duplicated final line in the SignalLog; the uncaught throw here turned
// that single crash artifact into a PERMANENT crash-loop — every restart
// replayed the same corrupt log and died again. Fail-closed to a fresh
// Initial seed; the quarantine bucket keeps the stream for forensics.
logger.Error(
"EnrollmentOrchestrator: SignalLog replay failed — quarantining all reducer " +
"segments and reseeding from Initial state.", ex);
snapshot.Quarantine("replay-failed: " + ex.Message);
SegmentQuarantine.QuarantineAll(
stateDirectory, "replay-failed: " + ex.Message, () => clock.UtcNow);
// Same pattern as the log-head-corrupt quarantine above: writers hold paths,
// not handles, but their in-memory counters are stale after the move —
// recreate to reset them to -1.
signalLog = new SignalLogWriter(signalLogPath);
journal = new JournalWriter(journalPath, () => clock.UtcNow);
eventSequence = new EventSequencePersistence(eventSequencePath);
seed = DecisionState.CreateInitial(sessionId, tenantId, agentBootUtc);
signalsToReplay = Array.Empty<DecisionSignal>();
initialState = seed;
branchTag += "+replay-quarantined";
wasStartupQuarantine = true;
}
logger.Info( logger.Info(
$"EnrollmentOrchestrator: recovery branch={branchTag}, " + $"EnrollmentOrchestrator: recovery branch={branchTag}, " +
@@ -76,12 +76,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Persistence
// WriteThrough + Flush(true) — belt-and-suspenders per L.12: OS cache // WriteThrough + Flush(true) — belt-and-suspenders per L.12: OS cache
// bypass plus explicit disk flush. Any return from Append means on-disk. // bypass plus explicit disk flush. Any return from Append means on-disk.
//
// bufferSize: 1 — at-most-once physical write. With the default 4096
// buffer a line shorter than the buffer stays in FileStream's internal
// buffer until Flush; if that flush faults AFTER the data landed on disk
// (observed 2026-07-09, session b9b92d89: process killed by the self-update
// restart mid-append), the buffer position is not reset and the using-
// Dispose flushes the SAME buffer again → byte-identical duplicate line →
// non-monotonic ordinal on the next recovery replay. An unbuffered write
// hands the payload to the OS exactly once; Dispose has nothing to re-flush.
using (var fs = new FileStream( using (var fs = new FileStream(
_path, _path,
FileMode.Append, FileMode.Append,
FileAccess.Write, FileAccess.Write,
FileShare.Read, FileShare.Read,
bufferSize: 4096, bufferSize: 1,
options: FileOptions.WriteThrough)) options: FileOptions.WriteThrough))
{ {
fs.Write(bytes, 0, bytes.Length); fs.Write(bytes, 0, bytes.Length);
@@ -106,10 +115,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Persistence
return signals; return signals;
} }
string? previousRawLine = null;
foreach (var rawLine in File.ReadAllLines(_path, Encoding.UTF8)) foreach (var rawLine in File.ReadAllLines(_path, Encoding.UTF8))
{ {
if (string.IsNullOrWhiteSpace(rawLine)) continue; if (string.IsNullOrWhiteSpace(rawLine)) continue;
// Byte-identical consecutive duplicate = known crash artifact, not
// tampering: a pre-fix agent killed mid-append (self-update restart,
// session b9b92d89 2026-07-09) could flush the same buffered line twice.
// Skipping it preserves every distinct signal; anything non-monotonic
// that ISN'T an exact duplicate still reaches the replay ordinal check
// (and its quarantine handling) untouched.
if (rawLine == previousRawLine) continue;
DecisionSignal parsed; DecisionSignal parsed;
try try
{ {
@@ -124,6 +142,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Persistence
} }
signals.Add(parsed); signals.Add(parsed);
previousRawLine = rawLine;
} }
return signals; return signals;