From f199719c3b1fdf63b89ec21ccab8bc07d4609aac Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Mon, 13 Jul 2026 09:43:55 +1200 Subject: [PATCH 1/4] excess drift monitoring --- .../Logging/ExcessDriftMonitor.cs | 82 +++++++++ src/OctopusTimeService/Logging/Log.cs | 14 +- src/OctopusTimeService/Program.cs | 6 + src/OctopusTimeService/Worker.cs | 13 +- .../Logging/ExcessDriftMonitorTests.cs | 162 ++++++++++++++++++ 5 files changed, 271 insertions(+), 6 deletions(-) create mode 100644 src/OctopusTimeService/Logging/ExcessDriftMonitor.cs create mode 100644 tests/TimeService.Tests/Logging/ExcessDriftMonitorTests.cs 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; + } +} From 04700167f1c153d7bb7cb60a5a3367155cb27049 Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Mon, 13 Jul 2026 09:53:33 +1200 Subject: [PATCH 2/4] excess drift checker --- Check-ExcessDrift.ps1 | 48 +++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 48 insertions(+) create mode 100644 Check-ExcessDrift.ps1 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 From e3d8901c139c1a25ecdd7e1b7bc29cd4cb62bd92 Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Mon, 13 Jul 2026 09:54:23 +1200 Subject: [PATCH 3/4] Temp: Create a prerelease --- .github/workflows/main.yaml | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/.github/workflows/main.yaml b/.github/workflows/main.yaml index 7ed0407..3abed45 100644 --- a/.github/workflows/main.yaml +++ b/.github/workflows/main.yaml @@ -72,17 +72,17 @@ jobs: fail-on-error: true - name: Publish AOT exe - if: github.event_name == 'push' && github.ref == 'refs/heads/main' || github.event_name == 'schedule' || github.event_name == 'workflow_dispatch' + #if: github.event_name == 'push' && github.ref == 'refs/heads/main' || github.event_name == 'schedule' || github.event_name == 'workflow_dispatch' run: dotnet publish src/OctopusTimeService/OctopusTimeService.csproj --configuration Release --runtime win-x64 /p:Version=${{ steps.version.outputs.octoversion_fullsemver }} /p:AssemblyVersion=${{ steps.version.outputs.octoversion_majorminorpatch }} /p:FileVersion=${{ steps.version.outputs.octoversion_majorminorpatch }} /p:InformationalVersion=${{ steps.version.outputs.octoversion_informationalversion }} --output artifacts/publish # Only create releases from main branch, not for scheduled or manual runs. - name: Package release zip - if: github.event_name == 'push' && github.ref == 'refs/heads/main' + #if: github.event_name == 'push' && github.ref == 'refs/heads/main' run: Compress-Archive -Path artifacts/publish/*.exe -DestinationPath artifacts/OctopusTimeService.${{ steps.version.outputs.octoversion_fullsemver }}.zip # Only create releases from main branch, not for scheduled or manual runs. - name: Create GitHub Release - if: github.event_name == 'push' && github.ref == 'refs/heads/main' + #if: github.event_name == 'push' && github.ref == 'refs/heads/main' uses: softprops/action-gh-release@72f2c25fcb47643c292f7107632f7a47c1df5cd8 # v2.3.2 with: tag_name: ${{ steps.version.outputs.octoversion_fullsemver }} From c01dd9f856ea0bebf8ab44ab819164b4088f628c Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Mon, 13 Jul 2026 10:32:31 +1200 Subject: [PATCH 4/4] Restore workflow --- .github/workflows/main.yaml | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/.github/workflows/main.yaml b/.github/workflows/main.yaml index 3abed45..7ed0407 100644 --- a/.github/workflows/main.yaml +++ b/.github/workflows/main.yaml @@ -72,17 +72,17 @@ jobs: fail-on-error: true - name: Publish AOT exe - #if: github.event_name == 'push' && github.ref == 'refs/heads/main' || github.event_name == 'schedule' || github.event_name == 'workflow_dispatch' + if: github.event_name == 'push' && github.ref == 'refs/heads/main' || github.event_name == 'schedule' || github.event_name == 'workflow_dispatch' run: dotnet publish src/OctopusTimeService/OctopusTimeService.csproj --configuration Release --runtime win-x64 /p:Version=${{ steps.version.outputs.octoversion_fullsemver }} /p:AssemblyVersion=${{ steps.version.outputs.octoversion_majorminorpatch }} /p:FileVersion=${{ steps.version.outputs.octoversion_majorminorpatch }} /p:InformationalVersion=${{ steps.version.outputs.octoversion_informationalversion }} --output artifacts/publish # Only create releases from main branch, not for scheduled or manual runs. - name: Package release zip - #if: github.event_name == 'push' && github.ref == 'refs/heads/main' + if: github.event_name == 'push' && github.ref == 'refs/heads/main' run: Compress-Archive -Path artifacts/publish/*.exe -DestinationPath artifacts/OctopusTimeService.${{ steps.version.outputs.octoversion_fullsemver }}.zip # Only create releases from main branch, not for scheduled or manual runs. - name: Create GitHub Release - #if: github.event_name == 'push' && github.ref == 'refs/heads/main' + if: github.event_name == 'push' && github.ref == 'refs/heads/main' uses: softprops/action-gh-release@72f2c25fcb47643c292f7107632f7a47c1df5cd8 # v2.3.2 with: tag_name: ${{ steps.version.outputs.octoversion_fullsemver }}