mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-26 05:29:43 +00:00
Compare commits
3 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| d294415d29 | |||
| 76af1234ed | |||
| 0515523e49 |
@@ -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
|
||||
|
||||
|
||||
@@ -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 `< - 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.
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -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
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -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
|
||||
|
||||
+107
@@ -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 "<![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");
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+39
@@ -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);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+17
-3
@@ -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");
|
||||
}
|
||||
}
|
||||
|
||||
+133
-43
@@ -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 <= 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><![LOG[message]LOG]!><time=... file=""></c>. The
|
||||
/// parser deliberately does NOT express that as one regex with a greedy <c>.*</c> message
|
||||
/// group in front of the <c>]LOG]!><time="</c> literal: on a line that never matches, such a
|
||||
/// regex re-tries every <c><![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><![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]!><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;
|
||||
|
||||
Reference in New Issue
Block a user