Excess drift reporting

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

src/OctopusTimeService/Logging/ExcessDriftMonitor.cs

@@ -0,0 +1,82 @@
+namespace TimeService.Logging;
+
+/// <summary>
+/// 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 <paramref name="threshold"/>; the alert
+/// fires once the streak of excessive measurements reaches <paramref name="consecutiveThreshold"/>
+/// in a row. A single within-threshold measurement resets the streak.
+///
+/// <para>When tripped it logs <see cref="Log.ExcessDriftDetected"/> (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.</para>
+/// </summary>
+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<ExcessDriftMonitor> 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<ExcessDriftMonitor> logger, string directory)
+        : this(logger, directory, DefaultThreshold, DefaultConsecutiveThreshold)
+    {
+    }
+
+    public ExcessDriftMonitor(
+        ILogger<ExcessDriftMonitor> logger,
+        string directory,
+        TimeSpan threshold,
+        int consecutiveThreshold)
+    {
+        this.logger = logger;
+        this.directory = directory;
+        this.threshold = threshold;
+        this.consecutiveThreshold = consecutiveThreshold;
+    }
+
+    /// <summary>
+    /// 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.
+    /// </summary>
+    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);
+        }
+    }
+}

src/OctopusTimeService/Logging/Log.cs

@@ -5,8 +5,8 @@ namespace TimeService.Logging;
 /// <summary>
 /// 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.
 /// </summary>
 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,

src/OctopusTimeService/Program.cs

@@ -52,6 +52,9 @@ static int RunAsService(string[] forwardedArgs)
     builder.Services.AddSingleton(sp => new DriftCsvLog(
         sp.GetRequiredService<ILogger<DriftCsvLog>>(),
         RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName)));
+    builder.Services.AddSingleton(sp => new ExcessDriftMonitor(
+        sp.GetRequiredService<ILogger<ExcessDriftMonitor>>(),
+        RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName)));
     builder.Services.AddSingleton(sp => new StartupSequence(
         sp.GetRequiredService<ILogger<StartupSequence>>(),
         sp.GetRequiredService<NtpClient>(),
@@ -69,6 +72,9 @@ static int RunAsConsole(string[] forwardedArgs)
     builder.Services.AddSingleton(sp => new DriftCsvLog(
         sp.GetRequiredService<ILogger<DriftCsvLog>>(),
         RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName)));
+    builder.Services.AddSingleton(sp => new ExcessDriftMonitor(
+        sp.GetRequiredService<ILogger<ExcessDriftMonitor>>(),
+        RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName)));
     builder.Services.AddSingleton(sp => new StartupSequence(
         sp.GetRequiredService<ILogger<StartupSequence>>(),
         sp.GetRequiredService<NtpClient>(),

src/OctopusTimeService/Worker.cs

@@ -8,7 +8,8 @@ public class Worker(
     ILogger<Worker> 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 <see cref="StartupSequence"/> so every
     /// measurement, whatever its origin, lands in both sinks identically. <paramref name="phase"/>
     /// 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 <paramref name="excessDriftMonitor"/> 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.
     /// </summary>
     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)
         {

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));
+
+    /// <summary>Minimal <see cref="ILogger{T}"/> that counts how many times each EventId was logged.</summary>
+    private sealed class RecordingLogger : ILogger<ExcessDriftMonitor>
+    {
+        private readonly Dictionary<int, int> countsByEventId = new();
+
+        public int CountOf(int eventId) => countsByEventId.GetValueOrDefault(eventId);
+
+        public void Log<TState>(
+            LogLevel logLevel, EventId eventId, TState state, Exception? exception,
+            Func<TState, Exception?, string> formatter)
+        {
+            countsByEventId[eventId.Id] = CountOf(eventId.Id) + 1;
+        }
+
+        public bool IsEnabled(LogLevel logLevel) => true;
+
+        public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
+    }
+}