mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 21:19:38 +00:00
Compare commits
9 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| 04b1a7c6e7 | |||
| 3b59dab2df | |||
| 389426f8f2 | |||
| e9dba11b96 | |||
| 828cbb5cd0 | |||
| 93a42ba5e4 | |||
| aaacc6ecb2 | |||
| bbc7a1d8b2 | |||
| 5f00124a86 |
+21
-12
@@ -67,29 +67,34 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
Assert.Equal("EnforcementState: Installing app X", entry.Message);
|
||||
Assert.Equal("AppEnforce", entry.Component);
|
||||
Assert.Equal(1, entry.Type);
|
||||
Assert.NotEqual(default, entry.Timestamp);
|
||||
Assert.True(entry.HasTimestamp);
|
||||
Assert.NotEqual(default, entry.LocalTimestamp);
|
||||
// Bias-less line: the parser refuses to guess the writer's zone, so no UTC value.
|
||||
Assert.Null(entry.BiasMinutes);
|
||||
Assert.Null(entry.TimestampUtc);
|
||||
Assert.Equal(DateTimeKind.Unspecified, entry.LocalTimestamp.Kind);
|
||||
}
|
||||
|
||||
// ── Structurally valid but unparseable timestamp → UtcNow fallback ────
|
||||
// ── Structurally valid but unparseable timestamp → flagged, not invented ──
|
||||
|
||||
[Fact]
|
||||
public void TryParseLine_falls_back_to_utcnow_for_unparseable_timestamp()
|
||||
public void TryParseLine_flags_unparseable_timestamp_instead_of_inventing_one()
|
||||
{
|
||||
// time/date satisfy the regex character classes ([\d:.]+ / [\d-]+) so the line MATCHES,
|
||||
// but "13-45-2026" / "25:99:99" fail every DateTime format → the parser falls back to
|
||||
// DateTime.UtcNow (CmTraceLogParser.cs:57) instead of throwing.
|
||||
var before = DateTime.UtcNow;
|
||||
// but "13-45-2026" / "25:99:99" fail every DateTime format. The parser used to stamp
|
||||
// DateTime.UtcNow here, which made a fabricated value indistinguishable from a real
|
||||
// one downstream. It now reports HasTimestamp=false and leaves the choice of fallback
|
||||
// to the caller, which is the only party that knows what a safe default is in context.
|
||||
var line = CmTraceLine("some message", "25:99:99.0000000", "13-45-2026");
|
||||
|
||||
var ok = CmTraceLogParser.TryParseLine(line, out var entry);
|
||||
var after = DateTime.UtcNow;
|
||||
|
||||
Assert.True(ok);
|
||||
Assert.NotNull(entry);
|
||||
Assert.Equal("some message", entry.Message);
|
||||
// Don't assert an exact instant — only that the fallback stamped a fresh "now"
|
||||
// (a successfully-parsed date would land in 2026, far outside this window).
|
||||
Assert.InRange(entry.Timestamp, before.AddSeconds(-5), after.AddSeconds(5));
|
||||
Assert.False(entry.HasTimestamp);
|
||||
Assert.Equal(default, entry.LocalTimestamp);
|
||||
Assert.Null(entry.TimestampUtc);
|
||||
}
|
||||
|
||||
// ── UTC-bias suffix on the time field → honored, not dropped ──────────
|
||||
@@ -108,10 +113,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
|
||||
Assert.True(ok);
|
||||
Assert.NotNull(entry);
|
||||
// A writer-declared bias IS the fact we otherwise have to measure, so it is honored
|
||||
// and resolved to UTC right here — unlike the bias-less form.
|
||||
Assert.Equal(expectedOffsetMinutes, entry.BiasMinutes);
|
||||
Assert.NotNull(entry.TimestampUtc);
|
||||
Assert.Equal(
|
||||
new DateTime(2026, 7, 29, 11, 46, 19, DateTimeKind.Utc).AddTicks(226610).AddMinutes(expectedOffsetMinutes),
|
||||
entry.Timestamp);
|
||||
Assert.Equal(DateTimeKind.Utc, entry.Timestamp.Kind);
|
||||
entry.TimestampUtc!.Value);
|
||||
Assert.Equal(DateTimeKind.Utc, entry.TimestampUtc!.Value.Kind);
|
||||
}
|
||||
|
||||
// ── Oversized line → parses, no throw, no truncation of the message ───
|
||||
|
||||
+190
@@ -0,0 +1,190 @@
|
||||
using System;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// Pins the measurement contract of <see cref="CmTraceOffsetCalibrator"/>.
|
||||
///
|
||||
/// <para>
|
||||
/// The cases are taken from real sessions: +1 h (GMT to W. Europe, session bfff9b1c) and
|
||||
/// -17 h (a writer left on the Pacific OOBE default while the agent had moved to
|
||||
/// E. Australia). The backlog case is the one the residual guard cannot catch on its own and
|
||||
/// is the reason the freshness rule exists.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public class CmTraceOffsetCalibratorTests
|
||||
{
|
||||
private const string Source = "IntuneManagementExtension.log";
|
||||
private static readonly DateTime UtcNow = new DateTime(2026, 08, 20, 07, 31, 46, DateTimeKind.Utc);
|
||||
|
||||
/// <summary>A line written "now" by a writer that believes it is at <paramref name="offset"/>.</summary>
|
||||
private static DateTime LineWrittenNow(TimeSpan offset, DateTime utcNow)
|
||||
=> DateTime.SpecifyKind(utcNow + offset, DateTimeKind.Unspecified);
|
||||
|
||||
[Theory]
|
||||
[InlineData(2)] // CEST — the bfff9b1c writer
|
||||
[InlineData(1)] // BST — what the agent wrongly assumed there
|
||||
[InlineData(-7)] // PDT — the OOBE default seen in the -17 h sessions
|
||||
[InlineData(10)] // E. Australia
|
||||
[InlineData(14)] // Line Islands, the upper bound
|
||||
[InlineData(-12)] // Dateline, the lower bound
|
||||
public void MeasuresWholeHourOffsets(int hours)
|
||||
{
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
var offset = TimeSpan.FromHours(hours);
|
||||
|
||||
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(offset, UtcNow), UtcNow));
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(sut.TryGetOffset(Source, out measured));
|
||||
Assert.Equal(offset, measured);
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(330)] // India, UTC+5:30
|
||||
[InlineData(345)] // Nepal, UTC+5:45
|
||||
[InlineData(570)] // Adelaide, UTC+9:30 — the +30 min sessions in the field data
|
||||
public void MeasuresQuarterHourOffsets(int minutes)
|
||||
{
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
var offset = TimeSpan.FromMinutes(minutes);
|
||||
|
||||
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(offset, UtcNow), UtcNow));
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(sut.TryGetOffset(Source, out measured));
|
||||
Assert.Equal(offset, measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void AbsorbsPollAndFlushLatency()
|
||||
{
|
||||
// The line was written a moment before we parsed it. That lag must vanish into the
|
||||
// grid rather than shift the measured offset.
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
var lineLocal = LineWrittenNow(TimeSpan.FromHours(2), UtcNow.AddMilliseconds(-450));
|
||||
|
||||
Assert.True(sut.TryCalibrate(Source, lineLocal, UtcNow));
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(sut.TryGetOffset(Source, out measured));
|
||||
Assert.Equal(TimeSpan.FromHours(2), measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RejectsBacklogLine_EvenWhenItRoundsCleanly()
|
||||
{
|
||||
// THE case the residual guard cannot catch alone: a line exactly 30 minutes old is a
|
||||
// clean multiple of the grid, so it rounds with zero residual — and would calibrate
|
||||
// the offset half an hour wrong. Only the caller's freshness rule prevents this from
|
||||
// ever being offered; this test pins that a 30-minute-old line does not silently
|
||||
// produce the true offset.
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
var thirtyMinutesOld = LineWrittenNow(TimeSpan.FromHours(2), UtcNow.AddMinutes(-30));
|
||||
|
||||
Assert.True(sut.TryCalibrate(Source, thirtyMinutesOld, UtcNow));
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(sut.TryGetOffset(Source, out measured));
|
||||
Assert.Equal(TimeSpan.FromMinutes(90), measured);
|
||||
Assert.NotEqual(TimeSpan.FromHours(2), measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RejectsOffGridCandidate()
|
||||
{
|
||||
// 7 minutes off the grid: not fresh, and not a timezone either.
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
var offGrid = LineWrittenNow(TimeSpan.FromHours(2), UtcNow.AddMinutes(-7));
|
||||
|
||||
Assert.False(sut.TryCalibrate(Source, offGrid, UtcNow));
|
||||
|
||||
TimeSpan ignored;
|
||||
Assert.False(sut.TryGetOffset(Source, out ignored));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RejectsOffsetOutsideAnyRealTimezone()
|
||||
{
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
var absurd = LineWrittenNow(TimeSpan.FromHours(20), UtcNow);
|
||||
|
||||
Assert.False(sut.TryCalibrate(Source, absurd, UtcNow));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SelfHeals_WhenTheWritingProcessPicksUpANewZone()
|
||||
{
|
||||
// The writer restarts mid-session and now believes CEST instead of the stale BST.
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(1), UtcNow), UtcNow));
|
||||
|
||||
var later = UtcNow.AddMinutes(5);
|
||||
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(2), later), later));
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(sut.TryGetOffset(Source, out measured));
|
||||
Assert.Equal(TimeSpan.FromHours(2), measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void IgnoresAnchorOlderThanTheCurrentOne()
|
||||
{
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
Assert.True(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(2), UtcNow), UtcNow));
|
||||
|
||||
// An out-of-order line from before the current anchor must not move the offset back.
|
||||
var earlier = UtcNow.AddMinutes(-10);
|
||||
Assert.False(sut.TryCalibrate(Source, LineWrittenNow(TimeSpan.FromHours(1), earlier), earlier));
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(sut.TryGetOffset(Source, out measured));
|
||||
Assert.Equal(TimeSpan.FromHours(2), measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void KeepsSourcesIndependent()
|
||||
{
|
||||
// IntuneManagementExtension.log and AppWorkload.log are written by different
|
||||
// processes and may hold different beliefs.
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
Assert.True(sut.TryCalibrate("IntuneManagementExtension.log", LineWrittenNow(TimeSpan.FromHours(2), UtcNow), UtcNow));
|
||||
Assert.True(sut.TryCalibrate("AppWorkload.log", LineWrittenNow(TimeSpan.FromHours(-7), UtcNow), UtcNow));
|
||||
|
||||
TimeSpan ime, appWorkload;
|
||||
Assert.True(sut.TryGetOffset("IntuneManagementExtension.log", out ime));
|
||||
Assert.True(sut.TryGetOffset("AppWorkload.log", out appWorkload));
|
||||
Assert.Equal(TimeSpan.FromHours(2), ime);
|
||||
Assert.Equal(TimeSpan.FromHours(-7), appWorkload);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ResolvesTheRealFieldLine_FromSessionBfff9b1c()
|
||||
{
|
||||
// Raw line: <![LOG[Agent version is: 1.104.102.0]LOG]!><time="09:31:46.5192284" ...>
|
||||
// Server-side ReceivedAt puts the true UTC at 07:31:46.4. The old code produced
|
||||
// 08:31:46.5192284 — local minus the agent's stale +1 h belief.
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
var trueUtc = new DateTime(2026, 08, 20, 07, 31, 46, 400, DateTimeKind.Utc);
|
||||
var lineLocal = new DateTime(2026, 08, 20, 09, 31, 46, 519, DateTimeKind.Unspecified);
|
||||
|
||||
Assert.True(sut.TryCalibrate(Source, lineLocal, trueUtc));
|
||||
|
||||
DateTime resolved;
|
||||
Assert.True(sut.TryResolveUtc(Source, lineLocal, out resolved));
|
||||
Assert.Equal(DateTimeKind.Utc, resolved.Kind);
|
||||
Assert.Equal(new DateTime(2026, 08, 20, 07, 31, 46, 519, DateTimeKind.Utc), resolved);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ReportsUncalibratedSource_SoTheCallerCanFlagIt()
|
||||
{
|
||||
var sut = new CmTraceOffsetCalibrator();
|
||||
|
||||
DateTime resolved;
|
||||
Assert.False(sut.TryResolveUtc(Source, UtcNow, out resolved));
|
||||
}
|
||||
}
|
||||
}
|
||||
+274
@@ -0,0 +1,274 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// End-to-end offset calibration through a real read cycle.
|
||||
///
|
||||
/// <para>
|
||||
/// A CMTrace line states local time and nothing else, so its UTC value depends on which zone
|
||||
/// the WRITING process believed it was in. The tracker used to substitute its own belief,
|
||||
/// which is right only when the two happen to agree.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// These tests are deliberately independent of the machine they run on: the assertion is
|
||||
/// always "a line written at instant T resolves to T", for every writer belief. That single
|
||||
/// property covers both field cases at once — the writer disagreeing with us (the bug) and
|
||||
/// the writer agreeing with us (the majority, which a naive fix would have broken).
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerOffsetCalibrationTests
|
||||
{
|
||||
private const string LogFileName = "IntuneManagementExtension.log";
|
||||
private static readonly DateTime T0 = new DateTime(2026, 8, 20, 7, 30, 0, DateTimeKind.Utc);
|
||||
|
||||
private static List<ImeLogPattern> Patterns() => new List<ImeLogPattern>
|
||||
{
|
||||
new ImeLogPattern
|
||||
{
|
||||
PatternId = "T-MARK", Category = "always", Enabled = true,
|
||||
Pattern = @"marker (?<n>\d+)",
|
||||
Action = "noop",
|
||||
Parameters = new Dictionary<string, string>(),
|
||||
},
|
||||
};
|
||||
|
||||
/// <summary>A CMTrace line as a writer holding <paramref name="writerOffset"/> renders instant <paramref name="utcInstant"/>.</summary>
|
||||
private static string Line(string message, DateTime utcInstant, TimeSpan writerOffset)
|
||||
{
|
||||
var local = utcInstant + writerOffset;
|
||||
return $"<![LOG[{message}]LOG]!><time=\"{local:HH:mm:ss.fffffff}\" date=\"{local:M-d-yyyy}\" " +
|
||||
"component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"1\" file=\"\">";
|
||||
}
|
||||
|
||||
private sealed class Harness : IDisposable
|
||||
{
|
||||
private readonly TempDirectory _tmp = new TempDirectory();
|
||||
public ImeLogTracker Tracker { get; }
|
||||
public DateTime Now { get; set; } = T0;
|
||||
|
||||
public Harness()
|
||||
{
|
||||
Tracker = new ImeLogTracker(
|
||||
logFolder: _tmp.Path,
|
||||
patterns: Patterns(),
|
||||
logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info));
|
||||
Tracker.UtcNowProvider = () => Now;
|
||||
}
|
||||
|
||||
public string LogPath => Path.Combine(_tmp.Path, LogFileName);
|
||||
|
||||
public void Append(string line) => File.AppendAllText(LogPath, line + Environment.NewLine);
|
||||
|
||||
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
public void Dispose()
|
||||
{
|
||||
Tracker.Dispose();
|
||||
_tmp.Dispose();
|
||||
}
|
||||
}
|
||||
|
||||
[Theory]
|
||||
// The writer's belief. The MEASUREMENT must recover it exactly, whatever it is.
|
||||
[InlineData(2)] // CEST
|
||||
[InlineData(1)] // BST
|
||||
[InlineData(-7)] // PDT — the OOBE default behind the -17 h and -9 h field cases
|
||||
[InlineData(10)] // E. Australia
|
||||
[InlineData(0)] // UTC
|
||||
public async Task MeasuresTheWritersOffsetExactly_ForAnyBelief(int writerOffsetHours)
|
||||
{
|
||||
// NOTE: this used to assert that a line written at T RESOLVES to T. That application
|
||||
// was reverted on 2026-08-20 after session e9753578: one offset per file is wrong when
|
||||
// a file holds two writer eras (IME restarting across a timezone change), which shifted
|
||||
// 5 script_started events by -9 h while their completions stayed correct and inflated
|
||||
// every script duration to ~32,400 s. Until the calibrator is era-aware, the measured
|
||||
// offset is observational and the reader-zone fallback is applied uniformly — wrong in
|
||||
// absolute terms but self-consistent, so derived durations stay right.
|
||||
var writerOffset = TimeSpan.FromHours(writerOffsetHours);
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append(Line("marker 1", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
h.Append(Line("marker 2", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out measured));
|
||||
Assert.Equal(writerOffset, measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task MeasuresTheWritersOffset_NotItsOwn()
|
||||
{
|
||||
using var h = new Harness();
|
||||
var writerOffset = TimeSpan.FromHours(2);
|
||||
|
||||
h.Append(Line("marker 1", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
h.Append(Line("marker 2", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
TimeSpan measured;
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out measured));
|
||||
Assert.Equal(writerOffset, measured);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task DoesNotCalibrateOnFirstSightOfAFile()
|
||||
{
|
||||
// The first pass reads from position 0, so the newest line in the file may be hours
|
||||
// old. Anchoring on it would measure the line's age instead of the writer's offset.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append(Line("marker 1", T0.AddHours(-3), TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
TimeSpan ignored;
|
||||
Assert.False(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out ignored));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task FollowsTheWriterAcrossARestartIntoANewZone()
|
||||
{
|
||||
// IME restarts mid-enrollment and picks up the timezone the OS moved to. The
|
||||
// measurement has to follow, otherwise every later line is off by the difference.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(1)));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
h.Append(Line("marker 2", h.Now, TimeSpan.FromHours(1)));
|
||||
await h.Pass();
|
||||
|
||||
TimeSpan before;
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out before));
|
||||
Assert.Equal(TimeSpan.FromHours(1), before);
|
||||
|
||||
// Writer restarts, now on +2.
|
||||
h.Now = T0.AddSeconds(20);
|
||||
h.Append(Line("marker 3", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(30);
|
||||
var writtenAt = h.Now;
|
||||
h.Append(Line("marker 4", writtenAt, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
TimeSpan after;
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out after));
|
||||
Assert.Equal(TimeSpan.FromHours(2), after);
|
||||
// The measurement follows the restart. Applying it is what the 2026-08-20 revert
|
||||
// removed — that is exactly the case a file with two writer eras breaks.
|
||||
Assert.Equal(120, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task HonorsAWriterDeclaredBiasWithoutMeasuring()
|
||||
{
|
||||
// A line carrying its own bias states the offset outright; it must be used as-is and
|
||||
// must never become a calibration anchor.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var writtenAt = h.Now;
|
||||
var local = writtenAt + TimeSpan.FromHours(-8); // a PST writer
|
||||
h.Append($"<![LOG[marker 2]LOG]!><time=\"{local:HH:mm:ss.fffffff}+480\" date=\"{local:M-d-yyyy}\" " +
|
||||
"component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"1\" file=\"\">");
|
||||
await h.Pass();
|
||||
|
||||
Assert.True(h.Tracker.LastMatchedLogTimestamp.HasValue);
|
||||
Assert.Equal(writtenAt, h.Tracker.LastMatchedLogTimestamp.Value);
|
||||
|
||||
TimeSpan ignored;
|
||||
Assert.False(h.Tracker.OffsetCalibrator.TryGetOffset(LogFileName, out ignored));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RecordsMeasuredOffsetSeparatelyFromTheAppliedOne()
|
||||
{
|
||||
// The regression that forced the revert shipped an event tagged "calibrated" while
|
||||
// carrying an offset that did not hold for that line. Measured and applied are now
|
||||
// separate fields so a future reader cannot mistake one for the other.
|
||||
using var h = new Harness();
|
||||
var writerOffset = TimeSpan.FromHours(-7); // PDT, the OOBE default
|
||||
|
||||
h.Append(Line("marker 1", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
h.Append(Line("marker 2", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(20);
|
||||
h.Append(Line("marker 3", h.Now, writerOffset));
|
||||
await h.Pass();
|
||||
|
||||
// Measured: the writer's actual belief.
|
||||
Assert.Equal(-420, h.Tracker.LastMatchedMeasuredWriterOffsetMinutes);
|
||||
|
||||
// Applied: still the reader zone, and reported as such — never as "calibrated".
|
||||
Assert.NotEqual(CmTraceOffsetOrigin.Calibrated, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RecordsProvenance_AsFallback_BeforeAnyCalibration()
|
||||
{
|
||||
// The warm-up pass: the offset is not measured yet, so the reader zone is assumed and
|
||||
// the event has to say so rather than look source-grounded.
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.None, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
Assert.True(h.Tracker.LastMatchedSourceLocalTimestamp.HasValue);
|
||||
|
||||
// The APPLIED offset is reported even on the fallback path — an event that states no
|
||||
// offset at all cannot be recomputed later, which defeats the purpose of recording
|
||||
// provenance. Asserted against the running machine's zone so this stays portable.
|
||||
var readerZone = (int)TimeZoneInfo.Local
|
||||
.GetUtcOffset(h.Tracker.LastMatchedSourceLocalTimestamp!.Value).TotalMinutes;
|
||||
Assert.Equal(readerZone, h.Tracker.LastMatchedSourceOffsetMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task RecordsProvenance_ForADeclaredBias()
|
||||
{
|
||||
using var h = new Harness();
|
||||
|
||||
h.Append(Line("marker 1", h.Now, TimeSpan.FromHours(2)));
|
||||
await h.Pass();
|
||||
|
||||
h.Now = T0.AddSeconds(10);
|
||||
var local = h.Now + TimeSpan.FromHours(-8);
|
||||
h.Append($"<![LOG[marker 2]LOG]!><time=\"{local:HH:mm:ss.fffffff}+480\" date=\"{local:M-d-yyyy}\" " +
|
||||
"component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"1\" file=\"\">");
|
||||
await h.Pass();
|
||||
|
||||
Assert.Equal(CmTraceOffsetOrigin.Bias, h.Tracker.LastMatchedSourceOffsetOrigin);
|
||||
// Reported in the same sense as a measured offset (local = UTC + offset), so the two
|
||||
// origins are directly comparable; the wire bias uses the opposite convention.
|
||||
Assert.Equal(-480, h.Tracker.LastMatchedSourceOffsetMinutes);
|
||||
}
|
||||
|
||||
}
|
||||
}
|
||||
+175
@@ -0,0 +1,175 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
/// <summary>How the UTC value of a CMTrace line was arrived at. Recorded as evidence.</summary>
|
||||
public enum CmTraceOffsetOrigin
|
||||
{
|
||||
/// <summary>No offset known — the caller fell back to its own clock.</summary>
|
||||
None = 0,
|
||||
|
||||
/// <summary>The writer declared its offset in the line ("+480"). Authoritative.</summary>
|
||||
Bias = 1,
|
||||
|
||||
/// <summary>Offset measured from a freshly appended line. See <see cref="CmTraceOffsetCalibrator"/>.</summary>
|
||||
Calibrated = 2,
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Measures the UTC offset that the process WRITING a CMTrace log believes it is in.
|
||||
///
|
||||
/// <para>
|
||||
/// A CMTrace line carries local time and no offset — IME 1.104 writes
|
||||
/// <c>DateTime.Now.TimeOfDay</c> in both of its trace listeners. Converting such a line with
|
||||
/// the agent's own <c>TimeZoneInfo.Local</c> assumes the two processes agree, and they do not:
|
||||
/// both cache their zone at process start and neither follows a later <c>tzutil</c> or a
|
||||
/// Windows auto-timezone change. The resulting error is
|
||||
/// <c>Offset_writer - Offset_agent</c> and is zero only by coincidence. Field measurement over
|
||||
/// 11,068 sessions found 26 sessions carrying a real zone-offset error, from +1 h
|
||||
/// (GMT to W. Europe) to -17 h (a writer still on the Pacific OOBE default while the agent had
|
||||
/// already moved to E. Australia).
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// So the offset is MEASURED, not assumed. The tracker tails the log on a 100 ms poll, so a
|
||||
/// line that appeared since the previous pass was written essentially "now":
|
||||
/// <code>
|
||||
/// candidate = lineLocalTime - agentUtcNow
|
||||
/// offset = round(candidate / 15 min) * 15 min
|
||||
/// lineUtc = lineLocalTime - offset
|
||||
/// </code>
|
||||
/// Every real UTC offset is a whole multiple of 15 minutes, so the rounding absorbs poll and
|
||||
/// flush latency without ambiguity.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// THE FRESHNESS REQUIREMENT IS WHAT MAKES THIS CORRECT. An anchor must be the newest line of
|
||||
/// a pass in which the file actually GREW. Without that rule a backlog line that happens to be
|
||||
/// an exact multiple of 15 minutes old (30 min, 45 min, ...) rounds to a clean value with zero
|
||||
/// residual and calibrates the offset to a wrong figure — the residual guard alone cannot
|
||||
/// catch it. Callers must only offer anchors they know to be fresh.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// Calibration is kept per source file: IntuneManagementExtension.log and AppWorkload.log are
|
||||
/// written by different processes and can hold different beliefs. Re-calibrating on every
|
||||
/// fresh anchor makes this self-healing — if the writing process restarts and picks up the
|
||||
/// current zone, the measurement follows within one poll.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class CmTraceOffsetCalibrator
|
||||
{
|
||||
/// <summary>Grid that every real UTC offset sits on.</summary>
|
||||
internal static readonly TimeSpan OffsetGrid = TimeSpan.FromMinutes(15);
|
||||
|
||||
/// <summary>
|
||||
/// How far a candidate may sit off the grid before it is rejected. Poll latency (100 ms)
|
||||
/// plus the writer's flush latency are far below this; anything larger means the anchor
|
||||
/// was not actually fresh.
|
||||
/// </summary>
|
||||
internal static readonly TimeSpan MaxGridResidual = TimeSpan.FromMinutes(2);
|
||||
|
||||
/// <summary>Real UTC offsets span UTC-12 (Dateline) to UTC+14 (Line Islands).</summary>
|
||||
internal static readonly TimeSpan MinOffset = TimeSpan.FromHours(-12);
|
||||
|
||||
/// <summary>Upper bound of a real UTC offset. See <see cref="MinOffset"/>.</summary>
|
||||
internal static readonly TimeSpan MaxOffset = TimeSpan.FromHours(14);
|
||||
|
||||
private sealed class Anchor
|
||||
{
|
||||
public TimeSpan Offset;
|
||||
public DateTime LocalTimestamp;
|
||||
}
|
||||
|
||||
private readonly object _lock = new object();
|
||||
|
||||
private readonly Dictionary<string, Anchor> _bySource =
|
||||
new Dictionary<string, Anchor>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
/// <summary>
|
||||
/// Offer a freshly appended line as a calibration anchor.
|
||||
/// <para>
|
||||
/// The caller MUST only pass a line it knows to be fresh — the newest line of a pass in
|
||||
/// which the file grew. See the freshness note on this class.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
/// <param name="sourceKey">Log file identity; the file name is enough.</param>
|
||||
/// <param name="localTimestamp">The line's local time exactly as written (Kind is ignored).</param>
|
||||
/// <param name="agentUtcNow">The agent's UTC clock at parse time.</param>
|
||||
/// <returns><c>true</c> when the anchor was accepted and the offset updated.</returns>
|
||||
public bool TryCalibrate(string sourceKey, DateTime localTimestamp, DateTime agentUtcNow)
|
||||
{
|
||||
if (string.IsNullOrEmpty(sourceKey)) return false;
|
||||
|
||||
var candidate = DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified)
|
||||
- DateTime.SpecifyKind(agentUtcNow, DateTimeKind.Unspecified);
|
||||
|
||||
var gridUnits = Math.Round(candidate.TotalMinutes / OffsetGrid.TotalMinutes,
|
||||
MidpointRounding.AwayFromZero);
|
||||
var offset = TimeSpan.FromMinutes(gridUnits * OffsetGrid.TotalMinutes);
|
||||
|
||||
// Off-grid by more than the tolerance: the anchor was not fresh, or the writer's own
|
||||
// clock is broken. Either way it must not become the offset.
|
||||
if ((candidate - offset).Duration() > MaxGridResidual) return false;
|
||||
|
||||
// Not a value any real timezone can produce.
|
||||
if (offset < MinOffset || offset > MaxOffset) return false;
|
||||
|
||||
lock (_lock)
|
||||
{
|
||||
if (_bySource.TryGetValue(sourceKey, out var existing))
|
||||
{
|
||||
// Only ever move the anchor forward. A line older than the current anchor
|
||||
// carries nothing newer and could re-introduce a stale belief.
|
||||
if (localTimestamp <= existing.LocalTimestamp) return false;
|
||||
existing.Offset = offset;
|
||||
existing.LocalTimestamp = localTimestamp;
|
||||
}
|
||||
else
|
||||
{
|
||||
_bySource[sourceKey] = new Anchor
|
||||
{
|
||||
Offset = offset,
|
||||
LocalTimestamp = localTimestamp,
|
||||
};
|
||||
}
|
||||
}
|
||||
|
||||
return true;
|
||||
}
|
||||
|
||||
/// <summary>The offset measured for this source, when one has been established.</summary>
|
||||
public bool TryGetOffset(string sourceKey, out TimeSpan offset)
|
||||
{
|
||||
offset = TimeSpan.Zero;
|
||||
if (string.IsNullOrEmpty(sourceKey)) return false;
|
||||
|
||||
lock (_lock)
|
||||
{
|
||||
Anchor anchor;
|
||||
if (!_bySource.TryGetValue(sourceKey, out anchor)) return false;
|
||||
offset = anchor.Offset;
|
||||
return true;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Convert a line's local time to UTC using the measured offset. Returns <c>false</c> when
|
||||
/// this source has not been calibrated yet — the caller then picks its own fallback and
|
||||
/// should mark the result as not source-grounded.
|
||||
/// </summary>
|
||||
public bool TryResolveUtc(string sourceKey, DateTime localTimestamp, out DateTime utc)
|
||||
{
|
||||
utc = default(DateTime);
|
||||
|
||||
TimeSpan offset;
|
||||
if (!TryGetOffset(sourceKey, out offset)) return false;
|
||||
|
||||
utc = DateTime.SpecifyKind(
|
||||
DateTime.SpecifyKind(localTimestamp, DateTimeKind.Unspecified) - offset,
|
||||
DateTimeKind.Utc);
|
||||
return true;
|
||||
}
|
||||
}
|
||||
}
|
||||
+165
-6
@@ -42,7 +42,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
return false;
|
||||
}
|
||||
|
||||
private async Task CheckLogFilesAsync(CancellationToken token)
|
||||
/// <remarks>internal (not private) as a test seam: the offset calibration depends on the
|
||||
/// pass structure — first observation versus a later pass over a grown file — which only
|
||||
/// a real read cycle exercises. Production still reaches it solely from the poll loop.</remarks>
|
||||
internal async Task CheckLogFilesAsync(CancellationToken token)
|
||||
{
|
||||
if (!Directory.Exists(_logFolder))
|
||||
return;
|
||||
@@ -74,6 +77,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var fileInfo = new FileInfo(filePath);
|
||||
if (!fileInfo.Exists) continue;
|
||||
|
||||
// Captured BEFORE GetSafePosition, which creates the entry as a side effect.
|
||||
// Growth measured against a previously observed size is what makes the last
|
||||
// line of this pass a valid "written now" calibration anchor.
|
||||
var hadPreviousObservation = _positionTracker.HasSeen(filePath);
|
||||
|
||||
var startPos = _positionTracker.GetSafePosition(filePath, fileInfo.Length);
|
||||
if (startPos >= fileInfo.Length)
|
||||
{
|
||||
@@ -86,6 +94,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (_logger.LogLevel >= AgentLogLevel.Trace)
|
||||
_logger.Trace($"ImeLogTracker: reading {Path.GetFileName(filePath)} from pos {startPos} (size={fileInfo.Length}, delta={fileInfo.Length - startPos})");
|
||||
|
||||
_currentSourceFileName = Path.GetFileName(filePath);
|
||||
|
||||
// Newest bias-less line of this pass — the calibration anchor. Bias-carrying
|
||||
// lines are skipped: they already state the writer's offset, so they need no
|
||||
// measurement and must not overwrite one.
|
||||
CmTraceLogEntry calibrationAnchor = null;
|
||||
|
||||
using (var stream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
|
||||
{
|
||||
stream.Seek(startPos, SeekOrigin.Begin);
|
||||
@@ -147,6 +162,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (CmTraceLogParser.TryParseLine(line, out entry))
|
||||
{
|
||||
messageToMatch = entry.Message;
|
||||
if (entry.HasTimestamp && !entry.BiasMinutes.HasValue)
|
||||
calibrationAnchor = entry;
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -160,7 +177,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// Simulation mode delay
|
||||
if (SimulationMode && entry != null)
|
||||
{
|
||||
await ApplySimulationDelay(entry.Timestamp, token);
|
||||
await ApplySimulationDelay(ResolveEntryUtc(entry), token);
|
||||
}
|
||||
|
||||
// Match against active patterns
|
||||
@@ -185,6 +202,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
_positionTracker.SetPosition(filePath, stream.Position);
|
||||
_stateDirty = true;
|
||||
|
||||
// Calibrate AFTER the pass: this pass's lines were resolved with the
|
||||
// offset established previously, at most one poll (100 ms) old. Buffering
|
||||
// the pass to calibrate first is not an option — the first pass of
|
||||
// AppWorkload.log can be hundreds of MB. The cost is a warm-up of one
|
||||
// growing pass, during which lines fall back to the reader zone and are
|
||||
// flagged as such.
|
||||
if (hadPreviousObservation && calibrationAnchor != null)
|
||||
CalibrateFrom(_currentSourceFileName, calibrationAnchor);
|
||||
}
|
||||
}
|
||||
catch (FileNotFoundException) { }
|
||||
@@ -222,7 +248,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
private void HandlePatternMatch(CompiledPattern pattern, Match match, string message, CmTraceLogEntry entry)
|
||||
{
|
||||
LastMatchedPatternId = pattern.PatternId;
|
||||
LastMatchedLogTimestamp = entry?.Timestamp;
|
||||
if (entry == null)
|
||||
{
|
||||
LastMatchedLogTimestamp = null;
|
||||
LastMatchedSourceLocalTimestamp = null;
|
||||
LastMatchedSourceOffsetMinutes = null;
|
||||
LastMatchedSourceOffsetOrigin = CmTraceOffsetOrigin.None;
|
||||
LastMatchedMeasuredWriterOffsetMinutes = null;
|
||||
}
|
||||
else
|
||||
{
|
||||
CmTraceOffsetOrigin origin;
|
||||
int? offsetMinutes;
|
||||
LastMatchedLogTimestamp = ResolveEntryUtc(entry, out origin, out offsetMinutes);
|
||||
LastMatchedSourceLocalTimestamp = entry.HasTimestamp ? entry.LocalTimestamp : (DateTime?)null;
|
||||
LastMatchedSourceOffsetMinutes = offsetMinutes;
|
||||
LastMatchedSourceOffsetOrigin = origin;
|
||||
|
||||
// Observational: what the calibrator measured for this file, distinct from what
|
||||
// was applied above.
|
||||
TimeSpan measuredWriterOffset;
|
||||
LastMatchedMeasuredWriterOffsetMinutes =
|
||||
_currentSourceFileName != null
|
||||
&& OffsetCalibrator.TryGetOffset(_currentSourceFileName, out measuredWriterOffset)
|
||||
? (int)measuredWriterOffset.TotalMinutes
|
||||
: (int?)null;
|
||||
}
|
||||
|
||||
// Generic pattern-match hook (M4.4.4). Invoked before action-specific callbacks so
|
||||
// subscribers (e.g. ImeLogTrackerAdapter emitting WhiteGloveSealingPatternDetected)
|
||||
@@ -237,10 +288,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// state nor the phase-change ignore list. SimulationMode (--replay-log-dir dev tool)
|
||||
// replays historic logs on purpose and bypasses the guard.
|
||||
var isStaleReplayLine = !SimulationMode && entry != null
|
||||
&& (UtcNowProvider() - NormalizeUtc(entry.Timestamp)) > HistoricReplayThreshold;
|
||||
&& (UtcNowProvider() - NormalizeUtc(ResolveEntryUtc(entry))) > HistoricReplayThreshold;
|
||||
if (isStaleReplayLine && AppMutatingActions.Contains(pattern.Action?.ToLower() ?? string.Empty))
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({entry.Timestamp:o})");
|
||||
_logger.Debug($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({ResolveEntryUtc(entry):o})");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -524,8 +575,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
internal void ProcessLogMessageForTest(string message, DateTime? sourceTimestampUtc = null)
|
||||
{
|
||||
if (string.IsNullOrEmpty(message)) return;
|
||||
// The test seam hands in an already-resolved UTC instant, so it takes the same route a
|
||||
// writer-declared bias does: TimestampUtc set, no zone left to guess.
|
||||
var entry = sourceTimestampUtc.HasValue
|
||||
? new CmTraceLogEntry { Timestamp = sourceTimestampUtc.Value, Message = message }
|
||||
? new CmTraceLogEntry
|
||||
{
|
||||
TimestampUtc = sourceTimestampUtc.Value,
|
||||
LocalTimestamp = DateTime.SpecifyKind(sourceTimestampUtc.Value, DateTimeKind.Unspecified),
|
||||
HasTimestamp = true,
|
||||
Message = message,
|
||||
}
|
||||
: null;
|
||||
foreach (var pattern in _activePatterns)
|
||||
{
|
||||
@@ -543,5 +602,105 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// Parses [DO TEL] JSON and links it to the correct app via FileId.
|
||||
/// The FileId contains the app GUID in the format: ...intunewin-bin_{appGuid}_{number}
|
||||
/// </summary>
|
||||
|
||||
/// <summary>
|
||||
/// Resolve a parsed CMTrace entry to UTC.
|
||||
///
|
||||
/// <para>
|
||||
/// Order of preference: a writer-declared bias (authoritative) > this process's own zone
|
||||
/// (a fallback carrying a known defect, see
|
||||
/// <see cref="CmTraceLogParser.ResolveUtcAssumingReaderZone"/>) > the agent clock for a
|
||||
/// line with no parseable timestamp.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// The reader-zone step is where the tracker is still wrong when IME's process holds a
|
||||
/// different zone belief than ours. It is preserved verbatim here so that splitting the
|
||||
/// parser changes no behaviour; the measured offset from <c>CmTraceOffsetCalibrator</c>
|
||||
/// slots in at exactly this point in the follow-up change.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
private DateTime ResolveEntryUtc(CmTraceLogEntry entry)
|
||||
{
|
||||
CmTraceOffsetOrigin origin;
|
||||
int? offsetMinutes;
|
||||
return ResolveEntryUtc(entry, out origin, out offsetMinutes);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Resolve a parsed entry to UTC and report HOW the offset was obtained, so the emitting
|
||||
/// side can attach the evidence (P8). See <see cref="CmTraceOffsetOrigin"/>.
|
||||
/// </summary>
|
||||
private DateTime ResolveEntryUtc(CmTraceLogEntry entry, out CmTraceOffsetOrigin origin, out int? offsetMinutes)
|
||||
{
|
||||
origin = CmTraceOffsetOrigin.None;
|
||||
offsetMinutes = null;
|
||||
|
||||
if (entry == null) return UtcNowProvider();
|
||||
|
||||
// Writer declared its own offset — nothing left to measure.
|
||||
if (entry.TimestampUtc.HasValue)
|
||||
{
|
||||
origin = CmTraceOffsetOrigin.Bias;
|
||||
// Bias uses the GetTimeZoneInformation convention (UTC = local + bias); report the
|
||||
// value in the same sense as a measured offset (local = UTC + offset).
|
||||
offsetMinutes = entry.BiasMinutes.HasValue ? -entry.BiasMinutes.Value : (int?)null;
|
||||
return entry.TimestampUtc.Value;
|
||||
}
|
||||
|
||||
if (!entry.HasTimestamp) return UtcNowProvider();
|
||||
|
||||
// REVERTED 2026-08-20 (session e9753578): the measured offset is NOT applied.
|
||||
//
|
||||
// Calibration keeps one offset per FILE, but a single log file can hold lines from
|
||||
// two writer eras — IME restarting across a timezone change leaves older lines in the
|
||||
// old zone and newer ones in the new zone, in the same file. The anchor is the newest
|
||||
// line, so its offset was also applied to the older lines, for which it is wrong. In
|
||||
// the field that shifted 5 script_started events by -9 h while their script_completed
|
||||
// counterparts were resolved correctly, inflating every script duration to ~32,400 s.
|
||||
//
|
||||
// The deeper lesson: applying the reader zone uniformly is wrong for ABSOLUTE times
|
||||
// but self-consistent for DERIVED ones — both ends of a duration are wrong by the same
|
||||
// amount, so the duration is right. Correcting only some timestamps produced a mixed
|
||||
// frame INSIDE one session, which is strictly worse. Until the calibrator is era-aware
|
||||
// (see tasks/todo.md), uniform beats partially-correct.
|
||||
//
|
||||
// The measurement itself still runs: it costs nothing, feeds the Info log and the
|
||||
// event provenance, and is the field data the era-aware fix will be built on.
|
||||
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(entry.LocalTimestamp);
|
||||
offsetMinutes = (int)readerZoneOffset.TotalMinutes;
|
||||
return CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp);
|
||||
}
|
||||
|
||||
/// <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)
|
||||
{
|
||||
TimeSpan previous;
|
||||
var hadOffset = OffsetCalibrator.TryGetOffset(sourceFileName, out previous);
|
||||
|
||||
if (!OffsetCalibrator.TryCalibrate(sourceFileName, anchor.LocalTimestamp, UtcNowProvider()))
|
||||
return;
|
||||
|
||||
TimeSpan measured;
|
||||
if (!OffsetCalibrator.TryGetOffset(sourceFileName, out measured)) return;
|
||||
if (hadOffset && measured == previous) return;
|
||||
|
||||
var readerZoneOffset = TimeZoneInfo.Local.GetUtcOffset(UtcNowProvider());
|
||||
if (measured == readerZoneOffset)
|
||||
{
|
||||
_logger?.Debug(
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured} (matches this process).");
|
||||
return;
|
||||
}
|
||||
|
||||
_logger?.Info(
|
||||
$"ImeLogTracker: {sourceFileName} writer offset measured {measured}, this process believes {readerZoneOffset} " +
|
||||
$"— timestamps from this file are corrected by {(measured - readerZoneOffset).Negate()}.");
|
||||
}
|
||||
|
||||
}
|
||||
}
|
||||
|
||||
@@ -85,6 +85,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// Unspecified depending on the parser path. Normalize via SpecifyKind=Utc rather than
|
||||
/// ToUniversalTime() to avoid double-conversion when Kind is already UTC.
|
||||
/// </summary>
|
||||
/// <summary>
|
||||
/// Measures the UTC offset the IME process believes it is in, per log file.
|
||||
/// <para>
|
||||
/// Only this tracker may WRITE to it: calibration requires tailing with growth detection
|
||||
/// so the freshness rule can be honoured, and no other collector tails. Exposed so the
|
||||
/// snapshot-reading collectors can eventually READ from a shared instance
|
||||
/// (tasks/todo.md, P3b).
|
||||
/// </para>
|
||||
/// </summary>
|
||||
internal CmTraceOffsetCalibrator OffsetCalibrator { get; } = new CmTraceOffsetCalibrator();
|
||||
|
||||
/// <summary>
|
||||
/// File whose lines are currently being processed. The polling loop walks files strictly
|
||||
/// sequentially on a single task, so a field is sufficient to give <c>ResolveEntryUtc</c>
|
||||
/// and the handlers the calibration key without threading it through every signature.
|
||||
/// </summary>
|
||||
private string _currentSourceFileName;
|
||||
|
||||
internal static DateTime NormalizeUtc(DateTime value) =>
|
||||
value.Kind == DateTimeKind.Utc ? value : DateTime.SpecifyKind(value, DateTimeKind.Utc);
|
||||
|
||||
@@ -191,6 +209,38 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public string LastMatchedPatternId { get; internal set; }
|
||||
public DateTime? LastMatchedLogTimestamp { get; internal set; }
|
||||
|
||||
/// <summary>
|
||||
/// Raw local time of the last matched line, exactly as the writer wrote it — no zone
|
||||
/// attached, because the line carries none.
|
||||
/// <para>
|
||||
/// Recorded so an emitted event can carry the evidence for its own timestamp. Without it
|
||||
/// a conversion error is only provable from the diagnostics archive, and of the 5,386
|
||||
/// sessions that went through a timezone change essentially none had one — the field
|
||||
/// analysis had to fall back to median statistics over thousands of sessions to show
|
||||
/// what one stored value would have made obvious per session.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public DateTime? LastMatchedSourceLocalTimestamp { get; internal set; }
|
||||
|
||||
/// <summary>Offset applied to <see cref="LastMatchedSourceLocalTimestamp"/>, in minutes.</summary>
|
||||
public int? LastMatchedSourceOffsetMinutes { get; internal set; }
|
||||
|
||||
/// <summary>How that offset was arrived at — declared, measured, or neither.</summary>
|
||||
public CmTraceOffsetOrigin LastMatchedSourceOffsetOrigin { get; internal set; }
|
||||
|
||||
/// <summary>
|
||||
/// The offset the calibrator MEASURED for the source file, which is not necessarily the
|
||||
/// one applied.
|
||||
/// <para>
|
||||
/// Since the 2026-08-20 revert the measurement is observational only: it is recorded so the
|
||||
/// field tells us what an era-aware calibrator would have to work with, without acting on
|
||||
/// it. Reported separately from <see cref="LastMatchedSourceOffsetMinutes"/> precisely so
|
||||
/// the two can never be confused — that event said "calibrated" while carrying a wrong
|
||||
/// value, and an honest record has to distinguish measured from applied.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public int? LastMatchedMeasuredWriterOffsetMinutes { get; internal set; }
|
||||
|
||||
// Callbacks to EnrollmentTracker
|
||||
public Action<string> OnEspPhaseChanged { get; set; }
|
||||
public Action<string> OnImeAgentVersion { get; set; }
|
||||
|
||||
+12
@@ -19,6 +19,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// has been rotated - resets to 0 to read from beginning.
|
||||
/// Returns 0 if no position has been recorded yet.
|
||||
/// </summary>
|
||||
/// <summary>
|
||||
/// Whether this file was already observed in an earlier pass.
|
||||
/// <para>
|
||||
/// The offset calibration depends on this: growth measured against a size we saw before
|
||||
/// means the new bytes were written within one poll interval, so the last line of that
|
||||
/// pass is a valid "written now" anchor. On the FIRST sight of a file we read it from
|
||||
/// position 0 and its last line may be arbitrarily old — anchoring on that would measure
|
||||
/// the line's age instead of the writer's timezone offset.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public bool HasSeen(string filePath) => _positions.ContainsKey(filePath);
|
||||
|
||||
public long GetSafePosition(string filePath, long currentFileSize)
|
||||
{
|
||||
FilePositionState state;
|
||||
|
||||
+16
-4
@@ -580,10 +580,22 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
var scanText = rawLine;
|
||||
if (CmTraceLogParser.TryParseLine(rawLine, out var entry))
|
||||
{
|
||||
// Provably stale → not progress. (TryParseLine falls back to now on an
|
||||
// unparseable timestamp, which keeps the line fresh — the safe default.)
|
||||
if (entry.Timestamp < cutoffUtc)
|
||||
continue;
|
||||
// Provably stale → not progress. A line without a parseable timestamp counts
|
||||
// as fresh — the safe default, since treating it as stale would hide progress.
|
||||
//
|
||||
// This collector reads a file snapshot rather than tailing it, so it cannot
|
||||
// measure the writer's UTC offset itself and falls back to this process's zone
|
||||
// (see ResolveUtcAssumingReaderZone). That fallback is wrong by exactly the
|
||||
// gap between the two processes' zone beliefs. It is the pre-existing
|
||||
// behaviour, kept deliberately unchanged here; the tracker-owned calibrator is
|
||||
// wired in separately so this commit shifts no behaviour.
|
||||
if (entry.HasTimestamp)
|
||||
{
|
||||
var entryUtc = entry.TimestampUtc
|
||||
?? CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp);
|
||||
if (entryUtc < cutoffUtc)
|
||||
continue;
|
||||
}
|
||||
scanText = entry.Message;
|
||||
}
|
||||
|
||||
|
||||
+11
-2
@@ -331,7 +331,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
data[groupName] = group.Value;
|
||||
}
|
||||
|
||||
data["logTimestamp"] = entry.Timestamp.ToString("o");
|
||||
// Gather-rule logs are arbitrary files this collector does not
|
||||
// tail, so no writer offset can be measured for them; the
|
||||
// reader-zone fallback carries its known defect (see
|
||||
// ResolveUtcAssumingReaderZone). Behaviour unchanged from before
|
||||
// the parser split.
|
||||
var entryUtc = entry.TimestampUtc
|
||||
?? (entry.HasTimestamp
|
||||
? CmTraceLogParser.ResolveUtcAssumingReaderZone(entry.LocalTimestamp)
|
||||
: DateTime.UtcNow);
|
||||
data["logTimestamp"] = entryUtc.ToString("o");
|
||||
data["logComponent"] = entry.Component;
|
||||
data["logType"] = entry.Type;
|
||||
data["logMessage"] = TruncateMessage(entry.Message, 500);
|
||||
@@ -348,7 +357,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
{
|
||||
SessionId = context.SessionId,
|
||||
TenantId = context.TenantId,
|
||||
Timestamp = entry.Timestamp,
|
||||
Timestamp = entryUtc,
|
||||
EventType = eventType,
|
||||
Severity = severity,
|
||||
Source = "GatherRuleExecutor",
|
||||
|
||||
@@ -124,6 +124,17 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
// in ImeLogTracker so the layers can never drift apart).
|
||||
private static readonly TimeSpan StaleSourceThreshold = ImeLogTracker.HistoricReplayThreshold;
|
||||
|
||||
/// <summary>
|
||||
/// How far ahead of the agent clock a source timestamp may sit before it is rejected.
|
||||
/// <para>
|
||||
/// Writer and reader share one system clock, so a correctly converted line is always at
|
||||
/// or behind "now"; this is pure jitter tolerance, not a skew allowance. Deliberately far
|
||||
/// below one hour — the value that a timezone mistake produces — so that such a mistake
|
||||
/// can actually trip it.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
private static readonly TimeSpan MaxFutureSourceSkew = TimeSpan.FromMinutes(2);
|
||||
|
||||
// Matches the deterministic marker line the bootstrap script writes via Write-Log,
|
||||
// e.g. "Bootstrap script version: v2.0" — see scripts/Bootstrap/Install-AutopilotMonitor.ps1.
|
||||
// Same shape as the web-side regex in utils/bootstrapVersion.ts; kept in sync intentionally.
|
||||
@@ -329,12 +340,28 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
|
||||
var clockNow = _clock.UtcNow;
|
||||
var ageHours = (clockNow - asUtc).TotalHours;
|
||||
if (ageHours > StaleSourceThreshold.TotalHours || ageHours < -1.0)
|
||||
|
||||
// Future guard. A source timestamp can never legitimately be ahead of the agent
|
||||
// clock: the writer stamps it from the SAME system clock, and the tracker only
|
||||
// sees the line after it was written. Anything ahead means the local-to-UTC
|
||||
// conversion was wrong.
|
||||
//
|
||||
// The previous threshold was ageHours < -1.0, which could not fire for the single
|
||||
// most common timezone error: with a one-hour offset mistake the real value is
|
||||
// parseLag - 3600 s, i.e. just ABOVE -1.0. It sat exactly on the boundary of the
|
||||
// case it was meant to catch. It was also asymmetric — a past-shifted error had to
|
||||
// exceed 24 h before anything noticed, while the measured field errors reached
|
||||
// -17 h. The bound is now a small jitter tolerance in the direction that is
|
||||
// physically impossible.
|
||||
var isFutureSkewed = asUtc > clockNow + MaxFutureSourceSkew;
|
||||
|
||||
if (ageHours > StaleSourceThreshold.TotalHours || isFutureSkewed)
|
||||
{
|
||||
// Pathologically stale (>24h old) or in the future (>1h skew) — log,
|
||||
// fall back, and let the caller flag the event.
|
||||
var reason = isFutureSkewed
|
||||
? $"ahead of the agent clock by {(asUtc - clockNow).TotalMinutes:F1} min"
|
||||
: $"pathologically stale (ageHours={ageHours:F1})";
|
||||
_logger?.Warning(
|
||||
$"ImeAdapter: source timestamp {asUtc:o} rejected (ageHours={ageHours:F1}); falling back to clock");
|
||||
$"ImeAdapter: source timestamp {asUtc:o} rejected — {reason}; falling back to clock");
|
||||
derivedFromClock = true;
|
||||
return clockNow;
|
||||
}
|
||||
@@ -347,12 +374,66 @@ namespace AutopilotMonitor.Agent.V2.Core.SignalAdapters
|
||||
return _clock.UtcNow;
|
||||
}
|
||||
|
||||
private static void TagDerivedTimestamp(IDictionary<string, string> data, bool derivedFromClock, DateTime? rawSourceTs)
|
||||
/// <summary>
|
||||
/// Attach the evidence for this event's timestamp: the raw local time as the writer wrote
|
||||
/// it, the offset applied, and how that offset was obtained.
|
||||
///
|
||||
/// <para>
|
||||
/// Without this the only record of a conversion is the converted value itself, so a wrong
|
||||
/// offset is indistinguishable from a correct one. Proving the field defect required the
|
||||
/// diagnostics archive — and of the 5,386 sessions that went through a timezone change,
|
||||
/// essentially none had one; the analysis had to fall back to median statistics across
|
||||
/// thousands of sessions. These three fields make each session answer the question on its
|
||||
/// own, and make a stored timestamp recomputable after the fact without an agent release.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// Only emitted for events whose time came from a CMTrace line. Agent-native events have
|
||||
/// no second clock frame, so there is nothing to record.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
private void TagDerivedTimestamp(IDictionary<string, string> data, bool derivedFromClock, DateTime? rawSourceTs)
|
||||
{
|
||||
var culture = System.Globalization.CultureInfo.InvariantCulture;
|
||||
|
||||
var sourceLocal = _tracker.LastMatchedSourceLocalTimestamp;
|
||||
if (sourceLocal.HasValue)
|
||||
{
|
||||
// No zone suffix: the value genuinely carries none, and formatting one in would
|
||||
// re-introduce the very assumption this whole change removes.
|
||||
data["sourceLocalTs"] = sourceLocal.Value.ToString("yyyy-MM-ddTHH:mm:ss.fffffff", culture);
|
||||
data["sourceOffsetOrigin"] = OriginTag(_tracker.LastMatchedSourceOffsetOrigin);
|
||||
|
||||
var offsetMinutes = _tracker.LastMatchedSourceOffsetMinutes;
|
||||
if (offsetMinutes.HasValue)
|
||||
data["sourceOffsetMinutes"] = offsetMinutes.Value.ToString(culture);
|
||||
|
||||
// Observational only — what the calibrator measured, which since the 2026-08-20
|
||||
// revert is deliberately NOT what was applied. Kept separate so the two can never
|
||||
// be read as the same thing.
|
||||
var measured = _tracker.LastMatchedMeasuredWriterOffsetMinutes;
|
||||
if (measured.HasValue)
|
||||
data["measuredWriterOffsetMinutes"] = measured.Value.ToString(culture);
|
||||
}
|
||||
|
||||
if (!derivedFromClock) return;
|
||||
data["derivedTimestamp"] = "true";
|
||||
if (rawSourceTs.HasValue)
|
||||
data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", System.Globalization.CultureInfo.InvariantCulture);
|
||||
data["rejectedSourceTimestamp"] = rawSourceTs.Value.ToString("o", culture);
|
||||
}
|
||||
|
||||
private static string OriginTag(CmTraceOffsetOrigin origin)
|
||||
{
|
||||
switch (origin)
|
||||
{
|
||||
case CmTraceOffsetOrigin.Bias: return "bias";
|
||||
case CmTraceOffsetOrigin.Calibrated: return "calibrated";
|
||||
// Unreachable since the 2026-08-20 revert; kept so the vocabulary survives the
|
||||
// era-aware fix rather than being reinvented.
|
||||
// The writer's offset was never measured, so this process's own zone was assumed —
|
||||
// correct only if the writer happens to share it.
|
||||
default: return "reader-zone-fallback";
|
||||
}
|
||||
}
|
||||
|
||||
// CMTrace Kind normalization — shared implementation lives on the tracker (used by its
|
||||
|
||||
+75
@@ -0,0 +1,75 @@
|
||||
using System;
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests
|
||||
{
|
||||
/// <summary>
|
||||
/// Pins the clock-frame contract of the agent-silence sweep.
|
||||
///
|
||||
/// <para>
|
||||
/// <c>LastEventAt</c> is the maximum AGENT-supplied event timestamp and therefore lives in the
|
||||
/// device clock frame — it carries the device's clock error and, for CMTrace-derived events,
|
||||
/// the writing process's timezone belief. Field measurement over 11k sessions found skews from
|
||||
/// -17 h to +1 h. Comparing that against a server-derived silence cutoff marked live agents
|
||||
/// Stalled ("Agent silent for 1020min") and left genuinely silent ones undetected for the
|
||||
/// duration of the skew. <c>LastIngestAt</c> is stamped from the server clock on every ingest
|
||||
/// and is the only value such a comparison may use.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public class MaintenanceServerFrameLastContactTests
|
||||
{
|
||||
private static readonly DateTime Now = new(2026, 08, 20, 12, 00, 00, DateTimeKind.Utc);
|
||||
|
||||
private static SessionSummary Session(DateTime? lastIngestAt, DateTime? lastEventAt, DateTime startedAt)
|
||||
=> new() { LastIngestAt = lastIngestAt, LastEventAt = lastEventAt, StartedAt = startedAt };
|
||||
|
||||
[Fact]
|
||||
public void PrefersServerFrameIngestStamp_OverDeviceFrameEventStamp()
|
||||
{
|
||||
var s = Session(lastIngestAt: Now.AddMinutes(-1), lastEventAt: Now.AddHours(-17), startedAt: Now.AddHours(-2));
|
||||
Assert.Equal(Now.AddMinutes(-1), MaintenanceService.ServerFrameLastContact(s));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void NegativeSkew_DoesNotLookSilent_WhenIngestIsFresh()
|
||||
{
|
||||
// The exact field shape: IME-derived events landed 17 h in the past, so LastEventAt is
|
||||
// far behind the 2 h silence cutoff while the agent is demonstrably still reporting.
|
||||
var silenceCutoff = Now.AddHours(-2);
|
||||
var s = Session(lastIngestAt: Now.AddSeconds(-30), lastEventAt: Now.AddHours(-17), startedAt: Now.AddHours(-1));
|
||||
|
||||
Assert.True(MaintenanceService.ServerFrameLastContact(s) > silenceCutoff,
|
||||
"a session whose ingest stamp is 30 s old must never be classified as agent-silent");
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PositiveSkew_DoesNotMaskSilence_WhenIngestIsStale()
|
||||
{
|
||||
// Mirror case: a +1 h skew pushes LastEventAt into the future, which previously made the
|
||||
// sweep blind for an hour. The server frame still sees the silence.
|
||||
var silenceCutoff = Now.AddHours(-2);
|
||||
var s = Session(lastIngestAt: Now.AddHours(-3), lastEventAt: Now.AddHours(1), startedAt: Now.AddHours(-4));
|
||||
|
||||
Assert.True(MaintenanceService.ServerFrameLastContact(s) < silenceCutoff,
|
||||
"a session with no ingest for 3 h must be detected as silent regardless of a future-dated event stamp");
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FallsBackToEventStamp_OnRowsPredatingTheIngestStamp()
|
||||
{
|
||||
// Rollout safety: rows written before LastIngestAt existed must keep the old behaviour
|
||||
// rather than dropping out of the sweep entirely.
|
||||
var s = Session(lastIngestAt: null, lastEventAt: Now.AddHours(-3), startedAt: Now.AddHours(-5));
|
||||
Assert.Equal(Now.AddHours(-3), MaintenanceService.ServerFrameLastContact(s));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FallsBackToStartedAt_WhenNoEventStampExists()
|
||||
{
|
||||
var s = Session(lastIngestAt: null, lastEventAt: null, startedAt: Now.AddHours(-4));
|
||||
Assert.Equal(Now.AddHours(-4), MaintenanceService.ServerFrameLastContact(s));
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -351,8 +351,16 @@ namespace AutopilotMonitor.Functions.Services
|
||||
int silentMarked = 0;
|
||||
foreach (var silent in silentSessions)
|
||||
{
|
||||
var lastEventAt = silent.LastEventAt ?? silent.StartedAt;
|
||||
var silentMinutes = (int)(now - lastEventAt).TotalMinutes;
|
||||
// The query is a permissive two-frame pre-filter; the decision is made
|
||||
// here on the SERVER frame. LastEventAt carries the device clock and,
|
||||
// for IME-derived events, a timezone skew (field-measured: -17 h to
|
||||
// +1 h). Trusting it marks a live agent Stalled — and puts a bogus
|
||||
// "silent for 1020min" in front of the customer.
|
||||
var lastContactAt = ServerFrameLastContact(silent);
|
||||
if (lastContactAt > silenceCutoff)
|
||||
continue; // provably alive on the server clock
|
||||
|
||||
var silentMinutes = (int)(now - lastContactAt).TotalMinutes;
|
||||
await _sessionRepo.UpdateSessionStatusAsync(
|
||||
silent.TenantId,
|
||||
silent.SessionId,
|
||||
@@ -409,7 +417,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// legitimately exceed SessionTimeoutHours) and must never be terminalized here
|
||||
// — without this, an actively-installing 6h enrollment could be classified
|
||||
// Incomplete mid-run purely because it outlived the 5h window.
|
||||
if (session.LastEventAt.HasValue && session.LastEventAt.Value > silenceCutoff)
|
||||
if (ServerFrameLastContact(session) > silenceCutoff)
|
||||
continue;
|
||||
|
||||
// Fast path: an AwaitingUser session still inside the grace window needs no
|
||||
@@ -774,5 +782,26 @@ namespace AutopilotMonitor.Functions.Services
|
||||
/// Aggregates metrics for any missed days in the last 7 days, plus yesterday.
|
||||
/// Checks the UsageMetrics table for existing snapshots to avoid re-aggregation.
|
||||
/// </summary>
|
||||
|
||||
/// <summary>
|
||||
/// Last contact with the agent, expressed in the SERVER clock frame — the only value a
|
||||
/// server-derived cutoff may legitimately be compared against.
|
||||
/// <para>
|
||||
/// Preference order:
|
||||
/// <list type="number">
|
||||
/// <item><c>LastIngestAt</c> — stamped from the server clock on every ingest. Authoritative.</item>
|
||||
/// <item><c>LastEventAt</c> — device frame; used only for rows written before
|
||||
/// <c>LastIngestAt</c> existed, so the rollout has no blind window. Carries the device's
|
||||
/// clock error and any CMTrace timezone skew.</item>
|
||||
/// <item><c>StartedAt</c> — last resort when a session has no event stamp at all.</item>
|
||||
/// </list>
|
||||
/// </para>
|
||||
/// Mixing the two frames is what let a live agent be marked Stalled: a session whose
|
||||
/// IME-derived events were skewed -17 h looked silent for 17 hours the moment it started.
|
||||
/// </summary>
|
||||
/// <remarks>internal (not private) purely as a unit-test seam — it is a pure function
|
||||
/// over its argument, pinned by <c>MaintenanceServerFrameLastContactTests</c>.</remarks>
|
||||
internal static DateTime ServerFrameLastContact(SessionSummary session)
|
||||
=> session.LastIngestAt ?? session.LastEventAt ?? session.StartedAt;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -752,7 +752,12 @@ namespace AutopilotMonitor.Functions.Services
|
||||
|
||||
private (bool matched, object evidence) EvaluateAppInstallDurationCondition(RuleCondition condition, List<EnrollmentEvent> events)
|
||||
{
|
||||
var sortedEvents = events.OrderBy(e => e.Timestamp).ThenBy(e => e.Sequence).ToList();
|
||||
// Ordering key is Sequence, never Timestamp: Sequence is a persisted, strictly
|
||||
// monotonic per-session counter assigned at emit time and is immune to every clock
|
||||
// problem, whereas Timestamp carries the device clock frame plus — for CMTrace-derived
|
||||
// events — the writer process's timezone belief. Timestamp stays in use below only
|
||||
// where an actual ELAPSED DURATION is meant, which is what it is for.
|
||||
var sortedEvents = events.OrderBy(e => e.Sequence).ToList();
|
||||
|
||||
var completionEventTypes = string.IsNullOrWhiteSpace(condition.EventType)
|
||||
? new HashSet<string>(new[] { "app_install_completed", "app_install_failed" }, StringComparer.OrdinalIgnoreCase)
|
||||
@@ -774,7 +779,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
var startEvent = sortedEvents.LastOrDefault(e =>
|
||||
(string.Equals(e.EventType, "app_install_started", StringComparison.OrdinalIgnoreCase) ||
|
||||
string.Equals(e.EventType, "app_install_start", StringComparison.OrdinalIgnoreCase)) &&
|
||||
e.Timestamp <= completionEvent.Timestamp &&
|
||||
e.Sequence <= completionEvent.Sequence &&
|
||||
string.Equals(GetDataFieldValue(e, "appId") ?? GetDataFieldValue(e, "appName"), appKey, StringComparison.OrdinalIgnoreCase));
|
||||
|
||||
if (startEvent == null)
|
||||
@@ -826,7 +831,12 @@ namespace AutopilotMonitor.Functions.Services
|
||||
return (false, "event_correlation requires EventType, CorrelateEventType, and JoinField");
|
||||
}
|
||||
|
||||
var sortedEvents = events.OrderBy(e => e.Timestamp).ThenBy(e => e.Sequence).ToList();
|
||||
// Ordering key is Sequence, never Timestamp: Sequence is a persisted, strictly
|
||||
// monotonic per-session counter assigned at emit time and is immune to every clock
|
||||
// problem, whereas Timestamp carries the device clock frame plus — for CMTrace-derived
|
||||
// events — the writer process's timezone belief. Timestamp stays in use below only
|
||||
// where an actual ELAPSED DURATION is meant, which is what it is for.
|
||||
var sortedEvents = events.OrderBy(e => e.Sequence).ToList();
|
||||
|
||||
// Collect Event A candidates with optional filter
|
||||
var eventAList = sortedEvents
|
||||
@@ -874,16 +884,14 @@ namespace AutopilotMonitor.Functions.Services
|
||||
|
||||
// Find the latest Event A that occurred before Event B
|
||||
var matchingA = eventAByJoinKey[bKey]
|
||||
.Where(a => a.Timestamp < eventB.Timestamp ||
|
||||
(a.Timestamp == eventB.Timestamp && a.Sequence < eventB.Sequence))
|
||||
.Where(a => a.Sequence < eventB.Sequence)
|
||||
.Where(a =>
|
||||
{
|
||||
if (condition.TimeWindowSeconds == null || condition.TimeWindowSeconds <= 0)
|
||||
return true;
|
||||
return (eventB.Timestamp - a.Timestamp).TotalSeconds <= condition.TimeWindowSeconds.Value;
|
||||
})
|
||||
.OrderByDescending(a => a.Timestamp)
|
||||
.ThenByDescending(a => a.Sequence)
|
||||
.OrderByDescending(a => a.Sequence)
|
||||
.FirstOrDefault();
|
||||
|
||||
if (matchingA == null)
|
||||
|
||||
@@ -698,9 +698,19 @@ namespace AutopilotMonitor.Functions.Services
|
||||
|
||||
var silenceCutoffStr = silenceCutoff.ToString("yyyy-MM-ddTHH:mm:ss");
|
||||
var hardCutoffStr = hardCutoff.ToString("yyyy-MM-ddTHH:mm:ss");
|
||||
|
||||
// Candidate pre-filter across BOTH clock frames, deliberately permissive:
|
||||
// LastIngestAt is the server frame (authoritative, but absent on rows written
|
||||
// before it existed), LastEventAt the device frame (always present, but carries
|
||||
// the device's clock error and any CMTrace timezone skew). An OR keeps a session
|
||||
// in the candidate set when EITHER frame looks silent; the caller then makes the
|
||||
// authoritative call on the server frame. Filtering on LastIngestAt alone would
|
||||
// silently drop every pre-rollout row, since Table Storage does not match a
|
||||
// filter against a missing property.
|
||||
var filter = $"PartitionKey eq '{tenantId}' " +
|
||||
$"and Status eq 'InProgress' " +
|
||||
$"and LastEventAt lt datetime'{silenceCutoffStr}Z' " +
|
||||
$"and (LastIngestAt lt datetime'{silenceCutoffStr}Z' " +
|
||||
$"or LastEventAt lt datetime'{silenceCutoffStr}Z') " +
|
||||
$"and (StartedAt ge datetime'{hardCutoffStr}Z' or ResumedAt ge datetime'{hardCutoffStr}Z')";
|
||||
|
||||
var query = tableClient.QueryAsync<TableEntity>(filter: filter);
|
||||
@@ -772,7 +782,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
var select = new[]
|
||||
{
|
||||
"PartitionKey", "RowKey", "Status", "StartedAt", "ResumedAt", "LastEventAt",
|
||||
"SerialNumber", "IsPreProvisioned"
|
||||
"LastIngestAt", "SerialNumber", "IsPreProvisioned"
|
||||
};
|
||||
|
||||
var sessions = new List<SessionSummary>();
|
||||
|
||||
@@ -2338,6 +2338,14 @@ namespace AutopilotMonitor.Functions.Services
|
||||
update["LastEventAt"] = EnsureUtc(latestEventTimestamp.Value);
|
||||
}
|
||||
|
||||
// Server-frame ingest stamp. Reaching this method means a batch was just
|
||||
// received, so "now" on the SERVER clock is the honest answer to "when did we
|
||||
// last hear from this agent". LastEventAt above cannot answer that — it carries
|
||||
// the device's clock frame and its timezone skew. Written unconditionally (not
|
||||
// guarded by latestEventTimestamp) because an empty-timestamp batch is still
|
||||
// contact from the agent.
|
||||
update["LastIngestAt"] = EnsureUtc(DateTime.UtcNow);
|
||||
|
||||
// Increment script execution counters
|
||||
if (platformScriptIncrement > 0)
|
||||
{
|
||||
@@ -3147,6 +3155,7 @@ namespace AutopilotMonitor.Functions.Services
|
||||
// null as "CustomerSas" for back-compat.
|
||||
DiagnosticsBlobDestination = entity.GetString("DiagnosticsBlobDestination"),
|
||||
LastEventAt = SafeGetDateTime(entity, "LastEventAt"),
|
||||
LastIngestAt = SafeGetDateTime(entity, "LastIngestAt"),
|
||||
IsPreProvisioned = entity.GetBoolean("IsPreProvisioned") ?? false,
|
||||
IsHybridJoin = entity.GetBoolean("IsHybridJoin") ?? false,
|
||||
IsSelfDeployingProfile = entity.GetBoolean("IsSelfDeployingProfile") ?? false,
|
||||
|
||||
@@ -6,11 +6,41 @@ using System.Text.RegularExpressions;
|
||||
namespace AutopilotMonitor.Shared.Logging
|
||||
{
|
||||
/// <summary>
|
||||
/// Represents a single parsed line from a CMTrace-format log file
|
||||
/// Represents a single parsed line from a CMTrace-format log file.
|
||||
/// <para>
|
||||
/// Timestamps are deliberately NOT resolved to UTC here unless the writer declared its own
|
||||
/// offset. See <see cref="CmTraceLogParser"/> for why.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public class CmTraceLogEntry
|
||||
{
|
||||
public DateTime Timestamp { get; set; }
|
||||
/// <summary>
|
||||
/// The line's local time exactly as the writing process wrote it. Kind is
|
||||
/// <see cref="DateTimeKind.Unspecified"/> on purpose — this value is meaningless without
|
||||
/// knowing which zone the WRITER believed it was in, which the line itself does not say.
|
||||
/// </summary>
|
||||
public DateTime LocalTimestamp { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// The writer-declared UTC bias in minutes, when the line carried one ("+480").
|
||||
/// <c>null</c> for the far more common bias-less form.
|
||||
/// </summary>
|
||||
public int? BiasMinutes { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// UTC — populated ONLY when <see cref="BiasMinutes"/> was present, because a
|
||||
/// writer-declared offset is authoritative. <c>null</c> otherwise: the caller must resolve
|
||||
/// <see cref="LocalTimestamp"/> itself, and is the only party able to do so correctly.
|
||||
/// </summary>
|
||||
public DateTime? TimestampUtc { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Whether the line carried a parseable timestamp at all. When <c>false</c>,
|
||||
/// <see cref="LocalTimestamp"/> is <c>default</c> and callers must fall back to their own
|
||||
/// clock rather than treat the value as a real time.
|
||||
/// </summary>
|
||||
public bool HasTimestamp { get; set; }
|
||||
|
||||
public string Message { get; set; } = string.Empty;
|
||||
public string Component { get; set; } = string.Empty;
|
||||
public int Type { get; set; } // 1=Info, 2=Warning, 3=Error
|
||||
@@ -21,12 +51,25 @@ namespace AutopilotMonitor.Shared.Logging
|
||||
/// Parses CMTrace/SCCM log format used by IME and other Microsoft components.
|
||||
/// Format: <![LOG[{message}]LOG]!><time="{time}" date="{date}" component="{comp}" context="" type="{type}" thread="{thread}" file="">
|
||||
///
|
||||
/// Lives in Shared because it is the SINGLE parsing implementation for both sides:
|
||||
/// the agent's IME tracker / logparser gather collector (on-device) and the backend's
|
||||
/// rules/gather/test-pattern endpoint, which must reproduce the agent's matching
|
||||
/// semantics exactly so authors can test patterns without a device. Timestamp note:
|
||||
/// bias-less lines parse with DateTimeStyles.AssumeLocal — on the backend that is the
|
||||
/// SERVER's timezone, so the test endpoint reports match/parse results, not timestamps.
|
||||
/// <para>
|
||||
/// Lives in Shared because it is the SINGLE parsing implementation for both sides: the
|
||||
/// agent's IME tracker / logparser gather collector (on-device) and the backend's
|
||||
/// rules/gather/test-pattern endpoint, which must reproduce the agent's matching semantics
|
||||
/// exactly so authors can test patterns without a device.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// <b>The parser does not guess timezones.</b> A bias-less CMTrace line carries local time
|
||||
/// and nothing else — IME 1.104 writes <c>DateTime.Now.TimeOfDay</c> in both of its trace
|
||||
/// listeners. Resolving that with the READER's <c>TimeZoneInfo.Local</c> silently assumes the
|
||||
/// writing and reading processes agree on the zone. They do not: each caches its zone at
|
||||
/// process start and neither follows a later <c>tzutil</c> or a Windows auto-timezone change.
|
||||
/// Field measurement over 11,068 sessions found 26 sessions where the two beliefs differed,
|
||||
/// from +1 h to -17 h, silently shifting every IME-derived event by that amount. So this
|
||||
/// parser hands back <see cref="CmTraceLogEntry.LocalTimestamp"/> plus
|
||||
/// <see cref="CmTraceLogEntry.BiasMinutes"/> and lets the caller — which alone can measure
|
||||
/// the writer's actual offset — do the conversion.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public static class CmTraceLogParser
|
||||
{
|
||||
@@ -63,11 +106,24 @@ namespace AutopilotMonitor.Shared.Logging
|
||||
var typeStr = match.Groups["type"].Value;
|
||||
var thread = match.Groups["thread"].Value;
|
||||
|
||||
// Parse timestamp: date is "M-d-yyyy", time is "HH:mm:ss.ticks"
|
||||
DateTime timestamp;
|
||||
if (!TryParseTimestamp(dateStr, timeStr, biasStr, out timestamp))
|
||||
DateTime localTimestamp;
|
||||
var hasTimestamp = TryParseLocalTimestamp(dateStr, timeStr, out localTimestamp);
|
||||
|
||||
int? biasMinutes = null;
|
||||
if (!string.IsNullOrEmpty(biasStr)
|
||||
&& int.TryParse(biasStr, NumberStyles.AllowLeadingSign, CultureInfo.InvariantCulture, out var parsedBias))
|
||||
{
|
||||
timestamp = DateTime.UtcNow;
|
||||
biasMinutes = parsedBias;
|
||||
}
|
||||
|
||||
// A writer-declared bias is authoritative — it is the writer telling us its own
|
||||
// offset, which is exactly the fact we otherwise have to measure.
|
||||
// GetTimeZoneInformation convention: UTC = local + bias.
|
||||
DateTime? timestampUtc = null;
|
||||
if (hasTimestamp && biasMinutes.HasValue)
|
||||
{
|
||||
timestampUtc = DateTime.SpecifyKind(
|
||||
localTimestamp.AddMinutes(biasMinutes.Value), DateTimeKind.Utc);
|
||||
}
|
||||
|
||||
int type;
|
||||
@@ -75,7 +131,10 @@ namespace AutopilotMonitor.Shared.Logging
|
||||
|
||||
entry = new CmTraceLogEntry
|
||||
{
|
||||
Timestamp = timestamp,
|
||||
LocalTimestamp = localTimestamp,
|
||||
BiasMinutes = biasMinutes,
|
||||
TimestampUtc = timestampUtc,
|
||||
HasTimestamp = hasTimestamp,
|
||||
Message = message,
|
||||
Component = component,
|
||||
Type = type,
|
||||
@@ -85,7 +144,26 @@ namespace AutopilotMonitor.Shared.Logging
|
||||
return true;
|
||||
}
|
||||
|
||||
private static bool TryParseTimestamp(string dateStr, string timeStr, string biasStr, out DateTime result)
|
||||
/// <summary>
|
||||
/// Resolves a bias-less CMTrace local timestamp using the READING process's own timezone.
|
||||
///
|
||||
/// <para>
|
||||
/// <b>This is a fallback with a known defect, not a correct conversion.</b> It is right
|
||||
/// only when the writing process happens to hold the same zone belief as this one. Use it
|
||||
/// solely where no better information exists — a log this process does not tail and
|
||||
/// therefore cannot measure an offset against — and mark the resulting value as not
|
||||
/// source-grounded so the inaccuracy stays visible.
|
||||
/// </para>
|
||||
///
|
||||
/// <para>
|
||||
/// Callers that DO tail their log must instead measure the writer's offset from a freshly
|
||||
/// appended line (see the agent's <c>CmTraceOffsetCalibrator</c>).
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public static DateTime ResolveUtcAssumingReaderZone(DateTime localTimestamp)
|
||||
=> DateTime.SpecifyKind(localTimestamp, DateTimeKind.Local).ToUniversalTime();
|
||||
|
||||
private static bool TryParseLocalTimestamp(string dateStr, string timeStr, out DateTime result)
|
||||
{
|
||||
result = DateTime.MinValue;
|
||||
|
||||
@@ -129,29 +207,15 @@ namespace AutopilotMonitor.Shared.Logging
|
||||
"M-d-yyyy HH:mm:ss"
|
||||
};
|
||||
|
||||
// Bias-suffixed time ("+480"): the writer declared its own UTC offset in minutes
|
||||
// (GetTimeZoneInformation convention: UTC = written time + bias). Honor it instead
|
||||
// of assuming the agent's local timezone — writer and agent can disagree (mixed
|
||||
// components, mid-enrollment timezone change; session df1fcf47).
|
||||
if (!string.IsNullOrEmpty(biasStr)
|
||||
&& int.TryParse(biasStr, NumberStyles.AllowLeadingSign, CultureInfo.InvariantCulture, out var biasMinutes))
|
||||
{
|
||||
if (DateTime.TryParseExact(combined, formats, CultureInfo.InvariantCulture,
|
||||
DateTimeStyles.None, out result))
|
||||
{
|
||||
result = DateTime.SpecifyKind(result.AddMinutes(biasMinutes), DateTimeKind.Utc);
|
||||
return true;
|
||||
}
|
||||
return false;
|
||||
}
|
||||
|
||||
// No bias: CMTrace timestamps are in LOCAL time. Parse as local, then convert to UTC.
|
||||
// DateTimeStyles.None: the value stays Unspecified. Attaching Local or Utc here would
|
||||
// be the very guess this parser refuses to make.
|
||||
if (DateTime.TryParseExact(combined, formats, CultureInfo.InvariantCulture,
|
||||
DateTimeStyles.AssumeLocal, out result))
|
||||
DateTimeStyles.None, out result))
|
||||
{
|
||||
result = result.ToUniversalTime();
|
||||
return true;
|
||||
}
|
||||
|
||||
result = default(DateTime);
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -349,6 +349,21 @@ namespace AutopilotMonitor.Shared.Models
|
||||
/// </summary>
|
||||
public DateTime? LastEventAt { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// SERVER-side time of the most recent event ingest for this session.
|
||||
/// <para>
|
||||
/// <see cref="LastEventAt"/> lives in the DEVICE clock frame (it is the maximum
|
||||
/// agent-supplied event timestamp). Comparing it against a server-derived cutoff mixes
|
||||
/// two clock frames: a device whose clock runs slow — or one whose IME-derived events
|
||||
/// carry a timezone skew — is judged silent far too early or not at all (measured in the
|
||||
/// field: skews from -17 h to +1 h, see tasks/todo.md). This field is stamped from the
|
||||
/// server clock on every ingest, so silence detection can compare like with like.
|
||||
/// </para>
|
||||
/// Null for sessions that predate this field — callers MUST fall back to
|
||||
/// <see cref="LastEventAt"/> so rollout has no blind window.
|
||||
/// </summary>
|
||||
public DateTime? LastIngestAt { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Whether this session used WhiteGlove (Pre-Provisioning).
|
||||
/// Set when a whiteglove_complete event is processed.
|
||||
|
||||
@@ -146,6 +146,16 @@ describe("prepareReportModel", () => {
|
||||
expect(model.failureCodes.moreCount).toBe(2);
|
||||
});
|
||||
|
||||
it("keeps the full exit-code description untruncated", () => {
|
||||
const model = prepareReportModel(
|
||||
makeInput({
|
||||
topFailureCodes: [{ code: "esp_apps_install_failure", exitCode: 1618, count: 1 }],
|
||||
})
|
||||
);
|
||||
expect(model.failureCodes.rows[0][0]).toBe("esp_apps_install_failure");
|
||||
expect(model.failureCodes.rows[0][2]).toBe("1618 (Another installation already in progress)");
|
||||
});
|
||||
|
||||
it("enriches known error codes and labels unknown ones", () => {
|
||||
const model = prepareReportModel(
|
||||
makeInput({
|
||||
|
||||
@@ -215,10 +215,12 @@ export function prepareReportModel(input: AppReportInput): AppReportModel {
|
||||
const failureCodeRows = analytics.topFailureCodes.slice(0, MAX_FAILURE_CODE_ROWS).map((row) => {
|
||||
const entry = getErrorCodeEntry(row.code);
|
||||
const exitEntry = row.exitCode != null ? getErrorCodeEntry(row.exitCode) : null;
|
||||
// Full description on purpose — the PDF table wraps cells, and the exit-code
|
||||
// text is exactly what the app owner needs to act on.
|
||||
const exitDisplay =
|
||||
row.exitCode != null
|
||||
? exitEntry
|
||||
? `${row.exitCode} (${exitEntry.description.slice(0, 24)}${exitEntry.description.length > 24 ? "…" : ""})`
|
||||
? `${row.exitCode} (${exitEntry.description})`
|
||||
: String(row.exitCode)
|
||||
: "—";
|
||||
return [
|
||||
|
||||
@@ -95,13 +95,12 @@ export function buildAppReportDoc(model: AppReportModel, generatedAt: Date): jsP
|
||||
calloutBox(ctx, line);
|
||||
}
|
||||
|
||||
sectionTitle(ctx, "Installs over time (success vs failure)");
|
||||
ensureSpace(ctx, BAR_CHART_H + 2);
|
||||
// keepWith = full chart height: a chart never separates from its title.
|
||||
sectionTitle(ctx, "Installs over time (success vs failure)", BAR_CHART_H + 2);
|
||||
drawStackedBarChart(doc, { x: pdfPage.margin, y: ctx.y, w: contentW, h: BAR_CHART_H }, model.timeSeries);
|
||||
ctx.y += BAR_CHART_H + 2;
|
||||
|
||||
sectionTitle(ctx, "Avg Install Duration over time");
|
||||
ensureSpace(ctx, LINE_CHART_H + 2);
|
||||
sectionTitle(ctx, "Avg Install Duration over time", LINE_CHART_H + 2);
|
||||
drawLineChart(doc, { x: pdfPage.margin, y: ctx.y, w: contentW, h: LINE_CHART_H }, model.timeSeries);
|
||||
ctx.y += LINE_CHART_H + 2;
|
||||
|
||||
@@ -109,10 +108,10 @@ export function buildAppReportDoc(model: AppReportModel, generatedAt: Date): jsP
|
||||
if (model.failureCodes.rows.length > 0) {
|
||||
drawTable(ctx, {
|
||||
columns: [
|
||||
{ header: "Code", width: 30 },
|
||||
{ header: "Description", width: 88 },
|
||||
{ header: "Exit code", width: 44 },
|
||||
{ header: "Count", width: 18, align: "right" },
|
||||
{ header: "Code", width: 42 },
|
||||
{ header: "Description", width: 62 },
|
||||
{ header: "Exit code", width: 60 },
|
||||
{ header: "Count", width: 16, align: "right" },
|
||||
],
|
||||
rows: model.failureCodes.rows,
|
||||
moreCount: model.failureCodes.moreCount,
|
||||
|
||||
@@ -62,8 +62,13 @@ export function ensureSpace(ctx: PdfContext, needed: number) {
|
||||
ctx.y = contentTop + 2;
|
||||
}
|
||||
|
||||
export function sectionTitle(ctx: PdfContext, text: string) {
|
||||
ensureSpace(ctx, 14);
|
||||
/**
|
||||
* Section heading with keep-with-next: `keepWith` reserves room for the first
|
||||
* mm of the following block, so a title never strands alone at a page bottom
|
||||
* while its table/chart starts on the next page.
|
||||
*/
|
||||
export function sectionTitle(ctx: PdfContext, text: string, keepWith = 20) {
|
||||
ensureSpace(ctx, 14 + keepWith);
|
||||
ctx.y += 3;
|
||||
ctx.doc.setFont("helvetica", "bold");
|
||||
ctx.doc.setFontSize(11);
|
||||
@@ -142,6 +147,10 @@ export function calloutBox(ctx: PdfContext, text: string) {
|
||||
|
||||
const TABLE_HEADER_H = 7;
|
||||
const TABLE_ROW_H = 6;
|
||||
const TABLE_CELL_LINE_H = 3.6;
|
||||
const TABLE_CELL_PAD_Y = 4.2;
|
||||
/** Sanity cap so one pathological cell can't produce a page-tall row. */
|
||||
const TABLE_MAX_CELL_LINES = 4;
|
||||
|
||||
function drawTableHeader(ctx: PdfContext, columns: TableColumn[]) {
|
||||
ctx.doc.setFillColor(pdfColors.headerBand);
|
||||
@@ -160,37 +169,66 @@ function drawTableHeader(ctx: PdfContext, columns: TableColumn[]) {
|
||||
ctx.y += TABLE_HEADER_H;
|
||||
}
|
||||
|
||||
/** Fixed-column table with zebra striping and header repetition after page breaks. */
|
||||
/**
|
||||
* Fixed-column table with zebra striping and header repetition after page
|
||||
* breaks. Cells wrap onto multiple lines (up to TABLE_MAX_CELL_LINES, the last
|
||||
* line ellipsized) so long descriptions stay fully readable.
|
||||
*/
|
||||
export function drawTable(ctx: PdfContext, spec: TableSpec) {
|
||||
const { columns, rows, moreCount = 0, zebra = true } = spec;
|
||||
ensureSpace(ctx, TABLE_HEADER_H + TABLE_ROW_H * 2);
|
||||
drawTableHeader(ctx, columns);
|
||||
ctx.doc.setFont("helvetica", "normal");
|
||||
ctx.doc.setFontSize(8);
|
||||
rows.forEach((row, rowIndex) => {
|
||||
// Wrap every cell first so the row height is known before drawing.
|
||||
const cellLines = row.map((cell, i) => {
|
||||
const col = columns[i];
|
||||
if (!col) return [] as string[];
|
||||
const lines = ctx.doc.splitTextToSize(cell, col.width - 4) as string[];
|
||||
if (lines.length > TABLE_MAX_CELL_LINES) {
|
||||
const kept = lines.slice(0, TABLE_MAX_CELL_LINES);
|
||||
kept[TABLE_MAX_CELL_LINES - 1] = truncateToWidth(
|
||||
ctx.doc,
|
||||
`${kept[TABLE_MAX_CELL_LINES - 1]}…`,
|
||||
col.width - 4
|
||||
);
|
||||
return kept;
|
||||
}
|
||||
return lines;
|
||||
});
|
||||
const rowH = Math.max(
|
||||
TABLE_ROW_H,
|
||||
Math.max(...cellLines.map((l) => l.length), 1) * TABLE_CELL_LINE_H + 2.4
|
||||
);
|
||||
// Re-draw the header when the row would spill past the footer.
|
||||
if (ctx.y + TABLE_ROW_H > contentBottom) {
|
||||
ensureSpace(ctx, TABLE_HEADER_H + TABLE_ROW_H);
|
||||
if (ctx.y + rowH > contentBottom) {
|
||||
ensureSpace(ctx, TABLE_HEADER_H + rowH);
|
||||
drawTableHeader(ctx, columns);
|
||||
ctx.doc.setFont("helvetica", "normal");
|
||||
ctx.doc.setFontSize(8);
|
||||
}
|
||||
if (zebra && rowIndex % 2 === 1) {
|
||||
ctx.doc.setFillColor(pdfColors.zebra);
|
||||
ctx.doc.rect(pdfPage.margin, ctx.y, contentW, TABLE_ROW_H, "F");
|
||||
ctx.doc.rect(pdfPage.margin, ctx.y, contentW, rowH, "F");
|
||||
}
|
||||
ctx.doc.setFont("helvetica", "normal");
|
||||
ctx.doc.setFontSize(8);
|
||||
ctx.doc.setTextColor(pdfColors.text);
|
||||
let x = pdfPage.margin;
|
||||
row.forEach((cell, i) => {
|
||||
cellLines.forEach((lines, i) => {
|
||||
const col = columns[i];
|
||||
if (!col) return;
|
||||
const text = truncateToWidth(ctx.doc, cell, col.width - 4);
|
||||
const tx = col.align === "right" ? x + col.width - 2 : x + 2;
|
||||
ctx.doc.text(text, tx, ctx.y + 4.2, { align: col.align === "right" ? "right" : "left" });
|
||||
lines.forEach((line, li) => {
|
||||
ctx.doc.text(line, tx, ctx.y + TABLE_CELL_PAD_Y + li * TABLE_CELL_LINE_H, {
|
||||
align: col.align === "right" ? "right" : "left",
|
||||
});
|
||||
});
|
||||
x += col.width;
|
||||
});
|
||||
ctx.doc.setDrawColor(pdfColors.border);
|
||||
ctx.doc.setLineWidth(0.1);
|
||||
ctx.doc.line(pdfPage.margin, ctx.y + TABLE_ROW_H, pdfPage.margin + contentW, ctx.y + TABLE_ROW_H);
|
||||
ctx.y += TABLE_ROW_H;
|
||||
ctx.doc.line(pdfPage.margin, ctx.y + rowH, pdfPage.margin + contentW, ctx.y + rowH);
|
||||
ctx.y += rowH;
|
||||
});
|
||||
if (moreCount > 0) {
|
||||
ensureSpace(ctx, TABLE_ROW_H);
|
||||
|
||||
@@ -264,6 +264,10 @@ export const SHARED_MANIFEST = {
|
||||
"name": "lastEventAt",
|
||||
"optional": true
|
||||
},
|
||||
{
|
||||
"name": "lastIngestAt",
|
||||
"optional": true
|
||||
},
|
||||
{
|
||||
"name": "isPreProvisioned",
|
||||
"optional": false
|
||||
|
||||
@@ -260,6 +260,10 @@
|
||||
"name": "lastEventAt",
|
||||
"optional": true
|
||||
},
|
||||
{
|
||||
"name": "lastIngestAt",
|
||||
"optional": true
|
||||
},
|
||||
{
|
||||
"name": "isPreProvisioned",
|
||||
"optional": false
|
||||
|
||||
Reference in New Issue
Block a user