Compare commits

...

3 Commits

14 changed files with 596 additions and 64 deletions
+6
View File
@@ -54,6 +54,12 @@ jobs:
ajv validate -s rules/schema/ime-log-pattern.schema.json -d "$f" --spec=draft2020 -c ajv-formats
done
# guardrails.json values are baked verbatim into generated TypeScript that is
# auto-committed to main and shipped to the portal - the schema forbids control
# and line-terminator characters so a "data" PR can never become code.
- name: Validate Guardrails
run: ajv validate -s rules/schema/guardrails.schema.json -d rules/guardrails.json --spec=draft2020 -c ajv-formats
- name: Combine rules into dist/
run: node rules/scripts/combine.js
+38 -1
View File
@@ -4,7 +4,7 @@ title: CMTrace Time Resolution — Per-Line Self-Anchoring
description: How the agent converts bias-less CMTrace local times to UTC without trusting any process's timezone belief — each provably fresh line anchors its own offset against the agent clock on the 15-minute grid; everything not provably fresh falls back uniformly and says so.
resource: src/Agent/AutopilotMonitor.Agent.V2.Core/Monitoring/Enrollment/Ime
tags: [agent, ime, cmtrace, timestamps, timezone, calibration, provenance]
timestamp: 2026-08-20
timestamp: 2026-08-30
---
# Problem
@@ -86,6 +86,40 @@ with the process zone).
* Mixed pairs remain possible across a restart (start resolved from backlog fallback,
completion line-anchored) and are recognizable via provenance.
# Line parsing (bounded cost)
`CmTraceLogParser.TryParseLine` (Shared) is the single CMTrace line parser for the agent
(`ImeLogTracker`, `LogParserCollector`, `StallProbeCollector`) and the backend
(`TestLogPatternFunction`). Both feed it input an outsider influences: tenant-supplied
sample lines (200 x 8 KB per request) on the backend, and on the agent every tailed log
file, including entries that IME assembles from installer or script output. It is
therefore not one regex. The former shape — a greedy `(?<message>.*)` in front of the
`]LOG]!><time="` literal, unanchored, no match timeout — re-tried every `<![LOG[`
occurrence as a fresh start and backtracked the message group across every later character
for each: quadratic in line length (an 8 KB line of repeated prefixes and `]` filler cost
~7 million engine steps; a 1 MB assembled entry would have spun the SYSTEM agent for
hours and blacked out IME tracking for the rest of the enrollment).
The parser reproduces exactly what that regex returned, in linear time: the message begins
after the first `<![LOG[` (a later start could only match when the first one does, since
`.*` spans the difference) and ends at the last `]LOG]!><time="` occurrence whose trailer
parses — earlier occurrences are tried in turn, which is the order greedy backtracking
visited them. The trailer is checked with a `\G`-anchored regex that has no ambiguous
quantifier and a 1-second match timeout as a backstop; a timeout means "not a CMTrace
line" (callers already have that path: raw-text matching in the tracker, `parse_failed`
on the backend), never an exception. `CmTraceLogParserTests` pins the equivalence against
the legacy regex over the shapes that matter (multiline messages, bias suffix, trailer
literal inside the message, a last trailer that fails to parse, BOM prefix) and the
reported worst case at 200 lines.
On the agent, `ImeLogTracker` additionally caps an assembled multiline entry at 100 raw
lines **and** 1 MB of characters (`MaxMultiLineBufferChars`). A capped entry is dropped
and logged at **Warning** — visible at the default `Info` level, so a real IME entry that
large shows up in the client log and can be acted on. The remaining physical lines of a
dropped entry are skipped until it closes or a new `<![LOG[` entry begins; previously they
fell through to raw-text pattern matching, so fragments of a discarded entry could fire
patterns without CMTrace context.
# Backend regression tripwire
The backend watches for the failure mode this design eliminates. On every terminal ingest
@@ -129,3 +163,6 @@ precisely so an anchoring regression can never surface as a customer finding.
* `tasks/todo.md` (2026-08-20) — full evidence trail: field measurements, the revert,
the two-writer-era fixture, and the disproven foreign-binary hypothesis (the SHA
mismatch was the known release race against the 5-minute AdminConfiguration cache).
* `CmTraceLogParser.TryParseLine` + `CmTraceLogParserTests` — the linear parser and its
legacy-regex equivalence oracle; `ImeLogTracker.LogProcessing.cs` multiline buffering
(`MaxMultiLineBufferLines` / `MaxMultiLineBufferChars`, `skippingDroppedEntry`).
+1 -1
View File
@@ -28,7 +28,7 @@ https://docs.autopilotmonitor.com (separate repository).
* [Zero User-Targeted Apps — the starved user-phase completion gate](agent/zero-user-apps-completion-gate.md) - Why a device with no user-targeted Intune apps could never satisfy the IME user-session gate — IME skips its "Completed user session" line entirely in the zero-app branch — turning the 30-minute completion backstop into `esp_exit_without_completion_evidence` on a third of one tenant's enrollments, with the user at the desktop and RealmJoin still installing. The two fixes: read the line IME does write (IME-USER-SESSION-ZERO-APPS), and never fail a session while a completion gate with its own armed deadline is deliberately holding it.
* [Secure Boot CA-2023 Detection](agent/secureboot-ca2023-detection.md) - Why ANALYZE-SEC-001 v3 reads the UEFI db/KEK variables directly instead of trusting the SecureBoot\Servicing registry, and how the one-sided uefiCa2023FirmwareConfirmed marker plus a not_exists precondition give absence-tolerant suppression across old and new agents.
* [Continue-Anyway Observation Mode](agent/continue-anyway-observation.md) - EnableEspContinueAnywayObservation (ConfigVersion 37, operator-set): Device-phase ESP terminal failures on Continue-Anyway profiles get a bounded 60-min observation instead of an immediate hard fail; the DAD-validated real-user desktop + Hello gate detect the true end, the session completes Succeeded + EspSoftFailure (amber "with issues" badge), expiry un-defangs to the original esp_terminal_failure.
* [CMTrace Time Resolution](agent/cmtrace-time-resolution.md) - Converting bias-less CMTrace local times to UTC without trusting any process's timezone belief: per-line self-anchoring on the 15-minute offset grid for provably fresh lines, uniform marked reader-zone fallback for backlog, and the provenance vocabulary (bias / line-anchored / reader-zone-fallback) that keeps every event re-derivable.
* [CMTrace Time Resolution](agent/cmtrace-time-resolution.md) - Converting bias-less CMTrace local times to UTC without trusting any process's timezone belief: per-line self-anchoring on the 15-minute offset grid for provably fresh lines, uniform marked reader-zone fallback for backlog, and the provenance vocabulary (bias / line-anchored / reader-zone-fallback) that keeps every event re-derivable; plus the linear-cost CMTrace line parser (first open / last parseable trailer, timeout-backed) and the agent multiline caps.
* [Registry App-State Second Pillar](agent/registry-app-state-pillar.md) - IME's authoritative per-app state read straight from the registry (Win32Apps EnforcementStateMessage, EspTrackingWin32Apps, StatusServiceReports) via a snapshot-and-diff watcher; registry/log reconciliation doubles as the built-in IME log-pattern drift alarm.
* [WDP Scenario Gates & Completion Backstop](agent/wdp-scenario-gates.md) - How the agent gates Autopilot/ESP-only machinery off on Windows Device Preparation sessions (deterministic ExecutionContext marker, fail-toward-Classic), which noise it suppresses (ZTD probe, esp_config unknown, ModernDeployment 100/417/418/1005, starved sweep), and the WDP completion model: High-confidence seed, desktop-based arm D, and the 30-min device_prep_completion backstop.
* [Power-State Watcher](agent/power-state-watcher.md) - Live AC↔battery transitions and 50/30/15% downward battery-threshold crossings during enrollment via a WMI Win32_PowerManagementEvent push subscription (zero polling, never armed on battery-less devices): the power_state_change event (transition field, per-level lifetime latch, 5s debounce, emission cap) and the analyze rules ANALYZE-DEV-009 (battery <15%, high) / ANALYZE-DEV-010 (AC→battery, warning) with on_event interim triggers.
+4
View File
@@ -1,5 +1,9 @@
# Log
## 2026-08-30 (2)
* **Update**: `agent/cmtrace-time-resolution.md` — new "Line parsing (bounded cost)" section: `CmTraceLogParser.TryParseLine` is no longer one greedy-`.*` regex (quadratic on hostile lines, no timeout) but a linear first-open / last-parseable-trailer search with a `\G`-anchored, timeout-backed trailer regex that returns exactly what the old regex did; the agent's multiline buffer gains a 1 MB char cap next to the 100-line cap, both logged at Warning, and the tail of a dropped entry is skipped instead of raw-matched.
## 2026-08-30 (1)
* **Update**: `agent/diagnostics-package.md` — reads are validated on the handle, not the path: `PinnedSourceFolder` pins each section folder (its final path must equal the validated path; held open so the chain cannot be renamed) and opens every file with `FILE_FLAG_OPEN_REPARSE_POINT`, requiring the handle's final path to be `<canonical folder>\<relative path>`. A subdirectory swapped for a junction between enumeration and open is skipped (`SKIPPED (resolved outside validated folder)`) instead of copied into the package.
+62
View File
@@ -0,0 +1,62 @@
{
"$schema": "https://json-schema.org/draft/2020-12/schema",
"$id": "https://raw.githubusercontent.com/OliverKieselbach/Autopilot-Monitor/main/rules/schema/guardrails.schema.json",
"title": "Autopilot Monitor Gather-Rule Guardrails",
"description": "Agent-side collection allowlists/blocklists. Every string is emitted verbatim into generated TypeScript (web + MCP), so values are single-line and must not contain control characters or the U+2028/U+2029 line terminators.",
"type": "object",
"properties": {
"$schema": { "type": "string" },
"registryPrefixes": { "$ref": "#/$defs/categorizedList" },
"filePrefixes": { "$ref": "#/$defs/stringList" },
"wmiQueryPrefixes": { "$ref": "#/$defs/stringList" },
"eventLogChannels": { "$ref": "#/$defs/categorizedList" },
"blockedEventLogChannels": { "$ref": "#/$defs/stringList" },
"allowedCommands": { "$ref": "#/$defs/categorizedList" },
"diagnosticsPathPrefixes": { "$ref": "#/$defs/stringList" },
"blockedFilePrefixes": { "$ref": "#/$defs/stringList" },
"blockedCommandPatterns": { "$ref": "#/$defs/stringList" },
"blockedInterimTriggerEventTypes": { "$ref": "#/$defs/stringList" },
"maxCommandLength": { "type": "integer", "minimum": 1, "maximum": 100000 }
},
"required": [
"registryPrefixes",
"filePrefixes",
"wmiQueryPrefixes",
"eventLogChannels",
"blockedEventLogChannels",
"allowedCommands",
"diagnosticsPathPrefixes",
"blockedFilePrefixes",
"blockedCommandPatterns",
"maxCommandLength"
],
"additionalProperties": false,
"$defs": {
"safeString": {
"type": "string",
"minLength": 1,
"maxLength": 2000,
"pattern": "^[^\\u0000-\\u001F\\u007F\\u2028\\u2029]+$"
},
"stringList": {
"type": "array",
"items": { "$ref": "#/$defs/safeString" }
},
"categorizedList": {
"type": "array",
"items": {
"type": "object",
"properties": {
"category": { "$ref": "#/$defs/safeString" },
"prefixes": { "$ref": "#/$defs/stringList" },
"channels": { "$ref": "#/$defs/stringList" },
"commands": { "$ref": "#/$defs/stringList" }
},
"required": ["category"],
"minProperties": 2,
"maxProperties": 2,
"additionalProperties": false
}
}
}
}
+58 -5
View File
@@ -97,18 +97,71 @@ const guardrailsOutput = path.resolve(
if (fs.existsSync(guardrailsPath)) {
const guardrails = JSON.parse(fs.readFileSync(guardrailsPath, 'utf8'));
/** Escape a string for use inside a TS string literal (double-quoted). */
const esc = (s) => s.replace(/\\/g, '\\\\').replace(/"/g, '\\"');
// Every value below is emitted into a TypeScript module that ships in the
// portal bundle (and is auto-committed + auto-deployed from main). A string
// containing a raw newline / CR / U+2028 / U+2029 inside a naive "..." literal
// would terminate the literal and turn the remainder of the value into CODE.
// Two independent defences: (1) reject any control/line-terminator character
// outright — no legitimate prefix, command or channel name contains one —
// and (2) render every literal through a complete encoder (JSON.stringify),
// so even a value that slipped past (1) stays an inert string constant.
// rules/schema/guardrails.schema.json enforces the same constraints in CI
// before this script runs; this in-process check keeps local runs honest.
const UNSAFE_CHAR = /[\u0000-\u001F\u007F\u2028\u2029]/;
const fail = (msg) => {
console.error(`ERROR: guardrails.json ${msg}`);
process.exit(1);
};
const assertSafeString = (value, where) => {
if (typeof value !== 'string' || value.length === 0) {
fail(`${where}: expected a non-empty string, got ${JSON.stringify(value)}`);
}
if (UNSAFE_CHAR.test(value)) {
fail(`${where}: control or line-terminator character in ${JSON.stringify(value)}`);
}
};
const assertStringList = (list, where) => {
if (!Array.isArray(list)) fail(`${where}: expected an array`);
list.forEach((s, i) => assertSafeString(s, `${where}[${i}]`));
};
const assertCategorized = (groups, itemsKey, where) => {
if (!Array.isArray(groups)) fail(`${where}: expected an array`);
groups.forEach((g, i) => {
assertSafeString(g && g.category, `${where}[${i}].category`);
assertStringList(g[itemsKey], `${where}[${i}].${itemsKey}`);
});
};
assertCategorized(guardrails.registryPrefixes, 'prefixes', 'registryPrefixes');
assertCategorized(guardrails.allowedCommands, 'commands', 'allowedCommands');
assertCategorized(guardrails.eventLogChannels, 'channels', 'eventLogChannels');
for (const key of [
'filePrefixes', 'wmiQueryPrefixes', 'diagnosticsPathPrefixes', 'blockedFilePrefixes',
'blockedEventLogChannels', 'blockedCommandPatterns'
]) {
assertStringList(guardrails[key], key);
}
assertStringList(guardrails.blockedInterimTriggerEventTypes ?? [], 'blockedInterimTriggerEventTypes');
if (!Number.isInteger(guardrails.maxCommandLength) || guardrails.maxCommandLength < 1) {
fail(`maxCommandLength: expected a positive integer, got ${JSON.stringify(guardrails.maxCommandLength)}`);
}
/**
* Render a string as a complete, self-contained TS double-quoted literal.
* JSON.stringify escapes backslash, quote and every C0 control character;
* U+2028/U+2029 are escaped on top because JSON does not require it.
*/
const lit = (s) => JSON.stringify(s).replace(/\u2028/g, '\\u2028').replace(/\u2029/g, '\\u2029');
/** Render an array of strings as a TS readonly array. */
const flatArray = (items) =>
items.map((s) => ` "${esc(s)}",`).join('\n');
items.map((s) => ` ${lit(s)},`).join('\n');
/** Render a categorized list as a TS readonly array of { category, items }. */
const categorizedArray = (groups, itemsKey) =>
groups.map((g) => {
const items = g[itemsKey].map((s) => ` "${esc(s)}",`).join('\n');
return ` {\n category: "${esc(g.category)}",\n items: [\n${items}\n ],\n },`;
const items = g[itemsKey].map((s) => ` ${lit(s)},`).join('\n');
return ` {\n category: ${lit(g.category)},\n items: [\n${items}\n ],\n },`;
}).join('\n');
// Flatten categorized lists for validation
@@ -1,4 +1,9 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Text;
using System.Text.RegularExpressions;
using AutopilotMonitor.Shared.Logging;
using Xunit;
@@ -137,5 +142,107 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
Assert.NotNull(entry);
Assert.Equal(hugeMessage.Length, entry.Message.Length);
}
// ── Hostile input: cost must be linear, never quadratic ───────────────
/// <summary>
/// The legacy single-regex parser (greedy <c>.*</c> message group before the trailer
/// literal, unanchored, Singleline, no timeout). Kept here ONLY as the semantic oracle:
/// the linear parser must return exactly what this regex returned for every line that
/// matches, and false for every line it rejected.
/// </summary>
private static readonly Regex LegacyRegex = new Regex(
@"<!\[LOG\[(?<message>.*)\]LOG\]!><time=""(?<time>[\d:.]+)(?<bias>[+-]\d{1,4})?""\s+date=""(?<date>[\d-]+)""\s+component=""(?<component>[^""]*)""\s+context=""[^""]*""\s+type=""(?<type>\d+)""\s+thread=""(?<thread>\d+)""\s+file=""[^""]*"">",
RegexOptions.Singleline);
public static IEnumerable<object[]> EquivalenceLines()
{
const string trailer = "]LOG]!><time=\"06:08:04.8834397\" date=\"2-8-2026\" component=\"C\" context=\"\" type=\"2\" thread=\"7\" file=\"\">";
const string badTrailer = "]LOG]!><time=\"06:08:04\" date=\"2-8-2026\" component=\"C\" context=\"\" type=\"x\" thread=\"7\" file=\"\">";
yield return new object[] { CmTraceLine("plain", "06:08:04.8834397", "2-8-2026") };
yield return new object[] { CmTraceLine("multi\nline\r\nmessage", "06:08:04.8834397", "2-8-2026") };
yield return new object[] { CmTraceLine("bias", "11:46:19.0226610+480", "7-29-2026") };
yield return new object[] { CmTraceLine("", "06:08:04.8834397", "2-8-2026") };
// The trailer literal INSIDE the message: greedy .* takes the LAST parseable trailer.
yield return new object[] { "<![LOG[inner " + trailer + " outer" + trailer };
// Last trailer occurrence does not parse (type="x") → the earlier one wins, and the
// failing trailer text is part of the message.
yield return new object[] { "<![LOG[first" + trailer + " second" + badTrailer };
// Only a broken trailer → false.
yield return new object[] { "<![LOG[msg" + badTrailer };
// A nested "<![LOG[" inside the message: the FIRST open wins (message keeps the inner one).
yield return new object[] { "<![LOG[outer <![LOG[inner" + trailer };
// Whitespace variants the old regex tolerated (\s+ between attributes).
yield return new object[] { "<![LOG[ws]LOG]!><time=\"06:08:04.8834397\" date=\"2-8-2026\"\tcomponent=\"C\" context=\"\" type=\"1\" thread=\"1\" file=\"x.cpp:12\">" };
// BOM-prefixed first line of a fresh log.
yield return new object[] { "\uFEFF" + CmTraceLine("bom", "06:08:04.8834397", "2-8-2026") };
// Trailer text without its leading ']' → false on both.
yield return new object[] { "<![LOG[" + trailer.Substring(1) };
yield return new object[] { "<![LOG[truncated" };
}
[Theory]
[MemberData(nameof(EquivalenceLines))]
public void TryParseLine_is_semantically_identical_to_the_legacy_greedy_regex(string line)
{
var legacy = LegacyRegex.Match(line);
var ok = CmTraceLogParser.TryParseLine(line, out var entry);
Assert.Equal(legacy.Success, ok);
if (!legacy.Success) return;
Assert.NotNull(entry);
Assert.Equal(legacy.Groups["message"].Value, entry.Message);
Assert.Equal(legacy.Groups["component"].Value, entry.Component);
Assert.Equal(int.Parse(legacy.Groups["type"].Value), entry.Type);
Assert.Equal(legacy.Groups["thread"].Value, entry.Thread);
var expectedBias = legacy.Groups["bias"].Success ? int.Parse(legacy.Groups["bias"].Value) : (int?)null;
Assert.Equal(expectedBias, entry.BiasMinutes);
}
/// <summary>
/// The reported worst case: 585 x "&lt;![LOG[" (4095 chars) + 4097 x "]" — passes the StartsWith
/// gate, never matches, and drove ~7 million backtracking steps through the legacy regex
/// (k prefix restarts x m filler positions). The linear parser has no trailer literal to
/// find and returns false in a handful of string searches.
/// </summary>
[Fact]
public void TryParseLine_rejects_reported_worst_case_in_bounded_time()
{
var line = string.Concat(Enumerable.Repeat("<![LOG[", 585)) + new string(']', 4097);
Assert.Equal(8192, line.Length);
var sw = Stopwatch.StartNew();
for (var i = 0; i < 200; i++)
{
Assert.False(CmTraceLogParser.TryParseLine(line, out _));
}
sw.Stop();
// 200 lines = one maximal backend request. Generous bound for a slow CI box; the
// legacy regex needed seconds here.
Assert.True(sw.ElapsedMilliseconds < 500, $"200 worst-case lines took {sw.ElapsedMilliseconds} ms");
}
/// <summary>
/// The agent variant: a multi-megabyte assembled entry stuffed with prefixes, trailer
/// literals whose attributes never parse, and filler — every occurrence is tried once,
/// each trailer probe fails at its first attribute, total work stays linear.
/// </summary>
[Fact]
public void TryParseLine_rejects_multi_megabyte_hostile_entry_in_bounded_time()
{
var sb = new StringBuilder(2 * 1024 * 1024);
sb.Append("<![LOG[");
while (sb.Length < 1024 * 1024)
sb.Append("<![LOG[").Append("]LOG]!><time=\"x\" ").Append(new string(']', 40)).Append('\n');
var line = sb.ToString();
var sw = Stopwatch.StartNew();
Assert.False(CmTraceLogParser.TryParseLine(line, out _));
sw.Stop();
Assert.True(sw.ElapsedMilliseconds < 1000, $"1 MB hostile entry took {sw.ElapsedMilliseconds} ms");
}
}
}
@@ -1,6 +1,7 @@
using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using AutopilotMonitor.Agent.V2.Core.Logging;
@@ -437,5 +438,43 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
}
private DateTime? _expectedForCurrentEntry;
// ── Multiline buffer caps ─────────────────────────────────────────────
/// <summary>
/// 100 raw lines of unbounded length could still assemble a multi-megabyte entry. The
/// char cap drops such an entry (its marker never fires) and says so at Warning, which
/// is visible at the default Info level — a capped real entry would be news worth
/// reacting to. A same-shaped entry under the cap still assembles and matches.
/// </summary>
[Theory]
[InlineData(2 * 1024 * 1024, false)] // over cap → dropped, warned
[InlineData(64 * 1024, true)] // under cap → assembled, matched
public async Task MultilineEntry_IsDroppedAndWarned_WhenItExceedsTheCharCap(int fillerChars, bool expectMatch)
{
using var h = new Harness();
h.Append("AgentExecutor.log", Line("marker 0", h.Now, TimeSpan.Zero));
await h.Pass();
var matched = new List<string>();
h.Tracker.OnPatternMatched += id => matched.Add(id);
// One entry spanning 3 physical lines; the closing trailer sits on the last line.
var filler = new string('x', fillerChars / 2);
h.Append("AgentExecutor.log", "<![LOG[write output done. output = " + filler);
h.Append("AgentExecutor.log", filler);
h.Append("AgentExecutor.log", Line("marker 7", h.Now, TimeSpan.Zero).Substring("<![LOG[".Length));
h.Now = T0.AddSeconds(10);
await h.Pass();
Assert.Equal(expectMatch ? 1 : 0, matched.Count);
var agentLog = string.Concat(Directory.GetFiles(h.PathOf(""), "*.log")
.Where(f => !Path.GetFileName(f).Equals("AgentExecutor.log", StringComparison.OrdinalIgnoreCase))
.Select(File.ReadAllText));
if (expectMatch)
Assert.DoesNotContain("discarding multiline CMTrace buffer", agentLog);
else
Assert.Contains("discarding multiline CMTrace buffer in AgentExecutor.log", agentLog);
}
}
}
@@ -123,12 +123,23 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
// "write output done. output = ..." spans many lines)
StringBuilder multiLineBuffer = null;
int multiLineCount = 0;
// Set after a capped entry is dropped: its remaining physical lines
// are skipped instead of being matched as raw text, until the entry
// closes or a new entry begins (so no real entry is lost).
bool skippingDroppedEntry = false;
string line;
while ((line = await reader.ReadLineAsync()) != null)
{
if (token.IsCancellationRequested) break;
if (skippingDroppedEntry)
{
if (line.Contains("]LOG]!>")) { skippingDroppedEntry = false; continue; }
if (!line.StartsWith("<![LOG[")) continue;
skippingDroppedEntry = false;
}
// --- Multiline CMTrace buffering ---
// CMTrace entries: <![LOG[message]LOG]!><time=...>
// When message contains newlines, the entry spans multiple lines.
@@ -146,12 +157,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
multiLineBuffer = null;
multiLineCount = 0;
}
else if (multiLineCount >= MaxMultiLineBufferLines)
else if (multiLineCount >= MaxMultiLineBufferLines || multiLineBuffer.Length >= MaxMultiLineBufferChars)
{
// Safety limit — discard to prevent unbounded memory usage
_logger.Debug($"ImeLogTracker: discarding multiline CMTrace buffer after {multiLineCount} lines (corrupt entry?)");
// Safety limit — discard to bound memory and parser work. Warning
// (not Debug) so a capped entry is visible in the client log at the
// default level: a real IME entry this large would be news.
_logger.Warning($"ImeLogTracker: discarding multiline CMTrace buffer in {Path.GetFileName(filePath)} after {multiLineCount} lines / {multiLineBuffer.Length} chars (cap {MaxMultiLineBufferLines} lines / {MaxMultiLineBufferChars} chars) — entry dropped");
multiLineBuffer = null;
multiLineCount = 0;
skippingDroppedEntry = true;
continue;
}
else
@@ -224,6 +224,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
private const int MaxScriptOutputLength = 2048;
private const int MaxMultiLineBufferLines = 100;
// Companion byte cap: 100 raw lines of unbounded length could still assemble a
// multi-megabyte entry. Any process able to append to a tailed log can plant one; the
// parser is linear, but memory and the per-entry work must stay bounded regardless.
// Real IME entries (AgentExecutor script output is capped by IME itself) stay far below.
internal const int MaxMultiLineBufferChars = 1024 * 1024;
// Counter for HS-NEW-RESULT JSON parse failures — visible to operators via tracker
// metrics so we can detect IME log-format drift in production.
@@ -0,0 +1,39 @@
using AutopilotMonitor.Functions.DataAccess.TableStorage;
using Xunit;
namespace AutopilotMonitor.Functions.Tests;
/// <summary>
/// BlockedDevices rows must be keyed case-insensitively: the enforcement cache
/// (BlockedDeviceService) and Autopilot inventory validation both compare serials
/// OrdinalIgnoreCase, so a case-variant serial must resolve to the same storage row.
/// </summary>
public class TableDeviceSecurityRepositoryKeyTests
{
[Theory]
[InlineData("ABC123", "ABC123")]
[InlineData("abc123", "ABC123")]
[InlineData(" aBc123 ", "ABC123")]
[InlineData(null, "")]
public void CanonicalizeSerial_TrimsAndUpperCases(string? input, string expected)
=> Assert.Equal(expected, TableDeviceSecurityRepository.CanonicalizeSerial(input));
[Theory]
[InlineData("ABC123", "abc123")]
[InlineData("ABC123", "Abc123 ")]
[InlineData("PF/1#2", "pf/1#2")]
public void DeviceRowKey_IsIdenticalForCaseVariants(string a, string b)
=> Assert.Equal(TableDeviceSecurityRepository.DeviceRowKey(a), TableDeviceSecurityRepository.DeviceRowKey(b));
[Fact]
public void DeviceRowKey_EscapesReservedCharacters()
=> Assert.Equal("PF%2F1%232", TableDeviceSecurityRepository.DeviceRowKey("pf/1#2"));
[Fact]
public void LegacyDeviceRowKey_IsNull_WhenAlreadyCanonical()
=> Assert.Null(TableDeviceSecurityRepository.LegacyDeviceRowKey("ABC123"));
[Fact]
public void LegacyDeviceRowKey_IsVerbatimKey_WhenCaseDiffers()
=> Assert.Equal("abc123", TableDeviceSecurityRepository.LegacyDeviceRowKey("abc123"));
}
@@ -1,3 +1,5 @@
using System.Diagnostics;
using System.Linq;
using System.Text.RegularExpressions;
using AutopilotMonitor.Functions.Functions.Rules;
@@ -142,4 +144,26 @@ public class TestLogPatternFunctionTests
}));
}
}
// ===== hostile sample lines: the built-in CMTrace parser must stay bounded =====
/// <summary>A maximal request (200 x 8192-char lines) built from the reported worst case:
/// each line passes the CMTrace prefix gate and never matches. The built-in parser used to
/// backtrack quadratically here (~1.4e9 steps per request) — before the tenant's own
/// 1-second-timeout regex ever ran.</summary>
[Fact]
public void CmTraceMode_WorstCaseSampleLines_CompleteInBoundedTime()
{
var line = string.Concat(Enumerable.Repeat("<![LOG[", 585)) + new string(']', 4097);
Assert.Equal(TestLogPatternFunction.MaxLineLength, line.Length);
var lines = Enumerable.Repeat(line, TestLogPatternFunction.MaxSampleLines).ToArray();
var sw = Stopwatch.StartNew();
var result = TestLogPatternFunction.EvaluatePattern(AgentRegex("error"), isTextMode: false, lines);
sw.Stop();
Assert.Equal(TestLogPatternFunction.MaxSampleLines, result.ParseFailureCount);
Assert.All(result.Lines, l => Assert.Equal("parse_failed", l.Outcome));
Assert.True(sw.ElapsedMilliseconds < 1000, $"maximal worst-case request took {sw.ElapsedMilliseconds} ms");
}
}
@@ -43,24 +43,44 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
if (string.IsNullOrEmpty(tenantId) || string.IsNullOrEmpty(serialNumber))
return (false, null, "Block", null);
var entity = await GetDeviceBlockEntityAsync(tenantId, serialNumber);
if (entity == null)
return (false, null, "Block", null);
var unblockAt = entity.GetDateTimeOffset("UnblockAt")?.UtcDateTime ?? DateTime.MinValue;
if (DateTime.UtcNow >= unblockAt)
return (false, null, "Block", null);
var action = entity.GetString("Action") ?? "Block";
var blockedSessionIds = entity.GetString("BlockedSessionIds");
return (true, unblockAt, action, blockedSessionIds);
}
/// <summary>
/// Point-reads the block row for a serial under its canonical key, falling back to the
/// legacy verbatim-case key for rows written before serials were canonicalized.
/// Returns null when neither exists.
/// </summary>
private async Task<TableEntity?> GetDeviceBlockEntityAsync(string tenantId, string serialNumber)
{
var entity = await TryGetEntityAsync(tenantId, DeviceRowKey(serialNumber));
if (entity != null)
return entity;
var legacyKey = LegacyDeviceRowKey(serialNumber);
return legacyKey == null ? null : await TryGetEntityAsync(tenantId, legacyKey);
}
private async Task<TableEntity?> TryGetEntityAsync(string partitionKey, string rowKey)
{
try
{
var response = await _blockedDevicesTable.GetEntityAsync<TableEntity>(tenantId, EncodeRowKey(serialNumber));
var entity = response?.Value;
if (entity == null)
return (false, null, "Block", null);
var unblockAt = entity.GetDateTimeOffset("UnblockAt")?.UtcDateTime ?? DateTime.MinValue;
if (DateTime.UtcNow >= unblockAt)
return (false, null, "Block", null);
var action = entity.GetString("Action") ?? "Block";
var blockedSessionIds = entity.GetString("BlockedSessionIds");
return (true, unblockAt, action, blockedSessionIds);
var response = await _blockedDevicesTable.GetEntityAsync<TableEntity>(partitionKey, rowKey);
return response?.Value;
}
catch (RequestFailedException ex) when (ex.Status == 404)
{
return (false, null, "Block", null);
return null;
}
}
@@ -81,6 +101,7 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
}
result.Add(MapToBlockedDeviceEntry(entity, tenantId, now));
await MigrateLegacyRowKeyAsync(entity);
}
// Clean up expired entries (fire-and-forget, best effort)
@@ -106,6 +127,7 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
}
result.Add(MapToBlockedDeviceEntry(entity, entity.PartitionKey, now));
await MigrateLegacyRowKeyAsync(entity);
}
// Clean up expired entries (fire-and-forget, best effort)
@@ -123,37 +145,31 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
{
var now = DateTime.UtcNow;
var unblockAt = now.AddHours(durationHours);
var canonicalSerial = CanonicalizeSerial(serialNumber);
// If a session-aware block already exists, merge session IDs
string? blockedSessionIds = blockedSessionId;
if (!string.IsNullOrEmpty(blockedSessionId))
{
try
{
var existing = await _blockedDevicesTable.GetEntityAsync<TableEntity>(tenantId, EncodeRowKey(serialNumber));
var existingSessionIds = existing?.Value?.GetString("BlockedSessionIds");
var existing = await GetDeviceBlockEntityAsync(tenantId, serialNumber);
var existingSessionIds = existing?.GetString("BlockedSessionIds");
if (existingSessionIds == null)
{
// Existing whole-device block takes precedence — don't downgrade to session-aware
if (existing?.Value != null)
blockedSessionIds = null;
}
else
{
// Merge: append new session ID if not already present
blockedSessionIds = MergeSessionId(existingSessionIds, blockedSessionId);
}
}
catch (RequestFailedException ex) when (ex.Status == 404)
if (existingSessionIds == null)
{
// No existing record — use single session ID
// Existing whole-device block takes precedence — don't downgrade to session-aware
if (existing != null)
blockedSessionIds = null;
}
else
{
// Merge: append new session ID if not already present
blockedSessionIds = MergeSessionId(existingSessionIds, blockedSessionId);
}
}
var entity = new TableEntity(tenantId, EncodeRowKey(serialNumber))
var entity = new TableEntity(tenantId, DeviceRowKey(serialNumber))
{
["SerialNumber"] = serialNumber,
["SerialNumber"] = canonicalSerial,
["BlockedAt"] = now,
["UnblockAt"] = unblockAt,
["BlockedByEmail"] = blockedByEmail ?? string.Empty,
@@ -166,7 +182,8 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
entity["BlockedSessionIds"] = blockedSessionIds;
await _blockedDevicesTable.UpsertEntityAsync(entity);
await _publisher.PublishAsync("device.blocked", new { tenantId, serialNumber, action, durationHours }, tenantId);
await DeleteLegacyRowAsync(tenantId, serialNumber);
await _publisher.PublishAsync("device.blocked", new { tenantId, serialNumber = canonicalSerial, action, durationHours }, tenantId);
}
internal static string MergeSessionId(string? existingList, string newSessionId)
@@ -189,16 +206,10 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
public async Task UnblockDeviceAsync(string tenantId, string serialNumber)
{
try
{
await _blockedDevicesTable.DeleteEntityAsync(tenantId, EncodeRowKey(serialNumber));
}
catch (RequestFailedException ex) when (ex.Status == 404)
{
// Already removed
}
await DeleteIgnoringNotFoundAsync(tenantId, DeviceRowKey(serialNumber));
await DeleteLegacyRowAsync(tenantId, serialNumber);
await _publisher.PublishAsync("device.unblocked", new { tenantId, serialNumber }, tenantId);
await _publisher.PublishAsync("device.unblocked", new { tenantId, serialNumber = CanonicalizeSerial(serialNumber) }, tenantId);
}
// -----------------------------------------------------------------------
@@ -396,6 +407,85 @@ namespace AutopilotMonitor.Functions.DataAccess.TableStorage
}
}
/// <summary>
/// Serial numbers are matched case-insensitively everywhere else (agent inventory
/// validation, BlockedDeviceService cache), so the storage key must not depend on the
/// casing the admin typed or the agent reported: trim + upper-case invariant.
/// </summary>
internal static string CanonicalizeSerial(string? serialNumber)
=> (serialNumber ?? string.Empty).Trim().ToUpperInvariant();
/// <summary>Canonical BlockedDevices RowKey for a serial number.</summary>
internal static string DeviceRowKey(string? serialNumber)
=> EncodeRowKey(CanonicalizeSerial(serialNumber));
/// <summary>
/// RowKey a pre-canonicalization row would have been written under (verbatim case),
/// or null when it is identical to the canonical key.
/// </summary>
internal static string? LegacyDeviceRowKey(string? serialNumber)
{
var legacy = EncodeRowKey(serialNumber ?? string.Empty);
return string.Equals(legacy, DeviceRowKey(serialNumber), StringComparison.Ordinal) ? null : legacy;
}
/// <summary>
/// Re-keys a row written under a non-canonical RowKey to its canonical key (best effort).
/// Runs from the list paths so the pre-canonicalization backlog drains over time.
/// </summary>
private async Task MigrateLegacyRowKeyAsync(TableEntity entity)
{
var serial = entity.GetString("SerialNumber") ?? DecodeRowKey(entity.RowKey);
var canonicalKey = DeviceRowKey(serial);
if (string.Equals(entity.RowKey, canonicalKey, StringComparison.Ordinal))
return;
try
{
var migrated = new TableEntity(entity.PartitionKey, canonicalKey);
foreach (var kv in entity)
{
if (kv.Key is "PartitionKey" or "RowKey" or "Timestamp" or "odata.etag" or "ETag")
continue;
migrated[kv.Key] = kv.Value;
}
migrated["SerialNumber"] = CanonicalizeSerial(serial);
// Never clobber a canonical row that already exists (it is the newer write).
await _blockedDevicesTable.AddEntityAsync(migrated);
}
catch (RequestFailedException ex) when (ex.Status == 409)
{
// Canonical row already present — just drop the legacy duplicate below.
}
catch (Exception ex)
{
_logger.LogWarning(ex, "Failed to migrate legacy BlockedDevices row {PartitionKey}/{RowKey}", entity.PartitionKey, entity.RowKey);
return;
}
await DeleteIgnoringNotFoundAsync(entity.PartitionKey, entity.RowKey);
}
private async Task DeleteLegacyRowAsync(string tenantId, string serialNumber)
{
var legacyKey = LegacyDeviceRowKey(serialNumber);
if (legacyKey != null)
await DeleteIgnoringNotFoundAsync(tenantId, legacyKey);
}
private async Task DeleteIgnoringNotFoundAsync(string partitionKey, string rowKey)
{
try
{
await _blockedDevicesTable.DeleteEntityAsync(partitionKey, rowKey);
}
catch (RequestFailedException ex) when (ex.Status == 404)
{
// Already removed
}
}
/// <summary>Azure Table RowKey must not contain /\#? and must be &lt;= 1KB. URL-encode to be safe.</summary>
internal static string EncodeRowKey(string value)
=> Uri.EscapeDataString(value);
@@ -73,32 +73,84 @@ namespace AutopilotMonitor.Shared.Logging
/// </summary>
public static class CmTraceLogParser
{
// Pre-compiled regex for the CMTrace format. The time field may carry a UTC-bias
// suffix in minutes ("06:08:04.8834397+480", GetTimeZoneInformation convention:
// UTC = local + bias) — without the optional bias group such lines would not match
// at all and their content would be invisible to every pattern.
private static readonly Regex CmTraceRegex = new Regex(
@"<!\[LOG\[(?<message>.*)\]LOG\]!><time=""(?<time>[\d:.]+)(?<bias>[+-]\d{1,4})?""\s+date=""(?<date>[\d-]+)""\s+component=""(?<component>[^""]*)""\s+context=""[^""]*""\s+type=""(?<type>\d+)""\s+thread=""(?<thread>\d+)""\s+file=""[^""]*"">",
RegexOptions.Compiled | RegexOptions.Singleline
/// <summary>
/// Every CMTrace line has the shape <c>&lt;![LOG[message]LOG]!&gt;&lt;time=... file=""&gt;</c>. The
/// parser deliberately does NOT express that as one regex with a greedy <c>.*</c> message
/// group in front of the <c>]LOG]!&gt;&lt;time="</c> literal: on a line that never matches, such a
/// regex re-tries every <c>&lt;![LOG[</c> occurrence as a fresh start and, for each, backtracks
/// <c>.*</c> across every later character — Theta(k*m), quadratic in line length. Both sinks
/// parse attacker-influenced input (tenant-supplied sample lines on the backend, tailed log
/// files assembled into multi-line entries on the SYSTEM agent), so the cost must be linear.
///
/// <para>
/// The greedy regex's semantics are reproduced exactly with string search: the message
/// starts after the FIRST <c>&lt;![LOG[</c> (a later start can only match when the first one
/// does too, since <c>.*</c> spans the difference), and the message ends at the LAST
/// <c>]LOG]!&gt;&lt;time="</c> occurrence whose trailer parses — earlier occurrences are tried in
/// turn exactly as backtracking would. The trailer regex is anchored with <c>\G</c>, has no
/// ambiguous quantifier, and additionally carries a match timeout as a backstop; a timeout
/// is reported as "does not match", never thrown.
/// </para>
/// </summary>
private const string LogOpen = "<![LOG[";
private const string TrailerOpen = "]LOG]!><time=\"";
// The time field may carry a UTC-bias suffix in minutes ("06:08:04.8834397+480",
// GetTimeZoneInformation convention: UTC = local + bias) — without the optional bias
// group such lines would not match at all and their content would be invisible to
// every pattern.
private static readonly Regex TrailerRegex = new Regex(
@"\G\]LOG\]!><time=""(?<time>[\d:.]+)(?<bias>[+-]\d{1,4})?""\s+date=""(?<date>[\d-]+)""\s+component=""(?<component>[^""]*)""\s+context=""[^""]*""\s+type=""(?<type>\d+)""\s+thread=""(?<thread>\d+)""\s+file=""[^""]*"">",
RegexOptions.Compiled,
TimeSpan.FromSeconds(1)
);
/// <summary>
/// Attempts to parse a single line of CMTrace-formatted log.
/// Returns true if parsing succeeded, false if the line doesn't match the format.
/// Cost is linear in the line length for arbitrary input; it never throws.
/// </summary>
public static bool TryParseLine(string? line, [NotNullWhen(true)] out CmTraceLogEntry? entry)
{
entry = null;
// netstandard2.0's IsNullOrEmpty lacks [NotNullWhen(false)] — assert non-null after it.
if (string.IsNullOrEmpty(line) || !line!.StartsWith("<![LOG["))
// StartsWith is culture-sensitive on purpose: a leading BOM (U+FEFF) is ignorable
// there, so a freshly created log's first line still parses.
if (string.IsNullOrEmpty(line) || !line!.StartsWith(LogOpen))
return false;
var match = CmTraceRegex.Match(line);
if (!match.Success)
var open = line.IndexOf(LogOpen, StringComparison.Ordinal);
if (open < 0)
return false;
var messageStart = open + LogOpen.Length;
Match? match = null;
var trailerPos = line.LastIndexOf(TrailerOpen, StringComparison.Ordinal);
try
{
while (trailerPos >= messageStart)
{
var candidate = TrailerRegex.Match(line, trailerPos);
if (candidate.Success)
{
match = candidate;
break;
}
if (trailerPos == messageStart)
break;
trailerPos = line.LastIndexOf(TrailerOpen, trailerPos - 1, StringComparison.Ordinal);
}
}
catch (RegexMatchTimeoutException)
{
return false;
}
if (match == null)
return false;
var message = match.Groups["message"].Value;
var message = line.Substring(messageStart, trailerPos - messageStart);
var timeStr = match.Groups["time"].Value;
var biasStr = match.Groups["bias"].Value;
var dateStr = match.Groups["date"].Value;