mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 21:19:38 +00:00
Compare commits
5 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 990641b19e | |||
| 3ca2f3b499 | |||
| b9fa760404 | |||
| ab61839685 | |||
| 34fd40c3ad |
+1
-1
Submodule .claude/commands updated: 3f98090747...2866e07882
@@ -86,10 +86,33 @@ with the process zone).
|
||||
* Mixed pairs remain possible across a restart (start resolved from backlog fallback,
|
||||
completion line-anchored) and are recognizable via provenance.
|
||||
|
||||
# Backend regression tripwire
|
||||
|
||||
The backend watches for the failure mode this design eliminates. On every terminal ingest
|
||||
batch, the counter reconcile's existing event-partition scan additionally collects
|
||||
`Δ = ReceivedAt − OccurredUtc` per event, split by `Source == "ImeLogTracker"` versus the
|
||||
rest (`CmTraceSkewTripwire`, hooked in `EventIngestProcessor`). If
|
||||
`median(Δ_IME) − median(Δ_other)` is a clean 15-minute multiple (residual < 2 min — the
|
||||
same constants as the anchoring grid guard above) with ≥ 20 samples over ≥ 3 distinct
|
||||
upload batches per side, a `CmTraceTimeSkewRegression` ops event fires (category Agent,
|
||||
warning), carrying all numbers plus the session's `sourceOffsetOrigin` histogram.
|
||||
Bias-dominated sessions are suppressed (writer-declared offsets cannot be an anchoring
|
||||
regression); `measuredWriterOffsetMinutes` is never consulted (sticky after era
|
||||
flip-backs). Kill switch: app setting `CmTraceSkewTripwireDisabled`. Goal state: the event
|
||||
never fires — any hit is an anchoring case the per-line design misses, or a detector bug.
|
||||
|
||||
Device-clock problems (the customer-actionable cousin) are covered separately by the
|
||||
`clock_skew` analyze condition behind `ANALYZE-DEV-008`, which excludes IME-derived events
|
||||
precisely so an anchoring regression can never surface as a customer finding.
|
||||
|
||||
# Citations
|
||||
|
||||
* `CmTraceOffsetCalibrator.TryMeasureOffset` — the pure grid measurement, shared by
|
||||
anchoring and the observational per-file path.
|
||||
* `CmTraceSkewTripwire` + `CmTraceSkewTripwireTests` — the backend tripwire above.
|
||||
* `RuleEngine.ConditionEvaluators.EvaluateClockSkewCondition` + `RuleEngineClockSkewTests`
|
||||
— the customer-facing device-clock metrics (batch-median frames, spool-spread filter,
|
||||
plateau step detection, end-state persistence).
|
||||
* `ImeLogTracker.LogProcessing.cs` `ResolveEntryUtc` — the resolution order above.
|
||||
* `ImeLogTrackerLineAnchoringTests` — resolves-to-T across writer beliefs, interleaved
|
||||
eras in one chunk, freshness boundaries (first sight, empty first sight, poll gap,
|
||||
|
||||
@@ -0,0 +1,84 @@
|
||||
---
|
||||
type: concept
|
||||
title: Send-Time Frame Separation (X-Send-Time-Utc)
|
||||
description: One device-clock send timestamp per upload batch splits ReceivedAt − OccurredUtc into pure spool delay and pure device-vs-server clock offset — turning clock diagnostics from median statistics into direct per-request measurement.
|
||||
resource: src/Backend/AutopilotMonitor.Functions/Functions/Ingest/IngestTelemetryFunction.cs
|
||||
tags: [backend, agent, ingest, timestamps, clock-skew, telemetry, provenance]
|
||||
timestamp: 2026-08-21
|
||||
---
|
||||
|
||||
# Problem
|
||||
|
||||
Events carry two time anchors: `OccurredUtc` (device clock at emission) and `ReceivedAt`
|
||||
(server clock at ingest). Their difference conflates two physically distinct phenomena:
|
||||
|
||||
* **Spool delay** — the event waited offline or in retry backoff before upload. Expected,
|
||||
harmless, minutes to hours.
|
||||
* **Device-vs-server clock offset** — the actual diagnostic signal.
|
||||
|
||||
A uniform spool backlog (events emitted close together, uploaded after an outage) is
|
||||
indistinguishable from a clock offset in that delta; a draining backlog fakes a clock jump
|
||||
ramp. Every consumer had to filter this statistically (spread caps, plateau guards,
|
||||
persistence tests) — and the first field clock-jump measurement failed exactly on this
|
||||
ambiguity.
|
||||
|
||||
# Schema
|
||||
|
||||
The agent stamps one header per upload attempt (`BackendTelemetryUploader`):
|
||||
|
||||
```
|
||||
X-Send-Time-Utc: <DateTime.UtcNow, ISO-8601 round-trip>
|
||||
```
|
||||
|
||||
Per **attempt**, not per batch content: a retry after backoff is a new send moment. The
|
||||
ingest function parses it (`ParseSendTimeHeader`: round-trip parse, UTC-normalized, values
|
||||
before year 2000 rejected as garbage — deliberately **no upper clamp**, a future-dated
|
||||
send time IS the clock-error measurement), and `StampServerFields` writes it as `SentAt`
|
||||
onto every event of the request — server-stamped, request-level, never trusted per-event
|
||||
from the wire. Stored as the nullable `SentAt` column on Events (absent for pre-header
|
||||
agents), mapped back everywhere events are read, exposed as `sentAt` in the `fields=`
|
||||
projection and verbatim on the raw endpoints.
|
||||
|
||||
The separation is then exact:
|
||||
|
||||
```
|
||||
SentAt − OccurredUtc = pure spool delay (both device frame; offset cancels)
|
||||
ReceivedAt − SentAt = network latency + clock offset (the only frame crossing)
|
||||
```
|
||||
|
||||
Network latency is seconds; anything beyond is device clock error, per request, no
|
||||
statistics required.
|
||||
|
||||
# Consumers
|
||||
|
||||
* **`clock_skew` analyze condition** (ANALYZE-DEV-008): batches whose events carry
|
||||
`SentAt` measure the batch offset directly as `SentAt − ReceivedAt` — spool-immune by
|
||||
construction, so the spread cap and the IME/clamped exclusions are unnecessary there
|
||||
(no event timestamps are read at all; IME-only sessions become measurable). Batches
|
||||
without `SentAt` keep the legacy per-event median + spread-cap path. Downstream logic
|
||||
(stability check, plateau step detection, end-state persistence) is shared; evidence
|
||||
carries `sentAtBatchCount`.
|
||||
* **`CmTraceSkewTripwire` deliberately unchanged**: `median(Δ_IME) − median(Δ_other)`
|
||||
cancels the device clock offset as common mode — send time adds nothing to that
|
||||
differential measurement.
|
||||
|
||||
# Constraints
|
||||
|
||||
* `SentAt` comes from the same device wall clock as the event timestamps — a clock jump
|
||||
between emission and send lands in the spool-delay term. That is the intended place for
|
||||
it to become visible, not a defect.
|
||||
* Signals and DecisionTransitions do not carry `SentAt` (no consumer); the header is
|
||||
request-level, so extending them later is a storage-only change.
|
||||
* Fleet coverage grows with agent rollout; all analyses must treat `SentAt == null`
|
||||
(legacy rows, old agents) as "legacy path", never as zero.
|
||||
|
||||
# Citations
|
||||
|
||||
* `BackendTelemetryUploader.UploadBatchAsync` — header stamping per attempt.
|
||||
* `IngestTelemetryFunction.ParseSendTimeHeader` + `IngestTelemetryFunctionTests` — parse
|
||||
contract incl. the no-upper-clamp decision.
|
||||
* `EventIngestProcessor.StampServerFields` + `IngestCriticalPathTests` — server-side
|
||||
stamping, forged per-event values overridden.
|
||||
* `RuleEngine.ConditionEvaluators.EvaluateClockSkewCondition` + `RuleEngineClockSkewTests`
|
||||
— the two measurement paths (the backlog-alias test pair pins why SentAt exists).
|
||||
* `tasks/todo.md` P14 (2026-08-21) — decision trail incl. why the tripwire stays as is.
|
||||
@@ -42,6 +42,7 @@ https://docs.autopilotmonitor.com (separate repository).
|
||||
# Backend
|
||||
|
||||
* [Business Timestamps](backend/business-timestamps.md) - Why the Azure Tables system Timestamp is never authoritative (migrations reset it), and the OccurredUtc + RowKey-decode compensation for AuditLogs/OpsEvents/Events after the 2026-07-18 migration.
|
||||
* [Send-Time Frame Separation](backend/send-time-frame-separation.md) - One device-clock send timestamp per upload batch (X-Send-Time-Utc → SentAt on Events) splits ReceivedAt − OccurredUtc into pure spool delay and pure device-vs-server clock offset; the clock_skew condition measures SentAt batches directly (spool-immune), the CMTrace tripwire deliberately stays on its differential math.
|
||||
* [OOBE Bootstrap go-Code Flow](backend/oobe-bootstrap-go-flow.md) - The bootstrap short-code lifecycle (portal-created session → `irm go.autopilotmonitor.com/CODE | iex` at Shift+F10 → GetBootstrapScriptFunction), the always-HTTP-200 text/plain contract, the two-line injection defense (GUID/URL/expiry validator + single-quoted PS literals, golden-pinned against the legacy TS template), and the per-IP rate-limit story behind Front Door.
|
||||
* [Device Journeys & First-Time-Right](backend/device-journeys.md) - How a device's terminal enrollment attempts are grouped into journeys (trim+casefold device key with junk-serial exclusion, first-success end, 30-day gap, WhiteGlove = one attempt), the DeviceHistories chain with its tombstone-driven deleted-session pruning, the additive daily FTR aggregates, and the banner/fleet/MCP surfaces.
|
||||
* [Enrollment Time Attribution](backend/time-attribution.md) - How a terminal session's authoritative wall clock (DurationSeconds, WhiteGlove pause excluded) is partitioned into named segments with an explicit unattributed remainder, ESP-blocking apps as positive evidence with "up to" what-if bounds, reboot spans from event gaps, and the breakdown/aggregate tables the sweep maintains.
|
||||
|
||||
@@ -1,7 +1,13 @@
|
||||
# Log
|
||||
|
||||
## 2026-08-21
|
||||
|
||||
* **New**: `backend/send-time-frame-separation.md` — P14: the agent stamps one device-clock send timestamp per upload attempt (`X-Send-Time-Utc`), the ingest function server-stamps it as `SentAt` on every event of the request. `SentAt − OccurredUtc` is pure spool delay, `ReceivedAt − SentAt` is network + device-vs-server clock offset — the two were indistinguishable before and had to be separated statistically. The `clock_skew` condition measures SentAt-carrying batches directly (spool-immune, no spread cap, IME-only sessions become measurable; evidence carries `sentAtBatchCount`), legacy batches keep the median path; the CMTrace tripwire deliberately stays on its differential math (common-mode clock offset cancels there).
|
||||
|
||||
## 2026-08-20
|
||||
|
||||
* **Update**: `agent/cmtrace-time-resolution.md` — new "Backend regression tripwire" section: the P6 split. Operator side: `CmTraceSkewTripwire` piggybacks on the terminal counter reconcile's partition scan (`Δ = ReceivedAt − OccurredUtc` per source, 15-min grid + 2-min residual, ≥20 samples / ≥3 distinct batches per side, bias-dominated sessions suppressed, `measuredWriterOffsetMinutes` never consulted) and emits the `CmTraceTimeSkewRegression` ops event — goal state: never fires; kill switch `CmTraceSkewTripwireDisabled`. Customer side: new `clock_skew` analyze condition source (`skewMetric: clock_jump | sustained_offset`, threshold in seconds, batch-median frames with spool-spread filter, plateau step detection, end-state persistence, IME-derived events excluded) behind the new built-in `ANALYZE-DEV-008` (300 s = the Kerberos/Entra 5-minute skew boundary) — the during-enrollment complement of ANALYZE-DEV-007's one-shot NTP check. P5 (agent-side observability event) is subsumed by the tripwire.
|
||||
|
||||
* **New**: `agent/cmtrace-time-resolution.md` — the era-aware answer to the CMTrace timezone skew: a bias-less line read in a provably fresh pass anchors its own UTC offset against the agent clock (15-minute grid, 2-minute residual), so interleaved writer eras in one file resolve line by line; everything not provably fresh keeps the uniform reader-zone fallback and says so via `sourceOffsetOrigin`. Freshness is a per-file `LastCheckedUtc` stamped on every poll look (empty first sights included) with a 30-second window, never restored across restarts. Replaces the reverted per-file offset application (04b1a7c6); the per-file measurement stays observational, now with the anchor timestamp logged as a tripwire for the still-unexplained e9753578 label/anchor crossing.
|
||||
|
||||
* **Update**: `agent/post-reboot-completion-recovery.md` — retitled to "ESP Completion Starvation — the sits-d Cloud-PC complex" and reframed on the evidence: the reboot was a red herring. The five stuck Cloud PCs carried `SkipUserStatusPage=True` (read 10+ times across three agent processes, `True` every time) and Windows honoured it — no user ESP page, hence no Shell-Core 62407 and no AccountSetup provisioning registry, verified over a six-hour uninterrupted post-reboot run with the watcher armed. Arm B of `ShouldTransitionToAwaitingHello` was open from the bootstrap onward, but every evaluation site hangs off a signal a skip-user flow cannot produce, and the `AdvisoryCompletion` backstop arms exclusively from an `EspExiting` signal — an open gate nobody knocks on. Fix: `HandleImeUserSessionCompletedV1` accepts the observed skip in place of the final-exit evidence (`skipUserExitEquivalent`; anchor + genuine IME completion + real-user desktop stay mandatory, WDP excluded). The knock deliberately lives on the IME edge, not desktop arrival — ordering-robust against Fix 10's AccountSetup bounce-back and semantically "user-phase work finished" rather than mid-install. `ClassicSkipUserEspUserSessionCompletionTests` replays the real 8110e262 ordering end to end. Docs and comments no longer claim an ESP-exit recovery that does not exist (stray duplicate summary in `ShellCoreTracker`, `ImeLogHost` restore-callback comment); the residual `SkipUser=false` exit-in-downtime gap is named honestly and surfaced by `ANALYZE-ESP-005` via `session_stalled` instead of being patched with an unorderable replay.
|
||||
|
||||
@@ -0,0 +1,69 @@
|
||||
{
|
||||
"$schema": "../schema/analyze-rule.schema.json",
|
||||
"ruleId": "ANALYZE-DEV-008",
|
||||
"title": "Device Clock Wrong During Enrollment — Jump or Sustained Offset",
|
||||
"description": "The device's clock changed by five or more minutes mid-session (clock jump) or ran five or more minutes off server time for the whole session (sustained offset), measured against the server receive frame of every uploaded event. Complements ANALYZE-DEV-007, which is a one-shot NTP check at agent startup and misses devices where NTP was unreachable or the clock changed later. IME-log-derived events are excluded from the measurement.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"author": "Autopilot Monitor",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
"whiteglove_sealed"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 60,
|
||||
"confidenceThreshold": 50,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "clock_jump",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "clock_jump",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
},
|
||||
{
|
||||
"signal": "sustained_offset",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "sustained_offset",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"confidenceFactors": [],
|
||||
"explanation": "This device's {{skewSummary}} (five-minute threshold). A clock that is off by five or more minutes breaks time-sensitive enrollment mechanisms: Kerberos tolerates at most 5 minutes of skew (Hybrid Join), Entra ID token validation allows about 5 minutes on token lifetimes, and freshly issued SCEP/PKCS certificates can be rejected as \"not yet valid\" when the clock is more than ~10 minutes behind the CA.\n\nUnlike ANALYZE-DEV-007 (a one-shot NTP comparison at agent startup), this finding is measured across the whole session against the server's receive time — it also catches devices where the NTP check could not run (UDP 123 blocked) or where the clock changed after startup (time sync correcting a wrong RTC, Windows auto-timezone, manual change).",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Fix the device clock and time source",
|
||||
"steps": [
|
||||
"Check the BIOS/RTC clock and the CMOS battery if the wrong time recurs on the same hardware.",
|
||||
"At OOBE, run 'w32tm /resync /force' (Shift+F10 command prompt) to sync with time.windows.com.",
|
||||
"Ensure UDP port 123 to time.windows.com is open in the deployment network.",
|
||||
"Review 'Set time automatically' and 'Set time zone automatically' behavior on the deployment image — automatic timezone changes mid-enrollment show up as clock jumps."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot known issues — device provisioning can fail (clock skew)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/known-issues"
|
||||
},
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot requirements — Networking (NTP)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/requirements?tabs=networking"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"clock-skew",
|
||||
"clock-jump",
|
||||
"time-sync",
|
||||
"kerberos",
|
||||
"certificates",
|
||||
"known-issue"
|
||||
]
|
||||
}
|
||||
+68
@@ -1516,6 +1516,74 @@
|
||||
"known-issue"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-DEV-008",
|
||||
"title": "Device Clock Wrong During Enrollment — Jump or Sustained Offset",
|
||||
"description": "The device's clock changed by five or more minutes mid-session (clock jump) or ran five or more minutes off server time for the whole session (sustained offset), measured against the server receive frame of every uploaded event. Complements ANALYZE-DEV-007, which is a one-shot NTP check at agent startup and misses devices where NTP was unreachable or the clock changed later. IME-log-derived events are excluded from the measurement.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"author": "Autopilot Monitor",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
"whiteglove_sealed"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 60,
|
||||
"confidenceThreshold": 50,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "clock_jump",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "clock_jump",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
},
|
||||
{
|
||||
"signal": "sustained_offset",
|
||||
"source": "clock_skew",
|
||||
"skewMetric": "sustained_offset",
|
||||
"operator": "gte",
|
||||
"value": "300",
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"confidenceFactors": [],
|
||||
"explanation": "This device's {{skewSummary}} (five-minute threshold). A clock that is off by five or more minutes breaks time-sensitive enrollment mechanisms: Kerberos tolerates at most 5 minutes of skew (Hybrid Join), Entra ID token validation allows about 5 minutes on token lifetimes, and freshly issued SCEP/PKCS certificates can be rejected as \"not yet valid\" when the clock is more than ~10 minutes behind the CA.\n\nUnlike ANALYZE-DEV-007 (a one-shot NTP comparison at agent startup), this finding is measured across the whole session against the server's receive time — it also catches devices where the NTP check could not run (UDP 123 blocked) or where the clock changed after startup (time sync correcting a wrong RTC, Windows auto-timezone, manual change).",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Fix the device clock and time source",
|
||||
"steps": [
|
||||
"Check the BIOS/RTC clock and the CMOS battery if the wrong time recurs on the same hardware.",
|
||||
"At OOBE, run 'w32tm /resync /force' (Shift+F10 command prompt) to sync with time.windows.com.",
|
||||
"Ensure UDP port 123 to time.windows.com is open in the deployment network.",
|
||||
"Review 'Set time automatically' and 'Set time zone automatically' behavior on the deployment image — automatic timezone changes mid-enrollment show up as clock jumps."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot known issues — device provisioning can fail (clock skew)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/known-issues"
|
||||
},
|
||||
{
|
||||
"title": "Microsoft Learn: Windows Autopilot requirements — Networking (NTP)",
|
||||
"url": "https://learn.microsoft.com/en-us/autopilot/requirements?tabs=networking"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"clock-skew",
|
||||
"clock-jump",
|
||||
"time-sync",
|
||||
"kerberos",
|
||||
"certificates",
|
||||
"known-issue"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-ENRL-001",
|
||||
"title": "Enrollment Failed",
|
||||
|
||||
@@ -169,7 +169,12 @@
|
||||
"source": {
|
||||
"type": "string",
|
||||
"description": "Source of the signal.",
|
||||
"enum": ["event_type", "event_data", "event_data_array", "phase_duration", "event_count", "app_install_duration", "event_correlation"]
|
||||
"enum": ["event_type", "event_data", "event_data_array", "phase_duration", "event_count", "app_install_duration", "event_correlation", "clock_skew"]
|
||||
},
|
||||
"skewMetric": {
|
||||
"type": "string",
|
||||
"description": "For clock_skew only: which device-clock metric to evaluate. clock_jump = persistent step in the device's clock frame mid-session; sustained_offset = whole session ran on a clock off by at least the threshold. value is the threshold in seconds; operator is limited to gt/gte on the magnitude. IME-log-derived events are excluded from the measurement.",
|
||||
"enum": ["clock_jump", "sustained_offset"]
|
||||
},
|
||||
"eventType": {
|
||||
"type": "string",
|
||||
|
||||
+25
@@ -107,6 +107,31 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
Assert.False(req.Headers.ContainsKey("X-Bootstrap-Token"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task UploadBatchAsync_stamps_send_time_header_per_attempt()
|
||||
{
|
||||
// P14: X-Send-Time-Utc carries the device clock at the SEND moment, round-trip
|
||||
// ISO-8601, one value per request. A retry is a new send moment — the header is
|
||||
// stamped inside UploadBatchAsync, so each attempt gets a fresh value.
|
||||
using var rig = new Rig();
|
||||
rig.Handler.QueueStatus(HttpStatusCode.ServiceUnavailable);
|
||||
rig.Handler.QueueStatus(HttpStatusCode.OK);
|
||||
|
||||
var before = DateTime.UtcNow;
|
||||
await rig.Sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
|
||||
await rig.Sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
|
||||
var after = DateTime.UtcNow;
|
||||
|
||||
Assert.Equal(2, rig.Handler.Captured.Count);
|
||||
foreach (var req in rig.Handler.Captured)
|
||||
{
|
||||
Assert.True(req.TryGetHeader("X-Send-Time-Utc", out var raw));
|
||||
var parsed = DateTime.Parse(raw, null, System.Globalization.DateTimeStyles.RoundtripKind);
|
||||
Assert.Equal(DateTimeKind.Utc, parsed.Kind);
|
||||
Assert.InRange(parsed, before.AddSeconds(-1), after.AddSeconds(1));
|
||||
}
|
||||
}
|
||||
|
||||
// ============================================================ Compression (bandwidth)
|
||||
|
||||
[Fact]
|
||||
|
||||
+34
-2
@@ -222,7 +222,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// growing pass, during which lines fall back to the reader zone and are
|
||||
// flagged as such.
|
||||
if (hadPreviousObservation && calibrationAnchor != null)
|
||||
CalibrateFrom(_currentSourceFileName, calibrationAnchor);
|
||||
CalibrateFrom(_currentSourceFileName, Path.GetFileName(filePath), calibrationAnchor);
|
||||
}
|
||||
}
|
||||
catch (FileNotFoundException) { }
|
||||
@@ -701,18 +701,50 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
return CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp);
|
||||
}
|
||||
|
||||
// Field-forensics (tripwire, 2026-08-20): sessions e9753578 and 067797d8 both logged a
|
||||
// measurement whose LABEL and ANCHOR could not have come from the same file iteration —
|
||||
// 067797d8's anchor value (19:51:26.948) does not even exist in ANY log file on the
|
||||
// device, and IntuneManagementExtension.log never produced its expected first
|
||||
// measurement at all. Mechanism unexplained; resolution is immune (per-line anchoring),
|
||||
// but the observational layer must convict the culprit on the next occurrence. Hence:
|
||||
// the stream's file name travels alongside the label (a mismatch is THE smoking gun),
|
||||
// and the first rejected anchor per file becomes visible instead of silent.
|
||||
private readonly HashSet<string> _calibrationRejectLogged = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// Feed the pass's newest bias-less line to the calibrator and report a measured offset
|
||||
/// that disagrees with this process's own zone — that disagreement is precisely the
|
||||
/// condition that used to corrupt every IME-derived timestamp silently.
|
||||
/// </summary>
|
||||
private void CalibrateFrom(string sourceFileName, CmTraceLogEntry anchor)
|
||||
/// <param name="sourceFileName">The calibration key (<c>_currentSourceFileName</c>).</param>
|
||||
/// <param name="streamFileName">The file the enclosing iteration actually read. Must equal
|
||||
/// <paramref name="sourceFileName"/> — logged loudly when it does not (see tripwire note).</param>
|
||||
private void CalibrateFrom(string sourceFileName, string streamFileName, CmTraceLogEntry anchor)
|
||||
{
|
||||
if (!string.Equals(sourceFileName, streamFileName, StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
_logger?.Warning(
|
||||
$"ImeLogTracker: CALIBRATION LABEL MISMATCH — key='{sourceFileName}' but the iteration read '{streamFileName}' " +
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}). Skipping this anchor; see tripwire note.");
|
||||
return;
|
||||
}
|
||||
|
||||
TimeSpan previous;
|
||||
var hadOffset = OffsetCalibrator.TryGetOffset(sourceFileName, out previous);
|
||||
|
||||
if (!OffsetCalibrator.TryCalibrate(sourceFileName, anchor.LocalTimestamp, UtcNowProvider()))
|
||||
{
|
||||
// Once per file: why a file that visibly grows never produces a measurement.
|
||||
// 067797d8 ran 24 s of growing IME.log passes with no measurement at all — this
|
||||
// silence is exactly what made the phenomenon undiagnosable from the log.
|
||||
if (_calibrationRejectLogged.Add(sourceFileName))
|
||||
{
|
||||
_logger?.Debug(
|
||||
$"ImeLogTracker: {sourceFileName} anchor rejected by calibrator " +
|
||||
$"(anchor local={anchor.LocalTimestamp:yyyy-MM-ddTHH:mm:ss.fffffff}, now={UtcNowProvider():HH:mm:ss.fff}Z) — first rejection for this file, further ones stay silent.");
|
||||
}
|
||||
return;
|
||||
}
|
||||
|
||||
TimeSpan measured;
|
||||
if (!OffsetCalibrator.TryGetOffset(sourceFileName, out measured)) return;
|
||||
|
||||
+6
@@ -119,6 +119,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Transport.Telemetry
|
||||
AddSecurityHeaders(request);
|
||||
request.Headers.Add("X-Correlation-ID", correlationId);
|
||||
|
||||
// P14: device-clock send time, one value per request. Lets the backend separate
|
||||
// spool delay (SentAt − OccurredUtc, both device frame) from device-vs-server
|
||||
// clock offset (ReceivedAt − SentAt) — indistinguishable without this header.
|
||||
// Stamped per attempt on purpose: a retry after backoff is a NEW send moment.
|
||||
request.Headers.Add("X-Send-Time-Utc", DateTime.UtcNow.ToString("O"));
|
||||
|
||||
HttpResponseMessage response;
|
||||
try
|
||||
{
|
||||
|
||||
@@ -0,0 +1,152 @@
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// Pins the CMTrace time-skew regression tripwire (CmTraceSkewTripwire.Evaluate): fires only
|
||||
/// when the IME-vs-other median delta divergence sits on the 15-minute offset grid (residual
|
||||
/// < 2 min) AND both sides have enough samples over enough distinct upload batches. The
|
||||
/// tripwire's goal state is to never fire, so the must-stay-silent directions are the primary
|
||||
/// cases: off-grid replays, sub-grid divergence, thin samples, batch-composition artifacts,
|
||||
/// and common-mode spool latency must all pass without a hit.
|
||||
/// </summary>
|
||||
public class CmTraceSkewTripwireTests
|
||||
{
|
||||
/// <summary>Scan with the given per-side medians, comfortably above all sample/batch minimums.</summary>
|
||||
private static SessionSkewScan MakeScan(
|
||||
double imeDeltaMinutes, double otherDeltaMinutes,
|
||||
int imeSamples = 30, int otherSamples = 30,
|
||||
int imeBatches = 5, int otherBatches = 5)
|
||||
{
|
||||
var scan = new SessionSkewScan
|
||||
{
|
||||
ImeDistinctBatchCount = imeBatches,
|
||||
OtherDistinctBatchCount = otherBatches,
|
||||
};
|
||||
for (int i = 0; i < imeSamples; i++)
|
||||
scan.ImeDeltaMinutes.Add(imeDeltaMinutes);
|
||||
for (int i = 0; i < otherSamples; i++)
|
||||
scan.OtherDeltaMinutes.Add(otherDeltaMinutes);
|
||||
return scan;
|
||||
}
|
||||
|
||||
// ── Must fire ──────────────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void Fires_OnLargeNegativeGridDivergence()
|
||||
{
|
||||
// −540 min = the field-measured E.-Australia-style skew (−9 h), exactly 36 grid steps.
|
||||
// Both sides share 1.2 min upload latency — it cancels in the difference.
|
||||
var result = CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: -538.8, otherDeltaMinutes: 1.2));
|
||||
|
||||
Assert.NotNull(result);
|
||||
Assert.Equal(-36, result!.GridSteps);
|
||||
Assert.Equal(-540.0, result.DiffMinutes, 3);
|
||||
Assert.True(result.ResidualMinutes < CmTraceSkewTripwire.ResidualToleranceMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Fires_OnSingleGridStepWithBoundaryResidual()
|
||||
{
|
||||
// +15 min divergence with residual 1.9 — just inside the 2-min tolerance.
|
||||
var result = CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 16.9, otherDeltaMinutes: 0.0));
|
||||
|
||||
Assert.NotNull(result);
|
||||
Assert.Equal(1, result!.GridSteps);
|
||||
Assert.Equal(1.9, result.ResidualMinutes, 3);
|
||||
}
|
||||
|
||||
// ── Must stay silent ───────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenResidualOffGrid()
|
||||
{
|
||||
// 17.5 min divergence: nearest grid step is 15, residual 2.5 ≥ tolerance — the replay
|
||||
// signature (old log lines re-read late land anywhere, not on the zone grid).
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 17.5, otherDeltaMinutes: 0.0)));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenDivergenceBelowOneGridStep()
|
||||
{
|
||||
// 9 min rounds to 1 step but with residual 6 — and 7 min rounds to 0 steps. Both silent.
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 9.0, otherDeltaMinutes: 0.0)));
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 7.0, otherDeltaMinutes: 0.0)));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenImeSampleCountBelowMinimum()
|
||||
{
|
||||
var scan = MakeScan(imeDeltaMinutes: -540.0, otherDeltaMinutes: 0.0,
|
||||
imeSamples: CmTraceSkewTripwire.MinSamplesPerSide - 1);
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(scan));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_WhenDistinctBatchesBelowMinimum()
|
||||
{
|
||||
// A perfect grid divergence backed by only 2 upload batches on one side is a
|
||||
// batch-composition artifact (ReceivedAt is stamped per batch, not per event).
|
||||
var scan = MakeScan(imeDeltaMinutes: -540.0, otherDeltaMinutes: 0.0,
|
||||
otherBatches: CmTraceSkewTripwire.MinDistinctBatchesPerSide - 1);
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(scan));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_OnCommonModeSpoolLatency()
|
||||
{
|
||||
// Offline spool: BOTH sides uploaded 45 min late. The difference of medians is ~0 —
|
||||
// shared latency must cancel, never read as skew.
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(MakeScan(imeDeltaMinutes: 45.3, otherDeltaMinutes: 45.1)));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Silent_OnNullOrEmptyScan()
|
||||
{
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(null));
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(new SessionSkewScan()));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void MedianIsRobustAgainstMinorityOutliers()
|
||||
{
|
||||
// A handful of replayed old lines (huge off-grid deltas) inside an otherwise healthy
|
||||
// IME stream must not drag the median onto the grid.
|
||||
var scan = MakeScan(imeDeltaMinutes: 0.5, otherDeltaMinutes: 0.4);
|
||||
scan.ImeDeltaMinutes.Add(-1327.0);
|
||||
scan.ImeDeltaMinutes.Add(-738.0);
|
||||
Assert.Null(CmTraceSkewTripwire.Evaluate(scan));
|
||||
}
|
||||
|
||||
// ── Bias suppression predicate ─────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void BiasDominated_WhenBiasIsHalfOrMore()
|
||||
{
|
||||
Assert.True(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>
|
||||
{
|
||||
["bias"] = 50,
|
||||
["line-anchored"] = 50,
|
||||
}));
|
||||
Assert.True(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>
|
||||
{
|
||||
["Bias"] = 3, // case-insensitive
|
||||
}));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void NotBiasDominated_WhenAnchoredMajorityOrNoData()
|
||||
{
|
||||
Assert.False(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>
|
||||
{
|
||||
["bias"] = 10,
|
||||
["line-anchored"] = 80,
|
||||
["reader-zone-fallback"] = 11,
|
||||
}));
|
||||
// Empty/missing histogram fails open toward reporting — a storage error must not
|
||||
// silently swallow a genuine regression hit.
|
||||
Assert.False(CmTraceSkewTripwire.IsBiasDominated(new Dictionary<string, int>()));
|
||||
Assert.False(CmTraceSkewTripwire.IsBiasDominated(null));
|
||||
}
|
||||
}
|
||||
@@ -33,6 +33,31 @@ public class IngestCriticalPathTests
|
||||
Assert.All(events, evt => Assert.Equal(receivedAt, evt.ReceivedAt));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void StampServerFields_SetsSentAtOnAllEvents_AndOverridesAgentValues()
|
||||
{
|
||||
// P14: SentAt is request-level and server-stamped — a per-event value coming off the
|
||||
// wire (agent bug, forged payload) must never survive.
|
||||
var sentAt = DateTime.UtcNow.AddSeconds(-4);
|
||||
var events = MakeEvents(3);
|
||||
events[1].SentAt = DateTime.UtcNow.AddYears(1);
|
||||
|
||||
EventIngestProcessor.StampServerFields(events, ValidTenantId, ValidSessionId, DateTime.UtcNow, sentAt);
|
||||
|
||||
Assert.All(events, evt => Assert.Equal(sentAt, evt.SentAt));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void StampServerFields_WithoutSendTimeHeader_LeavesSentAtNull()
|
||||
{
|
||||
var events = MakeEvents(2);
|
||||
events[0].SentAt = DateTime.UtcNow; // forged per-event value must be cleared, not kept
|
||||
|
||||
EventIngestProcessor.StampServerFields(events, ValidTenantId, ValidSessionId, DateTime.UtcNow);
|
||||
|
||||
Assert.All(events, evt => Assert.Null(evt.SentAt));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void StampServerFields_SetsTenantIdOnAllEvents()
|
||||
{
|
||||
|
||||
@@ -43,6 +43,45 @@ public class IngestTelemetryFunctionTests
|
||||
Assert.Equal(string.Empty, session);
|
||||
}
|
||||
|
||||
// ============================================================ X-Send-Time-Utc parsing (P14)
|
||||
|
||||
[Fact]
|
||||
public void ParseSendTimeHeader_RoundTripUtc_ParsesToUtc()
|
||||
{
|
||||
var parsed = IngestTelemetryFunction.ParseSendTimeHeader("2026-08-21T10:15:30.1234567Z");
|
||||
|
||||
Assert.Equal(new DateTime(2026, 8, 21, 10, 15, 30, DateTimeKind.Utc).AddTicks(1234567), parsed);
|
||||
Assert.Equal(DateTimeKind.Utc, parsed!.Value.Kind);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ParseSendTimeHeader_OffsetValue_NormalizedToUtc()
|
||||
{
|
||||
var parsed = IngestTelemetryFunction.ParseSendTimeHeader("2026-08-21T12:15:30+02:00");
|
||||
|
||||
Assert.Equal(new DateTime(2026, 8, 21, 10, 15, 30, DateTimeKind.Utc), parsed);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ParseSendTimeHeader_FutureDatedValue_KeptVerbatim()
|
||||
{
|
||||
// A future send time IS the device-clock-error measurement — no upper clamp.
|
||||
var parsed = IngestTelemetryFunction.ParseSendTimeHeader("2027-01-01T00:00:00Z");
|
||||
|
||||
Assert.Equal(new DateTime(2027, 1, 1, 0, 0, 0, DateTimeKind.Utc), parsed);
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(null)]
|
||||
[InlineData("")]
|
||||
[InlineData(" ")]
|
||||
[InlineData("not-a-date")]
|
||||
[InlineData("1999-12-31T23:59:59Z")] // pre-2000 can only be garbage (Table Storage floor guard)
|
||||
public void ParseSendTimeHeader_AbsentOrGarbage_ReturnsNull(string? headerValue)
|
||||
{
|
||||
Assert.Null(IngestTelemetryFunction.ParseSendTimeHeader(headerValue));
|
||||
}
|
||||
|
||||
// ============================================================ Payload size-cap guard
|
||||
|
||||
[Fact]
|
||||
|
||||
@@ -0,0 +1,450 @@
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared.DataAccess;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Moq;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// Pins the clock_skew condition source (EvaluateClockSkewCondition) behind ANALYZE-DEV-008.
|
||||
/// The evaluator measures d = Timestamp − ReceivedAt per event, reduces to per-upload-batch
|
||||
/// medians (wide-spread batches = spool backlogs are dropped), then detects either a persistent
|
||||
/// mid-session step between two flat plateaus (clock_jump) or a stable whole-session offset
|
||||
/// (sustained_offset). IME-log-derived events are excluded so a CMTrace anchoring regression
|
||||
/// (the e9753578 field incident) can never fire this customer-facing rule — that failure mode
|
||||
/// belongs to the operator-side CmTraceSkewTripwire.
|
||||
/// </summary>
|
||||
public class RuleEngineClockSkewTests
|
||||
{
|
||||
private const string TenantId = "a1b2c3d4-e5f6-7890-abcd-ef1234567890";
|
||||
private const string SessionId = "b2c3d4e5-f6a7-8901-bcde-f12345678901";
|
||||
|
||||
private static readonly DateTime T0 = new(2026, 8, 20, 10, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
// ── clock_jump: must fire ──────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_ForwardStepBetweenStableFrames_Fires()
|
||||
{
|
||||
// 4 batches on frame 0, then 4 batches on frame +1800 s (+30 min) that hold to
|
||||
// session end — the canonical "clock corrected forward mid-session".
|
||||
var events = Batches(offsetsSeconds: new double[] { 0, 0, 0, 0, 1800, 1800, 1800, 1800 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("forward", evidence["direction"]);
|
||||
Assert.Equal(1800, Convert.ToDouble(evidence["jumpSeconds"]), 0);
|
||||
Assert.Equal("skewSummary", evidence["field"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_BackwardStep_Fires()
|
||||
{
|
||||
var events = Batches(new double[] { 0, 0, 0, -1200, -1200, -1200 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("backward", evidence["direction"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_WrongClockCorrectedMidSession_Fires()
|
||||
{
|
||||
// Device started 30 min behind, time sync fixed it: the CORRECTED frame is the
|
||||
// persistent change, so this must fire (direction forward).
|
||||
var events = Batches(new double[] { -1800, -1800, -1800, 0, 0, 0 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("forward", evidence["direction"]);
|
||||
}
|
||||
|
||||
// ── clock_jump: must stay silent ───────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_ImeDerivedSkew_ExcludedFromMeasurement_Silent()
|
||||
{
|
||||
// e9753578 replica: IME-derived events carry grid-multiple wrong timestamps (−7 h /
|
||||
// +2 h writer eras) while the agent's own events are healthy. The IME events must be
|
||||
// excluded up front — a CMTrace anchoring regression may NEVER fire the customer rule.
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 0, 0 });
|
||||
var seq = 1000;
|
||||
foreach (var imeOffset in new double[] { -25200, -25200, 7200, 7200, -25200, 7200 })
|
||||
events.Add(MakeEvent(seq++, T0.AddMinutes(seq % 7), imeOffset, source: "ImeLogTracker"));
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_WideSpreadSpoolBatch_DroppedAndSilent()
|
||||
{
|
||||
// One upload batch whose events span 30 min of emission time (offline spool flushed
|
||||
// in a single request) — the internal spread disqualifies the batch entirely.
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 0, 0 });
|
||||
var flushReceivedAt = T0.AddMinutes(90);
|
||||
for (int i = 0; i < 20; i++)
|
||||
events.Add(MakeEvent(2000 + i, flushReceivedAt, offsetSeconds: -1800 + i * 90));
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_GradualBacklogDrainRamp_Silent()
|
||||
{
|
||||
// A chunked spool drain produces a RAMP of batch medians walking back to the live
|
||||
// frame. No flat pre/post plateau pair exists, so the step detector must reject every
|
||||
// candidate — this is a delivery artifact, not a clock change.
|
||||
var events = Batches(new double[] { -1800, -1500, -1200, -900, -600, -300, 0, 0 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_TransientExcursionReturnsToFrame_Silent()
|
||||
{
|
||||
// Frame dips for two batches and returns — whatever it was, it is not a SUSTAINED
|
||||
// clock change (end-state persistence fails).
|
||||
var events = Batches(new double[] { 0, 0, 0, -1800, -1800, 0, 0, 0 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_BelowThreshold_Silent()
|
||||
{
|
||||
var events = Batches(new double[] { 0, 0, 0, 240, 240, 240 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_TooFewBatches_Silent()
|
||||
{
|
||||
// 5 batches < 2×ConfirmBatches — not enough for two comparison windows.
|
||||
var events = Batches(new double[] { 0, 0, 1800, 1800, 1800 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_LegacyEventsWithoutReceivedAt_Silent()
|
||||
{
|
||||
var events = Batches(new double[] { 0, 0, 0, 1800, 1800, 1800 });
|
||||
foreach (var e in events)
|
||||
e.ReceivedAt = null;
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task ClockJump_ClampedEventsExcluded_Silent()
|
||||
{
|
||||
// The jumped frame exists only on clamped events (their OccurredUtc is already
|
||||
// server-substituted in production) — excluding them leaves a single stable frame.
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 0, 0 });
|
||||
var seq = 3000;
|
||||
foreach (var offset in new double[] { 1800, 1800, 1800 })
|
||||
{
|
||||
var evt = MakeEvent(seq, T0.AddMinutes(120 + seq % 5), offset);
|
||||
evt.TimestampClamped = true;
|
||||
events.Add(evt);
|
||||
seq++;
|
||||
}
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
// ── sustained_offset ───────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task SustainedOffset_ClockBehindWholeSession_Fires()
|
||||
{
|
||||
var events = Batches(new double[] { -1800, -1795, -1805, -1800, -1798 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal("behind", evidence["direction"]);
|
||||
Assert.Equal(-30.0, Convert.ToDouble(evidence["offsetMinutes"]), 1);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SustainedOffset_HealthyUploadLatencyBaseline_Silent()
|
||||
{
|
||||
// Healthy devices sit a few seconds NEGATIVE (upload latency) — far below threshold.
|
||||
var events = Batches(new double[] { -3, -5, -2, -4, -6 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SustainedOffset_UnstableBatchOffsets_Silent()
|
||||
{
|
||||
// Medians all over the place: no honest single-offset statement exists, even though
|
||||
// the overall median magnitude clears the threshold.
|
||||
var events = Batches(new double[] { -2400, 900, -1800, 300, -3600, -600 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
// ── P14: SentAt direct measurement (X-Send-Time-Utc batches) ───────────
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_SpoolFlushWithWideEventSpread_JumpStillMeasured_Fires()
|
||||
{
|
||||
// Every batch is a spool flush spanning 30 min of emission time — the legacy path
|
||||
// drops ALL of them via the spread cap and stays blind. SentAt measures the frame
|
||||
// crossing directly, so the +30 min step must fire regardless of event-timestamp
|
||||
// spread, and every batch counts as a SentAt batch.
|
||||
static double[] Wide(int _) => new double[] { -1800, -1350, -900, -450, 0 };
|
||||
var events = SentAtBatches(new double[] { 0, 0, 0, 0, 1800, 1800, 1800, 1800 }, Wide);
|
||||
|
||||
var outcome = await RunAsync(MakeRule("clock_jump", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["clock_jump"]);
|
||||
Assert.Equal("forward", evidence["direction"]);
|
||||
Assert.Equal(8, Convert.ToInt32(evidence["sentAtBatchCount"]));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_UniformBacklogBatches_ReadAsHealthy_Silent()
|
||||
{
|
||||
// EXACTLY the event shape of SustainedOffset_ClockBehindWholeSession_Fires (tight
|
||||
// −30 min Timestamp−ReceivedAt deltas), but the batches carry SentAt ≈ ReceivedAt:
|
||||
// the device clock is fine, the events are merely OLD (uniform spool backlog).
|
||||
// The legacy median cannot tell those apart — SentAt can, and must stay silent.
|
||||
static double[] Backlog(int b) => new double[] { -1800, -1795, -1805, -1800, -1798 };
|
||||
var events = SentAtBatches(new double[] { -3, -5, -2, -4, -6 }, Backlog);
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_SustainedOffset_MeasuredFromSendTime_Fires()
|
||||
{
|
||||
var events = SentAtBatches(new double[] { -1800, -1795, -1805, -1800, -1798 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal("behind", evidence["direction"]);
|
||||
Assert.Equal(-30.0, Convert.ToDouble(evidence["offsetMinutes"]), 1);
|
||||
Assert.Equal(5, Convert.ToInt32(evidence["sentAtBatchCount"]));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_ImeOnlyBatches_MeasurableViaSendTime_Fires()
|
||||
{
|
||||
// IME-source events are excluded from the LEGACY measurement (writer timezone
|
||||
// belief), but a SentAt batch never reads event timestamps — the device clock is
|
||||
// measured from the send moment, so IME-only sessions become measurable.
|
||||
var events = SentAtBatches(
|
||||
new double[] { -1800, -1800, -1800, -1800, -1800 }, source: "ImeLogTracker");
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal("behind", evidence["direction"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_HealthyUploadLatencyBaseline_Silent()
|
||||
{
|
||||
var events = SentAtBatches(new double[] { -3, -5, -2, -4, -6 });
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
Assert.Empty(outcome.Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task SentAt_MixedWithLegacyBatches_ConsistentFrame_Fires()
|
||||
{
|
||||
// Mid-session agent update: first half legacy (event-median), second half SentAt.
|
||||
// Both measure the same physical quantity, so a consistent −30 min frame across the
|
||||
// mix must still produce a sustained-offset verdict.
|
||||
var events = Batches(new double[] { -1800, -1795, -1805 });
|
||||
long seq = 1000;
|
||||
for (int b = 0; b < 3; b++)
|
||||
{
|
||||
var receivedAt = T0.AddMinutes(60 + b * 5);
|
||||
var sentAt = receivedAt.AddSeconds(-1800);
|
||||
for (int i = 0; i < 5; i++)
|
||||
{
|
||||
var evt = MakeEvent(seq++, receivedAt, -1800 + (i - 2));
|
||||
evt.SentAt = sentAt;
|
||||
events.Add(evt);
|
||||
}
|
||||
}
|
||||
|
||||
var outcome = await RunAsync(MakeRule("sustained_offset", "300"), events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
var evidence = Assert.IsAssignableFrom<IDictionary<string, object>>(result.MatchedConditions["sustained_offset"]);
|
||||
Assert.Equal(-30.0, Convert.ToDouble(evidence["offsetMinutes"]), 1);
|
||||
Assert.Equal(3, Convert.ToInt32(evidence["sentAtBatchCount"]));
|
||||
Assert.Equal(6, Convert.ToInt32(evidence["batchCount"]));
|
||||
}
|
||||
|
||||
// ── ANALYZE-DEV-008 shape: two optional conditions ─────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task Dev008Shape_JumpOnlySession_FiresWithSingleMatchedCondition()
|
||||
{
|
||||
// Mirrors the shipped rule: both conditions required:false, baseConfidence 60,
|
||||
// threshold 50 — one matching metric must be enough to fire.
|
||||
var rule = MakeRule("clock_jump", "300");
|
||||
rule.Conditions[0].Required = false;
|
||||
rule.Conditions.Add(new RuleCondition
|
||||
{
|
||||
Signal = "sustained_offset",
|
||||
Source = "clock_skew",
|
||||
SkewMetric = "sustained_offset",
|
||||
Operator = "gte",
|
||||
Value = "300",
|
||||
Required = false,
|
||||
});
|
||||
|
||||
var events = Batches(new double[] { 0, 0, 0, 0, 1800, 1800, 1800, 1800 });
|
||||
|
||||
var outcome = await RunAsync(rule, events);
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
Assert.True(result.MatchedConditions.ContainsKey("clock_jump"));
|
||||
}
|
||||
|
||||
// ===== Helpers =====
|
||||
|
||||
private static AnalyzeRule MakeRule(string skewMetric, string thresholdSeconds) => new()
|
||||
{
|
||||
RuleId = "ANALYZE-TST-CLK",
|
||||
Title = "clock_skew test rule",
|
||||
Severity = "warning",
|
||||
Category = "device",
|
||||
Enabled = true,
|
||||
IsBuiltIn = false,
|
||||
BaseConfidence = 60,
|
||||
ConfidenceThreshold = 50,
|
||||
Conditions = new List<RuleCondition>
|
||||
{
|
||||
new()
|
||||
{
|
||||
Signal = skewMetric,
|
||||
Source = "clock_skew",
|
||||
SkewMetric = skewMetric,
|
||||
Operator = "gte",
|
||||
Value = thresholdSeconds,
|
||||
Required = true,
|
||||
}
|
||||
},
|
||||
Explanation = "test {{skewSummary}}",
|
||||
};
|
||||
|
||||
/// <summary>
|
||||
/// One upload batch per entry: 5 events sharing the batch's ReceivedAt, each with
|
||||
/// Timestamp = ReceivedAt + offsetSeconds (±2 s in-batch jitter, well under the spread cap).
|
||||
/// </summary>
|
||||
private static List<EnrollmentEvent> Batches(double[] offsetsSeconds)
|
||||
{
|
||||
var events = new List<EnrollmentEvent>();
|
||||
long seq = 1;
|
||||
for (int b = 0; b < offsetsSeconds.Length; b++)
|
||||
{
|
||||
var receivedAt = T0.AddMinutes(b * 5);
|
||||
for (int i = 0; i < 5; i++)
|
||||
events.Add(MakeEvent(seq++, receivedAt, offsetsSeconds[b] + (i - 2)));
|
||||
}
|
||||
return events;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// One SentAt-carrying upload batch per frame offset: SentAt = ReceivedAt + frameOffset
|
||||
/// (the P14 direct measurement), event timestamps default to healthy in-batch jitter but
|
||||
/// can be overridden per batch to simulate spool spreads or backlogs.
|
||||
/// </summary>
|
||||
private static List<EnrollmentEvent> SentAtBatches(
|
||||
double[] frameOffsetsSeconds,
|
||||
Func<int, double[]>? eventOffsetsForBatch = null,
|
||||
string source = "DecisionEngine")
|
||||
{
|
||||
var events = new List<EnrollmentEvent>();
|
||||
long seq = 1;
|
||||
for (int b = 0; b < frameOffsetsSeconds.Length; b++)
|
||||
{
|
||||
var receivedAt = T0.AddMinutes(b * 5);
|
||||
var sentAt = receivedAt.AddSeconds(frameOffsetsSeconds[b]);
|
||||
var offsets = eventOffsetsForBatch?.Invoke(b) ?? new double[] { -2, -1, 0, 1, 2 };
|
||||
foreach (var offset in offsets)
|
||||
{
|
||||
var evt = MakeEvent(seq++, receivedAt, offset, source);
|
||||
evt.SentAt = sentAt;
|
||||
events.Add(evt);
|
||||
}
|
||||
}
|
||||
return events;
|
||||
}
|
||||
|
||||
private static EnrollmentEvent MakeEvent(long sequence, DateTime receivedAt, double offsetSeconds,
|
||||
string source = "DecisionEngine") => new()
|
||||
{
|
||||
EventId = Guid.NewGuid().ToString(),
|
||||
TenantId = TenantId,
|
||||
SessionId = SessionId,
|
||||
EventType = "status_update",
|
||||
Source = source,
|
||||
Timestamp = receivedAt.AddSeconds(offsetSeconds),
|
||||
ReceivedAt = receivedAt,
|
||||
Sequence = sequence,
|
||||
Data = new Dictionary<string, object>(),
|
||||
};
|
||||
|
||||
private static async Task<AnalysisOutcome> RunAsync(AnalyzeRule rule, List<EnrollmentEvent> events)
|
||||
{
|
||||
var ruleRepo = new Mock<IRuleRepository>();
|
||||
ruleRepo.Setup(r => r.GetAnalyzeRulesAsync("global")).ReturnsAsync(new List<AnalyzeRule> { rule });
|
||||
ruleRepo.Setup(r => r.GetAnalyzeRulesAsync(TenantId)).ReturnsAsync(new List<AnalyzeRule>());
|
||||
ruleRepo.Setup(r => r.GetRuleStatesAsync(It.IsAny<string>())).ReturnsAsync(new Dictionary<string, RuleState>());
|
||||
ruleRepo.Setup(r => r.GetRuleResultsAsync(It.IsAny<string>(), It.IsAny<string>())).ReturnsAsync(new List<RuleResult>());
|
||||
|
||||
var sessionRepo = new Mock<ISessionRepository>();
|
||||
sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny<int>())).ReturnsAsync(events);
|
||||
|
||||
var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger<AnalyzeRuleService>.Instance);
|
||||
var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger<RuleEngineClockSkewTests>.Instance);
|
||||
|
||||
return await engine.AnalyzeSessionAsync(TenantId, SessionId);
|
||||
}
|
||||
}
|
||||
@@ -270,6 +270,59 @@ public class RuleEngineDryRunTests
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("joinField"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Validate_ClockSkewMissingOrUnknownMetric_Error()
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = null;
|
||||
rule.Conditions[0].Operator = "gte";
|
||||
rule.Conditions[0].Value = "300";
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("skewMetric"));
|
||||
|
||||
rule.Conditions[0].SkewMetric = "drift"; // not a known metric
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("skewMetric"));
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData("lt")]
|
||||
[InlineData("equals")]
|
||||
public void Validate_ClockSkewUnsupportedOperator_Error(string op)
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = "clock_jump";
|
||||
rule.Conditions[0].Operator = op;
|
||||
rule.Conditions[0].Value = "300";
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("only gt/gte"));
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData("")]
|
||||
[InlineData("abc")]
|
||||
[InlineData("-300")]
|
||||
[InlineData("0")]
|
||||
public void Validate_ClockSkewNonPositiveThreshold_Error(string value)
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = "sustained_offset";
|
||||
rule.Conditions[0].Operator = "gte";
|
||||
rule.Conditions[0].Value = value;
|
||||
Assert.Contains(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule), e => e.Contains("positive numeric value"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Validate_ClockSkewValidCondition_NoErrors()
|
||||
{
|
||||
var rule = MakeRule();
|
||||
rule.Conditions[0].Source = "clock_skew";
|
||||
rule.Conditions[0].SkewMetric = "clock_jump";
|
||||
rule.Conditions[0].Operator = "gte";
|
||||
rule.Conditions[0].Value = "300";
|
||||
Assert.Empty(DryRunAnalyzeRuleFunction.ValidateDraftRule(rule));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Validate_InvalidRegex_Error()
|
||||
{
|
||||
|
||||
+4
-1
@@ -131,9 +131,12 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
|
||||
earliestEventTimestamp, latestEventTimestamp, currentPhase,
|
||||
platformScriptIncrement, remediationScriptIncrement, rebootIncrement);
|
||||
|
||||
public Task ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
public Task<SessionSkewScan?> ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
=> _storage.ReconcileSessionCountersAsync(tenantId, sessionId);
|
||||
|
||||
public Task<Dictionary<string, int>> GetImeOffsetOriginHistogramAsync(string tenantId, string sessionId, int maxRows = 500)
|
||||
=> _storage.GetImeOffsetOriginHistogramAsync(tenantId, sessionId, maxRows);
|
||||
|
||||
public Task UpdateSessionDiagnosticsBlobAsync(
|
||||
string tenantId, string sessionId, string blobName, string? destination = null)
|
||||
=> _storage.UpdateSessionDiagnosticsBlobAsync(tenantId, sessionId, blobName, destination);
|
||||
|
||||
@@ -606,16 +606,14 @@ namespace AutopilotMonitor.Functions.Functions.Apps
|
||||
return date.AddDays(-diff);
|
||||
}
|
||||
|
||||
// Internal so AppVersionRegressionRadar shares the same nearest-rank convention
|
||||
// (a third percentile implementation would invite subtle median drift).
|
||||
// Internal so AppVersionRegressionRadar shares the same nearest-rank convention.
|
||||
// Thin delegation onto the single shared implementation (PercentileMath) — parallel
|
||||
// implementations would invite subtle median drift.
|
||||
internal static int Percentile(List<int> values, double percentile)
|
||||
{
|
||||
if (values.Count == 0) return 0;
|
||||
var sorted = values.OrderBy(v => v).ToList();
|
||||
var rank = (int)Math.Ceiling(percentile * sorted.Count) - 1;
|
||||
if (rank < 0) rank = 0;
|
||||
if (rank >= sorted.Count) rank = sorted.Count - 1;
|
||||
return sorted[rank];
|
||||
var sorted = values.Select(v => (double)v).OrderBy(v => v).ToList();
|
||||
return (int)Helpers.PercentileMath.Percentile(sorted, percentile);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -221,10 +221,17 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
// EventIngestProcessor, saving one Sessions point-read per batch.
|
||||
var preFetchedStatus = TryReadSessionStatus(guardSessionRow);
|
||||
|
||||
// P14: device-clock send time of this upload (one value per request). Separates
|
||||
// spool delay from device-vs-server clock offset downstream; absent/garbage → null.
|
||||
var sentAtHeader = req.Headers.Contains("X-Send-Time-Utc")
|
||||
? req.Headers.GetValues("X-Send-Time-Utc").FirstOrDefault()
|
||||
: null;
|
||||
var sentAt = ParseSendTimeHeader(sentAtHeader);
|
||||
|
||||
// Partition + persist. Events are routed through EventIngestProcessor which runs the
|
||||
// full pipeline (rule engine / app-install aggregation / SignalR / webhooks / ...);
|
||||
// Signal + Transition go straight to their repositories.
|
||||
var outcome = await PersistItemsAsync(items, bodyTenantId, sessionId, validation, preFetchedStatus);
|
||||
var outcome = await PersistItemsAsync(items, bodyTenantId, sessionId, validation, preFetchedStatus, sentAt);
|
||||
|
||||
_logger.LogInformation(
|
||||
"IngestTelemetry: tenant={Tenant} session={Session} events={E} signals={S} transitions={T} unknown={U}",
|
||||
@@ -349,7 +356,8 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
string tenantId,
|
||||
string sessionId,
|
||||
SecurityValidationResult validation,
|
||||
SessionStatus? preFetchedStatus)
|
||||
SessionStatus? preFetchedStatus,
|
||||
DateTime? sentAt)
|
||||
{
|
||||
var events = new List<EnrollmentEvent>();
|
||||
var signals = new List<SignalRecord>();
|
||||
@@ -435,6 +443,7 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
SessionId = sessionId,
|
||||
TenantId = tenantId,
|
||||
Events = events,
|
||||
SentAt = sentAt,
|
||||
};
|
||||
var processed = await _eventProcessor.ProcessEventsAsync(eventRequest, validation, preFetchedStatus);
|
||||
|
||||
@@ -570,6 +579,29 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
return false;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Parses the <c>X-Send-Time-Utc</c> header (agent device-clock send time, ISO-8601
|
||||
/// round-trip). Returns null for absent/unparseable values and for anything before
|
||||
/// year 2000 — Table Storage rejects pre-1601 DateTimes outright, and a sub-2000
|
||||
/// value can only be garbage, never a measurable clock offset. Deliberately NO upper
|
||||
/// clamp: a future-dated send time IS the device-clock-error measurement this field
|
||||
/// exists to capture.
|
||||
/// </summary>
|
||||
internal static DateTime? ParseSendTimeHeader(string? headerValue)
|
||||
{
|
||||
if (string.IsNullOrWhiteSpace(headerValue)) return null;
|
||||
|
||||
if (!DateTimeOffset.TryParse(
|
||||
headerValue,
|
||||
System.Globalization.CultureInfo.InvariantCulture,
|
||||
System.Globalization.DateTimeStyles.RoundtripKind,
|
||||
out var parsed))
|
||||
return null;
|
||||
|
||||
var utc = parsed.UtcDateTime;
|
||||
return utc.Year >= 2000 ? utc : (DateTime?)null;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// PartitionKey convention is <c>{tenantId}_{sessionId}</c> — both GUIDs with dashes, so
|
||||
/// splitting on the single underscore between them is unambiguous. Returns false for any
|
||||
|
||||
+18
-1
@@ -128,7 +128,12 @@ namespace AutopilotMonitor.Functions.Functions.Rules
|
||||
internal static readonly HashSet<string> KnownSources = new(StringComparer.Ordinal)
|
||||
{
|
||||
"event_type", "event_data", "event_data_array", "event_count",
|
||||
"phase_duration", "app_install_duration", "event_correlation",
|
||||
"phase_duration", "app_install_duration", "event_correlation", "clock_skew",
|
||||
};
|
||||
|
||||
internal static readonly HashSet<string> KnownSkewMetrics = new(StringComparer.Ordinal)
|
||||
{
|
||||
"clock_jump", "sustained_offset",
|
||||
};
|
||||
|
||||
internal static readonly HashSet<string> KnownOperators = new(StringComparer.OrdinalIgnoreCase)
|
||||
@@ -196,6 +201,18 @@ namespace AutopilotMonitor.Functions.Functions.Rules
|
||||
errors.Add($"{label}: event_correlation requires joinField");
|
||||
}
|
||||
|
||||
if (string.Equals(c.Source, "clock_skew", StringComparison.Ordinal))
|
||||
{
|
||||
if (string.IsNullOrWhiteSpace(c.SkewMetric) || !KnownSkewMetrics.Contains(c.SkewMetric))
|
||||
errors.Add($"{label}: clock_skew requires skewMetric (one of: {string.Join(", ", KnownSkewMetrics)})");
|
||||
if (!string.Equals(c.Operator, "gt", StringComparison.OrdinalIgnoreCase)
|
||||
&& !string.Equals(c.Operator, "gte", StringComparison.OrdinalIgnoreCase))
|
||||
errors.Add($"{label}: clock_skew supports only gt/gte (magnitude vs threshold)");
|
||||
if (!double.TryParse(c.Value, System.Globalization.NumberStyles.Float,
|
||||
System.Globalization.CultureInfo.InvariantCulture, out var skewThreshold) || skewThreshold <= 0)
|
||||
errors.Add($"{label}: clock_skew requires a positive numeric value (threshold in seconds)");
|
||||
}
|
||||
|
||||
if ((string.Equals(c.Operator, "regex", StringComparison.OrdinalIgnoreCase)
|
||||
|| string.Equals(c.Operator, "not_regex", StringComparison.OrdinalIgnoreCase))
|
||||
&& !string.IsNullOrEmpty(c.Value))
|
||||
|
||||
@@ -63,7 +63,7 @@ namespace AutopilotMonitor.Functions.Helpers
|
||||
private static readonly HashSet<string> KnownFieldKeys = new(StringComparer.OrdinalIgnoreCase)
|
||||
{
|
||||
"eventId", "sessionId", "tenantId", "eventType", "severity", "source", "phase",
|
||||
"phaseName", "timestamp", "receivedAt", "message", "sequence", "rowKey",
|
||||
"phaseName", "timestamp", "receivedAt", "sentAt", "message", "sequence", "rowKey",
|
||||
"originalTimestamp", "timestampClamped", "causedByTransitionStepIndex",
|
||||
"causedBySignalOrdinal", "data",
|
||||
};
|
||||
@@ -86,6 +86,7 @@ namespace AutopilotMonitor.Functions.Helpers
|
||||
if (fields.Contains("phaseName")) dict["phaseName"] = e.PhaseName;
|
||||
if (fields.Contains("timestamp")) dict["timestamp"] = e.Timestamp;
|
||||
if (fields.Contains("receivedAt")) dict["receivedAt"] = e.ReceivedAt;
|
||||
if (fields.Contains("sentAt")) dict["sentAt"] = e.SentAt;
|
||||
if (fields.Contains("message")) dict["message"] = e.Message;
|
||||
if (fields.Contains("sequence")) dict["sequence"] = e.Sequence;
|
||||
if (fields.Contains("rowKey")) dict["rowKey"] = e.RowKey;
|
||||
|
||||
@@ -0,0 +1,30 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.Linq;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Helpers
|
||||
{
|
||||
/// <summary>
|
||||
/// The single nearest-rank percentile implementation (rank = ceil(p·n) − 1, clamped).
|
||||
/// AppsAnalyticsHelper.Percentile and PlatformMetricsService.Percentile delegate here;
|
||||
/// keep it that way — parallel implementations invite subtle median drift between
|
||||
/// surfaces that report the "same" statistic.
|
||||
/// </summary>
|
||||
internal static class PercentileMath
|
||||
{
|
||||
/// <summary>Nearest-rank percentile over an ascending-sorted list.</summary>
|
||||
internal static double Percentile(IReadOnlyList<double> sortedValues, double percentile)
|
||||
{
|
||||
if (sortedValues.Count == 0) return 0;
|
||||
var rank = (int)Math.Ceiling(percentile * sortedValues.Count) - 1;
|
||||
return sortedValues[Math.Max(0, Math.Min(rank, sortedValues.Count - 1))];
|
||||
}
|
||||
|
||||
/// <summary>Median (p50) over unsorted values.</summary>
|
||||
internal static double Median(IEnumerable<double> values)
|
||||
{
|
||||
var sorted = values.OrderBy(v => v).ToList();
|
||||
return Percentile(sorted, 0.50);
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,107 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using AutopilotMonitor.Functions.Helpers;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Services
|
||||
{
|
||||
/// <summary>
|
||||
/// Regression tripwire for the agent's CMTrace time resolution (per-line self-anchoring,
|
||||
/// docs/agent/cmtrace-time-resolution.md). Runs once per session on the terminal ingest
|
||||
/// batch, over samples the counter reconcile collected in its existing partition scan.
|
||||
///
|
||||
/// Detection: diff = median(Δ_IME) − median(Δ_other), where Δ = ReceivedAt − OccurredUtc.
|
||||
/// Shared upload/spool latency is common-mode and cancels in the difference; a timezone
|
||||
/// mis-conversion shifts only the IME side and lands on the 15-minute offset grid.
|
||||
/// Replayed old log lines produce large OFF-grid deltas — the grid-residual test is what
|
||||
/// separates the two (field measurement 2026-08-20: without it, 48 instead of 26 true hits).
|
||||
///
|
||||
/// Goal state: this never fires. Any hit is either a case the per-line anchoring does not
|
||||
/// cover or a detector bug — both are actionable findings, never noise to tune away.
|
||||
/// </summary>
|
||||
internal static class CmTraceSkewTripwire
|
||||
{
|
||||
// Same grid the agent anchors on and the same residual tolerance as its own grid
|
||||
// guard (docs/agent/cmtrace-time-resolution.md) — keep these in lockstep with the
|
||||
// agent so a future anchoring change stays traceable to this detector.
|
||||
internal const int GridMinutes = 15;
|
||||
internal const double ResidualToleranceMinutes = 2.0;
|
||||
internal const int MinSamplesPerSide = 20;
|
||||
// ReceivedAt is stamped per upload batch, not per event; a side backed by fewer
|
||||
// distinct batches yields a batch-composition artifact, not a session property.
|
||||
internal const int MinDistinctBatchesPerSide = 3;
|
||||
|
||||
internal sealed class Result
|
||||
{
|
||||
public double MedianImeDeltaMinutes { get; set; }
|
||||
public double MedianOtherDeltaMinutes { get; set; }
|
||||
public double DiffMinutes { get; set; }
|
||||
public int GridSteps { get; set; }
|
||||
public double ResidualMinutes { get; set; }
|
||||
public int ImeSampleCount { get; set; }
|
||||
public int OtherSampleCount { get; set; }
|
||||
public int ImeBatchCount { get; set; }
|
||||
public int OtherBatchCount { get; set; }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Pure detector: non-null exactly when the session shows a grid-aligned divergence
|
||||
/// between IME-derived and other event timestamps. All suppression inputs live in the
|
||||
/// scan itself so the decision is fully unit-testable.
|
||||
/// </summary>
|
||||
internal static Result? Evaluate(SessionSkewScan? scan)
|
||||
{
|
||||
if (scan == null)
|
||||
return null;
|
||||
if (scan.ImeDeltaMinutes.Count < MinSamplesPerSide || scan.OtherDeltaMinutes.Count < MinSamplesPerSide)
|
||||
return null;
|
||||
if (scan.ImeDistinctBatchCount < MinDistinctBatchesPerSide || scan.OtherDistinctBatchCount < MinDistinctBatchesPerSide)
|
||||
return null;
|
||||
|
||||
var medianIme = PercentileMath.Median(scan.ImeDeltaMinutes);
|
||||
var medianOther = PercentileMath.Median(scan.OtherDeltaMinutes);
|
||||
var diff = medianIme - medianOther;
|
||||
var steps = (int)Math.Round(diff / GridMinutes, MidpointRounding.AwayFromZero);
|
||||
var residual = Math.Abs(diff - steps * (double)GridMinutes);
|
||||
|
||||
if (Math.Abs(steps) < 1 || residual >= ResidualToleranceMinutes)
|
||||
return null;
|
||||
|
||||
return new Result
|
||||
{
|
||||
MedianImeDeltaMinutes = medianIme,
|
||||
MedianOtherDeltaMinutes = medianOther,
|
||||
DiffMinutes = diff,
|
||||
GridSteps = steps,
|
||||
ResidualMinutes = residual,
|
||||
ImeSampleCount = scan.ImeDeltaMinutes.Count,
|
||||
OtherSampleCount = scan.OtherDeltaMinutes.Count,
|
||||
ImeBatchCount = scan.ImeDistinctBatchCount,
|
||||
OtherBatchCount = scan.OtherDistinctBatchCount,
|
||||
};
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// True when the session's IME events are dominated by writer-declared ("bias")
|
||||
/// offsets — a bias offset comes verbatim from the log line's own zone marker and
|
||||
/// cannot be an anchoring regression, so a grid hit there is not ours to alarm on.
|
||||
/// measuredWriterOffsetMinutes is deliberately NOT consulted: the per-file
|
||||
/// observation sticks to a stale value after an era flip-back (monotonicity guard),
|
||||
/// making it non-authoritative for exactly the sessions this tripwire inspects.
|
||||
/// </summary>
|
||||
internal static bool IsBiasDominated(IReadOnlyDictionary<string, int>? originHistogram)
|
||||
{
|
||||
if (originHistogram == null || originHistogram.Count == 0)
|
||||
return false;
|
||||
|
||||
int total = 0, bias = 0;
|
||||
foreach (var kv in originHistogram)
|
||||
{
|
||||
total += kv.Value;
|
||||
if (string.Equals(kv.Key, "bias", StringComparison.OrdinalIgnoreCase))
|
||||
bias += kv.Value;
|
||||
}
|
||||
return total > 0 && bias * 2 >= total;
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -6,6 +6,7 @@ using AutopilotMonitor.Shared.DataAccess;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Microsoft.ApplicationInsights;
|
||||
using Microsoft.Azure.Functions.Worker;
|
||||
using Microsoft.Extensions.Configuration;
|
||||
using Microsoft.Extensions.Logging;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Services
|
||||
@@ -44,6 +45,10 @@ namespace AutopilotMonitor.Functions.Services
|
||||
private readonly AutopilotMonitor.Functions.Services.Analyze.InterimTriggerRegistry _interimTriggerRegistry;
|
||||
private readonly IVulnerabilityCorrelateProducer _vulnProducer;
|
||||
private readonly Ime.IImeMsiArchiveProducer _imeMsiArchiveProducer;
|
||||
private readonly IConfiguration _configuration;
|
||||
|
||||
/// <summary>App setting kill switch: set to "true" to skip the CMTrace skew tripwire entirely. Fail-open — the tripwire only notifies, it never mutates data.</summary>
|
||||
internal const string CmTraceSkewTripwireKillSwitchSetting = "CmTraceSkewTripwireDisabled";
|
||||
|
||||
public EventIngestProcessor(
|
||||
ILogger<EventIngestProcessor> logger,
|
||||
@@ -60,7 +65,8 @@ namespace AutopilotMonitor.Functions.Services
|
||||
AutopilotMonitor.Functions.Services.Analyze.IAnalyzeOnEnrollmentEndProducer analyzeProducer,
|
||||
AutopilotMonitor.Functions.Services.Analyze.InterimTriggerRegistry interimTriggerRegistry,
|
||||
IVulnerabilityCorrelateProducer vulnProducer,
|
||||
Ime.IImeMsiArchiveProducer imeMsiArchiveProducer)
|
||||
Ime.IImeMsiArchiveProducer imeMsiArchiveProducer,
|
||||
IConfiguration configuration)
|
||||
{
|
||||
_logger = logger;
|
||||
_sessionRepo = sessionRepo;
|
||||
@@ -77,6 +83,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
_interimTriggerRegistry = interimTriggerRegistry;
|
||||
_vulnProducer = vulnProducer;
|
||||
_imeMsiArchiveProducer = imeMsiArchiveProducer;
|
||||
_configuration = configuration;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -106,7 +113,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
validation.RateLimitResult?.MaxRequests);
|
||||
|
||||
var receivedAt = DateTime.UtcNow;
|
||||
StampServerFields(request.Events, request.TenantId, request.SessionId, receivedAt);
|
||||
StampServerFields(request.Events, request.TenantId, request.SessionId, receivedAt, request.SentAt);
|
||||
SanitizeEventTimestamps(request.Events, receivedAt, _logger);
|
||||
|
||||
var storedEvents = await _sessionRepo.StoreEventsBatchAsync(request.Events);
|
||||
@@ -247,7 +254,17 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// replays where UpdateSessionStatusAsync no-ops.
|
||||
// Idempotent (no-ops when already correct) and fail-soft.
|
||||
if (isTerminalBatch)
|
||||
await _sessionRepo.ReconcileSessionCountersAsync(request.TenantId, request.SessionId);
|
||||
{
|
||||
var skewScan = await _sessionRepo.ReconcileSessionCountersAsync(request.TenantId, request.SessionId);
|
||||
|
||||
// CMTrace time-skew tripwire (goal state: never fires). Gated on the actual
|
||||
// status transition so terminal-batch REPLAYS (statusTransitioned == false)
|
||||
// cannot re-emit — the reconcile above runs on replays by design, the
|
||||
// tripwire must not. Fail-soft: ingest stays a 200 no matter what.
|
||||
if (skewScan != null && (statusTransitioned || whiteGloveStatusTransitioned))
|
||||
await TryFireCmTraceSkewTripwireAsync(request.TenantId, request.SessionId,
|
||||
updatedSession?.AgentVersion, skewScan);
|
||||
}
|
||||
|
||||
// Auto-analyze fan-out: enqueue a queue message instead of running fire-and-forget
|
||||
// Task.Run inside the function. The previous in-function approach could be killed
|
||||
@@ -545,18 +562,83 @@ namespace AutopilotMonitor.Functions.Services
|
||||
System.Globalization.CultureInfo.InvariantCulture, out value);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// CMTrace time-skew regression tripwire. Evaluates the per-source timestamp-delta
|
||||
/// samples the counter reconcile collected and emits a CmTraceTimeSkewRegression ops
|
||||
/// event when the IME-derived events diverge from the other sources by a clean
|
||||
/// 15-minute-grid multiple (see <see cref="CmTraceSkewTripwire"/>). One extra bounded
|
||||
/// storage read happens ONLY on the suspicion path (≈ never): the sourceOffsetOrigin
|
||||
/// histogram that rules out writer-declared ("bias") offsets, which come verbatim
|
||||
/// from the log line and cannot be an anchoring regression.
|
||||
/// </summary>
|
||||
private async Task TryFireCmTraceSkewTripwireAsync(
|
||||
string tenantId, string sessionId, string? agentVersion, SessionSkewScan skewScan)
|
||||
{
|
||||
try
|
||||
{
|
||||
if (string.Equals(_configuration[CmTraceSkewTripwireKillSwitchSetting], "true", StringComparison.OrdinalIgnoreCase))
|
||||
return;
|
||||
|
||||
var result = CmTraceSkewTripwire.Evaluate(skewScan);
|
||||
if (result == null)
|
||||
return;
|
||||
|
||||
var histogram = await _sessionRepo.GetImeOffsetOriginHistogramAsync(tenantId, sessionId);
|
||||
if (CmTraceSkewTripwire.IsBiasDominated(histogram))
|
||||
{
|
||||
_logger.LogInformation(
|
||||
"CMTrace skew tripwire suppressed for session {SessionId}: grid divergence {DiffMinutes:+0.0;-0.0} min, but IME offsets are bias-dominated (writer-declared)",
|
||||
sessionId, result.DiffMinutes);
|
||||
return;
|
||||
}
|
||||
|
||||
var origins = string.Join(", ",
|
||||
histogram.OrderByDescending(kv => kv.Value).Select(kv => $"{kv.Key} {kv.Value}"));
|
||||
var message =
|
||||
$"IME-derived events skewed {result.DiffMinutes:+0.0;-0.0} min vs other sources " +
|
||||
$"({result.GridSteps}x15min grid, residual {result.ResidualMinutes:0.0} min; " +
|
||||
$"median dIME {result.MedianImeDeltaMinutes:0.0} / dOther {result.MedianOtherDeltaMinutes:0.0} min; " +
|
||||
$"{result.ImeSampleCount}/{result.OtherSampleCount} samples over {result.ImeBatchCount}/{result.OtherBatchCount} batches; " +
|
||||
$"origins: {(origins.Length > 0 ? origins : "none")})";
|
||||
|
||||
await _opsEventService.RecordCmTraceTimeSkewRegressionAsync(tenantId, sessionId, agentVersion, message, new
|
||||
{
|
||||
sessionId,
|
||||
agentVersion,
|
||||
diffMinutes = Math.Round(result.DiffMinutes, 2),
|
||||
gridSteps = result.GridSteps,
|
||||
residualMinutes = Math.Round(result.ResidualMinutes, 2),
|
||||
medianImeDeltaMinutes = Math.Round(result.MedianImeDeltaMinutes, 2),
|
||||
medianOtherDeltaMinutes = Math.Round(result.MedianOtherDeltaMinutes, 2),
|
||||
imeSampleCount = result.ImeSampleCount,
|
||||
otherSampleCount = result.OtherSampleCount,
|
||||
imeBatchCount = result.ImeBatchCount,
|
||||
otherBatchCount = result.OtherBatchCount,
|
||||
sourceOffsetOrigins = histogram,
|
||||
});
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogWarning(ex, "CMTrace skew tripwire failed for session {SessionId}", sessionId);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Stamps authoritative server-side fields onto all events before storage.
|
||||
/// TenantId and SessionId always come from the validated request metadata,
|
||||
/// overriding any values the agent may have sent per-event.
|
||||
/// overriding any values the agent may have sent per-event. SentAt is the
|
||||
/// request-level device-clock send time (P14) — one value for every event of
|
||||
/// the batch, null for agents that pre-date the X-Send-Time-Utc header.
|
||||
/// Exposed as internal for unit testing.
|
||||
/// </summary>
|
||||
internal static void StampServerFields(
|
||||
List<EnrollmentEvent> events, string tenantId, string sessionId, DateTime receivedAt)
|
||||
List<EnrollmentEvent> events, string tenantId, string sessionId, DateTime receivedAt,
|
||||
DateTime? sentAt = null)
|
||||
{
|
||||
foreach (var evt in events)
|
||||
{
|
||||
evt.ReceivedAt = receivedAt;
|
||||
evt.SentAt = sentAt;
|
||||
evt.TenantId = tenantId;
|
||||
evt.SessionId = sessionId;
|
||||
}
|
||||
|
||||
@@ -622,6 +622,22 @@ namespace AutopilotMonitor.Functions.Services
|
||||
$"Agent binary integrity mismatch on session {sessionId ?? "?"} (agent {agentVersion ?? "?"}): {message}",
|
||||
tenantId, "System.EmergencyChannel", new { sessionId, agentVersion });
|
||||
|
||||
/// <summary>
|
||||
/// The CMTrace time-skew tripwire fired: a terminal session's IME-derived event
|
||||
/// timestamps diverge from its other events by a clean 15-minute-grid multiple —
|
||||
/// the signature of a timezone mis-conversion the per-line self-anchoring
|
||||
/// (docs/agent/cmtrace-time-resolution.md) failed to catch. Goal state: this event
|
||||
/// NEVER fires; any occurrence is a real anchoring regression or a detector bug,
|
||||
/// both actionable. Emitted by <see cref="EventIngestProcessor"/> once per session
|
||||
/// (gated on the terminal status transition). The message carries the full numbers
|
||||
/// so the event is verifiable without a portal round-trip.
|
||||
/// Dual-register per memory feedback_ops_event_types_dual_register.
|
||||
/// </summary>
|
||||
public Task RecordCmTraceTimeSkewRegressionAsync(string tenantId, string sessionId, string? agentVersion, string message, object details)
|
||||
=> WriteAsync(OpsEventCategory.Agent, "CmTraceTimeSkewRegression", OpsEventSeverity.Warning,
|
||||
$"CMTrace time-skew tripwire on session {sessionId} (agent {agentVersion ?? "?"}): {message}",
|
||||
tenantId, "System.Ingest", details);
|
||||
|
||||
public Task RecordExcessiveSessionEventsAsync(string tenantId, string sessionId, int eventCount, int threshold)
|
||||
=> WriteAsync(OpsEventCategory.Agent, "ExcessiveSessionEvents", OpsEventSeverity.Warning,
|
||||
$"Session {sessionId} has {eventCount} events (threshold {threshold}) — likely agent loop bug",
|
||||
|
||||
@@ -312,12 +312,9 @@ namespace AutopilotMonitor.Functions.Services
|
||||
};
|
||||
}
|
||||
|
||||
// Thin delegation onto the single shared nearest-rank implementation (PercentileMath).
|
||||
private static double Percentile(List<double> sortedValues, double percentile)
|
||||
{
|
||||
if (sortedValues.Count == 0) return 0;
|
||||
var index = (int)Math.Ceiling(percentile * sortedValues.Count) - 1;
|
||||
return sortedValues[Math.Max(0, Math.Min(index, sortedValues.Count - 1))];
|
||||
}
|
||||
=> Helpers.PercentileMath.Percentile(sortedValues, percentile);
|
||||
|
||||
// Payload getters live in AgentMetricsAggregation (shared with the efficiency
|
||||
// service); these thin wrappers keep the call sites above unchanged.
|
||||
|
||||
@@ -98,6 +98,9 @@ namespace AutopilotMonitor.Functions.Services
|
||||
case "event_correlation":
|
||||
return EvaluateEventCorrelationCondition(condition, events);
|
||||
|
||||
case "clock_skew":
|
||||
return EvaluateClockSkewCondition(condition, events);
|
||||
|
||||
default:
|
||||
return (false, "unknown source");
|
||||
}
|
||||
@@ -808,6 +811,209 @@ namespace AutopilotMonitor.Functions.Services
|
||||
return (false, "no app install duration matched");
|
||||
}
|
||||
|
||||
// ===== clock_skew constants =====
|
||||
// Named constants, deliberately NOT condition fields: promoting a constant to a field
|
||||
// later is non-breaking, the reverse is not.
|
||||
/// <summary>Frame windows (in upload batches) that must agree before/after a step for it to count as a clock jump.</summary>
|
||||
internal const int ClockSkewConfirmBatches = 3;
|
||||
/// <summary>Floor for the per-batch internal-spread cap, seconds.</summary>
|
||||
internal const double ClockSkewSpoolSpreadFloorSeconds = 60;
|
||||
/// <summary>Per-batch internal-spread cap as a fraction of the condition threshold.</summary>
|
||||
internal const double ClockSkewSpoolSpreadCapFraction = 0.5;
|
||||
/// <summary>Fraction of surviving batches that must sit near the overall median for a sustained-offset verdict.</summary>
|
||||
internal const double ClockSkewStableBatchFraction = 0.75;
|
||||
|
||||
/// <summary>
|
||||
/// Detects DEVICE clock problems from a per-upload-batch offset between the device's
|
||||
/// clock frame and the server's receive frame (seconds; healthy baseline ≈
|
||||
/// −upload-latency, i.e. a few seconds negative).
|
||||
/// skewMetric "clock_jump": a persistent step in the device's clock frame mid-session
|
||||
/// (time sync correcting a wrong RTC, Windows auto-timezone, manual change).
|
||||
/// skewMetric "sustained_offset": the whole session ran on a clock off by ≥ threshold
|
||||
/// — the during-enrollment complement of ANALYZE-DEV-007's one-shot NTP check.
|
||||
///
|
||||
/// Batch offset, two measurement paths (P14):
|
||||
/// - Events carrying SentAt (X-Send-Time-Utc header, one device-clock value per ingest
|
||||
/// request): offset = SentAt − ReceivedAt, a DIRECT frame-crossing measurement. No
|
||||
/// event timestamps involved → immune to spool backlog, CMTrace writer beliefs and
|
||||
/// clamping by construction, so no spread filter is needed and every batch counts.
|
||||
/// - Legacy batches (agents without the header): median of per-event Timestamp −
|
||||
/// ReceivedAt with a spread cap that drops replayed spool backlogs, excluding
|
||||
/// CMTrace-derived events (Source == "ImeLogTracker") — their Timestamp carries the
|
||||
/// log WRITER's timezone belief, so an anchoring regression must fire the
|
||||
/// operator-side CmTraceSkewTripwire, never this customer-facing rule.
|
||||
///
|
||||
/// Ordering key is Sequence, never Timestamp (see EvaluateAppInstallDurationCondition).
|
||||
/// The legacy path then inspects Timestamp AGAINST that Sequence order ON PURPOSE — a
|
||||
/// device-clock problem is precisely a Timestamp anomaly relative to the clock-immune
|
||||
/// Sequence/ReceivedAt frame. Timestamp is a MEASUREMENT here, never a sort key.
|
||||
/// </summary>
|
||||
private (bool matched, object evidence) EvaluateClockSkewCondition(RuleCondition condition, List<EnrollmentEvent> events)
|
||||
{
|
||||
var metric = condition.SkewMetric ?? string.Empty;
|
||||
if (!double.TryParse(condition.Value, System.Globalization.NumberStyles.Float,
|
||||
System.Globalization.CultureInfo.InvariantCulture, out var thresholdSeconds) || thresholdSeconds <= 0)
|
||||
return (false, "clock_skew requires a positive numeric value (threshold in seconds)");
|
||||
|
||||
var usable = events
|
||||
.Where(e => e.ReceivedAt.HasValue)
|
||||
.OrderBy(e => e.Sequence)
|
||||
.ToList();
|
||||
if (usable.Count == 0)
|
||||
return (false, "no events with a server receive frame");
|
||||
|
||||
// Group into upload batches (ReceivedAt is stamped once per ingest request). Legacy
|
||||
// rationale for the spread cap: a clock offset shifts a whole batch uniformly
|
||||
// (internal spread ≈ upload debounce, seconds); a spool-backlog batch spans the
|
||||
// offline period (spread = minutes–hours). Dropping wide-spread batches is what
|
||||
// makes replayed backlogs inert on the legacy path.
|
||||
var spreadCap = Math.Max(ClockSkewSpoolSpreadFloorSeconds, thresholdSeconds * ClockSkewSpoolSpreadCapFraction);
|
||||
var batches = new List<(double MedianOffsetSeconds, EnrollmentEvent FirstEvent)>();
|
||||
int usedSamples = 0;
|
||||
int sentAtBatchCount = 0;
|
||||
foreach (var batch in usable.GroupBy(e => e.ReceivedAt!.Value))
|
||||
{
|
||||
// P14 direct path — SentAt is request-level, so any event's value speaks for
|
||||
// the whole batch.
|
||||
var sentAt = batch.Select(e => e.SentAt).FirstOrDefault(s => s.HasValue);
|
||||
if (sentAt.HasValue)
|
||||
{
|
||||
sentAtBatchCount++;
|
||||
usedSamples += batch.Count();
|
||||
batches.Add(((sentAt.Value - batch.Key).TotalSeconds, batch.First()));
|
||||
continue;
|
||||
}
|
||||
|
||||
// Legacy path — see the method doc for the IME/clamped exclusions.
|
||||
var measurable = batch
|
||||
.Where(e => !e.TimestampClamped
|
||||
&& !string.Equals(e.Source, "ImeLogTracker", StringComparison.OrdinalIgnoreCase))
|
||||
.ToList();
|
||||
if (measurable.Count == 0)
|
||||
continue;
|
||||
|
||||
var offsets = measurable.Select(e => (e.Timestamp - batch.Key).TotalSeconds).OrderBy(v => v).ToList();
|
||||
if (offsets[offsets.Count - 1] - offsets[0] > spreadCap)
|
||||
continue;
|
||||
usedSamples += offsets.Count;
|
||||
batches.Add((Helpers.PercentileMath.Percentile(offsets, 0.50), measurable[0]));
|
||||
}
|
||||
|
||||
switch (metric)
|
||||
{
|
||||
case "sustained_offset":
|
||||
{
|
||||
if (batches.Count < 2)
|
||||
return (false, "insufficient upload batches for an offset measurement");
|
||||
|
||||
var batchMedians = batches.Select(b => b.MedianOffsetSeconds).ToList();
|
||||
var overall = Helpers.PercentileMath.Median(batchMedians);
|
||||
|
||||
// Constant offset, not drift chaos: most batches must individually sit near
|
||||
// the session median, otherwise no single "the clock was off by X" statement
|
||||
// is honest.
|
||||
var stable = batchMedians.Count(m => Math.Abs(m - overall) <= spreadCap);
|
||||
if (stable < Math.Max(2, (int)Math.Ceiling(batchMedians.Count * ClockSkewStableBatchFraction)))
|
||||
return (false, "batch offsets too unstable for a sustained-offset verdict");
|
||||
|
||||
if (!CompareClockSkewThreshold(Math.Abs(overall), condition.Operator, thresholdSeconds))
|
||||
return (false, $"sustained offset {overall:0} s below threshold");
|
||||
|
||||
var first = batches[0].FirstEvent;
|
||||
var offsetMinutes = Math.Round(overall / 60.0, 1);
|
||||
var direction = overall > 0 ? "ahead" : "behind";
|
||||
return (true, new Dictionary<string, object>
|
||||
{
|
||||
// field/value pair drives {{skewSummary}} template interpolation
|
||||
// (lib/interpolateRuleTemplate.ts resolves field→value first).
|
||||
["field"] = "skewSummary",
|
||||
["value"] = $"clock ran {Math.Abs(offsetMinutes)} min {direction} of server time throughout the session",
|
||||
["offsetSeconds"] = Math.Round(overall, 0),
|
||||
["offsetMinutes"] = offsetMinutes,
|
||||
["direction"] = direction,
|
||||
["eventId"] = first.EventId,
|
||||
["sequence"] = first.Sequence,
|
||||
["timestamp"] = first.Timestamp,
|
||||
["sampleCount"] = usedSamples,
|
||||
["batchCount"] = batches.Count,
|
||||
["sentAtBatchCount"] = sentAtBatchCount,
|
||||
});
|
||||
}
|
||||
|
||||
case "clock_jump":
|
||||
{
|
||||
const int w = ClockSkewConfirmBatches;
|
||||
if (batches.Count < 2 * w)
|
||||
return (false, "insufficient upload batches for a frame comparison");
|
||||
|
||||
var medians = batches.Select(b => b.MedianOffsetSeconds).ToList();
|
||||
(int Index, double Pre, double Post, double Jump)? best = null;
|
||||
for (int j = w - 1; j <= batches.Count - 1 - w; j++)
|
||||
{
|
||||
var preWindow = medians.Skip(j - w + 1).Take(w).ToList();
|
||||
var postWindow = medians.Skip(j + 1).Take(w).ToList();
|
||||
|
||||
// Both comparison windows must be flat plateaus: a genuine clock change
|
||||
// is a step between two stable frames, while a gradually draining spool
|
||||
// backlog produces a RAMP of batch medians — sloping windows would let
|
||||
// any pre/post pair straddling the ramp fake a step.
|
||||
if (preWindow.Max() - preWindow.Min() > spreadCap || postWindow.Max() - postWindow.Min() > spreadCap)
|
||||
continue;
|
||||
|
||||
var pre = Helpers.PercentileMath.Median(preWindow);
|
||||
var post = Helpers.PercentileMath.Median(postWindow);
|
||||
var jump = post - pre;
|
||||
if (CompareClockSkewThreshold(Math.Abs(jump), condition.Operator, thresholdSeconds)
|
||||
&& (best == null || Math.Abs(jump) > Math.Abs(best.Value.Jump)))
|
||||
best = (j, pre, post, jump);
|
||||
}
|
||||
if (best == null)
|
||||
return (false, "no persistent clock step");
|
||||
|
||||
// End-state persistence: a transient excursion that returns to the original
|
||||
// frame (spool backlog draining, historic replay) must stay silent; a genuine
|
||||
// clock change — including "wrong clock corrected by time sync mid-session" —
|
||||
// persists to session end, because the corrected frame IS the change.
|
||||
var tail = Helpers.PercentileMath.Median(medians.Skip(medians.Count - w).Take(w));
|
||||
var tailShift = tail - best.Value.Pre;
|
||||
if (Math.Abs(tailShift) < thresholdSeconds || Math.Sign(tailShift) != Math.Sign(best.Value.Jump))
|
||||
return (false, "transient timestamp excursion, not a sustained clock change");
|
||||
|
||||
var boundary = batches[best.Value.Index + 1].FirstEvent;
|
||||
var jumpMinutes = Math.Round(best.Value.Jump / 60.0, 1);
|
||||
var direction = best.Value.Jump > 0 ? "forward" : "backward";
|
||||
return (true, new Dictionary<string, object>
|
||||
{
|
||||
// field/value pair drives {{skewSummary}} template interpolation
|
||||
// (lib/interpolateRuleTemplate.ts resolves field→value first).
|
||||
["field"] = "skewSummary",
|
||||
["value"] = $"clock jumped {Math.Abs(jumpMinutes)} min {direction} mid-session",
|
||||
["jumpSeconds"] = Math.Round(best.Value.Jump, 0),
|
||||
["jumpMinutes"] = jumpMinutes,
|
||||
["direction"] = direction,
|
||||
["beforeOffsetMinutes"] = Math.Round(best.Value.Pre / 60.0, 1),
|
||||
["afterOffsetMinutes"] = Math.Round(best.Value.Post / 60.0, 1),
|
||||
["eventId"] = boundary.EventId,
|
||||
["sequence"] = boundary.Sequence,
|
||||
["timestamp"] = boundary.Timestamp,
|
||||
["eventType"] = boundary.EventType,
|
||||
["sampleCount"] = usedSamples,
|
||||
["batchCount"] = batches.Count,
|
||||
["sentAtBatchCount"] = sentAtBatchCount,
|
||||
});
|
||||
}
|
||||
|
||||
default:
|
||||
return (false, $"unknown skewMetric '{metric}' (expected clock_jump or sustained_offset)");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>gt/gte magnitude comparison for clock_skew; unknown operators behave as gte (validation rejects them upstream).</summary>
|
||||
private static bool CompareClockSkewThreshold(double magnitude, string? op, double thresholdSeconds)
|
||||
=> string.Equals(op, "gt", StringComparison.OrdinalIgnoreCase)
|
||||
? magnitude > thresholdSeconds
|
||||
: magnitude >= thresholdSeconds;
|
||||
|
||||
/// <summary>
|
||||
/// Generic event correlation: finds pairs of events (A before B) sharing
|
||||
/// the same value in a join field, with optional filters on each event
|
||||
|
||||
@@ -815,6 +815,11 @@ namespace AutopilotMonitor.Functions.Services
|
||||
["TimestampClamped"] = evt.TimestampClamped
|
||||
};
|
||||
|
||||
// P14: request-level device-clock send time; column stays unset for
|
||||
// events from agents that pre-date the X-Send-Time-Utc header.
|
||||
if (evt.SentAt.HasValue)
|
||||
entity["SentAt"] = EnsureUtc(evt.SentAt.Value);
|
||||
|
||||
if (evt.OriginalTimestamp.HasValue)
|
||||
entity["OriginalTimestamp"] = EnsureUtc(evt.OriginalTimestamp.Value);
|
||||
|
||||
@@ -912,6 +917,10 @@ namespace AutopilotMonitor.Functions.Services
|
||||
["TimestampClamped"] = evt.TimestampClamped
|
||||
};
|
||||
|
||||
// P14: see StoreEventAsync.
|
||||
if (evt.SentAt.HasValue)
|
||||
entity["SentAt"] = EnsureUtc(evt.SentAt.Value);
|
||||
|
||||
if (evt.OriginalTimestamp.HasValue)
|
||||
entity["OriginalTimestamp"] = EnsureUtc(evt.OriginalTimestamp.Value);
|
||||
|
||||
@@ -2418,17 +2427,20 @@ namespace AutopilotMonitor.Functions.Services
|
||||
/// are left untouched rather than being zeroed. Idempotent: no-ops when the row is
|
||||
/// already correct. PlatformScriptCount/RemediationScriptCount stay increment-only (their
|
||||
/// drift is bounded and they feed no enforcement heuristics; EventCount does).
|
||||
/// Returns the skew-scan samples collected during the authoritative count's partition
|
||||
/// scan (CmTraceSkewTripwire input), or null when the scan itself failed — the counter
|
||||
/// reconcile outcome does not affect the returned scan.
|
||||
/// </summary>
|
||||
public async Task ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
public async Task<SessionSkewScan?> ReconcileSessionCountersAsync(string tenantId, string sessionId)
|
||||
{
|
||||
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
|
||||
SecurityValidator.EnsureValidGuid(sessionId, nameof(sessionId));
|
||||
|
||||
var authoritative = await CountSessionEventRowsAsync(tenantId, sessionId);
|
||||
if (!authoritative.HasValue)
|
||||
return; // storage error — keep the incremental live values, do not zero them
|
||||
return null; // storage error — keep the incremental live values, do not zero them
|
||||
|
||||
var (totalEvents, rebootEvents) = authoritative.Value;
|
||||
var (totalEvents, rebootEvents, skewScan) = authoritative.Value;
|
||||
|
||||
const int maxRetries = 5;
|
||||
int retryCount = 0;
|
||||
@@ -2440,7 +2452,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
var tableClient = _tableServiceClient.GetTableClient(Constants.TableNames.Sessions);
|
||||
var entityResponse = await tableClient.GetEntityIfExistsAsync<TableEntity>(tenantId, sessionId);
|
||||
if (!entityResponse.HasValue)
|
||||
return;
|
||||
return skewScan;
|
||||
var entity = entityResponse.Value!;
|
||||
|
||||
// No-op when already correct — avoids a needless write + index sync on the
|
||||
@@ -2459,7 +2471,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
drifted = true;
|
||||
}
|
||||
if (!drifted)
|
||||
return;
|
||||
return skewScan;
|
||||
|
||||
var currentStartedAt = entity.GetDateTimeOffset("StartedAt")?.UtcDateTime ?? DateTime.MaxValue;
|
||||
|
||||
@@ -2468,7 +2480,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// Dual-write: keep SessionsIndex in sync (merge — no StartedAt shift here).
|
||||
await SyncSessionIndexAsync(tenantId, sessionId, entity, update, currentStartedAt, null);
|
||||
|
||||
return;
|
||||
return skewScan;
|
||||
}
|
||||
catch (Azure.RequestFailedException ex) when (ex.Status == 412)
|
||||
{
|
||||
@@ -2476,7 +2488,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
if (retryCount >= maxRetries)
|
||||
{
|
||||
_logger.LogWarning($"Failed to reconcile session counters for session {sessionId} after {maxRetries} retries due to ETag conflicts");
|
||||
return;
|
||||
return skewScan;
|
||||
}
|
||||
var baseDelay = 50 * (int)Math.Pow(2, retryCount - 1);
|
||||
await Task.Delay(baseDelay + Random.Shared.Next(0, baseDelay));
|
||||
@@ -2484,9 +2496,11 @@ namespace AutopilotMonitor.Functions.Services
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogError(ex, $"Failed to reconcile session counters for session {sessionId}");
|
||||
return;
|
||||
return skewScan;
|
||||
}
|
||||
}
|
||||
|
||||
return skewScan;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -3083,6 +3097,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
Data = DeserializeEventData(entity.GetString("DataJson")),
|
||||
RowKey = entity.RowKey,
|
||||
ReceivedAt = entity.GetDateTimeOffset("ReceivedAt")?.UtcDateTime,
|
||||
SentAt = entity.GetDateTimeOffset("SentAt")?.UtcDateTime,
|
||||
OriginalTimestamp = entity.GetDateTimeOffset("OriginalTimestamp")?.UtcDateTime,
|
||||
TimestampClamped = entity.GetBoolean("TimestampClamped") ?? false,
|
||||
// Codex follow-up #3 — forward-link columns (nullable for legacy rows).
|
||||
@@ -3287,9 +3302,10 @@ namespace AutopilotMonitor.Functions.Services
|
||||
/// and a unique RowKey per event, so the number of stored rows equals the true distinct
|
||||
/// count — making this an idempotent, retry-immune authoritative count (used to reconcile
|
||||
/// EventCount + RebootCount at the terminal transition). Single partition scan with a
|
||||
/// RowKey+EventType projection so both counts cost one query.
|
||||
/// slim projection so both counts cost one query. The CmTraceSkewTripwire's per-source
|
||||
/// timestamp-delta samples piggyback on the same enumeration (zero extra reads).
|
||||
/// </summary>
|
||||
private async Task<(int Total, int Reboots)?> CountSessionEventRowsAsync(string tenantId, string sessionId)
|
||||
private async Task<(int Total, int Reboots, SessionSkewScan Skew)?> CountSessionEventRowsAsync(string tenantId, string sessionId)
|
||||
{
|
||||
try
|
||||
{
|
||||
@@ -3297,17 +3313,38 @@ namespace AutopilotMonitor.Functions.Services
|
||||
var partitionKey = $"{tenantId}_{sessionId}";
|
||||
var query = tableClient.QueryAsync<TableEntity>(
|
||||
filter: $"PartitionKey eq '{partitionKey}'",
|
||||
select: new[] { "RowKey", "EventType" }
|
||||
select: new[] { "RowKey", "EventType", "Source", "ReceivedAt", BusinessTimestamp.OccurredUtcColumn, "TimestampClamped" }
|
||||
);
|
||||
|
||||
int total = 0, reboots = 0;
|
||||
var skew = new SessionSkewScan();
|
||||
var imeBatches = new HashSet<DateTime>();
|
||||
var otherBatches = new HashSet<DateTime>();
|
||||
const int maxSkewSamplesPerSide = 20_000;
|
||||
await foreach (var entity in query)
|
||||
{
|
||||
total++;
|
||||
if (entity.GetString("EventType") == Constants.EventTypes.SystemRebootDetected)
|
||||
reboots++;
|
||||
|
||||
// Skew sample. Clamped events carry a server-substituted OccurredUtc
|
||||
// (Δ ≈ 0) and would dilute the medians; legacy rows without ReceivedAt
|
||||
// have no server frame at all — both are skipped, never zero-filled.
|
||||
if (entity.GetBoolean("TimestampClamped") == true)
|
||||
continue;
|
||||
var receivedAt = entity.GetDateTimeOffset("ReceivedAt")?.UtcDateTime;
|
||||
var occurredAt = ResolveEventTimestampOrNull(entity);
|
||||
if (!receivedAt.HasValue || !occurredAt.HasValue)
|
||||
continue;
|
||||
var isIme = string.Equals(entity.GetString("Source"), "ImeLogTracker", StringComparison.OrdinalIgnoreCase);
|
||||
var side = isIme ? skew.ImeDeltaMinutes : skew.OtherDeltaMinutes;
|
||||
if (side.Count < maxSkewSamplesPerSide)
|
||||
side.Add((receivedAt.Value - occurredAt.Value).TotalMinutes);
|
||||
(isIme ? imeBatches : otherBatches).Add(receivedAt.Value);
|
||||
}
|
||||
return (total, reboots);
|
||||
skew.ImeDistinctBatchCount = imeBatches.Count;
|
||||
skew.OtherDistinctBatchCount = otherBatches.Count;
|
||||
return (total, reboots, skew);
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -3316,6 +3353,49 @@ namespace AutopilotMonitor.Functions.Services
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Bounded histogram of the <c>sourceOffsetOrigin</c> provenance values ("bias",
|
||||
/// "line-anchored", "reader-zone-fallback", retired "calibrated") over a session's
|
||||
/// IME-derived events. Only read on the CmTraceSkewTripwire suspicion path (≈ never),
|
||||
/// so the row cap bounds the worst case rather than tuning the common one. Fail-soft:
|
||||
/// storage errors return an empty map, which the caller treats as "not bias-dominated"
|
||||
/// — the tripwire fails open toward reporting.
|
||||
/// </summary>
|
||||
public async Task<Dictionary<string, int>> GetImeOffsetOriginHistogramAsync(string tenantId, string sessionId, int maxRows = 500)
|
||||
{
|
||||
SecurityValidator.EnsureValidGuid(tenantId, nameof(tenantId));
|
||||
SecurityValidator.EnsureValidGuid(sessionId, nameof(sessionId));
|
||||
|
||||
var histogram = new Dictionary<string, int>(StringComparer.OrdinalIgnoreCase);
|
||||
try
|
||||
{
|
||||
var tableClient = _tableServiceClient.GetTableClient(Constants.TableNames.Events);
|
||||
var partitionKey = $"{tenantId}_{sessionId}";
|
||||
var query = tableClient.QueryAsync<TableEntity>(
|
||||
filter: $"PartitionKey eq '{partitionKey}' and Source eq 'ImeLogTracker'",
|
||||
select: new[] { "RowKey", "DataJson" });
|
||||
|
||||
int rows = 0;
|
||||
await foreach (var entity in query)
|
||||
{
|
||||
if (++rows > maxRows)
|
||||
break;
|
||||
var data = DeserializeEventData(entity.GetString("DataJson"));
|
||||
if (data != null && data.TryGetValue("sourceOffsetOrigin", out var origin))
|
||||
{
|
||||
var key = origin?.ToString();
|
||||
if (!string.IsNullOrEmpty(key))
|
||||
histogram[key!] = histogram.TryGetValue(key!, out var count) ? count + 1 : 1;
|
||||
}
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.LogDebug(ex, $"Could not read IME offset-origin histogram for session {sessionId}");
|
||||
}
|
||||
return histogram;
|
||||
}
|
||||
|
||||
#region IME Version History
|
||||
|
||||
/// <summary>
|
||||
|
||||
@@ -361,6 +361,41 @@ describe('analyze semantic lint', () => {
|
||||
expect(errors(validateRuleDraft(corr).findings).some((m) => m.includes('joinField'))).toBe(true);
|
||||
});
|
||||
|
||||
it('clock_skew: missing/unknown skewMetric, bad operator, bad threshold are errors; {{skewSummary}} resolves', () => {
|
||||
const missingMetric = validAnalyze();
|
||||
(missingMetric.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', operator: 'gte', value: '300', required: true,
|
||||
};
|
||||
expect(errors(validateRuleDraft(missingMetric).findings).some((m) => m.includes('skewMetric'))).toBe(true);
|
||||
|
||||
const badOperator = validAnalyze();
|
||||
(badOperator.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'lt', value: '300', required: true,
|
||||
};
|
||||
expect(errors(validateRuleDraft(badOperator).findings).some((m) => m.includes('gt/gte'))).toBe(true);
|
||||
|
||||
const badThreshold = validAnalyze();
|
||||
(badThreshold.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'gte', value: '-5', required: true,
|
||||
};
|
||||
expect(errors(validateRuleDraft(badThreshold).findings).some((m) => m.includes('positive numeric'))).toBe(true);
|
||||
|
||||
const noisy = validAnalyze();
|
||||
(noisy.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'gte', value: '30', required: true,
|
||||
};
|
||||
expect(warnings(validateRuleDraft(noisy).findings).some((m) => m.includes('upload-latency noise'))).toBe(true);
|
||||
|
||||
const good = validAnalyze();
|
||||
(good.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
signal: 'clock_jump', source: 'clock_skew', skewMetric: 'clock_jump', operator: 'gte', value: '300', required: true,
|
||||
};
|
||||
good.explanation = 'This device {{skewSummary}}.';
|
||||
const r = validateRuleDraft(good);
|
||||
expect(errors(r.findings)).toEqual([]);
|
||||
expect(warnings(r.findings).filter((m) => m.includes('{{'))).toEqual([]);
|
||||
});
|
||||
|
||||
it('invalid regex is an error; unanchored not_regex warns', () => {
|
||||
const bad = validAnalyze();
|
||||
(bad.conditions as Array<Record<string, unknown>>)[0] = {
|
||||
|
||||
@@ -165,6 +165,13 @@ export const RULE_AUTHORING_GUIDE = {
|
||||
'Join two event types over a shared field: eventType + correlateEventType + joinField, ' +
|
||||
'optional timeWindowSeconds, optional eventAFilterField/-Operator/-Value to pre-filter the ' +
|
||||
'first event, optional dataField+operator+value tested on the correlated pair.',
|
||||
clock_skew:
|
||||
'Device-clock check against the server receive frame: skewMetric=clock_jump (persistent ' +
|
||||
'mid-session step) or sustained_offset (whole session off by >= value). value = threshold ' +
|
||||
'seconds, operator gt/gte on the magnitude. No eventType/dataField; IME-log-derived events ' +
|
||||
'are excluded from the measurement. Batches from agents that send X-Send-Time-Utc are ' +
|
||||
'measured directly from the send time (spool-immune; evidence sentAtBatchCount counts them), ' +
|
||||
'older agents fall back to per-event timestamp medians.',
|
||||
},
|
||||
caseSensitivity:
|
||||
'source values are matched CASE-SENSITIVELY by the engine — write them exactly as listed ' +
|
||||
@@ -270,7 +277,7 @@ export const RULE_AUTHORING_GUIDE = {
|
||||
gatherOutputSeverities: ['Info', 'Warning', 'Error', 'Critical'],
|
||||
gatherCollectorTypes: ['registry', 'eventlog', 'wmi', 'file', 'json', 'xml', 'command_allowlisted', 'logparser'],
|
||||
gatherTriggers: ['startup', 'phase_change', 'phase_exit', 'interval', 'on_event'],
|
||||
analyzeConditionSources: ['event_type', 'event_data', 'event_data_array', 'phase_duration', 'event_count', 'app_install_duration', 'event_correlation'],
|
||||
analyzeConditionSources: ['event_type', 'event_data', 'event_data_array', 'phase_duration', 'event_count', 'app_install_duration', 'event_correlation', 'clock_skew'],
|
||||
analyzeEvaluateOnTriggers: ['enrollment_end', 'whiteglove_sealed', 'on_event:<eventType>'],
|
||||
},
|
||||
|
||||
|
||||
@@ -439,7 +439,16 @@ export const ANALYZE_RULE_SCHEMA: Record<string, unknown> = {
|
||||
"phase_duration",
|
||||
"event_count",
|
||||
"app_install_duration",
|
||||
"event_correlation"
|
||||
"event_correlation",
|
||||
"clock_skew"
|
||||
]
|
||||
},
|
||||
"skewMetric": {
|
||||
"type": "string",
|
||||
"description": "For clock_skew only: which device-clock metric to evaluate. clock_jump = persistent step in the device's clock frame mid-session; sustained_offset = whole session ran on a clock off by at least the threshold. value is the threshold in seconds; operator is limited to gt/gte on the magnitude. IME-log-derived events are excluded from the measurement.",
|
||||
"enum": [
|
||||
"clock_jump",
|
||||
"sustained_offset"
|
||||
]
|
||||
},
|
||||
"eventType": {
|
||||
|
||||
@@ -238,6 +238,7 @@ interface DraftCondition {
|
||||
required?: boolean;
|
||||
correlateEventType?: string;
|
||||
joinField?: string;
|
||||
skewMetric?: string;
|
||||
}
|
||||
|
||||
function checkEventTypeKnown(eventType: string | undefined, where: string): ValidationFinding[] {
|
||||
@@ -293,6 +294,24 @@ function lintAnalyzeRule(rule: Record<string, unknown>): ValidationFinding[] {
|
||||
findings.push(...checkEventTypeKnown(c.correlateEventType, `${label}.correlateEventType`));
|
||||
}
|
||||
|
||||
if (c.source === 'clock_skew') {
|
||||
if (c.skewMetric !== 'clock_jump' && c.skewMetric !== 'sustained_offset') {
|
||||
findings.push({ level: 'error', message: `${label}: clock_skew requires skewMetric ("clock_jump" or "sustained_offset").` });
|
||||
}
|
||||
if (c.operator !== 'gt' && c.operator !== 'gte') {
|
||||
findings.push({ level: 'error', message: `${label}: clock_skew supports only gt/gte — the threshold is compared against the skew MAGNITUDE.` });
|
||||
}
|
||||
const threshold = Number(c.value);
|
||||
if (!c.value || !Number.isFinite(threshold) || threshold <= 0) {
|
||||
findings.push({ level: 'error', message: `${label}: clock_skew requires a positive numeric value (threshold in seconds).` });
|
||||
} else if (threshold < 60) {
|
||||
findings.push({ level: 'warning', message: `${label}: clock_skew threshold below 60 s sits inside normal upload-latency noise — expect false positives.` });
|
||||
}
|
||||
if (c.eventType || c.dataField) {
|
||||
findings.push({ level: 'warning', message: `${label}: clock_skew ignores eventType/dataField — it measures Timestamp against ReceivedAt across the whole session.` });
|
||||
}
|
||||
}
|
||||
|
||||
findings.push(...checkEventTypeKnown(c.eventType, label));
|
||||
|
||||
if ((c.operator === 'regex' || c.operator === 'not_regex') && c.value) {
|
||||
@@ -364,6 +383,9 @@ function lintAnalyzeRule(rule: Record<string, unknown>): ValidationFinding[] {
|
||||
// event_data_array evidence carries the matched element under field=itemField,
|
||||
// so {{itemField}} interpolates at runtime (see EvaluateEventDataArrayCondition).
|
||||
if (c.itemField) resolvable.add(c.itemField);
|
||||
// clock_skew evidence carries a preformatted summary under field=skewSummary,
|
||||
// so {{skewSummary}} interpolates at runtime (see EvaluateClockSkewCondition).
|
||||
if (c.source === 'clock_skew') resolvable.add('skewSummary');
|
||||
}
|
||||
for (const token of extractTokens(rule)) {
|
||||
if (!resolvable.has(token)) {
|
||||
|
||||
@@ -411,7 +411,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated:
|
||||
severity: z.enum(['Info', 'Warning', 'Error', 'Critical']).optional(),
|
||||
source: z.string().optional().describe('Filter by event source/app name (e.g. "MicrosoftTeams")'),
|
||||
fields: z.string().optional()
|
||||
.describe('Comma-separated lean projection (e.g. "eventType,severity,timestamp,message"). Drops the heavy "data" payload unless "data" is listed. Valid keys: eventId, sessionId, tenantId, eventType, severity, source, phase, phaseName, timestamp, receivedAt, message, sequence, rowKey, originalTimestamp, timestampClamped, causedByTransitionStepIndex, causedBySignalOrdinal, data.'),
|
||||
.describe('Comma-separated lean projection (e.g. "eventType,severity,timestamp,message"). Drops the heavy "data" payload unless "data" is listed. Valid keys: eventId, sessionId, tenantId, eventType, severity, source, phase, phaseName, timestamp, receivedAt, sentAt, message, sequence, rowKey, originalTimestamp, timestampClamped, causedByTransitionStepIndex, causedBySignalOrdinal, data.'),
|
||||
pageSize: z.coerce.number().int().min(1).max(1000).optional().default(200)
|
||||
.describe('Page size (1-1000, default 200). The endpoint returns this many events per call; follow nextLink to fetch more.'),
|
||||
continuation: z.string().optional()
|
||||
|
||||
@@ -109,8 +109,17 @@ namespace AutopilotMonitor.Shared.DataAccess
|
||||
/// Reconciles the stored EventCount and RebootCount with the authoritative row counts
|
||||
/// from the Events table (rows dedupe on deterministic RowKeys; the read-modify-write
|
||||
/// increments do not). Call as the last counter write on terminal ingest batches.
|
||||
/// Returns the per-source timestamp-delta samples collected during the same partition
|
||||
/// scan (input to the CMTrace time-skew tripwire), or null when the scan failed.
|
||||
/// </summary>
|
||||
Task ReconcileSessionCountersAsync(string tenantId, string sessionId);
|
||||
Task<SessionSkewScan?> ReconcileSessionCountersAsync(string tenantId, string sessionId);
|
||||
|
||||
/// <summary>
|
||||
/// Bounded histogram of the sourceOffsetOrigin provenance values over a session's
|
||||
/// IME-derived events ("bias" / "line-anchored" / "reader-zone-fallback"). Read only
|
||||
/// on the CMTrace skew tripwire's suspicion path; fail-soft (empty map on error).
|
||||
/// </summary>
|
||||
Task<Dictionary<string, int>> GetImeOffsetOriginHistogramAsync(string tenantId, string sessionId, int maxRows = 500);
|
||||
Task UpdateSessionDiagnosticsBlobAsync(
|
||||
string tenantId, string sessionId, string blobName, string? destination = null);
|
||||
Task SetSessionPreProvisionedAsync(string tenantId, string sessionId, bool isPreProvisioned,
|
||||
|
||||
@@ -38,6 +38,16 @@ namespace AutopilotMonitor.Shared.Models
|
||||
/// </summary>
|
||||
public DateTime? ReceivedAt { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Device-clock UTC timestamp of the moment the agent SENT the upload batch carrying
|
||||
/// this event (X-Send-Time-Utc request header, one value per ingest request — never
|
||||
/// set by the agent per event). Same clock frame as <see cref="Timestamp"/>, so
|
||||
/// SentAt − Timestamp is pure spool delay and ReceivedAt − SentAt is network latency
|
||||
/// plus device-vs-server clock offset — the two are indistinguishable without this
|
||||
/// field. Null for events from agents that pre-date the header.
|
||||
/// </summary>
|
||||
public DateTime? SentAt { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Type of event (e.g., "phase_transition", "app_install_start", "error")
|
||||
/// </summary>
|
||||
|
||||
@@ -222,11 +222,19 @@ namespace AutopilotMonitor.Shared.Models
|
||||
|
||||
/// <summary>
|
||||
/// Source of the signal: "event_type", "event_data", "event_data_array", "phase_duration",
|
||||
/// "event_count", "app_install_duration", "event_correlation".
|
||||
/// "event_count", "app_install_duration", "event_correlation", "clock_skew".
|
||||
/// Must stay in sync with DryRunAnalyzeRuleFunction.KnownSources and the RuleEngine switch.
|
||||
/// </summary>
|
||||
public string Source { get; set; } = default!;
|
||||
|
||||
/// <summary>
|
||||
/// For "clock_skew" only: which device-clock metric to evaluate — "clock_jump"
|
||||
/// (persistent step in the device's clock frame mid-session) or "sustained_offset"
|
||||
/// (whole session ran on a clock off by ≥ Value). Value is the threshold in seconds;
|
||||
/// Operator is limited to gt/gte on the magnitude.
|
||||
/// </summary>
|
||||
public string? SkewMetric { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Event type to match on.
|
||||
/// For "event_type"/"event_data": the event type to match.
|
||||
|
||||
@@ -61,6 +61,14 @@ namespace AutopilotMonitor.Shared.Models
|
||||
public List<EnrollmentEvent> Events { get; set; }
|
||||
public bool IsCompressed { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Device-clock send time of the carrying upload request (X-Send-Time-Utc header),
|
||||
/// parsed by the ingest function. One value per request; stamped onto every event
|
||||
/// in <c>EventIngestProcessor.StampServerFields</c>. Null when the agent pre-dates
|
||||
/// the header or sent an unparseable value.
|
||||
/// </summary>
|
||||
public DateTime? SentAt { get; set; }
|
||||
|
||||
public IngestEventsRequest()
|
||||
{
|
||||
Events = new List<EnrollmentEvent>();
|
||||
|
||||
@@ -0,0 +1,31 @@
|
||||
using System.Collections.Generic;
|
||||
|
||||
namespace AutopilotMonitor.Shared.Models
|
||||
{
|
||||
/// <summary>
|
||||
/// Per-session timestamp-delta samples collected during the terminal counter reconcile's
|
||||
/// single event-partition scan (zero extra storage reads). Samples are split by producing
|
||||
/// source: CMTrace-derived events (Source == "ImeLogTracker") versus everything else.
|
||||
/// Consumed by the CMTrace time-skew tripwire, which compares the two sides' median
|
||||
/// (ReceivedAt − OccurredUtc) deltas — shared upload/spool latency is common-mode and
|
||||
/// cancels in that difference; a timezone mis-conversion shifts only the IME side.
|
||||
/// </summary>
|
||||
public class SessionSkewScan
|
||||
{
|
||||
/// <summary>(ReceivedAt − OccurredUtc) in minutes for events with Source == "ImeLogTracker".</summary>
|
||||
public List<double> ImeDeltaMinutes { get; } = new List<double>();
|
||||
|
||||
/// <summary>(ReceivedAt − OccurredUtc) in minutes for all other event sources.</summary>
|
||||
public List<double> OtherDeltaMinutes { get; } = new List<double>();
|
||||
|
||||
/// <summary>
|
||||
/// Distinct ReceivedAt values seen on the IME side. ReceivedAt is stamped once per
|
||||
/// upload BATCH, not per event — a median over one or two batches is a
|
||||
/// batch-composition artifact, not a session property.
|
||||
/// </summary>
|
||||
public int ImeDistinctBatchCount { get; set; }
|
||||
|
||||
/// <summary>Distinct ReceivedAt values seen on the non-IME side.</summary>
|
||||
public int OtherDistinctBatchCount { get; set; }
|
||||
}
|
||||
}
|
||||
@@ -151,6 +151,12 @@ const OPS_EVENT_TYPES: Record<string, string[]> = {
|
||||
// build). Emitted by ReportAgentErrorFunction (RecordAgentBinaryIntegrityMismatchAsync).
|
||||
// Dual-register per memory feedback_ops_event_types_dual_register.
|
||||
"AgentBinaryIntegrityMismatch",
|
||||
// CMTrace time-skew regression tripwire: a terminal session's IME-derived event
|
||||
// timestamps diverged from its other events by a clean 15-minute-grid multiple — the
|
||||
// per-line self-anchoring missed a case. Goal state: never fires. Emitted by
|
||||
// EventIngestProcessor (RecordCmTraceTimeSkewRegressionAsync). Dual-register per memory
|
||||
// feedback_ops_event_types_dual_register.
|
||||
"CmTraceTimeSkewRegression",
|
||||
],
|
||||
Platform: [
|
||||
// Azure Monitor alerts relayed through POST ops/alert-webhook (Common Alert Schema →
|
||||
|
||||
@@ -382,6 +382,7 @@ export default function AnalyzeRuleCard({
|
||||
<span className="text-gray-600 font-medium">Source:</span> {condition.source}
|
||||
{condition.eventType && (<span> | <span className="text-gray-600 font-medium">Event Type:</span> {condition.eventType}</span>)}
|
||||
{condition.dataField && (<span> | <span className="text-gray-600 font-medium">Field:</span> <code className="bg-gray-200 px-1 rounded text-xs">{condition.dataField}</code></span>)}
|
||||
{condition.skewMetric && (<span> | <span className="text-gray-600 font-medium">Skew Metric:</span> <code className="bg-gray-200 px-1 rounded text-xs">{condition.skewMetric}</code></span>)}
|
||||
</p>
|
||||
<p>
|
||||
<span className="text-gray-600 font-medium">Operator:</span> <code className="bg-gray-200 px-1 rounded text-xs">{condition.operator}</code>{" "}
|
||||
|
||||
+20
-2
@@ -2,7 +2,7 @@
|
||||
|
||||
import {
|
||||
RuleForm, RuleCondition, RulePrecondition,
|
||||
CATEGORIES, SEVERITIES, TRIGGERS, OPERATORS, SOURCES, PRECONDITION_OPERATORS,
|
||||
CATEGORIES, SEVERITIES, TRIGGERS, OPERATORS, SOURCES, PRECONDITION_OPERATORS, SKEW_METRICS,
|
||||
EMPTY_CONDITION, EMPTY_FACTOR, EMPTY_PRECONDITION,
|
||||
validateOnEventTypes,
|
||||
} from "../types";
|
||||
@@ -184,6 +184,7 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
{form.conditions.map((cond, idx) => {
|
||||
const isCorrelation = cond.source === "event_correlation";
|
||||
const isArray = cond.source === "event_data_array";
|
||||
const isClockSkew = cond.source === "clock_skew";
|
||||
const updateCond = (patch: Partial<RuleCondition>) => {
|
||||
const c = [...form.conditions];
|
||||
c[idx] = { ...c[idx], ...patch };
|
||||
@@ -196,6 +197,7 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
Condition {idx + 1}
|
||||
{isCorrelation && <span className="ml-2 px-1.5 py-0.5 bg-indigo-100 text-indigo-700 rounded text-xs">event_correlation</span>}
|
||||
{isArray && <span className="ml-2 px-1.5 py-0.5 bg-teal-100 text-teal-700 rounded text-xs">event_data_array</span>}
|
||||
{isClockSkew && <span className="ml-2 px-1.5 py-0.5 bg-amber-100 text-amber-700 rounded text-xs">clock_skew</span>}
|
||||
</span>
|
||||
{form.conditions.length > 1 && (
|
||||
<button type="button" onClick={() => setForm({ ...form, conditions: form.conditions.filter((_, i) => i !== idx) })} className="text-xs text-red-500 hover:text-red-700">Remove</button>
|
||||
@@ -205,7 +207,7 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
{/* Row 1: Signal, Source, Event Type A */}
|
||||
<div className="grid grid-cols-1 sm:grid-cols-3 gap-2">
|
||||
<input type="text" value={cond.signal} onChange={(e) => updateCond({ signal: e.target.value })} placeholder="Signal name" autoComplete="off" className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 placeholder-gray-400 focus:outline-none focus:ring-1 focus:ring-green-500" />
|
||||
<select value={cond.source} onChange={(e) => updateCond({ source: e.target.value })} className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 bg-white focus:outline-none focus:ring-1 focus:ring-green-500">
|
||||
<select value={cond.source} onChange={(e) => updateCond({ source: e.target.value, ...(e.target.value === "clock_skew" && !cond.skewMetric ? { skewMetric: "clock_jump" } : {}) })} className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 bg-white focus:outline-none focus:ring-1 focus:ring-green-500">
|
||||
{SOURCES.map((s) => (<option key={s} value={s}>{s}</option>))}
|
||||
</select>
|
||||
<input type="text" value={cond.eventType} onChange={(e) => updateCond({ eventType: e.target.value })} placeholder={isCorrelation ? "Event A type (e.g. app_install_completed)" : "Event type"} autoComplete="off" className="px-3 py-1.5 border border-gray-300 rounded text-sm text-gray-900 placeholder-gray-400 focus:outline-none focus:ring-1 focus:ring-green-500" />
|
||||
@@ -259,6 +261,22 @@ export default function AnalyzeRuleFormFields({ form, setForm, showRuleId, exist
|
||||
</div>
|
||||
)}
|
||||
|
||||
{/* clock_skew extra fields */}
|
||||
{isClockSkew && (
|
||||
<div className="pt-2 border-t border-amber-200 space-y-2">
|
||||
<p className="text-xs font-medium text-amber-700">Clock skew settings</p>
|
||||
<div>
|
||||
<label className="block text-xs text-gray-500 mb-1">Skew metric <span className="text-red-500">*</span></label>
|
||||
<select value={cond.skewMetric ?? "clock_jump"} onChange={(e) => updateCond({ skewMetric: e.target.value })} className="w-full px-3 py-1.5 border border-amber-300 rounded text-sm text-gray-900 bg-white focus:outline-none focus:ring-1 focus:ring-amber-500">
|
||||
{SKEW_METRICS.map((m) => (<option key={m} value={m}>{m}</option>))}
|
||||
</select>
|
||||
</div>
|
||||
<p className="text-xs text-gray-500">
|
||||
<strong>Value</strong> is the threshold in seconds; operator is limited to <code className="bg-gray-100 px-1 rounded">gt</code>/<code className="bg-gray-100 px-1 rounded">gte</code> on the skew magnitude. Event type and data field are ignored — the metric measures each event's timestamp against the server receive time across the whole session (IME-log-derived events excluded). <code className="bg-gray-100 px-1 rounded">clock_jump</code> = persistent mid-session step; <code className="bg-gray-100 px-1 rounded">sustained_offset</code> = whole session off by at least the threshold.
|
||||
</p>
|
||||
</div>
|
||||
)}
|
||||
|
||||
{/* event_data_array extra field */}
|
||||
{isArray && (
|
||||
<div className="pt-2 border-t border-teal-200 space-y-2">
|
||||
|
||||
@@ -37,6 +37,9 @@ export interface RuleCondition {
|
||||
eventAFilterField?: string;
|
||||
eventAFilterOperator?: string;
|
||||
eventAFilterValue?: string;
|
||||
// clock_skew: which device-clock metric to evaluate ("clock_jump" | "sustained_offset");
|
||||
// value is the threshold in seconds, operator is limited to gt/gte on the magnitude
|
||||
skewMetric?: string;
|
||||
}
|
||||
|
||||
export interface RulePrecondition {
|
||||
@@ -126,7 +129,8 @@ export const CATEGORIES = ["network", "identity", "apps", "device", "esp", "enro
|
||||
export const SEVERITIES = ["info", "warning", "high", "critical"] as const;
|
||||
export const TRIGGERS = ["single", "correlation"] as const;
|
||||
export const OPERATORS = ["equals", "not_equals", "contains", "not_contains", "regex", "not_regex", "gt", "lt", "gte", "lte", "exists", "not_exists", "count_gte", "count_per_group_gte", "in", "not_in"] as const;
|
||||
export const SOURCES = ["event_type", "event_data", "event_data_array", "phase_duration", "app_install_duration", "event_count", "event_correlation"] as const;
|
||||
export const SOURCES = ["event_type", "event_data", "event_data_array", "phase_duration", "app_install_duration", "event_count", "event_correlation", "clock_skew"] as const;
|
||||
export const SKEW_METRICS = ["clock_jump", "sustained_offset"] as const;
|
||||
export const PRECONDITION_OPERATORS = ["equals", "not_equals", "contains", "not_contains", "regex", "not_regex", "gt", "lt", "gte", "lte", "exists", "not_exists", "in", "not_in"] as const;
|
||||
|
||||
export const SEVERITY_COLORS: Record<string, { bg: string; text: string; border: string; dot: string }> = {
|
||||
@@ -168,6 +172,9 @@ export const EMPTY_CONDITION: RuleCondition = {
|
||||
eventAFilterField: "",
|
||||
eventAFilterOperator: "equals",
|
||||
eventAFilterValue: "",
|
||||
// skewMetric deliberately absent: it is an enum field ("clock_jump" | "sustained_offset")
|
||||
// and an empty string would violate the schema — the source select defaults it when
|
||||
// switching a condition to clock_skew.
|
||||
};
|
||||
|
||||
export const EMPTY_FACTOR: ConfidenceFactor = {
|
||||
|
||||
@@ -4,6 +4,8 @@ import { useState, useMemo } from "react";
|
||||
import { EnrollmentEvent, Session } from "@/types";
|
||||
import { normalizeEventDataForDisplay, shortenBuildHashInMessage } from "../utils/eventHelpers";
|
||||
import { getEnrichedOrLookup, formatErrorCode, type ErrorCodeEntry } from "@/utils/errorCodeMap";
|
||||
import { readTimeProvenance, classifyTimeJump } from "@/lib/timeProvenance";
|
||||
import { formatDuration, formatUtcOffset } from "@/lib/formatting";
|
||||
|
||||
interface EventTimelineProps {
|
||||
filteredEvents: EnrollmentEvent[];
|
||||
@@ -184,7 +186,7 @@ export default function EventTimeline({
|
||||
<RawEventRow
|
||||
key={ev.eventId || `${ev.sessionId}-${ev.sequence}`}
|
||||
event={ev}
|
||||
prevDisplayTime={i > 0 ? getDisplayTime(sortedBySequence[i - 1]) : null}
|
||||
prevEvent={i > 0 ? sortedBySequence[i - 1] : null}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -350,7 +352,7 @@ function PhaseSection({
|
||||
key={event.eventId || `${event.sessionId}-${event.sequence}`}
|
||||
event={event}
|
||||
showScriptOutput={showScriptOutput}
|
||||
prevDisplayTime={i > 0 ? getDisplayTime(events[i - 1]) : null}
|
||||
prevEvent={i > 0 ? events[i - 1] : null}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -402,11 +404,61 @@ function GapBadge({ prevTime, eventTime }: { prevTime: Date | null; eventTime: D
|
||||
);
|
||||
}
|
||||
|
||||
function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: EnrollmentEvent; showScriptOutput?: boolean; prevDisplayTime?: Date | null }) {
|
||||
// A displayed time stepping BACKWARDS within the sequence order is information, not a
|
||||
// rendering bug (P13): rows are ordered by the clock-immune sequence counter, while the
|
||||
// displayed time is corrected UTC — a backdated log line or an era-mixed log makes it
|
||||
// step back. Shown on the row AFTER the jump (GapBadge convention) and only at ≥5 min
|
||||
// (BACKWARD_JUMP_THRESHOLD_MS), so normal interleaved-writer jitter (≤2 min by the
|
||||
// agent's grid tolerance) never renders a badge. Known causes get the informational sky
|
||||
// tier; an unexplained backwards step gets amber.
|
||||
const TIME_JUMP_ORDER_NOTE = "Events are shown in true write order (sequence).";
|
||||
|
||||
function TimeJumpBadge({ prevEvent, event }: { prevEvent?: EnrollmentEvent | null; event: EnrollmentEvent }) {
|
||||
if (!prevEvent) return null;
|
||||
const jump = classifyTimeJump(
|
||||
{ displayTime: getDisplayTime(prevEvent), provenance: readTimeProvenance(prevEvent.data) },
|
||||
{ displayTime: getDisplayTime(event), provenance: readTimeProvenance(event.data) },
|
||||
);
|
||||
if (!jump) return null;
|
||||
|
||||
const label = jump.deltaMs >= 48 * 60 * 60 * 1000
|
||||
? `−${Math.round(jump.deltaMs / (24 * 60 * 60 * 1000))}d`
|
||||
: jump.deltaMs >= 60 * 60 * 1000
|
||||
? `−${Math.round(jump.deltaMs / (60 * 60 * 1000))}h`
|
||||
: `−${Math.round(jump.deltaMs / (60 * 1000))}m`;
|
||||
const human = formatDuration(jump.deltaMs / 1000);
|
||||
const times = `(${getDisplayTime(prevEvent).toLocaleTimeString()} → ${getDisplayTime(event).toLocaleTimeString()})`;
|
||||
|
||||
const title =
|
||||
jump.cause === "era-offset"
|
||||
? `Time moved backwards by ${human} vs the previous event ${times}. The two log lines were corrected with different UTC offsets (era-mixed log) — the jump reflects the offset change, not reordering. ${TIME_JUMP_ORDER_NOTE}`
|
||||
: jump.cause === "derived-timestamp"
|
||||
? `Backdated log line: written ${human} before the previous event's displayed time ${times}. Its own timestamp was unusable, so the agent's clock time is shown. ${TIME_JUMP_ORDER_NOTE}`
|
||||
: jump.cause === "rejected-source"
|
||||
? `Time moved backwards by ${human} vs the previous event ${times}. The line's own timestamp was rejected by the staleness clamp; the agent's clock time is shown instead. ${TIME_JUMP_ORDER_NOTE}`
|
||||
: `Time moved backwards by ${human} vs the previous event ${times}. ${TIME_JUMP_ORDER_NOTE} Displayed times are corrected UTC and can step backwards when the source log mixes clock eras.`;
|
||||
|
||||
const color = jump.cause ? "bg-sky-100 text-sky-800" : "bg-amber-100 text-amber-800";
|
||||
return (
|
||||
<span className={`px-1.5 py-0.5 rounded text-xs font-medium whitespace-nowrap flex-shrink-0 ${color}`} title={title}>
|
||||
↩ {label}
|
||||
</span>
|
||||
);
|
||||
}
|
||||
|
||||
const CLAMPED_TOOLTIP_PREFIX =
|
||||
"The device-reported timestamp was outside the accepted range and was clamped to server receive time on ingest.";
|
||||
|
||||
function EventRow({ event, showScriptOutput, prevEvent }: { event: EnrollmentEvent; showScriptOutput?: boolean; prevEvent?: EnrollmentEvent | null }) {
|
||||
const prevDisplayTime = prevEvent ? getDisplayTime(prevEvent) : null;
|
||||
const [showDetails, setShowDetails] = useState(false);
|
||||
const [showRaw, setShowRaw] = useState(false);
|
||||
const [copied, setCopied] = useState(false);
|
||||
const [copiedDetail, setCopiedDetail] = useState(false);
|
||||
// Collapsed by default: the same values sit in the raw JSON dump — this labeled view is
|
||||
// an opt-in dive, it must not inflate the metadata block (user decision 2026-08-20).
|
||||
const [showProvenance, setShowProvenance] = useState(false);
|
||||
const timeProvenance = useMemo(() => readTimeProvenance(event.data), [event.data]);
|
||||
const rawDetailData = useMemo(() => normalizeEventDataForDisplay(event.data), [event.data]);
|
||||
|
||||
// Filter stdout from script events when showScriptOutput is false.
|
||||
@@ -489,6 +541,7 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
)}
|
||||
</span>
|
||||
<GapBadge prevTime={prevDisplayTime ?? null} eventTime={recordedAt ?? new Date(event.timestamp)} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} />
|
||||
<SeverityBadge severity={event.severity} />
|
||||
{isBackfilled && (
|
||||
<span
|
||||
@@ -498,6 +551,14 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
⟲ Backfilled
|
||||
</span>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<span
|
||||
className="px-2 py-0.5 rounded text-xs font-medium bg-amber-100 text-amber-800"
|
||||
title={`${CLAMPED_TOOLTIP_PREFIX}${event.originalTimestamp ? ` Original device timestamp: ${event.originalTimestamp}.` : ""}`}
|
||||
>
|
||||
⧖ Clamped
|
||||
</span>
|
||||
)}
|
||||
<span className="text-sm font-medium text-gray-900">{event.eventType}</span>
|
||||
</div>
|
||||
<p className="mt-1 text-sm text-gray-600" title={event.message || undefined}>{shortenBuildHashInMessage(event.message)}</p>
|
||||
@@ -680,8 +741,23 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
)}
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Created</span>
|
||||
<span className="font-mono">{event.timestamp}</span>
|
||||
<span className="font-mono">
|
||||
{event.timestamp}
|
||||
{(timeProvenance || event.timestampClamped) && (
|
||||
<button
|
||||
type="button"
|
||||
onClick={() => setShowProvenance(!showProvenance)}
|
||||
className="ml-2 font-sans text-gray-400 hover:text-green-600"
|
||||
title="How this timestamp was produced (offset, origin, raw log time)"
|
||||
>
|
||||
{showProvenance ? "▾ time provenance" : "▸ time provenance"}
|
||||
</button>
|
||||
)}
|
||||
</span>
|
||||
</div>
|
||||
{showProvenance && (timeProvenance || event.timestampClamped) && (
|
||||
<TimeProvenanceRows event={event} provenance={timeProvenance} />
|
||||
)}
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Received</span>
|
||||
<span className="font-mono">
|
||||
@@ -817,11 +893,108 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
);
|
||||
}
|
||||
|
||||
function RawEventRow({ event, prevDisplayTime }: { event: EnrollmentEvent; prevDisplayTime?: Date | null }) {
|
||||
// Origin chip styling/wording for the sourceOffsetOrigin provenance value. Unknown
|
||||
// values render verbatim in gray so a future agent origin never breaks the UI.
|
||||
const ORIGIN_CHIP: Record<string, { className: string; title: string }> = {
|
||||
"line-anchored": {
|
||||
className: "bg-sky-100 text-sky-800",
|
||||
title: "Offset anchored to a UTC reference line near this log line — the most precise source.",
|
||||
},
|
||||
bias: {
|
||||
className: "bg-slate-200 text-slate-600",
|
||||
title: "Offset taken from the log line's own timezone bias — declared by the writer, authoritative.",
|
||||
},
|
||||
"reader-zone-fallback": {
|
||||
className: "bg-amber-100 text-amber-800",
|
||||
title: "No anchor available — the reader's timezone was assumed for the whole file. Times are internally consistent but the absolute frame may be wrong.",
|
||||
},
|
||||
calibrated: {
|
||||
className: "bg-gray-100 text-gray-500",
|
||||
title: "Legacy origin emitted by older agents (retired).",
|
||||
},
|
||||
};
|
||||
|
||||
// The raw CMTrace time-resolution values (P13): how this event's UTC timestamp was
|
||||
// produced. Collapsed behind the "time provenance" toggle on the Created row — the same
|
||||
// values sit in the raw JSON dump, so this labeled view is an opt-in dive that must not
|
||||
// inflate the default metadata block. Per-row badges stay reserved for jump/clamp cases.
|
||||
function TimeProvenanceRows({ event, provenance }: { event: EnrollmentEvent; provenance: ReturnType<typeof readTimeProvenance> }) {
|
||||
const origin = provenance?.sourceOffsetOrigin;
|
||||
const originChip = origin ? ORIGIN_CHIP[origin] ?? { className: "bg-gray-100 text-gray-500", title: origin } : null;
|
||||
|
||||
return (
|
||||
<div className="ml-2 pl-2 border-l-2 border-gray-200">
|
||||
{provenance?.sourceLocalTs && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Local time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.sourceLocalTs}
|
||||
<span className="text-gray-400 ml-1 font-sans">(as written in the log)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.sourceOffsetMinutes !== null && provenance?.sourceOffsetMinutes !== undefined && (
|
||||
<div className="flex mt-0.5 items-center">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">UTC offset</span>
|
||||
<span className="font-mono">{formatUtcOffset(provenance.sourceOffsetMinutes)}</span>
|
||||
<span className="text-gray-400 ml-1">(applied)</span>
|
||||
{originChip && origin && (
|
||||
<span className={`ml-2 px-1.5 py-0.5 rounded text-[10px] font-medium ${originChip.className}`} title={originChip.title}>
|
||||
{origin}
|
||||
{origin === "calibrated" && <span className="ml-1 font-normal">(retired)</span>}
|
||||
</span>
|
||||
)}
|
||||
</div>
|
||||
)}
|
||||
{provenance?.measuredWriterOffsetMinutes !== null && provenance?.measuredWriterOffsetMinutes !== undefined && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Writer offset</span>
|
||||
<span
|
||||
className="font-mono"
|
||||
title="Measured from the log writer's paired local/UTC lines. Sticky after era flip-backs, so it can lag reality. The applied correction is the UTC offset above."
|
||||
>
|
||||
{formatUtcOffset(provenance.measuredWriterOffsetMinutes)}
|
||||
<span className="text-gray-400 ml-1 font-sans">(observed from the writer's own UTC lines — not the applied correction)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.derivedTimestamp && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Derived time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.derivedTimestamp}
|
||||
<span className="text-gray-400 ml-1 font-sans">(line timestamp unusable — agent clock substituted)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.rejectedSourceTimestamp && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Rejected time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.rejectedSourceTimestamp}
|
||||
<span className="text-gray-400 ml-1 font-sans">(rejected by the staleness clamp)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Original time</span>
|
||||
<span className="font-mono">
|
||||
{event.originalTimestamp ?? "—"}
|
||||
<span className="text-gray-400 ml-1 font-sans">(before ingest clamp)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
</div>
|
||||
);
|
||||
}
|
||||
|
||||
function RawEventRow({ event, prevEvent }: { event: EnrollmentEvent; prevEvent?: EnrollmentEvent | null }) {
|
||||
const [expanded, setExpanded] = useState(false);
|
||||
const detailData = useMemo(() => normalizeEventDataForDisplay(event.data), [event.data]);
|
||||
const hasDetails = detailData && Object.keys(detailData).length > 0;
|
||||
const { isBackfilled, recordedAt } = getBackfillInfo(event);
|
||||
const prevDisplayTime = prevEvent ? getDisplayTime(prevEvent) : null;
|
||||
|
||||
const sevColor: Record<string, string> = {
|
||||
Trace: "text-purple-500",
|
||||
@@ -838,10 +1011,14 @@ function RawEventRow({ event, prevDisplayTime }: { event: EnrollmentEvent; prevD
|
||||
<span className="text-gray-400 w-8 text-right flex-shrink-0">{event.sequence}</span>
|
||||
<span className="text-gray-500 flex-shrink-0">{(recordedAt ?? new Date(event.timestamp)).toLocaleTimeString()}</span>
|
||||
<GapBadge prevTime={prevDisplayTime ?? null} eventTime={recordedAt ?? new Date(event.timestamp)} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} />
|
||||
<span className={`flex-shrink-0 w-14 ${sevColor[event.severity] || "text-gray-500"}`}>{event.severity}</span>
|
||||
{isBackfilled && (
|
||||
<span className="text-slate-500 flex-shrink-0" title={BACKFILL_TOOLTIP}>⟲</span>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<span className="text-amber-600 flex-shrink-0" title={`${CLAMPED_TOOLTIP_PREFIX}${event.originalTimestamp ? ` Original device timestamp: ${event.originalTimestamp}.` : ""}`}>⧖</span>
|
||||
)}
|
||||
<span className="text-gray-900 font-medium flex-shrink-0">{event.eventType}</span>
|
||||
<span className="text-gray-500 truncate flex-1 min-w-0" title={event.message || undefined}>{shortenBuildHashInMessage(event.message)}</span>
|
||||
{hasDetails && (
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import { formatBytes, formatThroughput, formatDuration, formatPercent } from "../formatting";
|
||||
import { formatBytes, formatThroughput, formatDuration, formatPercent, formatUtcOffset } from "../formatting";
|
||||
|
||||
describe("formatBytes", () => {
|
||||
it("returns the zero sentinel for 0 / negative / non-finite", () => {
|
||||
@@ -51,3 +51,17 @@ describe("formatPercent", () => {
|
||||
expect(formatPercent(5, 0)).toBe("—");
|
||||
});
|
||||
});
|
||||
|
||||
describe("formatUtcOffset", () => {
|
||||
it("renders signed HH:MM offsets, including quarter-hour zones", () => {
|
||||
expect(formatUtcOffset(0)).toBe("UTC+00:00");
|
||||
expect(formatUtcOffset(120)).toBe("UTC+02:00");
|
||||
expect(formatUtcOffset(-540)).toBe("UTC−09:00");
|
||||
expect(formatUtcOffset(345)).toBe("UTC+05:45"); // Nepal
|
||||
expect(formatUtcOffset(-270)).toBe("UTC−04:30");
|
||||
});
|
||||
|
||||
it("dashes on non-finite input", () => {
|
||||
expect(formatUtcOffset(NaN)).toBe("—");
|
||||
});
|
||||
});
|
||||
|
||||
@@ -0,0 +1,61 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import { groupEventsByPhase } from "../../app/sessions/utils/eventHelpers";
|
||||
import type { EnrollmentEvent } from "@/types";
|
||||
|
||||
/**
|
||||
* Pins the P13 guardrail: the timeline orders by SEQUENCE, never by time. Sequence is a
|
||||
* persisted, strictly monotonic per-session counter assigned at emit time and immune to
|
||||
* every clock problem; the timestamp carries the device clock frame plus, for
|
||||
* CMTrace-derived events, the writer's timezone belief. A backdated line (the field case:
|
||||
* mdm_policy_reboot_required at −58 min amid live events) must stay at its sequence
|
||||
* position — the display marks the jump, the order never moves.
|
||||
*/
|
||||
|
||||
const PHASE_NAMES: Record<number, string> = { 0: "Unknown", 1: "Start" };
|
||||
const PHASE_ORDER = ["Start"];
|
||||
|
||||
function makeEvent(sequence: number, timestamp: string, phase = 0): EnrollmentEvent {
|
||||
return {
|
||||
eventId: `evt-${sequence}`,
|
||||
sessionId: "s",
|
||||
timestamp,
|
||||
eventType: "status_update",
|
||||
severity: "Info",
|
||||
source: "DecisionEngine",
|
||||
phase,
|
||||
message: "",
|
||||
sequence,
|
||||
};
|
||||
}
|
||||
|
||||
describe("groupEventsByPhase ordering", () => {
|
||||
it("orders strictly by sequence — a backdated timestamp never moves an event", () => {
|
||||
// Shuffled input; sequence 4 carries a timestamp 9 h EARLIER than its neighbors
|
||||
// (era-mixed CMTrace line). Time-based sorting would pull it to the front.
|
||||
const events = [
|
||||
makeEvent(5, "2026-08-20T10:05:00Z"),
|
||||
makeEvent(2, "2026-08-20T10:01:00Z"),
|
||||
makeEvent(4, "2026-08-20T01:03:00Z"), // backdated by ~9h, higher sequence
|
||||
makeEvent(1, "2026-08-20T10:00:00Z", 1),
|
||||
makeEvent(3, "2026-08-20T10:02:00Z"),
|
||||
];
|
||||
|
||||
const { eventsByPhase, orderedPhases } = groupEventsByPhase(events, PHASE_NAMES, PHASE_ORDER);
|
||||
|
||||
expect(orderedPhases).toEqual(["Start"]);
|
||||
expect(eventsByPhase["Start"].map(e => e.sequence)).toEqual([1, 2, 3, 4, 5]);
|
||||
});
|
||||
|
||||
it("uses the timestamp only as a tie-break for EQUAL sequence values", () => {
|
||||
// Equal sequences happen when the counter was not persisted across a reboot.
|
||||
const events = [
|
||||
makeEvent(1, "2026-08-20T10:00:00Z", 1),
|
||||
{ ...makeEvent(7, "2026-08-20T10:09:00Z"), eventId: "b" },
|
||||
{ ...makeEvent(7, "2026-08-20T10:07:00Z"), eventId: "a" },
|
||||
];
|
||||
|
||||
const { eventsByPhase } = groupEventsByPhase(events, PHASE_NAMES, PHASE_ORDER);
|
||||
|
||||
expect(eventsByPhase["Start"].map(e => e.eventId)).toEqual(["evt-1", "a", "b"]);
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,118 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import {
|
||||
readTimeProvenance,
|
||||
classifyTimeJump,
|
||||
BACKWARD_JUMP_THRESHOLD_MS,
|
||||
type TimeJumpInput,
|
||||
} from "../timeProvenance";
|
||||
|
||||
const T0 = new Date("2026-08-20T10:00:00Z");
|
||||
const minutes = (m: number) => new Date(T0.getTime() + m * 60 * 1000);
|
||||
|
||||
function input(displayTime: Date, data?: Record<string, unknown>): TimeJumpInput {
|
||||
return { displayTime, provenance: readTimeProvenance(data) };
|
||||
}
|
||||
|
||||
describe("readTimeProvenance", () => {
|
||||
it("reads camelCase keys and parses numeric strings", () => {
|
||||
const p = readTimeProvenance({
|
||||
sourceLocalTs: "2026-08-20T05:31:46.5192284",
|
||||
sourceOffsetMinutes: "-540",
|
||||
sourceOffsetOrigin: "line-anchored",
|
||||
measuredWriterOffsetMinutes: "120",
|
||||
derivedTimestamp: "true",
|
||||
rejectedSourceTimestamp: "2026-08-13T09:00:00Z",
|
||||
});
|
||||
expect(p).not.toBeNull();
|
||||
expect(p!.sourceOffsetMinutes).toBe(-540);
|
||||
expect(p!.measuredWriterOffsetMinutes).toBe(120);
|
||||
expect(p!.sourceOffsetOrigin).toBe("line-anchored");
|
||||
expect(p!.derivedTimestamp).toBe("true");
|
||||
});
|
||||
|
||||
it("falls back to snake_case keys (historicReplay.ts convention)", () => {
|
||||
const p = readTimeProvenance({
|
||||
source_offset_minutes: "120",
|
||||
source_offset_origin: "reader-zone-fallback",
|
||||
});
|
||||
expect(p!.sourceOffsetMinutes).toBe(120);
|
||||
expect(p!.sourceOffsetOrigin).toBe("reader-zone-fallback");
|
||||
});
|
||||
|
||||
it("returns null when no provenance key is present (undefined data, truncated payload)", () => {
|
||||
expect(readTimeProvenance(undefined)).toBeNull();
|
||||
expect(readTimeProvenance(null)).toBeNull();
|
||||
expect(readTimeProvenance({})).toBeNull();
|
||||
// DataJson >30KB gets stored truncated; the UI then holds { _rawDataJson: "..." }.
|
||||
expect(readTimeProvenance({ _rawDataJson: '{"sourceOffsetMinutes":"120", …' })).toBeNull();
|
||||
expect(readTimeProvenance({ appId: "x", exitCode: "0" })).toBeNull();
|
||||
});
|
||||
|
||||
it("keeps partial provenance and nulls malformed numbers", () => {
|
||||
const p = readTimeProvenance({ sourceOffsetOrigin: "bias", sourceOffsetMinutes: "not-a-number" });
|
||||
expect(p).not.toBeNull();
|
||||
expect(p!.sourceOffsetOrigin).toBe("bias");
|
||||
expect(p!.sourceOffsetMinutes).toBeNull();
|
||||
expect(p!.sourceLocalTs).toBeNull();
|
||||
});
|
||||
|
||||
it("passes unknown origin strings through verbatim (forward compatibility)", () => {
|
||||
expect(readTimeProvenance({ sourceOffsetOrigin: "future-origin" })!.sourceOffsetOrigin).toBe("future-origin");
|
||||
});
|
||||
});
|
||||
|
||||
describe("classifyTimeJump", () => {
|
||||
it("pins the badge threshold at 5 minutes", () => {
|
||||
expect(BACKWARD_JUMP_THRESHOLD_MS).toBe(300_000);
|
||||
});
|
||||
|
||||
it("returns null without a previous rendered row", () => {
|
||||
expect(classifyTimeJump(null, input(T0))).toBeNull();
|
||||
});
|
||||
|
||||
it("ignores forward movement and sub-threshold backwards jitter", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(90)))).toBeNull();
|
||||
// 2 min backwards = interleaved-writer jitter inside the agent's grid tolerance.
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-2)))).toBeNull();
|
||||
});
|
||||
|
||||
it("fires exactly at the threshold boundary", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-5)))).toEqual({ deltaMs: 300_000, cause: null });
|
||||
expect(classifyTimeJump(input(T0), input(new Date(T0.getTime() - 299_999)))).toBeNull();
|
||||
});
|
||||
|
||||
it("names an era-mixed log when both rows carry differing applied offsets", () => {
|
||||
const prev = input(T0, { sourceOffsetMinutes: "120" });
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420" });
|
||||
expect(classifyTimeJump(prev, curr)).toEqual({ deltaMs: 540 * 60 * 1000, cause: "era-offset" });
|
||||
});
|
||||
|
||||
it("does not claim era-offset when either side lacks an offset", () => {
|
||||
const prev = input(T0);
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420" });
|
||||
expect(classifyTimeJump(prev, curr)!.cause).toBeNull();
|
||||
});
|
||||
|
||||
it("derivedTimestamp wins over era-offset (precedence)", () => {
|
||||
const prev = input(T0, { sourceOffsetMinutes: "120" });
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420", derivedTimestamp: "true" });
|
||||
expect(classifyTimeJump(prev, curr)!.cause).toBe("derived-timestamp");
|
||||
});
|
||||
|
||||
it("names a rejected source timestamp", () => {
|
||||
const curr = input(minutes(-30), { rejectedSourceTimestamp: "2026-08-13T09:00:00Z" });
|
||||
expect(classifyTimeJump(input(T0), curr)!.cause).toBe("rejected-source");
|
||||
});
|
||||
|
||||
it("classifies a week-old backdated replay with the correct magnitude", () => {
|
||||
const weekAgo = new Date(T0.getTime() - 7 * 24 * 60 * 60 * 1000);
|
||||
const jump = classifyTimeJump(input(T0), input(weekAgo));
|
||||
expect(jump).not.toBeNull();
|
||||
expect(jump!.deltaMs).toBe(7 * 24 * 60 * 60 * 1000);
|
||||
expect(jump!.cause).toBeNull();
|
||||
});
|
||||
|
||||
it("respects a caller-supplied threshold", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-3)), 120_000)).toEqual({ deltaMs: 180_000, cause: null });
|
||||
});
|
||||
});
|
||||
@@ -50,3 +50,17 @@ export function formatPercent(numerator: number, denominator: number, decimals =
|
||||
if (!Number.isFinite(numerator) || !Number.isFinite(denominator) || denominator <= 0) return zero;
|
||||
return `${((numerator / denominator) * 100).toFixed(decimals)}%`;
|
||||
}
|
||||
|
||||
/**
|
||||
* Signed HH:MM UTC offset from a minutes value: 120 -> "UTC+02:00", -345 -> "UTC−05:45",
|
||||
* 0 -> "UTC+00:00". Quarter-hour zones (Nepal +05:45, Chatham +12:45) render exactly.
|
||||
* Non-finite returns `zero`.
|
||||
*/
|
||||
export function formatUtcOffset(minutes: number, zero = "—"): string {
|
||||
if (!Number.isFinite(minutes)) return zero;
|
||||
const sign = minutes < 0 ? "−" : "+";
|
||||
const abs = Math.abs(Math.round(minutes));
|
||||
const h = Math.floor(abs / 60);
|
||||
const m = abs % 60;
|
||||
return `UTC${sign}${String(h).padStart(2, "0")}:${String(m).padStart(2, "0")}`;
|
||||
}
|
||||
|
||||
@@ -0,0 +1,127 @@
|
||||
/**
|
||||
* CMTrace time-resolution provenance (P13): the agent's per-line self-anchoring stamps
|
||||
* CMTrace-derived events with how their UTC timestamp was produced — the raw local time
|
||||
* as written in the log, the applied UTC offset and its origin, the purely observational
|
||||
* per-file writer offset, and the clock-fallback markers. All values arrive as STRINGS
|
||||
* inside the event data payload (see docs/agent/cmtrace-time-resolution.md).
|
||||
*
|
||||
* The timeline sorts by sequence — always, never by time (user guardrail). A displayed
|
||||
* time that steps BACKWARDS within that order is therefore information, not a rendering
|
||||
* bug: a backdated log line, a staleness-clamp fallback, or an era-mixed log whose lines
|
||||
* were corrected with different offsets (session e9753578 carried ±9 h of exactly that).
|
||||
* `classifyTimeJump` names the phenomenon so the timeline can mark the spot instead of
|
||||
* leaving the reader to distrust the order.
|
||||
*/
|
||||
|
||||
export interface TimeProvenance {
|
||||
/** Raw local timestamp as written in the log line (no zone suffix, by design). */
|
||||
sourceLocalTs: string | null;
|
||||
/** UTC offset in minutes that was APPLIED to resolve the timestamp. */
|
||||
sourceOffsetMinutes: number | null;
|
||||
/** How the applied offset was obtained: "bias" | "line-anchored" | "reader-zone-fallback" | retired "calibrated". */
|
||||
sourceOffsetOrigin: string | null;
|
||||
/**
|
||||
* Observational per-file measurement from the writer's own UTC lines — NOT the applied
|
||||
* correction, and sticky after era flip-backs (the monotonicity guard rejects newer
|
||||
* anchors), so it can lag reality. Never present it as "what was applied".
|
||||
*/
|
||||
measuredWriterOffsetMinutes: number | null;
|
||||
/** "true" when the line's own timestamp was unusable and the agent clock was substituted. */
|
||||
derivedTimestamp: string | null;
|
||||
/** The line's own timestamp that the staleness clamp rejected (set alongside derivedTimestamp). */
|
||||
rejectedSourceTimestamp: string | null;
|
||||
}
|
||||
|
||||
function readString(data: Record<string, unknown>, camel: string, snake: string): string | null {
|
||||
const raw = data[camel] ?? data[snake];
|
||||
return typeof raw === "string" && raw.length > 0 ? raw : null;
|
||||
}
|
||||
|
||||
function readNumber(data: Record<string, unknown>, camel: string, snake: string): number | null {
|
||||
const raw = data[camel] ?? data[snake];
|
||||
if (typeof raw === "number") return Number.isFinite(raw) ? raw : null;
|
||||
if (typeof raw !== "string" || raw.length === 0) return null;
|
||||
const parsed = Number(raw);
|
||||
return Number.isFinite(parsed) ? parsed : null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Reads the provenance fields from an event's data payload. Returns null when NO
|
||||
* provenance key is present — which also covers `data` being undefined and the
|
||||
* DataJson-truncation fallback (`_rawDataJson`), where the payload is not an object
|
||||
* of parsed keys at all.
|
||||
*/
|
||||
export function readTimeProvenance(data: Record<string, unknown> | undefined | null): TimeProvenance | null {
|
||||
if (!data || typeof data !== "object") return null;
|
||||
const provenance: TimeProvenance = {
|
||||
sourceLocalTs: readString(data, "sourceLocalTs", "source_local_ts"),
|
||||
sourceOffsetMinutes: readNumber(data, "sourceOffsetMinutes", "source_offset_minutes"),
|
||||
sourceOffsetOrigin: readString(data, "sourceOffsetOrigin", "source_offset_origin"),
|
||||
measuredWriterOffsetMinutes: readNumber(data, "measuredWriterOffsetMinutes", "measured_writer_offset_minutes"),
|
||||
derivedTimestamp: readString(data, "derivedTimestamp", "derived_timestamp"),
|
||||
rejectedSourceTimestamp: readString(data, "rejectedSourceTimestamp", "rejected_source_timestamp"),
|
||||
};
|
||||
const hasAny =
|
||||
provenance.sourceLocalTs !== null ||
|
||||
provenance.sourceOffsetMinutes !== null ||
|
||||
provenance.sourceOffsetOrigin !== null ||
|
||||
provenance.measuredWriterOffsetMinutes !== null ||
|
||||
provenance.derivedTimestamp !== null ||
|
||||
provenance.rejectedSourceTimestamp !== null;
|
||||
return hasAny ? provenance : null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Row-badge threshold for a backwards step of the displayed time. Field-measured
|
||||
* (2026-08-20, 20 sessions): normal sessions max out at 0.6–1.7 min of interleaved-writer
|
||||
* jitter (the agent's own grid tolerance is 2 min), while every genuine offset phenomenon
|
||||
* starts at the 15-minute zone quantum. 5 min sits safely between the two — at this
|
||||
* threshold 12/12 normal sessions showed zero badges.
|
||||
*/
|
||||
export const BACKWARD_JUMP_THRESHOLD_MS = 5 * 60 * 1000;
|
||||
|
||||
export type TimeJumpCause = "era-offset" | "derived-timestamp" | "rejected-source" | null;
|
||||
|
||||
export interface TimeJump {
|
||||
/** Positive magnitude of the backwards step in milliseconds. */
|
||||
deltaMs: number;
|
||||
cause: TimeJumpCause;
|
||||
}
|
||||
|
||||
export interface TimeJumpInput {
|
||||
displayTime: Date;
|
||||
provenance: TimeProvenance | null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Detects a backwards step of the displayed time versus the previous RENDERED row and
|
||||
* names its cause when the provenance identifies one. Cause precedence: a clock-fallback
|
||||
* (derived) timestamp explains the row by itself; a rejected source timestamp likewise;
|
||||
* only then is an offset difference between the two rows read as an era-mixed log.
|
||||
* Callers pass prev = null at phase-section starts (jump detection never spans sections).
|
||||
*/
|
||||
export function classifyTimeJump(
|
||||
prev: TimeJumpInput | null,
|
||||
curr: TimeJumpInput,
|
||||
thresholdMs: number = BACKWARD_JUMP_THRESHOLD_MS,
|
||||
): TimeJump | null {
|
||||
if (!prev) return null;
|
||||
const deltaMs = prev.displayTime.getTime() - curr.displayTime.getTime();
|
||||
if (!Number.isFinite(deltaMs) || deltaMs < thresholdMs) return null;
|
||||
|
||||
let cause: TimeJumpCause = null;
|
||||
if (curr.provenance?.derivedTimestamp) {
|
||||
cause = "derived-timestamp";
|
||||
} else if (curr.provenance?.rejectedSourceTimestamp) {
|
||||
cause = "rejected-source";
|
||||
} else if (
|
||||
prev.provenance?.sourceOffsetMinutes !== null &&
|
||||
prev.provenance?.sourceOffsetMinutes !== undefined &&
|
||||
curr.provenance?.sourceOffsetMinutes !== null &&
|
||||
curr.provenance?.sourceOffsetMinutes !== undefined &&
|
||||
prev.provenance.sourceOffsetMinutes !== curr.provenance.sourceOffsetMinutes
|
||||
) {
|
||||
cause = "era-offset";
|
||||
}
|
||||
return { deltaMs, cause };
|
||||
}
|
||||
@@ -11,6 +11,10 @@ export interface EnrollmentEvent {
|
||||
sequence: number;
|
||||
receivedAt?: string;
|
||||
data?: Record<string, unknown>;
|
||||
/** True when ingest clamped an out-of-range device timestamp to server time. */
|
||||
timestampClamped?: boolean;
|
||||
/** The pre-clamp device timestamp; only set when timestampClamped is true. */
|
||||
originalTimestamp?: string | null;
|
||||
}
|
||||
|
||||
export interface RuleResult {
|
||||
|
||||
@@ -445,6 +445,7 @@ export const SHARED_MANIFEST = {
|
||||
],
|
||||
"analyzeRuleSources": [
|
||||
"app_install_duration",
|
||||
"clock_skew",
|
||||
"event_correlation",
|
||||
"event_count",
|
||||
"event_data",
|
||||
|
||||
@@ -441,6 +441,7 @@
|
||||
],
|
||||
"analyzeRuleSources": [
|
||||
"app_install_duration",
|
||||
"clock_skew",
|
||||
"event_correlation",
|
||||
"event_count",
|
||||
"event_data",
|
||||
|
||||
Reference in New Issue
Block a user