From 34ec44e3d478cec9b71324d085fc7dbab7704f39 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Fri, 4 Sep 2026 21:34:15 +0200 Subject: [PATCH] backend: duration evaluators refuse mixed timestamp provenance only MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The first cut refused every reader-zone-fallback endpoint. The DeviceSetup line is written before the agent starts and is backlog on every device, so that silenced ANALYZE-ESP-001 for all agents without an era anchor (control sessions 2708e6b4 and 18d80f9c came back "not measurable" after the deploy). Two fallback endpoints share the writer-zone error and cancel it; only a span mixing a fallback endpoint with an anchored one (or with "now" for an open phase) is unmeasurable — the a7140f98 shape. Co-Authored-By: Claude Fable 5.1 --- internal | 2 +- rules/schema/analyze-rule.schema.json | 2 +- .../RuleEngineDurationProvenanceTests.cs | 55 ++++++++++++++++++- .../RuleEngine.ConditionEvaluators.cs | 54 +++++++++++------- .../src/rule-authoring-guide.ts | 11 ++-- .../src/rule-authoring.generated.ts | 2 +- 6 files changed, 95 insertions(+), 31 deletions(-) diff --git a/internal b/internal index 9f75da24..40bc57dd 160000 --- a/internal +++ b/internal @@ -1 +1 @@ -Subproject commit 9f75da246a3662fa23a9b96237997159195432f4 +Subproject commit 40bc57dd5f1a51bc3f3365a155bd4ec1f561a56b diff --git a/rules/schema/analyze-rule.schema.json b/rules/schema/analyze-rule.schema.json index b408a44d..02852d59 100644 --- a/rules/schema/analyze-rule.schema.json +++ b/rules/schema/analyze-rule.schema.json @@ -168,7 +168,7 @@ }, "source": { "type": "string", - "description": "Source of the signal. phase_duration and app_install_duration never derive a duration from an IME-log timestamp whose sourceOffsetOrigin is reader-zone-fallback (writer timezone unknown to the agent): such a condition evaluates false with evidence timestampProvenance=reader-zone-fallback.", + "description": "Source of the signal. phase_duration and app_install_duration never derive a duration from a span with mixed timestamp provenance (exactly one IME-log endpoint with sourceOffsetOrigin=reader-zone-fallback, i.e. the writer timezone was unknown to the agent for one endpoint only): such a condition evaluates false with evidence timestampProvenance=reader-zone-fallback. Two fallback endpoints share the same error and stay measurable.", "enum": ["event_type", "event_data", "event_data_array", "phase_duration", "event_count", "app_install_duration", "event_correlation", "clock_skew"] }, "skewMetric": { diff --git a/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs index 985bd8cc..4b111abc 100644 --- a/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs +++ b/src/Backend/AutopilotMonitor.Functions.Tests/RuleEngineDurationProvenanceTests.cs @@ -10,8 +10,9 @@ namespace AutopilotMonitor.Functions.Tests; /// Timestamp provenance in the duration evaluators (phase_duration, app_install_duration). /// IME-log-derived events carry data.sourceOffsetOrigin; reader-zone-fallback /// means the agent assumed its own timezone for the log writer, so the Timestamp can be hours -/// off. A duration with such an endpoint is not measurable: the condition is false with a -/// provenance reason. Other origins and agent-native events (no tag) stay measurable. +/// off. A span with MIXED provenance — one fallback endpoint, the other anchored or "now" — is +/// not measurable: the condition is false with a provenance reason. Two fallback endpoints share +/// the writer's error and stay measurable, as do other origins and agent-native events (no tag). /// Field case: a 20-minute DeviceSetup rendered as 3 h 22 min fired ANALYZE-ESP-001 (high). /// public class RuleEngineDurationProvenanceTests @@ -130,8 +131,42 @@ public class RuleEngineDurationProvenanceTests Assert.Equal("start", AsString(AsDict(fallbackCondition.Evidence!)["provenanceEndpoint"])); } + [Fact] + public async Task PhaseDuration_BothEndsFallback_IsComputed() + { + // Two fallback endpoints carry the same writer-zone error, so the span is right — and + // this is the shape of every session from an agent without an era anchor, because the + // DeviceSetup line is written before the agent starts. + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, Fallback), + PhaseEvent("AccountSetup", T0.AddHours(3), 20, Fallback), + }; + + var (dry, _, _) = await DryRunAsync(PhaseRule("DeviceSetup"), events); + + var condition = Assert.Single(dry.Conditions); + Assert.True(condition.Matched); + Assert.Equal(10800d, Convert.ToDouble(AsDict(condition.Evidence!)["durationSeconds"])); + } + // ===== app_install_duration ===== + [Fact] + public async Task AppInstallDuration_BothEndsFallback_IsComputed() + { + var events = new List + { + AppEvent("app_install_started", "app-a", T0, 10, Fallback), + AppEvent("app_install_completed", "app-a", T0.AddHours(1), 20, Fallback), + }; + + var (dry, _, _) = await DryRunAsync(AppDurationRule(minSeconds: 600), events); + + var condition = Assert.Single(dry.Conditions); + Assert.True(condition.Matched); + } + [Fact] public async Task AppInstallDuration_StartWithFallbackProvenance_IsNotMeasurable() { @@ -242,6 +277,22 @@ public class RuleEngineDurationProvenanceTests Assert.Empty(outcome.Results); } + [Fact] + public async Task ANALYZE_ESP_001_still_fires_when_both_endpoints_are_fallback() + { + var rule = BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == "ANALYZE-ESP-001"); + + var events = new List + { + PhaseEvent("DeviceSetup", T0, 10, Fallback), + PhaseEvent("AccountSetup", T0.AddHours(3), 20, Fallback), + }; + + var outcome = await RunBuiltInAsync(rule, events); + var result = Assert.Single(outcome.Results); + Assert.Equal("ANALYZE-ESP-001", result.RuleId); + } + [Fact] public async Task ANALYZE_ESP_001_fires_on_the_same_span_when_line_anchored() { diff --git a/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs b/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs index 657b1a0f..5c7e515a 100644 --- a/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs +++ b/src/Backend/AutopilotMonitor.Functions/Services/RuleEngine.ConditionEvaluators.cs @@ -503,13 +503,21 @@ namespace AutopilotMonitor.Functions.Services phaseEnd = DateTime.UtcNow; // Phase is still active — the end carries no provenance } - // A duration is only as good as the weaker of its two endpoints: a reader-zone - // fallback timestamp can be hours off, which turned a 20-minute DeviceSetup into a - // 3 h "ESP Blocking App Timeout" (ANALYZE-ESP-001). - if (HasReaderZoneFallbackTimestamp(evt)) - return (false, UnmeasurableDurationEvidence("phase duration", "start", evt, evt)); - if (phaseEndEvent != null && HasReaderZoneFallbackTimestamp(phaseEndEvent)) - return (false, UnmeasurableDurationEvidence("phase duration", "end", evt, phaseEndEvent)); + // MIXED provenance is what breaks a duration: a reader-zone fallback timestamp can + // be hours off, and when the other endpoint is anchored (or is "now" for an open + // phase) the error lands in the span — a 20-minute DeviceSetup became a 3 h "ESP + // Blocking App Timeout" (ANALYZE-ESP-001, session a7140f98). Two fallback endpoints + // share the same writer-zone error and cancel it, so that pair stays measurable — + // otherwise the rule would go silent on every agent that has no era anchor, because + // the DeviceSetup line is written before the agent starts and is always backlog. + var startFallback = HasReaderZoneFallbackTimestamp(evt); + var endFallback = phaseEndEvent != null && HasReaderZoneFallbackTimestamp(phaseEndEvent); + if (startFallback != endFallback) + { + return (false, startFallback + ? UnmeasurableDurationEvidence("phase duration", "start", evt, evt) + : UnmeasurableDurationEvidence("phase duration", "end", evt, phaseEndEvent!)); + } var durationSeconds = (phaseEnd - evt.Timestamp).TotalSeconds; @@ -540,9 +548,12 @@ namespace AutopilotMonitor.Functions.Services // ===== Timestamp provenance of CMTrace-derived events ===== // IME-log-derived events (esp_phase_changed, app_install_*, …) carry data.sourceOffsetOrigin: - // "bias" | "calibrated" | "line-anchored" | "reader-zone-fallback". The last one means the - // agent could not determine the log writer's timezone and assumed its own, so the - // Timestamp may be off by whole hours. Agent-native events carry no tag and are trusted. + // "bias" | "calibrated" | "line-anchored" | "era-anchored" | "reader-zone-fallback". The + // last one means the agent could not determine the log writer's timezone and assumed its + // own, so the Timestamp may be off by whole hours — but by the SAME hours for every line + // of that writer era, so a span with two fallback endpoints is still measurable; only a + // span mixing a fallback endpoint with an anchored one (or with "now") is not. + // Agent-native events carry no tag and are trusted. /// Data key written by the agent's IME log adapter for CMTrace-derived events. internal const string SourceOffsetOriginField = "sourceOffsetOrigin"; @@ -554,7 +565,8 @@ namespace AutopilotMonitor.Functions.Services /// /// Non-match evidence for a duration whose ("start" | "end") - /// timestamp is a reader-zone fallback. is the event the evaluator + /// timestamp is a reader-zone fallback while the other endpoint is not (mixed provenance). + /// is the event the evaluator /// normally reports as its match (eventId/sequence), the endpoint /// event carrying the fallback tag. /// @@ -562,7 +574,7 @@ namespace AutopilotMonitor.Functions.Services string what, string endpoint, EnrollmentEvent anchor, EnrollmentEvent offender) => new() { - ["reason"] = $"{what} not measurable: {endpoint} timestamp derived from reader-zone fallback", + ["reason"] = $"{what} not measurable: {endpoint} timestamp derived from reader-zone fallback while the other endpoint is anchored (mixed provenance)", ["timestampProvenance"] = ReaderZoneFallbackOrigin, ["provenanceEndpoint"] = endpoint, ["provenanceEventId"] = offender.EventId ?? string.Empty, @@ -844,8 +856,9 @@ namespace AutopilotMonitor.Functions.Services .Where(e => completionEventTypes.Contains(e.EventType ?? string.Empty)) .ToList(); - // First pair skipped because one endpoint is a reader-zone fallback timestamp (see - // HasReaderZoneFallbackTimestamp). Other apps stay measurable; the skip only becomes + // First pair skipped because exactly one endpoint is a reader-zone fallback timestamp + // (mixed provenance — see the phase evaluator; two fallback endpoints cancel their + // shared error and stay measurable). Other apps stay measurable; the skip only becomes // the reported reason when nothing else matched. Dictionary? unmeasurable = null; @@ -867,14 +880,13 @@ namespace AutopilotMonitor.Functions.Services if (startEvent == null) continue; - if (HasReaderZoneFallbackTimestamp(startEvent)) + var startFallback = HasReaderZoneFallbackTimestamp(startEvent); + var endFallback = HasReaderZoneFallbackTimestamp(completionEvent); + if (startFallback != endFallback) { - unmeasurable ??= UnmeasurableDurationEvidence("app install duration", "start", completionEvent, startEvent); - continue; - } - if (HasReaderZoneFallbackTimestamp(completionEvent)) - { - unmeasurable ??= UnmeasurableDurationEvidence("app install duration", "end", completionEvent, completionEvent); + unmeasurable ??= startFallback + ? UnmeasurableDurationEvidence("app install duration", "start", completionEvent, startEvent) + : UnmeasurableDurationEvidence("app install duration", "end", completionEvent, completionEvent); continue; } diff --git a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts index 15450785..7b7d9091 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring-guide.ts @@ -163,15 +163,16 @@ export const RULE_AUTHORING_GUIDE = { 'Match a phase (eventType=esp_phase_changed, dataField=espPhase, operator=equals, ' + 'value=); the evidence carries durationSeconds. Combine with a confidenceFactor ' + '"phase_duration > N" for the actual duration check. The condition is false (reason ' + - '"not measurable", evidence timestampProvenance=reader-zone-fallback) when the phase start ' + - 'or the next phase event is an IME-log event whose sourceOffsetOrigin is reader-zone-fallback ' + - '— that timestamp can be hours off, so no duration is derived from it.', + '"not measurable", evidence timestampProvenance=reader-zone-fallback) when exactly one of the ' + + 'phase start and the next phase event carries sourceOffsetOrigin=reader-zone-fallback — that ' + + 'timestamp can be hours off, so a mixed span derives no duration; two fallback endpoints share ' + + 'the same error and stay measurable.', app_install_duration: 'Compare app install duration in seconds (operator gt/lt/gte/lte, value=seconds). ' + 'Attempt-scoped: pairs each completion with the LATEST app_install_started before it ' + '(sequence order), so an IME re-evaluation pass an hour earlier does not inflate the ' + - 'value — same semantics as the apps dashboard since 2026-08. A start/completion pair with a ' + - 'reader-zone-fallback sourceOffsetOrigin on either side is skipped as not measurable.', + 'value — same semantics as the apps dashboard since 2026-08. A start/completion pair with ' + + 'mixed provenance (reader-zone-fallback on exactly one side) is skipped as not measurable.', event_correlation: 'Join two event types over a shared field: eventType + correlateEventType + joinField, ' + 'optional timeWindowSeconds, optional eventAFilterField/-Operator/-Value to pre-filter the ' + diff --git a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts index bb324abf..34e43b5c 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/rule-authoring.generated.ts @@ -431,7 +431,7 @@ export const ANALYZE_RULE_SCHEMA: Record = { }, "source": { "type": "string", - "description": "Source of the signal. phase_duration and app_install_duration never derive a duration from an IME-log timestamp whose sourceOffsetOrigin is reader-zone-fallback (writer timezone unknown to the agent): such a condition evaluates false with evidence timestampProvenance=reader-zone-fallback.", + "description": "Source of the signal. phase_duration and app_install_duration never derive a duration from a span with mixed timestamp provenance (exactly one IME-log endpoint with sourceOffsetOrigin=reader-zone-fallback, i.e. the writer timezone was unknown to the agent for one endpoint only): such a condition evaluates false with evidence timestampProvenance=reader-zone-fallback. Two fallback endpoints share the same error and stay measurable.", "enum": [ "event_type", "event_data",