backend: duration evaluators refuse mixed timestamp provenance only

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 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-09-04 21:34:15 +02:00
parent f607e21c13
commit 34ec44e3d4
6 changed files with 95 additions and 31 deletions
+1 -1
View File
@@ -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": {
@@ -10,8 +10,9 @@ namespace AutopilotMonitor.Functions.Tests;
/// Timestamp provenance in the duration evaluators (phase_duration, app_install_duration).
/// IME-log-derived events carry <c>data.sourceOffsetOrigin</c>; <c>reader-zone-fallback</c>
/// 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).
/// </summary>
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<EnrollmentEvent>
{
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<EnrollmentEvent>
{
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<EnrollmentEvent>
{
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()
{
@@ -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.
/// <summary>Data key written by the agent's IME log adapter for CMTrace-derived events.</summary>
internal const string SourceOffsetOriginField = "sourceOffsetOrigin";
@@ -554,7 +565,8 @@ namespace AutopilotMonitor.Functions.Services
/// <summary>
/// Non-match evidence for a duration whose <paramref name="endpoint"/> ("start" | "end")
/// timestamp is a reader-zone fallback. <paramref name="anchor"/> is the event the evaluator
/// timestamp is a reader-zone fallback while the other endpoint is not (mixed provenance).
/// <paramref name="anchor"/> is the event the evaluator
/// normally reports as its match (eventId/sequence), <paramref name="offender"/> the endpoint
/// event carrying the fallback tag.
/// </summary>
@@ -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<string, object>? 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;
}
@@ -163,15 +163,16 @@ export const RULE_AUTHORING_GUIDE = {
'Match a phase (eventType=esp_phase_changed, dataField=espPhase, operator=equals, ' +
'value=<phase>); 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 ' +
@@ -431,7 +431,7 @@ export const ANALYZE_RULE_SCHEMA: Record<string, unknown> = {
},
"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",