diff --git a/Check-ExcessDrift.ps1 b/Check-ExcessDrift.ps1 new file mode 100644 index 0000000..3bac2c2 --- /dev/null +++ b/Check-ExcessDrift.ps1 @@ -0,0 +1,48 @@ +#!/usr/bin/env pwsh +param( + [string] $LogFolder = 'C:\Octopus\TimeService', + [double] $DurationHours = 12, + [double] $SleepMinutes = 30 +) + +$ErrorActionPreference = 'Stop' + +$markerFileName = 'EXCESS_DRIFT' +$markerPath = Join-Path $LogFolder $markerFileName + +function Write-Log { + param([string] $Message) + $stamp = (Get-Date).ToString('yyyy-MM-ddTHH:mm:ssK') + Write-Host "[$stamp] $Message" + # TeamCity service message: surfaces the line prominently in the build log. + $escaped = $Message -replace "\|", "||" -replace "'", "|'" -replace "\[", "|[" -replace "\]", "|]" -replace "\r", "" -replace "\n", "|n" + Write-Host "##teamcity[message text='$escaped' status='WARNING']" +} + +Write-Log "Checking for excess-drift marker at '$markerPath'." + +if (-not (Test-Path -LiteralPath $markerPath -PathType Leaf)) { + Write-Log "No EXCESS_DRIFT marker found. Clock drift is within tolerance; nothing to do." + exit 0 +} + +$deadline = (Get-Date).AddHours($DurationHours) +$sleep = [TimeSpan]::FromMinutes($SleepMinutes) + +Write-Log "EXCESS_DRIFT marker found. Holding for $DurationHours hour(s), logging every $SleepMinutes minute(s). Will finish at $($deadline.ToString('yyyy-MM-ddTHH:mm:ssK'))." + +while ($true) { + $remaining = $deadline - (Get-Date) + if ($remaining -le [TimeSpan]::Zero) { break } + + Write-Log "Excess clock drift detected by OctopusTimeService (marker: '$markerPath'). $([int]$remaining.TotalMinutes) minute(s) remaining." + + # Don't overshoot the 12-hour deadline on the final iteration. + $thisSleep = if ($remaining -lt $sleep) { $remaining } else { $sleep } + if ($thisSleep -gt [TimeSpan]::Zero) { + Start-Sleep -Seconds ([int]$thisSleep.TotalSeconds) + } +} + +Write-Log "Excess-drift hold complete after $DurationHours hour(s)." +exit 0 diff --git a/src/OctopusTimeService/Logging/ExcessDriftMonitor.cs b/src/OctopusTimeService/Logging/ExcessDriftMonitor.cs new file mode 100644 index 0000000..ab0bb3f --- /dev/null +++ b/src/OctopusTimeService/Logging/ExcessDriftMonitor.cs @@ -0,0 +1,82 @@ +namespace TimeService.Logging; + +/// +/// Watches successive NTP drift measurements and raises a one-time alert when the clock has been +/// excessively wrong for several consecutive measurements. "Excessive" means the absolute drift +/// (server ahead of, or behind, the local clock) exceeds ; the alert +/// fires once the streak of excessive measurements reaches +/// in a row. A single within-threshold measurement resets the streak. +/// +/// When tripped it logs (EventId 1500) and drops an +/// empty EXCESS_DRIFT marker file into the log folder. The alert fires at most once per process +/// lifetime. State is held in memory, which suits this long-running service. Thread-safe. +/// +public sealed class ExcessDriftMonitor +{ + public const string MarkerFileName = "EXCESS_DRIFT"; + public const int DefaultConsecutiveThreshold = 3; + public static readonly TimeSpan DefaultThreshold = TimeSpan.FromSeconds(60); + + private readonly ILogger logger; + private readonly string directory; + private readonly TimeSpan threshold; + private readonly int consecutiveThreshold; + private readonly Lock gate = new(); + + private int consecutiveExcessCount; + private bool alerted; + + public ExcessDriftMonitor(ILogger logger, string directory) + : this(logger, directory, DefaultThreshold, DefaultConsecutiveThreshold) + { + } + + public ExcessDriftMonitor( + ILogger logger, + string directory, + TimeSpan threshold, + int consecutiveThreshold) + { + this.logger = logger; + this.directory = directory; + this.threshold = threshold; + this.consecutiveThreshold = consecutiveThreshold; + } + + /// + /// Records one drift measurement, updating the consecutive-excess streak and firing the + /// one-time alert if the streak reaches the configured threshold. Drift may be positive or + /// negative; only its magnitude relative to the threshold matters. + /// + public void Record(TimeSpan drift) + { + lock (gate) + { + var excess = drift.Duration() > threshold; + consecutiveExcessCount = excess ? consecutiveExcessCount + 1 : 0; + + if (alerted || consecutiveExcessCount < consecutiveThreshold) + return; + + alerted = true; + Log.ExcessDriftDetected(logger); + WriteMarkerFile(); + } + } + + private void WriteMarkerFile() + { + var path = Path.Combine(directory, MarkerFileName); + try + { + Directory.CreateDirectory(directory); + // Empty placeholder. OpenOrCreate leaves any existing marker untouched — a marker + // already on disk (e.g. left by a prior run) is expected, not an error. + using var _ = File.Open(path, FileMode.OpenOrCreate, FileAccess.Write, FileShare.ReadWrite); + } + catch (Exception ex) + { + Log.ExcessDriftMarkerWriteFailed(logger, path, ex); + } + } +} diff --git a/src/OctopusTimeService/Logging/Log.cs b/src/OctopusTimeService/Logging/Log.cs index c24db93..e56ce7d 100644 --- a/src/OctopusTimeService/Logging/Log.cs +++ b/src/OctopusTimeService/Logging/Log.cs @@ -5,8 +5,8 @@ namespace TimeService.Logging; /// /// Source-generated logging for the service. Each entry has a stable EventId so individual /// events are identifiable in the Windows Event Log. -/// Ranges: 1000-1099 Worker, 2000-2099 StartupSequence, 3000-3099 WindowsServiceOps, -/// 4000-4099 ScheduledTaskOps. +/// Ranges: 1000-1099 Worker, 1500-1599 drift monitoring, 2000-2099 StartupSequence, +/// 3000-3099 WindowsServiceOps, 4000-4099 ScheduledTaskOps. /// internal static partial class Log { @@ -44,6 +44,16 @@ internal static partial class Log Message = "Failed to write drift measurement to CSV log at {Path}")] public static partial void DriftCsvWriteFailed(ILogger logger, string path, Exception ex); + // -------- Drift monitoring (1500-1599) -------- + + [LoggerMessage(EventId = 1500, Level = LogLevel.Error, + Message = "Excess Drift Detected")] + public static partial void ExcessDriftDetected(ILogger logger); + + [LoggerMessage(EventId = 1501, Level = LogLevel.Warning, + Message = "Failed to write EXCESS_DRIFT marker file at {Path}")] + public static partial void ExcessDriftMarkerWriteFailed(ILogger logger, string path, Exception ex); + // -------- StartupSequence (2000-2099) -------- [LoggerMessage(EventId = 2001, Level = LogLevel.Information, diff --git a/src/OctopusTimeService/Program.cs b/src/OctopusTimeService/Program.cs index e84408a..684efc7 100644 --- a/src/OctopusTimeService/Program.cs +++ b/src/OctopusTimeService/Program.cs @@ -52,6 +52,9 @@ static int RunAsService(string[] forwardedArgs) builder.Services.AddSingleton(sp => new DriftCsvLog( sp.GetRequiredService>(), RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName))); + builder.Services.AddSingleton(sp => new ExcessDriftMonitor( + sp.GetRequiredService>(), + RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName))); builder.Services.AddSingleton(sp => new StartupSequence( sp.GetRequiredService>(), sp.GetRequiredService(), @@ -69,6 +72,9 @@ static int RunAsConsole(string[] forwardedArgs) builder.Services.AddSingleton(sp => new DriftCsvLog( sp.GetRequiredService>(), RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName))); + builder.Services.AddSingleton(sp => new ExcessDriftMonitor( + sp.GetRequiredService>(), + RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName))); builder.Services.AddSingleton(sp => new StartupSequence( sp.GetRequiredService>(), sp.GetRequiredService(), diff --git a/src/OctopusTimeService/Worker.cs b/src/OctopusTimeService/Worker.cs index 8f28dd6..4147008 100644 --- a/src/OctopusTimeService/Worker.cs +++ b/src/OctopusTimeService/Worker.cs @@ -8,7 +8,8 @@ public class Worker( ILogger logger, NtpClient ntpClient, StartupSequence startupSequence, - DriftCsvLog driftCsvLog) : BackgroundService + DriftCsvLog driftCsvLog, + ExcessDriftMonitor excessDriftMonitor) : BackgroundService { private readonly TimeSpan measurementInterval = TimeSpan.FromSeconds( RegistrySettings.ReadNtpCheckIntervalSeconds(ServiceDefaults.ServiceName)); @@ -38,7 +39,7 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) using var timer = new PeriodicTimer(measurementInterval); while (!stoppingToken.IsCancellationRequested && await timer.WaitForNextTickAsync(stoppingToken)) { - await MeasureAndLogDriftAsync(logger, ntpClient, driftCsvLog, "steady-state", stoppingToken); + await MeasureAndLogDriftAsync(logger, ntpClient, driftCsvLog, "steady-state", stoppingToken, excessDriftMonitor); } } @@ -47,14 +48,17 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) /// on-disk CSV log. Shared by the steady-state loop and so every /// measurement, whatever its origin, lands in both sinks identically. /// labels the measurement in the event log (e.g. "steady-state", "pre-resync", "post-resync"). - /// Measurement failures are logged and swallowed; host cancellation is propagated. + /// When an is supplied, each successful measurement is fed + /// to it so it can track consecutive excess-drift streaks. Measurement failures are logged and + /// swallowed (and do not touch the monitor); host cancellation is propagated. /// public static async Task MeasureAndLogDriftAsync( ILogger logger, NtpClient ntpClient, DriftCsvLog driftCsvLog, string phase, - CancellationToken cancellationToken) + CancellationToken cancellationToken, + ExcessDriftMonitor? excessDriftMonitor = null) { try { @@ -63,6 +67,7 @@ public static async Task MeasureAndLogDriftAsync( var ntpTime = localTime + result.Drift; Log.ClockDrift(logger, phase, ntpClient.Server, result.Drift, result.MarginOfError); driftCsvLog.Append(localTime, ntpTime, result.Drift, result.MarginOfError); + excessDriftMonitor?.Record(result.Drift); } catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { diff --git a/tests/TimeService.Tests/Logging/ExcessDriftMonitorTests.cs b/tests/TimeService.Tests/Logging/ExcessDriftMonitorTests.cs new file mode 100644 index 0000000..e18465e --- /dev/null +++ b/tests/TimeService.Tests/Logging/ExcessDriftMonitorTests.cs @@ -0,0 +1,162 @@ +using Microsoft.Extensions.Logging; +using TimeService.Logging; + +namespace TimeService.Tests.Logging; + +public class ExcessDriftMonitorTests +{ + private const int ExcessDriftEventId = 1500; + private static readonly TimeSpan Threshold = TimeSpan.FromSeconds(60); + + // Excess = strictly more than 60s away, positive or negative. + private static readonly TimeSpan Excess = TimeSpan.FromSeconds(61); + private static readonly TimeSpan ExcessNegative = TimeSpan.FromSeconds(-61); + private static readonly TimeSpan Good = TimeSpan.FromSeconds(10); + + [Fact] + public void Does_not_trip_before_three_consecutive_excess_measurements() + { + var (monitor, logger, dir) = NewMonitor(); + + monitor.Record(Excess); + monitor.Record(Excess); + + Assert.Equal(0, logger.CountOf(ExcessDriftEventId)); + Assert.False(MarkerExists(dir)); + } + + [Fact] + public void Trips_on_third_consecutive_excess_measurement() + { + var (monitor, logger, dir) = NewMonitor(); + + monitor.Record(Excess); + monitor.Record(Excess); + monitor.Record(Excess); + + Assert.Equal(1, logger.CountOf(ExcessDriftEventId)); + Assert.True(MarkerExists(dir)); + } + + [Fact] + public void A_good_measurement_resets_the_streak() + { + var (monitor, logger, dir) = NewMonitor(); + + // Two excess, then a good one resets, so the following two are not enough. + monitor.Record(Excess); + monitor.Record(Excess); + monitor.Record(Good); + monitor.Record(Excess); + monitor.Record(Excess); + + Assert.Equal(0, logger.CountOf(ExcessDriftEventId)); + Assert.False(MarkerExists(dir)); + + // A third consecutive excess after the reset finally trips it. + monitor.Record(Excess); + + Assert.Equal(1, logger.CountOf(ExcessDriftEventId)); + Assert.True(MarkerExists(dir)); + } + + [Fact] + public void Negative_drift_counts_as_excess() + { + var (monitor, logger, dir) = NewMonitor(); + + monitor.Record(ExcessNegative); + monitor.Record(ExcessNegative); + monitor.Record(ExcessNegative); + + Assert.Equal(1, logger.CountOf(ExcessDriftEventId)); + Assert.True(MarkerExists(dir)); + } + + [Fact] + public void Drift_exactly_at_the_threshold_is_not_excess() + { + var (monitor, logger, dir) = NewMonitor(); + + // Exactly 60s is "more than 60s away"? No — the rule is strictly greater than 60s. + monitor.Record(Threshold); + monitor.Record(Threshold); + monitor.Record(Threshold); + + Assert.Equal(0, logger.CountOf(ExcessDriftEventId)); + Assert.False(MarkerExists(dir)); + } + + [Fact] + public void Alert_fires_only_once_even_with_further_excess_measurements() + { + var (monitor, logger, dir) = NewMonitor(); + + for (var i = 0; i < 10; i++) + monitor.Record(Excess); + + Assert.Equal(1, logger.CountOf(ExcessDriftEventId)); + Assert.True(MarkerExists(dir)); + } + + [Fact] + public void An_existing_marker_file_is_not_an_error() + { + var (monitor, logger, dir) = NewMonitor(); + Directory.CreateDirectory(dir); + var markerPath = Path.Combine(dir, ExcessDriftMonitor.MarkerFileName); + File.WriteAllText(markerPath, "left over from a prior run"); + + monitor.Record(Excess); + monitor.Record(Excess); + monitor.Record(Excess); + + Assert.Equal(1, logger.CountOf(ExcessDriftEventId)); + Assert.True(File.Exists(markerPath)); + } + + [Fact] + public void Marker_file_is_created_empty() + { + var (monitor, _, dir) = NewMonitor(); + + monitor.Record(Excess); + monitor.Record(Excess); + monitor.Record(Excess); + + var markerPath = Path.Combine(dir, ExcessDriftMonitor.MarkerFileName); + Assert.True(File.Exists(markerPath)); + Assert.Equal(0, new FileInfo(markerPath).Length); + } + + private static (ExcessDriftMonitor Monitor, RecordingLogger Logger, string Directory) NewMonitor() + { + var dir = Path.Combine(Path.GetTempPath(), $"octopus-timeservice-tests-{Guid.NewGuid():N}"); + var logger = new RecordingLogger(); + var monitor = new ExcessDriftMonitor( + logger, dir, Threshold, ExcessDriftMonitor.DefaultConsecutiveThreshold); + return (monitor, logger, dir); + } + + private static bool MarkerExists(string directory) => + File.Exists(Path.Combine(directory, ExcessDriftMonitor.MarkerFileName)); + + /// Minimal that counts how many times each EventId was logged. + private sealed class RecordingLogger : ILogger + { + private readonly Dictionary countsByEventId = new(); + + public int CountOf(int eventId) => countsByEventId.GetValueOrDefault(eventId); + + public void Log( + LogLevel logLevel, EventId eventId, TState state, Exception? exception, + Func formatter) + { + countsByEventId[eventId.Id] = CountOf(eventId.Id) + 1; + } + + public bool IsEnabled(LogLevel logLevel) => true; + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + } +}