mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 12:42:38 +00:00
enhanced device blocking
This commit is contained in:
@@ -1 +1 @@
|
||||
892
|
||||
894
|
||||
|
||||
@@ -1,6 +1,7 @@
|
||||
using AutopilotMonitor.Functions.Functions.Ingest;
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Microsoft.Extensions.Logging;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
@@ -29,7 +30,7 @@ public class EventTimestampValidationTests
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_ValidRecentUtcTimestamp_ReturnsSameValue()
|
||||
{
|
||||
var valid = new DateTime(2026, 3, 15, 10, 30, 0, DateTimeKind.Utc);
|
||||
var valid = new DateTime(2026, 3, 25, 10, 30, 0, DateTimeKind.Utc);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(valid, FixedUtcNow);
|
||||
|
||||
@@ -37,11 +38,12 @@ public class EventTimestampValidationTests
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_DateTimeMinValue_ClampsToMinReasonable()
|
||||
public void SanitizeTimestamp_DateTimeMinValue_ClampsToUtcNow()
|
||||
{
|
||||
// Catastrophic value — falls through past-drift clamp to the safe fallback (receive time).
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(DateTime.MinValue, FixedUtcNow);
|
||||
|
||||
Assert.Equal(EventTimestampValidator.MinReasonableTimestamp, result);
|
||||
Assert.Equal(FixedUtcNow, result);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
@@ -53,13 +55,13 @@ public class EventTimestampValidationTests
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_FarPast1999_ClampsToMinReasonable()
|
||||
public void SanitizeTimestamp_FarPast1999_ClampsToUtcNow()
|
||||
{
|
||||
var farPast = new DateTime(1999, 6, 15, 0, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(farPast, FixedUtcNow);
|
||||
|
||||
Assert.Equal(EventTimestampValidator.MinReasonableTimestamp, result);
|
||||
Assert.Equal(FixedUtcNow, result);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
@@ -107,7 +109,7 @@ public class EventTimestampValidationTests
|
||||
public void SanitizeTimestamp_LocalKind_ConvertsToUtcThenValidates()
|
||||
{
|
||||
// A recent Local kind timestamp — should be converted to UTC, then pass validation
|
||||
var local = new DateTime(2026, 3, 15, 10, 0, 0, DateTimeKind.Local);
|
||||
var local = new DateTime(2026, 3, 25, 10, 0, 0, DateTimeKind.Local);
|
||||
var expectedUtc = local.ToUniversalTime();
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(local, FixedUtcNow);
|
||||
@@ -119,23 +121,14 @@ public class EventTimestampValidationTests
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_UnspecifiedKind_TreatedAsUtc()
|
||||
{
|
||||
var unspecified = new DateTime(2026, 3, 15, 10, 0, 0, DateTimeKind.Unspecified);
|
||||
var unspecified = new DateTime(2026, 3, 25, 10, 0, 0, DateTimeKind.Unspecified);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(unspecified, FixedUtcNow);
|
||||
|
||||
Assert.Equal(DateTimeKind.Utc, result.Kind);
|
||||
Assert.Equal(2026, result.Year);
|
||||
Assert.Equal(3, result.Month);
|
||||
Assert.Equal(15, result.Day);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_ExactMinBound_PassesThrough()
|
||||
{
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(
|
||||
EventTimestampValidator.MinReasonableTimestamp, FixedUtcNow);
|
||||
|
||||
Assert.Equal(EventTimestampValidator.MinReasonableTimestamp, result);
|
||||
Assert.Equal(25, result.Day);
|
||||
}
|
||||
|
||||
// =========================================================================
|
||||
@@ -145,7 +138,7 @@ public class EventTimestampValidationTests
|
||||
[Fact]
|
||||
public void IsReasonableTimestamp_ValidDate_ReturnsTrue()
|
||||
{
|
||||
var valid = new DateTime(2026, 3, 15, 10, 0, 0, DateTimeKind.Utc);
|
||||
var valid = new DateTime(2026, 3, 25, 10, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
Assert.True(EventTimestampValidator.IsReasonableTimestamp(valid, FixedUtcNow));
|
||||
}
|
||||
@@ -171,8 +164,9 @@ public class EventTimestampValidationTests
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void IsReasonableTimestamp_JustBeforeMin_ReturnsFalse()
|
||||
public void IsReasonableTimestamp_Year2019_ReturnsFalse()
|
||||
{
|
||||
// Beyond 7-day past-tolerance — not reasonable relative to FixedUtcNow (2026).
|
||||
var justBefore = new DateTime(2019, 12, 31, 23, 59, 59, DateTimeKind.Utc);
|
||||
|
||||
Assert.False(EventTimestampValidator.IsReasonableTimestamp(justBefore, FixedUtcNow));
|
||||
@@ -254,13 +248,13 @@ public class EventTimestampValidationTests
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SafeRowKeyTimestamp_MinValue_ProducesMinBoundKey()
|
||||
public void SafeRowKeyTimestamp_MinValue_ClampsToUtcNow()
|
||||
{
|
||||
// DateTime.MinValue must be clamped — never produce "00010101000000000"
|
||||
var result = EventTimestampValidator.SafeRowKeyTimestamp(DateTime.MinValue, FixedUtcNow);
|
||||
|
||||
Assert.Equal("20200101000000000", result);
|
||||
Assert.DoesNotContain("0001", result);
|
||||
Assert.StartsWith("2026", result); // Clamped to FixedUtcNow (past-drift fallback)
|
||||
}
|
||||
|
||||
[Fact]
|
||||
@@ -282,7 +276,7 @@ public class EventTimestampValidationTests
|
||||
{
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = new DateTime(2026, 3, 15, 10, 0, 0, DateTimeKind.Utc) }
|
||||
new() { Timestamp = new DateTime(2026, 3, 25, 10, 0, 0, DateTimeKind.Utc) }
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow);
|
||||
@@ -304,13 +298,13 @@ public class EventTimestampValidationTests
|
||||
|
||||
Assert.True(events[0].TimestampClamped);
|
||||
Assert.Equal(badTimestamp, events[0].OriginalTimestamp);
|
||||
Assert.Equal(EventTimestampValidator.MinReasonableTimestamp, events[0].Timestamp);
|
||||
Assert.Equal(FixedUtcNow, events[0].Timestamp);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_MixedValidAndInvalid_OnlyInvalidGetFlag()
|
||||
{
|
||||
var validTs = new DateTime(2026, 3, 15, 10, 0, 0, DateTimeKind.Utc);
|
||||
var validTs = new DateTime(2026, 3, 25, 10, 0, 0, DateTimeKind.Utc);
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = validTs, EventType = "valid_event" },
|
||||
@@ -325,10 +319,10 @@ public class EventTimestampValidationTests
|
||||
Assert.Null(events[0].OriginalTimestamp);
|
||||
Assert.Equal(validTs, events[0].Timestamp);
|
||||
|
||||
// Bad past: clamped to min, original preserved
|
||||
// Bad past: clamped to utcNow, original preserved
|
||||
Assert.True(events[1].TimestampClamped);
|
||||
Assert.Equal(DateTime.MinValue, events[1].OriginalTimestamp);
|
||||
Assert.Equal(EventTimestampValidator.MinReasonableTimestamp, events[1].Timestamp);
|
||||
Assert.Equal(FixedUtcNow, events[1].Timestamp);
|
||||
|
||||
// Bad future: clamped to utcNow, original preserved
|
||||
Assert.True(events[2].TimestampClamped);
|
||||
@@ -343,7 +337,7 @@ public class EventTimestampValidationTests
|
||||
{
|
||||
new() { Timestamp = DateTime.MinValue },
|
||||
new() { Timestamp = DateTime.MaxValue },
|
||||
new() { Timestamp = new DateTime(2026, 3, 15, 10, 0, 0, DateTimeKind.Utc) },
|
||||
new() { Timestamp = new DateTime(2026, 3, 25, 10, 0, 0, DateTimeKind.Utc) },
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow);
|
||||
@@ -451,7 +445,7 @@ public class EventTimestampValidationTests
|
||||
new EnrollmentEvent
|
||||
{
|
||||
EventType = "phase_changed",
|
||||
Timestamp = new DateTime(2026, 3, 15, 10, 0, 0, DateTimeKind.Utc) // valid
|
||||
Timestamp = new DateTime(2026, 3, 25, 10, 0, 0, DateTimeKind.Utc) // valid
|
||||
}),
|
||||
Newtonsoft.Json.JsonConvert.SerializeObject(
|
||||
new EnrollmentEvent
|
||||
@@ -503,7 +497,7 @@ public class EventTimestampValidationTests
|
||||
|
||||
// Clamped timestamp produces valid RowKey format
|
||||
var rowKey = $"{evt.Timestamp:yyyyMMddHHmmssfff}_{evt.Sequence:D10}";
|
||||
Assert.StartsWith("2020", rowKey); // Clamped to MinReasonableTimestamp
|
||||
Assert.StartsWith("2026", rowKey); // Clamped to FixedUtcNow (past-drift fallback)
|
||||
Assert.DoesNotContain("0001", rowKey);
|
||||
|
||||
// Original preserved for troubleshooting
|
||||
@@ -539,4 +533,281 @@ public class EventTimestampValidationTests
|
||||
Assert.NotNull(events[1].OriginalTimestamp);
|
||||
Assert.NotNull(events[2].OriginalTimestamp);
|
||||
}
|
||||
|
||||
// =========================================================================
|
||||
// Past-drift clamping (MaxPastToleranceHours = 168h / 7 days)
|
||||
//
|
||||
// Regression guard for production incident: devices with bad hardware clocks
|
||||
// submitted events with agent-side timestamps ~18 days in the past. Since the
|
||||
// old validator only clamped to 2020-01-01, those timestamps flowed through
|
||||
// untouched, pushed Sessions.StartedAt back by 18 days, and triggered repeated
|
||||
// false-positive "ExcessiveDataSender" blocks.
|
||||
// =========================================================================
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_PastDrift6Days_PassesThrough()
|
||||
{
|
||||
// 6 days back, within 7d tolerance
|
||||
var sixDaysBack = FixedUtcNow.AddDays(-6);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(sixDaysBack, FixedUtcNow);
|
||||
|
||||
Assert.Equal(sixDaysBack, result);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_PastDriftExactly7Days_PassesThrough()
|
||||
{
|
||||
// Exactly at the 7d boundary — inclusive
|
||||
var boundary = FixedUtcNow.AddHours(-EventTimestampValidator.MaxPastToleranceHours);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(boundary, FixedUtcNow);
|
||||
|
||||
Assert.Equal(boundary, result);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_PastDrift7DaysPlus1Second_ClampsToUtcNow()
|
||||
{
|
||||
// 1 second beyond the 7d boundary — should clamp
|
||||
var beyond = FixedUtcNow.AddHours(-EventTimestampValidator.MaxPastToleranceHours).AddSeconds(-1);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(beyond, FixedUtcNow);
|
||||
|
||||
Assert.Equal(FixedUtcNow, result);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_PastDrift18Days_ClampsToUtcNow()
|
||||
{
|
||||
// The smoking-gun production case: device clock 18 days behind.
|
||||
var smokingGun = FixedUtcNow.AddDays(-18);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(smokingGun, FixedUtcNow);
|
||||
|
||||
Assert.Equal(FixedUtcNow, result);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeTimestamp_PastDrift18DaysLocalKind_ClampsAndReturnsUtc()
|
||||
{
|
||||
// Local kind with past-drift: must convert to UTC, then clamp, then return UTC kind.
|
||||
var local = DateTime.SpecifyKind(FixedUtcNow.AddDays(-18), DateTimeKind.Local);
|
||||
|
||||
var result = EventTimestampValidator.SanitizeTimestamp(local, FixedUtcNow);
|
||||
|
||||
Assert.Equal(DateTimeKind.Utc, result.Kind);
|
||||
Assert.Equal(FixedUtcNow, result);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void IsReasonableTimestamp_PastDrift6Days_ReturnsTrue()
|
||||
{
|
||||
var valid = FixedUtcNow.AddDays(-6);
|
||||
Assert.True(EventTimestampValidator.IsReasonableTimestamp(valid, FixedUtcNow));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void IsReasonableTimestamp_PastDrift8Days_ReturnsFalse()
|
||||
{
|
||||
var tooOld = FixedUtcNow.AddDays(-8);
|
||||
Assert.False(EventTimestampValidator.IsReasonableTimestamp(tooOld, FixedUtcNow));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_PastDrift18Days_PreservesOriginalAndSetsFlag()
|
||||
{
|
||||
var badTs = FixedUtcNow.AddDays(-18);
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = badTs, EventType = "bad_clock_event" }
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow);
|
||||
|
||||
Assert.True(events[0].TimestampClamped);
|
||||
Assert.Equal(badTs, events[0].OriginalTimestamp);
|
||||
Assert.Equal(FixedUtcNow, events[0].Timestamp);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_MixedPastFuture_AllClampedToUtcNow()
|
||||
{
|
||||
// All clamping cases (catastrophic, past-drift, future-drift) resolve to utcNow.
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = DateTime.MinValue, EventType = "catastrophic" }, // MinValue → past
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-18), EventType = "past_drift" }, // 18d back
|
||||
new() { Timestamp = FixedUtcNow.AddHours(25), EventType = "future_drift" }, // 25h ahead
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-2), EventType = "valid_past" }, // valid
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow);
|
||||
|
||||
// Catastrophic: clamped to utcNow (falls into past-drift category)
|
||||
Assert.True(events[0].TimestampClamped);
|
||||
Assert.Equal(FixedUtcNow, events[0].Timestamp);
|
||||
|
||||
// Past-drift: clamped to utcNow
|
||||
Assert.True(events[1].TimestampClamped);
|
||||
Assert.Equal(FixedUtcNow, events[1].Timestamp);
|
||||
|
||||
// Future-drift: clamped to utcNow
|
||||
Assert.True(events[2].TimestampClamped);
|
||||
Assert.Equal(FixedUtcNow, events[2].Timestamp);
|
||||
|
||||
// Valid: unchanged
|
||||
Assert.False(events[3].TimestampClamped);
|
||||
Assert.Equal(FixedUtcNow.AddDays(-2), events[3].Timestamp);
|
||||
}
|
||||
|
||||
// =========================================================================
|
||||
// Clock-skew observability logging
|
||||
//
|
||||
// Verifies that SanitizeEventTimestamps emits a structured Warning when any
|
||||
// event in a batch was clamped — enables App Insights querying for bad-clock
|
||||
// devices via: traces | where message startswith "Agent clock skew"
|
||||
// =========================================================================
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_NoClamping_DoesNotLog()
|
||||
{
|
||||
var logger = new CapturingLogger();
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-2), EventType = "valid" },
|
||||
new() { Timestamp = FixedUtcNow.AddMinutes(-30), EventType = "valid" },
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow, logger);
|
||||
|
||||
Assert.Empty(logger.WarningMessages);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_PastDrift_EmitsSingleWarning()
|
||||
{
|
||||
var logger = new CapturingLogger();
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-18), EventType = "bad_1", TenantId = ValidTenantId, SessionId = ValidSessionId },
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-15), EventType = "bad_2", TenantId = ValidTenantId, SessionId = ValidSessionId },
|
||||
new() { Timestamp = FixedUtcNow.AddHours(-2), EventType = "valid", TenantId = ValidTenantId, SessionId = ValidSessionId },
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow, logger);
|
||||
|
||||
// Exactly one aggregate warning per batch (not one per event)
|
||||
Assert.Single(logger.WarningMessages);
|
||||
var msg = logger.WarningMessages[0];
|
||||
Assert.StartsWith("Agent clock skew detected", msg);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_MixedDirections_WarningCarriesStructuredProps()
|
||||
{
|
||||
var logger = new CapturingLogger();
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-18), EventType = "past1", TenantId = ValidTenantId, SessionId = ValidSessionId },
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-10), EventType = "past2", TenantId = ValidTenantId, SessionId = ValidSessionId },
|
||||
new() { Timestamp = FixedUtcNow.AddHours(30), EventType = "future", TenantId = ValidTenantId, SessionId = ValidSessionId },
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow, logger);
|
||||
|
||||
Assert.Single(logger.WarningMessages);
|
||||
var props = logger.WarningProperties[0];
|
||||
|
||||
// Verify structured props are populated (values are logged in-order via message template)
|
||||
Assert.Equal(ValidTenantId, props["TenantId"]?.ToString());
|
||||
Assert.Equal(ValidSessionId, props["SessionId"]?.ToString());
|
||||
Assert.Equal(3, Convert.ToInt32(props["TotalEvents"]));
|
||||
Assert.Equal(2, Convert.ToInt32(props["ClampedPast"]));
|
||||
Assert.Equal(1, Convert.ToInt32(props["ClampedFuture"]));
|
||||
|
||||
// Max past drift should be ~432h (18 days from the oldest event)
|
||||
var maxPast = Convert.ToDouble(props["MaxPastDriftHours"]);
|
||||
Assert.InRange(maxPast, 431.9, 432.1);
|
||||
|
||||
// Max future drift should be ~30h
|
||||
var maxFuture = Convert.ToDouble(props["MaxFutureDriftHours"]);
|
||||
Assert.InRange(maxFuture, 29.9, 30.1);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_DateTimeMinValue_FallsIntoPastCategory()
|
||||
{
|
||||
// Regression guard: DateTime.MinValue must be classified as "past-drift" (not a
|
||||
// separate floor category) and produce an absurdly large drift, making it trivial
|
||||
// to spot in logs.
|
||||
var logger = new CapturingLogger();
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = DateTime.MinValue, EventType = "catastrophic", TenantId = ValidTenantId, SessionId = ValidSessionId },
|
||||
};
|
||||
|
||||
IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow, logger);
|
||||
|
||||
Assert.Single(logger.WarningMessages);
|
||||
var props = logger.WarningProperties[0];
|
||||
Assert.Equal(1, Convert.ToInt32(props["ClampedPast"]));
|
||||
Assert.Equal(0, Convert.ToInt32(props["ClampedFuture"]));
|
||||
|
||||
// ~17.7 million hours (2026 years). Anything > 1 million is clearly catastrophic.
|
||||
var maxPast = Convert.ToDouble(props["MaxPastDriftHours"]);
|
||||
Assert.True(maxPast > 1_000_000);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SanitizeEventTimestamps_NullLogger_DoesNotThrow()
|
||||
{
|
||||
// Backward-compat: default call without a logger must still work.
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
new() { Timestamp = FixedUtcNow.AddDays(-18), EventType = "bad_clock" }
|
||||
};
|
||||
|
||||
var ex = Record.Exception(() => IngestEventsFunction.SanitizeEventTimestamps(events, FixedUtcNow));
|
||||
|
||||
Assert.Null(ex);
|
||||
Assert.True(events[0].TimestampClamped);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Minimal in-memory logger that captures Warning-level messages and their structured
|
||||
/// properties for assertion in tests. Implements ILogger directly — avoids pulling in
|
||||
/// a mocking library for a single use case.
|
||||
/// </summary>
|
||||
private sealed class CapturingLogger : ILogger
|
||||
{
|
||||
public List<string> WarningMessages { get; } = new();
|
||||
public List<IReadOnlyDictionary<string, object?>> WarningProperties { get; } = new();
|
||||
|
||||
public IDisposable BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance;
|
||||
|
||||
public bool IsEnabled(LogLevel logLevel) => true;
|
||||
|
||||
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
|
||||
{
|
||||
if (logLevel != LogLevel.Warning)
|
||||
return;
|
||||
|
||||
WarningMessages.Add(formatter(state, exception));
|
||||
|
||||
var props = new Dictionary<string, object?>();
|
||||
if (state is IReadOnlyList<KeyValuePair<string, object?>> kvps)
|
||||
{
|
||||
foreach (var kv in kvps)
|
||||
props[kv.Key] = kv.Value;
|
||||
}
|
||||
WarningProperties.Add(props);
|
||||
}
|
||||
|
||||
private sealed class NullScope : IDisposable
|
||||
{
|
||||
public static readonly NullScope Instance = new();
|
||||
public void Dispose() { }
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+57
-7
@@ -157,7 +157,7 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
|
||||
// Sanitize agent-side timestamps: clamp out-of-range values to prevent storage/sorting issues.
|
||||
// Original timestamps are preserved in OriginalTimestamp for troubleshooting.
|
||||
SanitizeEventTimestamps(request.Events, receivedAt);
|
||||
SanitizeEventTimestamps(request.Events, receivedAt, _logger);
|
||||
|
||||
// Store events in Azure Table Storage (batch write for efficiency)
|
||||
var storedEvents = await _sessionRepo.StoreEventsBatchAsync(request.Events);
|
||||
@@ -850,19 +850,69 @@ namespace AutopilotMonitor.Functions.Functions.Ingest
|
||||
/// When a timestamp is clamped, the original value is preserved in OriginalTimestamp
|
||||
/// and TimestampClamped is set to true — keeping the raw data available for
|
||||
/// troubleshooting and root-cause analysis of clock issues on devices.
|
||||
///
|
||||
/// Emits structured logs for observability:
|
||||
/// - Debug level per clamped event (TenantId/SessionId/EventType/drift) — opt-in via log level
|
||||
/// - One Warning per ingest batch that had any clamping, with aggregate counts and max drifts.
|
||||
/// This is what to query in App Insights to find bad-clock devices:
|
||||
/// traces | where message startswith "Agent clock skew"
|
||||
///
|
||||
/// Exposed as internal for unit testing.
|
||||
/// </summary>
|
||||
internal static void SanitizeEventTimestamps(List<EnrollmentEvent> events, DateTime utcNow)
|
||||
internal static void SanitizeEventTimestamps(List<EnrollmentEvent> events, DateTime utcNow, ILogger? logger = null)
|
||||
{
|
||||
int clampedPast = 0;
|
||||
int clampedFuture = 0;
|
||||
double maxPastDriftHours = 0;
|
||||
double maxFutureDriftHours = 0;
|
||||
|
||||
foreach (var evt in events)
|
||||
{
|
||||
var sanitized = EventTimestampValidator.SanitizeTimestamp(evt.Timestamp, utcNow);
|
||||
if (sanitized != evt.Timestamp)
|
||||
var original = evt.Timestamp;
|
||||
var sanitized = EventTimestampValidator.SanitizeTimestamp(original, utcNow);
|
||||
if (sanitized == original)
|
||||
continue;
|
||||
|
||||
evt.OriginalTimestamp = original;
|
||||
evt.TimestampClamped = true;
|
||||
evt.Timestamp = sanitized;
|
||||
|
||||
// Classify the clamping direction (for aggregate stats) and track max drift.
|
||||
// Compare in UTC so Local/Unspecified Kinds don't skew the direction check.
|
||||
// Note: catastrophic values like DateTime.MinValue fall into the "past" bucket
|
||||
// with a very large drift — this is intentional and makes them easy to spot in logs.
|
||||
var originalUtc = EventTimestampValidator.EnsureUtc(original);
|
||||
if (originalUtc > utcNow)
|
||||
{
|
||||
evt.OriginalTimestamp = evt.Timestamp;
|
||||
evt.TimestampClamped = true;
|
||||
evt.Timestamp = sanitized;
|
||||
clampedFuture++;
|
||||
var drift = (originalUtc - utcNow).TotalHours;
|
||||
if (drift > maxFutureDriftHours) maxFutureDriftHours = drift;
|
||||
}
|
||||
else
|
||||
{
|
||||
clampedPast++;
|
||||
var drift = (utcNow - originalUtc).TotalHours;
|
||||
if (drift > maxPastDriftHours) maxPastDriftHours = drift;
|
||||
}
|
||||
|
||||
logger?.LogDebug(
|
||||
"Event timestamp clamped: TenantId={TenantId}, SessionId={SessionId}, EventType={EventType}, Original={Original:O}, Sanitized={Sanitized:O}",
|
||||
evt.TenantId, evt.SessionId, evt.EventType, original, sanitized);
|
||||
}
|
||||
|
||||
if (clampedPast + clampedFuture > 0 && logger != null)
|
||||
{
|
||||
// Pull tenant/session from the first clamped event (all events in a batch share the same context).
|
||||
var firstClamped = events.Find(e => e.TimestampClamped);
|
||||
logger.LogWarning(
|
||||
"Agent clock skew detected: TenantId={TenantId}, SessionId={SessionId}, TotalEvents={TotalEvents}, ClampedPast={ClampedPast}, ClampedFuture={ClampedFuture}, MaxPastDriftHours={MaxPastDriftHours:F1}, MaxFutureDriftHours={MaxFutureDriftHours:F1}",
|
||||
firstClamped?.TenantId,
|
||||
firstClamped?.SessionId,
|
||||
events.Count,
|
||||
clampedPast,
|
||||
clampedFuture,
|
||||
maxPastDriftHours,
|
||||
maxFutureDriftHours);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -10,17 +10,30 @@ namespace AutopilotMonitor.Functions.Services
|
||||
/// </summary>
|
||||
internal static class EventTimestampValidator
|
||||
{
|
||||
/// <summary>
|
||||
/// Earliest reasonable timestamp — the product did not exist before this date.
|
||||
/// </summary>
|
||||
internal static readonly DateTime MinReasonableTimestamp = new(2020, 1, 1, 0, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
/// <summary>
|
||||
/// Maximum clock skew tolerance for agent-side timestamps ahead of server time.
|
||||
/// Agents may have slightly fast clocks; 24 hours covers timezone misconfiguration too.
|
||||
/// </summary>
|
||||
internal const int MaxFutureToleranceHours = 24;
|
||||
|
||||
/// <summary>
|
||||
/// Maximum clock skew tolerance for agent-side timestamps BEHIND server time, relative
|
||||
/// to the ingest receive time. Anything older than this is treated as a clock-skew bug
|
||||
/// and clamped to the server's receive time. 7 days (168h) covers legitimate spool replay
|
||||
/// after short outages while still catching devices whose hardware clock is weeks in the
|
||||
/// past (observed in field: 18-day drift causing ghost "excessive data sender" blocks).
|
||||
///
|
||||
/// Rationale for 168h (not tighter):
|
||||
/// - EventSpool has no max-age and could theoretically hold events from earlier sessions.
|
||||
/// - WhiteGlove Part-2 events are freshly stamped by the restarted agent → not affected.
|
||||
/// - Pre-provisioned sessions are already excluded from excessive-data detection.
|
||||
///
|
||||
/// This constant is also the effective lower bound for sanitized timestamps: any value
|
||||
/// older than utcNow − 168h (including catastrophic cases like DateTime.MinValue) is
|
||||
/// clamped to utcNow. There is no separate "floor" constant — past-drift subsumes it.
|
||||
/// </summary>
|
||||
internal const int MaxPastToleranceHours = 168;
|
||||
|
||||
/// <summary>
|
||||
/// Default maximum duration in seconds (7 days) for SafeDurationSeconds clamping.
|
||||
/// </summary>
|
||||
@@ -38,26 +51,31 @@ namespace AutopilotMonitor.Functions.Services
|
||||
};
|
||||
|
||||
/// <summary>
|
||||
/// Checks whether a timestamp falls within the reasonable range [MinReasonableTimestamp, utcNow + 24h].
|
||||
/// Checks whether a timestamp falls within the reasonable range.
|
||||
/// Valid range: [utcNow − 168h, utcNow + 24h].
|
||||
/// </summary>
|
||||
internal static bool IsReasonableTimestamp(DateTime timestamp, DateTime utcNow)
|
||||
{
|
||||
var utcTs = EnsureUtc(timestamp);
|
||||
return utcTs >= MinReasonableTimestamp && utcTs <= utcNow.AddHours(MaxFutureToleranceHours);
|
||||
return utcTs >= utcNow.AddHours(-MaxPastToleranceHours)
|
||||
&& utcTs <= utcNow.AddHours(MaxFutureToleranceHours);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Sanitizes a timestamp by ensuring UTC kind and clamping to the valid range.
|
||||
/// - Below MinReasonableTimestamp → clamped to MinReasonableTimestamp
|
||||
/// - Above utcNow + 24h → clamped to utcNow (server receive time as best-effort fallback)
|
||||
/// Clamping rules:
|
||||
/// - Below utcNow − 168h → clamped to utcNow (past-drift from bad device clock; server receive
|
||||
/// time is the best fallback because the event definitely arrived "now"). This also catches
|
||||
/// catastrophic values like DateTime.MinValue.
|
||||
/// - Above utcNow + 24h → clamped to utcNow (future-drift, same rationale).
|
||||
/// Returns the original value unchanged if it is within the valid range.
|
||||
/// </summary>
|
||||
internal static DateTime SanitizeTimestamp(DateTime timestamp, DateTime utcNow)
|
||||
{
|
||||
var utcTs = EnsureUtc(timestamp);
|
||||
|
||||
if (utcTs < MinReasonableTimestamp)
|
||||
return MinReasonableTimestamp;
|
||||
if (utcTs < utcNow.AddHours(-MaxPastToleranceHours))
|
||||
return EnsureUtc(utcNow);
|
||||
|
||||
if (utcTs > utcNow.AddHours(MaxFutureToleranceHours))
|
||||
return EnsureUtc(utcNow);
|
||||
|
||||
Reference in New Issue
Block a user