From 979b54b492a42f9e1981952a7982cb40e2cc098d Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Thu, 4 Jun 2026 22:26:17 +1200 Subject: [PATCH 1/4] Refactor; move monitorOnly logic into startupsequence to reduce duplication --- src/OctopusTimeService/Ntp/NtpClient.cs | 4 +- src/OctopusTimeService/Program.cs | 10 +- .../Startup/StartupSequence.cs | 106 +++++++++++------- src/OctopusTimeService/Worker.cs | 38 +------ .../Startup/StartupSequenceTests.cs | 68 +++++++++++ 5 files changed, 149 insertions(+), 77 deletions(-) create mode 100644 tests/TimeService.Tests/Startup/StartupSequenceTests.cs diff --git a/src/OctopusTimeService/Ntp/NtpClient.cs b/src/OctopusTimeService/Ntp/NtpClient.cs index 5ea9179..d5457e7 100644 --- a/src/OctopusTimeService/Ntp/NtpClient.cs +++ b/src/OctopusTimeService/Ntp/NtpClient.cs @@ -5,7 +5,7 @@ namespace TimeService.Ntp; /// /// Measures clock drift between the local machine and an NTP server using SNTP/NTPv4. /// -public sealed class NtpClient +public class NtpClient { public const string DefaultServer = "time.windows.com"; public const int NtpPort = 123; @@ -26,7 +26,7 @@ public NtpClient(string server = DefaultServer, TimeSpan? timeout = null) /// Measures local clock drift against the configured NTP server. /// Returns the offset (server-time minus local-time) and the margin of error. /// - public async Task MeasureDriftAsync(CancellationToken cancellationToken = default) + public virtual async Task MeasureDriftAsync(CancellationToken cancellationToken = default) { var request = NtpPacket.CreateClientRequest(); diff --git a/src/OctopusTimeService/Program.cs b/src/OctopusTimeService/Program.cs index b0dedb3..751a53a 100644 --- a/src/OctopusTimeService/Program.cs +++ b/src/OctopusTimeService/Program.cs @@ -48,7 +48,10 @@ static int RunAsService(string[] forwardedArgs) // Information-level drift measurements reach the Windows Event Log. builder.Logging.AddFilter(null, LogLevel.Information); builder.Services.AddSingleton(_ => new NtpClient()); - builder.Services.AddSingleton(); + builder.Services.AddSingleton(sp => new StartupSequence( + sp.GetRequiredService>(), + sp.GetRequiredService(), + RegistrySettings.ReadMonitorOnly(ServiceDefaults.ServiceName))); builder.Services.AddHostedService(); builder.Build().Run(); return 0; @@ -58,7 +61,10 @@ static int RunAsConsole(string[] forwardedArgs) { var builder = Host.CreateApplicationBuilder(forwardedArgs); builder.Services.AddSingleton(_ => new NtpClient()); - builder.Services.AddSingleton(); + builder.Services.AddSingleton(sp => new StartupSequence( + sp.GetRequiredService>(), + sp.GetRequiredService(), + RegistrySettings.ReadMonitorOnly(ServiceDefaults.ServiceName))); builder.Services.AddHostedService(); builder.Build().Run(); return 0; diff --git a/src/OctopusTimeService/Startup/StartupSequence.cs b/src/OctopusTimeService/Startup/StartupSequence.cs index e320623..be6963a 100644 --- a/src/OctopusTimeService/Startup/StartupSequence.cs +++ b/src/OctopusTimeService/Startup/StartupSequence.cs @@ -8,12 +8,16 @@ namespace TimeService.Startup; /// Runs once at service start: measures drift, brings the OS time services up, /// forces a Windows time resync, then locks the OS time services back down so /// only this service is responsible for clock observation going forward. +/// In monitorOnly mode the resync/lockdown work is skipped and only a baseline +/// drift sample is taken. /// -public sealed class StartupSequence(ILogger logger, NtpClient ntpClient) +public sealed class StartupSequence(ILogger logger, NtpClient ntpClient, bool monitorOnly) { private const string WindowsTimeService = "W32Time"; private const string HyperVTimeSyncService = "vmictimesync"; + private static readonly TimeSpan StartupBudget = TimeSpan.FromMinutes(3); + private static readonly string[] TimeSyncScheduledTasks = [ @"\Microsoft\Windows\Time Synchronization\ForceSynchronizeTime", @@ -22,54 +26,80 @@ public sealed class StartupSequence(ILogger logger, NtpClient n public async Task RunAsync(CancellationToken cancellationToken) { - Log.StartupBeginning(logger); + using var startupCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); + startupCts.CancelAfter(StartupBudget); - await MeasureAndLogDriftAsync("pre-resync", cancellationToken); + try + { + Log.StartupBeginning(logger); - var ops = new WindowsServiceOps(logger); + Action logEvt = monitorOnly ? Log.MonitorOnlyMode : Log.StartupBeginning; + logEvt(logger); - // Windows Time is required for w32tm /resync to work. - var w32TimeRunning = await ops.EnsureRunningAsync(WindowsTimeService, cancellationToken); + await MeasureAndLogDriftAsync(monitorOnly ? "monitor-only" : "pre-resync", cancellationToken); - // Hyper-V time sync is only present in VMs; missing is fine, missing-and-failing is not. - var hyperVRunning = false; - if (WindowsServiceOps.ServiceExists(HyperVTimeSyncService)) - { - hyperVRunning = await ops.EnsureRunningAsync(HyperVTimeSyncService, cancellationToken); - } - else - { - Log.HyperVTimeNotInstalled(logger, HyperVTimeSyncService); - } + // Any operation which modifies the state of the system should be after this line. + if (monitorOnly) return; - if (w32TimeRunning) - { - await RunW32tmResyncAsync(cancellationToken); - } - else - { - Log.SkippingW32tm(logger, WindowsTimeService); - } + var ops = new WindowsServiceOps(logger); + + // Windows Time is required for w32tm /resync to work. + var w32TimeRunning = await ops.EnsureRunningAsync(WindowsTimeService, cancellationToken); + + // Hyper-V time sync is only present in VMs; missing is fine, missing-and-failing is not. + var hyperVRunning = false; + if (WindowsServiceOps.ServiceExists(HyperVTimeSyncService)) + { + hyperVRunning = await ops.EnsureRunningAsync(HyperVTimeSyncService, cancellationToken); + } + else + { + Log.HyperVTimeNotInstalled(logger, HyperVTimeSyncService); + } - // Disable the Windows Time Synchronization scheduled tasks so they don't relaunch - // a sync behind our back. Best-effort: missing tasks and schtasks failures are logged - // by ScheduledTaskOps and swallowed. - var schTaskOps = new ScheduledTaskOps(logger); - foreach (var taskPath in TimeSyncScheduledTasks) + if (w32TimeRunning) + { + await RunW32tmResyncAsync(cancellationToken); + } + else + { + Log.SkippingW32tm(logger, WindowsTimeService); + } + + // Disable the Windows Time Synchronization scheduled tasks so they don't relaunch + // a sync behind our back. Best-effort: missing tasks and schtasks failures are logged + // by ScheduledTaskOps and swallowed. + var schTaskOps = new ScheduledTaskOps(logger); + foreach (var taskPath in TimeSyncScheduledTasks) + { + await schTaskOps.DisableAsync(taskPath, cancellationToken); + } + + // Lock both back down. Best-effort: log failures, don't throw. + await ops.StopAndDisableAsync(WindowsTimeService, cancellationToken); + if (hyperVRunning || WindowsServiceOps.ServiceExists(HyperVTimeSyncService)) + { + await ops.StopAndDisableAsync(HyperVTimeSyncService, cancellationToken); + } + + await MeasureAndLogDriftAsync("post-resync", cancellationToken); + + Log.StartupComplete(logger); + } + catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { - await schTaskOps.DisableAsync(taskPath, cancellationToken); + // Host is genuinely shutting down — propagate so the host can abort start. + throw; } - - // Lock both back down. Best-effort: log failures, don't throw. - await ops.StopAndDisableAsync(WindowsTimeService, cancellationToken); - if (hyperVRunning || WindowsServiceOps.ServiceExists(HyperVTimeSyncService)) + catch (Exception ex) { - await ops.StopAndDisableAsync(HyperVTimeSyncService, cancellationToken); + Log.StartupSequenceFailed(logger, StartupBudget, ex); } + } - await MeasureAndLogDriftAsync("post-resync", cancellationToken); - - Log.StartupComplete(logger); + private async Task RunFullStartupAsync(CancellationToken cancellationToken) + { + } private async Task MeasureAndLogDriftAsync(string phase, CancellationToken cancellationToken) diff --git a/src/OctopusTimeService/Worker.cs b/src/OctopusTimeService/Worker.cs index 2cffa33..e51b620 100644 --- a/src/OctopusTimeService/Worker.cs +++ b/src/OctopusTimeService/Worker.cs @@ -9,48 +9,16 @@ public class Worker( NtpClient ntpClient, StartupSequence startupSequence) : BackgroundService { - private static readonly TimeSpan StartupBudget = TimeSpan.FromMinutes(3); - private readonly TimeSpan measurementInterval = TimeSpan.FromSeconds( RegistrySettings.ReadNtpCheckIntervalSeconds(ServiceDefaults.ServiceName)); - private readonly bool monitorOnly = - RegistrySettings.ReadMonitorOnly(ServiceDefaults.ServiceName); - public override async Task StartAsync(CancellationToken cancellationToken) { Log.ServiceStarting(logger, ServiceDefaults.ServiceName, ntpClient.Server, measurementInterval); - if (monitorOnly) - { - // Pure observation: skip the resync/lockdown work and just take a baseline reading - // so we still have a fresh sample at boot before the loop's first interval elapses. - Log.MonitorOnlyMode(logger); - await MeasureAndLogAsync(cancellationToken); - } - else - { - // Run startup inline so SCM (or the host in console mode) doesn't see us as Running - // until the startup sequence has finished. base.StartAsync then schedules ExecuteAsync. - // - // A failed or hung startup sequence must not prevent the service from coming up, - // so we cap it at StartupBudget and swallow anything that isn't a real shutdown. - using var startupCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); - startupCts.CancelAfter(StartupBudget); - try - { - await startupSequence.RunAsync(startupCts.Token); - } - catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) - { - // Host is genuinely shutting down — propagate so the host can abort start. - throw; - } - catch (Exception ex) - { - Log.StartupSequenceFailed(logger, StartupBudget, ex); - } - } + // Run startup inline so SCM (or the host in console mode) doesn't see us as Running + // until the startup sequence has finished. base.StartAsync then schedules ExecuteAsync. + await startupSequence.RunAsync(cancellationToken); await base.StartAsync(cancellationToken); } diff --git a/tests/TimeService.Tests/Startup/StartupSequenceTests.cs b/tests/TimeService.Tests/Startup/StartupSequenceTests.cs new file mode 100644 index 0000000..68387d7 --- /dev/null +++ b/tests/TimeService.Tests/Startup/StartupSequenceTests.cs @@ -0,0 +1,68 @@ +using Microsoft.Extensions.Logging.Abstractions; +using TimeService.Ntp; +using TimeService.Startup; + +namespace TimeService.Tests.Startup; + +public class StartupSequenceTests +{ + [Fact] + public async Task Monitor_only_takes_exactly_one_drift_measurement_and_skips_full_startup() + { + var ntp = new CountingNtpClient(); + var sequence = new StartupSequence(NullLogger.Instance, ntp, monitorOnly: true); + + await sequence.RunAsync(CancellationToken.None); + + // The full startup path would invoke MeasureDriftAsync twice (pre- and post-resync). + // Monitor-only takes exactly one baseline reading; observing 1 call therefore proves + // the full sequence was not executed. + Assert.Equal(1, ntp.CallCount); + } + + [Fact] + public async Task Monitor_only_swallows_drift_measurement_failures() + { + var ntp = new ThrowingNtpClient(new InvalidOperationException("boom")); + var sequence = new StartupSequence(NullLogger.Instance, ntp, monitorOnly: true); + + // No exception should propagate: monitor-only mode must not prevent the host coming up + // just because a baseline drift sample failed. + await sequence.RunAsync(CancellationToken.None); + + Assert.Equal(1, ntp.CallCount); + } + + [Fact] + public async Task Monitor_only_propagates_host_cancellation() + { + using var cts = new CancellationTokenSource(); + cts.Cancel(); + var ntp = new ThrowingNtpClient(new OperationCanceledException(cts.Token)); + var sequence = new StartupSequence(NullLogger.Instance, ntp, monitorOnly: true); + + await Assert.ThrowsAnyAsync(() => sequence.RunAsync(cts.Token)); + } + + private class CountingNtpClient : NtpClient + { + public int CallCount { get; private set; } + + public override Task MeasureDriftAsync(CancellationToken cancellationToken = default) + { + CallCount++; + return Task.FromResult(new NtpDriftResult(TimeSpan.Zero, TimeSpan.Zero)); + } + } + + private class ThrowingNtpClient(Exception toThrow) : NtpClient + { + public int CallCount { get; private set; } + + public override Task MeasureDriftAsync(CancellationToken cancellationToken = default) + { + CallCount++; + throw toThrow; + } + } +} From 4c86c373cb20f04d0f46456dd00ccf172abffb3c Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Thu, 4 Jun 2026 22:59:57 +1200 Subject: [PATCH 2/4] Write drift to CSV as well as windows event log --- Gather-OSLogs.ps1 | 275 ++++++++++++++++++ README.md | 8 +- src/OctopusTimeService/Logging/DriftCsvLog.cs | 50 ++++ src/OctopusTimeService/Logging/Log.cs | 20 +- src/OctopusTimeService/Program.cs | 5 + .../Startup/StartupSequence.cs | 33 +-- src/OctopusTimeService/Worker.cs | 26 +- .../Startup/StartupSequenceTests.cs | 13 +- 8 files changed, 383 insertions(+), 47 deletions(-) create mode 100644 Gather-OSLogs.ps1 create mode 100644 src/OctopusTimeService/Logging/DriftCsvLog.cs diff --git a/Gather-OSLogs.ps1 b/Gather-OSLogs.ps1 new file mode 100644 index 0000000..a3aa181 --- /dev/null +++ b/Gather-OSLogs.ps1 @@ -0,0 +1,275 @@ +# Gather-OSLogs.ps1 +# +# Collects OS-level provisioning / early-boot logs into C:\Octopus\TimeService\OSLogs +# preserving the directory structure relative to %windir%. +# +# Compatible with Windows PowerShell (Desktop) 3.0+ on Windows Server 2012, 2016, 2019, 2022. + +# Use Continue globally so unexpected non-terminating errors don't halt the script. +# Catchable operations use -ErrorAction Stop locally. +$ErrorActionPreference = 'Continue' + +# --------------------------------------------------------------------------- +# Configuration +# --------------------------------------------------------------------------- +$WinDir = $env:windir # %windir% +$SystemRoot = $env:SystemRoot # %SystemRoot% -- same directory as %windir%, kept separate to mirror Microsoft's notation +$BaseDir = 'C:\Octopus\TimeService' +$OutputRoot = Join-Path $BaseDir 'OSLogs' +$LogFile = Join-Path $BaseDir 'oslog-copy.log' +$MaxAttempts = 3 +$RetryDelaySeconds = 2 + +# Shared state +$script:Processed = @{} # de-dupe by source full path (lower-cased) +$script:Enumerated = @() # scratch buffer for retried enumerations +$script:Stats = @{ Copied = 0; Failed = 0; Skipped = 0 } + +# --------------------------------------------------------------------------- +# Functions +# --------------------------------------------------------------------------- + +function Write-Log { + param([string]$Message) + + $timestamp = (Get-Date).ToString('yyyy-MM-dd HH:mm:ss') + $line = "$timestamp $Message" + try { + Add-Content -LiteralPath $LogFile -Value $line -ErrorAction Stop + } catch { + # If we can't write to the log file, don't let it stop collection. + } + Write-Host $line +} + +# Runs a scriptblock, retrying up to $MaxAttempts times on error. +# Returns $true on success, $false if all attempts failed. +function Invoke-WithRetry { + param( + [ScriptBlock]$Action, + [string]$Description + ) + + for ($attempt = 1; $attempt -le $MaxAttempts; $attempt++) { + try { + & $Action + return $true + } catch { + $errMessage = $_.Exception.Message + if ($attempt -lt $MaxAttempts) { + Write-Log ("WARN Attempt {0}/{1} failed for {2}: {3}" -f $attempt, $MaxAttempts, $Description, $errMessage) + Start-Sleep -Seconds $RetryDelaySeconds + } else { + Write-Log ("ERROR All {0} attempts failed for {1}: {2}" -f $MaxAttempts, $Description, $errMessage) + } + } + } + return $false +} + +# Maps a source path under %windir% to its destination under $OutputRoot, +# preserving the structure relative to %windir%. +function Get-DestinationPath { + param([string]$SourceFullPath) + + $base = $WinDir.TrimEnd('\') + if ($SourceFullPath.Length -ge $base.Length -and + $SourceFullPath.Substring(0, $base.Length).ToLower() -eq $base.ToLower()) { + $relative = $SourceFullPath.Substring($base.Length).TrimStart('\') + } else { + # Fallback for anything not under %windir%: strip the drive qualifier. + $relative = $SourceFullPath -replace '^[A-Za-z]:[\\/]', '' + } + + if ([string]::IsNullOrEmpty($relative)) { + return $OutputRoot + } + return (Join-Path $OutputRoot $relative) +} + +function New-DirectoryWithRetry { + param([string]$Path) + + Invoke-WithRetry -Description ("Create directory {0}" -f $Path) -Action { + if (-not (Test-Path -LiteralPath $Path)) { + New-Item -ItemType Directory -Path $Path -Force -ErrorAction Stop | Out-Null + } + } | Out-Null +} + +# Fallback for event log files (.evtx), which are usually held open by the +# Event Log service and therefore can't be copied directly. Exports the live +# channel via wevtutil instead. Returns $true on success. +function Invoke-EvtxExportFallback { + param([string]$SourceFile, [string]$DestFile) + + $channel = [System.IO.Path]::GetFileNameWithoutExtension($SourceFile) + Write-Log ("INFO Attempting wevtutil export of channel '{0}' -> {1}" -f $channel, $DestFile) + + $ok = Invoke-WithRetry -Description ("wevtutil export of channel {0}" -f $channel) -Action { + $destParent = Split-Path -Path $DestFile -Parent + if (-not (Test-Path -LiteralPath $destParent)) { + New-Item -ItemType Directory -Path $destParent -Force -ErrorAction Stop | Out-Null + } + # /ow:true overwrites any partial file left by the failed direct copy. + $output = & wevtutil.exe epl $channel $DestFile /ow:true 2>&1 + if ($LASTEXITCODE -ne 0) { + throw ("wevtutil exited with code {0}: {1}" -f $LASTEXITCODE, ($output -join ' ')) + } + } + + if ($ok) { + Write-Log ("OK Exported channel '{0}' -> {1} via wevtutil" -f $channel, $DestFile) + } + return $ok +} + +# Copies a single file with retry. If the copy fails after all retries and a +# $FallbackAction scriptblock was supplied, it is invoked with ($SourceFile, +# $DestFile) and is expected to return $true/$false. +function Copy-OneFile { + param( + [string]$SourceFile, + [ScriptBlock]$FallbackAction + ) + + $key = $SourceFile.ToLower() + if ($script:Processed.ContainsKey($key)) { + return + } + $script:Processed[$key] = $true + + $destFile = Get-DestinationPath $SourceFile + $ok = Invoke-WithRetry -Description ("Copy {0}" -f $SourceFile) -Action { + $destParent = Split-Path -Path $destFile -Parent + if (-not (Test-Path -LiteralPath $destParent)) { + New-Item -ItemType Directory -Path $destParent -Force -ErrorAction Stop | Out-Null + } + Copy-Item -LiteralPath $SourceFile -Destination $destFile -Force -ErrorAction Stop + } + + if ($ok) { + $script:Stats.Copied++ + Write-Log ("OK Copied {0} -> {1}" -f $SourceFile, $destFile) + return + } + + # Primary copy failed after all retries. Try the fallback if one was supplied. + if ($FallbackAction) { + Write-Log ("INFO Direct copy failed for {0}; invoking fallback." -f $SourceFile) + $fallbackOk = & $FallbackAction $SourceFile $destFile + if ($fallbackOk) { + $script:Stats.Copied++ + return + } + } + + $script:Stats.Failed++ +} + +function Copy-Directory { + param([string]$SourceDir) + + # Ensure the destination root for this directory exists. + New-DirectoryWithRetry (Get-DestinationPath $SourceDir) + + # Recreate sub-directories first (preserves empty folders), with retry on enumeration. + $script:Enumerated = @() + $listedDirs = Invoke-WithRetry -Description ("List subdirectories of {0}" -f $SourceDir) -Action { + $script:Enumerated = @(Get-ChildItem -LiteralPath $SourceDir -Recurse -Force -ErrorAction Stop | + Where-Object { $_.PSIsContainer }) + } + if ($listedDirs) { + foreach ($dir in $script:Enumerated) { + New-DirectoryWithRetry (Get-DestinationPath $dir.FullName) + } + } + + # Copy files (recursively), each with its own retry so one locked file + # doesn't stop the rest. + $script:Enumerated = @() + $listedFiles = Invoke-WithRetry -Description ("List files of {0}" -f $SourceDir) -Action { + $script:Enumerated = @(Get-ChildItem -LiteralPath $SourceDir -Recurse -Force -ErrorAction Stop | + Where-Object { -not $_.PSIsContainer }) + } + if (-not $listedFiles) { + return + } + foreach ($file in $script:Enumerated) { + Copy-OneFile -SourceFile $file.FullName + } +} + +function Copy-SourceItem { + param( + [string]$SourcePath, + [ScriptBlock]$FallbackAction + ) + + if (-not (Test-Path -LiteralPath $SourcePath)) { + $script:Stats.Skipped++ + Write-Log ("SKIP Source not found: {0}" -f $SourcePath) + return + } + + $item = $null + try { $item = Get-Item -LiteralPath $SourcePath -Force -ErrorAction Stop } catch { } + + if ($item -and $item.PSIsContainer) { + Write-Log ("INFO Processing directory: {0}" -f $SourcePath) + Copy-Directory -SourceDir $SourcePath + } else { + Write-Log ("INFO Processing file: {0}" -f $SourcePath) + Copy-OneFile -SourceFile $SourcePath -FallbackAction $FallbackAction + } +} + +# --------------------------------------------------------------------------- +# Sources to collect (relative to %windir%). +# The two .evtx files are given a wevtutil export fallback for when the live +# Event Log service holds them open. Panther\UnattendGC lives under Panther; +# the de-dupe guard in Copy-OneFile prevents a double copy. +# --------------------------------------------------------------------------- +$EvtxFallback = { + param($SourceFile, $DestFile) + Invoke-EvtxExportFallback -SourceFile $SourceFile -DestFile $DestFile +} + +$SourceItems = @( + @{ Path = (Join-Path $WinDir 'System32\Sysprep\Panther') }, + @{ Path = (Join-Path $WinDir 'Panther') }, + @{ Path = (Join-Path $WinDir 'Panther\UnattendGC') }, + @{ Path = (Join-Path $WinDir 'inf\Setupapi.offline.log') }, + @{ Path = (Join-Path $WinDir 'inf\Setupapi.dev.log') }, + @{ Path = (Join-Path $WinDir 'inf\Setupapi.app.log') }, + @{ Path = (Join-Path $WinDir 'servicing\sessions\Sessions.xml') }, + @{ Path = (Join-Path $SystemRoot 'System32\Winevt\Logs\System.evtx'); Fallback = $EvtxFallback }, + @{ Path = (Join-Path $SystemRoot 'System32\Winevt\Logs\Application.evtx'); Fallback = $EvtxFallback } +) + +# --------------------------------------------------------------------------- +# Main +# --------------------------------------------------------------------------- + +# Bootstrap the base directory before the first log write. +if (-not (Test-Path -LiteralPath $BaseDir)) { + New-Item -ItemType Directory -Path $BaseDir -Force | Out-Null +} + +Write-Log "==========================================================" +Write-Log ("INFO OS log collection started. windir={0}" -f $WinDir) +Write-Log ("INFO Output: {0}" -f $OutputRoot) + +New-DirectoryWithRetry $OutputRoot + +foreach ($entry in $SourceItems) { + $fallback = $null + if ($entry.ContainsKey('Fallback')) { + $fallback = $entry.Fallback + } + Copy-SourceItem -SourcePath $entry.Path -FallbackAction $fallback +} + +Write-Log ("INFO Collection finished. Copied={0} Failed={1} Skipped={2}" -f ` + $script:Stats.Copied, $script:Stats.Failed, $script:Stats.Skipped) +Write-Log "==========================================================" diff --git a/README.md b/README.md index 4cad2f1..2d819a1 100644 --- a/README.md +++ b/README.md @@ -40,8 +40,12 @@ the service name. Each log entry has a stable Event ID; the ranges are: | 3000-3099 | WindowsServiceOps (start/stop/disable of `W32Time` etc.) | | 4000-4099 | ScheduledTaskOps (disabling scheduled tasks) | -The steady-state drift measurement is Event ID **1005**; a failed -measurement is **1006**. +Every drift measurement — whether taken at startup (`pre-resync`, +`post-resync`, `monitor-only`) or by the steady-state loop — is logged +under Event ID **1005** (or **1006** on failure), with the phase named in +the message. The same measurements are also appended to a CSV log at +`C:\Octopus\TimeService\ntp-drift.csv` +(columns: `LocalTime,NtpTime,Drift,MarginOfError`). ## Installation diff --git a/src/OctopusTimeService/Logging/DriftCsvLog.cs b/src/OctopusTimeService/Logging/DriftCsvLog.cs new file mode 100644 index 0000000..6ed0a7e --- /dev/null +++ b/src/OctopusTimeService/Logging/DriftCsvLog.cs @@ -0,0 +1,50 @@ +using System.Globalization; + +namespace TimeService.Logging; + +/// +/// Appends NTP drift measurements to a CSV file on disk, alongside the Windows Event Log. +/// Columns: LocalTime, NtpTime (ISO 8601, UTC), Drift, MarginOfError (TimeSpan round-trip format). +/// Write failures are logged and swallowed so a locked/unwritable file never disrupts measurement. +/// +public sealed class DriftCsvLog(ILogger logger, string filePath = DriftCsvLog.DefaultPath) +{ + public const string DefaultPath = @"C:\Octopus\TimeService\ntp-drift.csv"; + private const string Header = "LocalTime,NtpTime,Drift,MarginOfError"; + + private readonly Lock gate = new(); + + /// + /// Appends one measurement row. and + /// must be UTC (Kind=Utc) so the ISO 8601 output carries the trailing 'Z'. + /// + public void Append(DateTime localTimeUtc, DateTime ntpTimeUtc, TimeSpan drift, TimeSpan marginOfError) + { + var inv = CultureInfo.InvariantCulture; + var line = string.Join(',', + localTimeUtc.ToString("O", inv), + ntpTimeUtc.ToString("O", inv), + drift.ToString(null, inv), + marginOfError.ToString(null, inv)); + + try + { + lock (gate) + { + var dir = Path.GetDirectoryName(filePath); + if (!string.IsNullOrEmpty(dir)) + Directory.CreateDirectory(dir); + + var needsHeader = !File.Exists(filePath) || new FileInfo(filePath).Length == 0; + using var writer = new StreamWriter(filePath, append: true); + if (needsHeader) + writer.WriteLine(Header); + writer.WriteLine(line); + } + } + catch (Exception ex) + { + Log.DriftCsvWriteFailed(logger, filePath, ex); + } + } +} diff --git a/src/OctopusTimeService/Logging/Log.cs b/src/OctopusTimeService/Logging/Log.cs index a3feeb1..c24db93 100644 --- a/src/OctopusTimeService/Logging/Log.cs +++ b/src/OctopusTimeService/Logging/Log.cs @@ -29,17 +29,21 @@ internal static partial class Log public static partial void ServiceStopped(ILogger logger, string serviceName); [LoggerMessage(EventId = 1005, Level = LogLevel.Information, - Message = "Clock drift against {Server}: {Drift} (±{Margin})")] - public static partial void ClockDrift(ILogger logger, string server, TimeSpan drift, TimeSpan margin); + Message = "Clock drift ({Phase}) against {Server}: {Drift} (±{Margin})")] + public static partial void ClockDrift(ILogger logger, string phase, string server, TimeSpan drift, TimeSpan margin); [LoggerMessage(EventId = 1006, Level = LogLevel.Warning, - Message = "Failed to measure clock drift against {Server}")] - public static partial void ClockDriftFailed(ILogger logger, string server, Exception ex); + Message = "Failed to measure clock drift ({Phase}) against {Server}")] + public static partial void ClockDriftFailed(ILogger logger, string phase, string server, Exception ex); [LoggerMessage(EventId = 1007, Level = LogLevel.Information, Message = "MonitorOnly mode: skipping startup sequence, observation only")] public static partial void MonitorOnlyMode(ILogger logger); + [LoggerMessage(EventId = 1008, Level = LogLevel.Warning, + Message = "Failed to write drift measurement to CSV log at {Path}")] + public static partial void DriftCsvWriteFailed(ILogger logger, string path, Exception ex); + // -------- StartupSequence (2000-2099) -------- [LoggerMessage(EventId = 2001, Level = LogLevel.Information, @@ -58,14 +62,6 @@ internal static partial class Log Message = "Startup sequence complete")] public static partial void StartupComplete(ILogger logger); - [LoggerMessage(EventId = 2005, Level = LogLevel.Information, - Message = "Clock drift ({Phase}) against {Server}: {Drift} (±{Margin})")] - public static partial void ClockDriftPhase(ILogger logger, string phase, string server, TimeSpan drift, TimeSpan margin); - - [LoggerMessage(EventId = 2006, Level = LogLevel.Warning, - Message = "Failed to measure clock drift ({Phase}) against {Server}")] - public static partial void ClockDriftPhaseFailed(ILogger logger, string phase, string server, Exception ex); - [LoggerMessage(EventId = 2007, Level = LogLevel.Information, Message = "Running 'w32tm /resync /force'")] public static partial void RunningW32tm(ILogger logger); diff --git a/src/OctopusTimeService/Program.cs b/src/OctopusTimeService/Program.cs index 751a53a..e8f3ee4 100644 --- a/src/OctopusTimeService/Program.cs +++ b/src/OctopusTimeService/Program.cs @@ -2,6 +2,7 @@ using Microsoft.Extensions.Hosting.WindowsServices; using Microsoft.Extensions.Logging.EventLog; using TimeService; +using TimeService.Logging; using TimeService.Ntp; using TimeService.Startup; @@ -48,9 +49,11 @@ static int RunAsService(string[] forwardedArgs) // Information-level drift measurements reach the Windows Event Log. builder.Logging.AddFilter(null, LogLevel.Information); builder.Services.AddSingleton(_ => new NtpClient()); + builder.Services.AddSingleton(sp => new DriftCsvLog(sp.GetRequiredService>())); builder.Services.AddSingleton(sp => new StartupSequence( sp.GetRequiredService>(), sp.GetRequiredService(), + sp.GetRequiredService(), RegistrySettings.ReadMonitorOnly(ServiceDefaults.ServiceName))); builder.Services.AddHostedService(); builder.Build().Run(); @@ -61,9 +64,11 @@ static int RunAsConsole(string[] forwardedArgs) { var builder = Host.CreateApplicationBuilder(forwardedArgs); builder.Services.AddSingleton(_ => new NtpClient()); + builder.Services.AddSingleton(sp => new DriftCsvLog(sp.GetRequiredService>())); builder.Services.AddSingleton(sp => new StartupSequence( sp.GetRequiredService>(), sp.GetRequiredService(), + sp.GetRequiredService(), RegistrySettings.ReadMonitorOnly(ServiceDefaults.ServiceName))); builder.Services.AddHostedService(); builder.Build().Run(); diff --git a/src/OctopusTimeService/Startup/StartupSequence.cs b/src/OctopusTimeService/Startup/StartupSequence.cs index be6963a..8cdc731 100644 --- a/src/OctopusTimeService/Startup/StartupSequence.cs +++ b/src/OctopusTimeService/Startup/StartupSequence.cs @@ -11,7 +11,11 @@ namespace TimeService.Startup; /// In monitorOnly mode the resync/lockdown work is skipped and only a baseline /// drift sample is taken. /// -public sealed class StartupSequence(ILogger logger, NtpClient ntpClient, bool monitorOnly) +public sealed class StartupSequence( + ILogger logger, + NtpClient ntpClient, + DriftCsvLog driftCsvLog, + bool monitorOnly) { private const string WindowsTimeService = "W32Time"; private const string HyperVTimeSyncService = "vmictimesync"; @@ -36,7 +40,8 @@ public async Task RunAsync(CancellationToken cancellationToken) Action logEvt = monitorOnly ? Log.MonitorOnlyMode : Log.StartupBeginning; logEvt(logger); - await MeasureAndLogDriftAsync(monitorOnly ? "monitor-only" : "pre-resync", cancellationToken); + await Worker.MeasureAndLogDriftAsync( + logger, ntpClient, driftCsvLog, monitorOnly ? "monitor-only" : "pre-resync", cancellationToken); // Any operation which modifies the state of the system should be after this line. if (monitorOnly) return; @@ -82,7 +87,7 @@ public async Task RunAsync(CancellationToken cancellationToken) await ops.StopAndDisableAsync(HyperVTimeSyncService, cancellationToken); } - await MeasureAndLogDriftAsync("post-resync", cancellationToken); + await Worker.MeasureAndLogDriftAsync(logger, ntpClient, driftCsvLog, "post-resync", cancellationToken); Log.StartupComplete(logger); } @@ -97,28 +102,6 @@ public async Task RunAsync(CancellationToken cancellationToken) } } - private async Task RunFullStartupAsync(CancellationToken cancellationToken) - { - - } - - private async Task MeasureAndLogDriftAsync(string phase, CancellationToken cancellationToken) - { - try - { - var result = await ntpClient.MeasureDriftAsync(cancellationToken); - Log.ClockDriftPhase(logger, phase, ntpClient.Server, result.Drift, result.MarginOfError); - } - catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) - { - throw; - } - catch (Exception ex) - { - Log.ClockDriftPhaseFailed(logger, phase, ntpClient.Server, ex); - } - } - private async Task RunW32tmResyncAsync(CancellationToken cancellationToken) { Log.RunningW32tm(logger); diff --git a/src/OctopusTimeService/Worker.cs b/src/OctopusTimeService/Worker.cs index e51b620..8f28dd6 100644 --- a/src/OctopusTimeService/Worker.cs +++ b/src/OctopusTimeService/Worker.cs @@ -7,7 +7,8 @@ namespace TimeService; public class Worker( ILogger logger, NtpClient ntpClient, - StartupSequence startupSequence) : BackgroundService + StartupSequence startupSequence, + DriftCsvLog driftCsvLog) : BackgroundService { private readonly TimeSpan measurementInterval = TimeSpan.FromSeconds( RegistrySettings.ReadNtpCheckIntervalSeconds(ServiceDefaults.ServiceName)); @@ -37,16 +38,31 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken) using var timer = new PeriodicTimer(measurementInterval); while (!stoppingToken.IsCancellationRequested && await timer.WaitForNextTickAsync(stoppingToken)) { - await MeasureAndLogAsync(stoppingToken); + await MeasureAndLogDriftAsync(logger, ntpClient, driftCsvLog, "steady-state", stoppingToken); } } - private async Task MeasureAndLogAsync(CancellationToken cancellationToken) + /// + /// Takes a single NTP drift measurement and records it to both the Windows Event Log and the + /// 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. + /// + public static async Task MeasureAndLogDriftAsync( + ILogger logger, + NtpClient ntpClient, + DriftCsvLog driftCsvLog, + string phase, + CancellationToken cancellationToken) { try { var result = await ntpClient.MeasureDriftAsync(cancellationToken); - Log.ClockDrift(logger, ntpClient.Server, result.Drift, result.MarginOfError); + var localTime = DateTime.UtcNow; + var ntpTime = localTime + result.Drift; + Log.ClockDrift(logger, phase, ntpClient.Server, result.Drift, result.MarginOfError); + driftCsvLog.Append(localTime, ntpTime, result.Drift, result.MarginOfError); } catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { @@ -54,7 +70,7 @@ private async Task MeasureAndLogAsync(CancellationToken cancellationToken) } catch (Exception ex) { - Log.ClockDriftFailed(logger, ntpClient.Server, ex); + Log.ClockDriftFailed(logger, phase, ntpClient.Server, ex); } } } diff --git a/tests/TimeService.Tests/Startup/StartupSequenceTests.cs b/tests/TimeService.Tests/Startup/StartupSequenceTests.cs index 68387d7..4c8ccfa 100644 --- a/tests/TimeService.Tests/Startup/StartupSequenceTests.cs +++ b/tests/TimeService.Tests/Startup/StartupSequenceTests.cs @@ -1,4 +1,5 @@ using Microsoft.Extensions.Logging.Abstractions; +using TimeService.Logging; using TimeService.Ntp; using TimeService.Startup; @@ -6,11 +7,17 @@ namespace TimeService.Tests.Startup; public class StartupSequenceTests { + // CSV log pointed at a throwaway temp path so the shared measure-and-log path doesn't + // touch the real C:\Octopus location during tests. + private static DriftCsvLog TempCsvLog() => + new(NullLogger.Instance, + Path.Combine(Path.GetTempPath(), $"octopus-timeservice-tests-{Guid.NewGuid():N}.csv")); + [Fact] public async Task Monitor_only_takes_exactly_one_drift_measurement_and_skips_full_startup() { var ntp = new CountingNtpClient(); - var sequence = new StartupSequence(NullLogger.Instance, ntp, monitorOnly: true); + var sequence = new StartupSequence(NullLogger.Instance, ntp, TempCsvLog(), monitorOnly: true); await sequence.RunAsync(CancellationToken.None); @@ -24,7 +31,7 @@ public async Task Monitor_only_takes_exactly_one_drift_measurement_and_skips_ful public async Task Monitor_only_swallows_drift_measurement_failures() { var ntp = new ThrowingNtpClient(new InvalidOperationException("boom")); - var sequence = new StartupSequence(NullLogger.Instance, ntp, monitorOnly: true); + var sequence = new StartupSequence(NullLogger.Instance, ntp, TempCsvLog(), monitorOnly: true); // No exception should propagate: monitor-only mode must not prevent the host coming up // just because a baseline drift sample failed. @@ -39,7 +46,7 @@ public async Task Monitor_only_propagates_host_cancellation() using var cts = new CancellationTokenSource(); cts.Cancel(); var ntp = new ThrowingNtpClient(new OperationCanceledException(cts.Token)); - var sequence = new StartupSequence(NullLogger.Instance, ntp, monitorOnly: true); + var sequence = new StartupSequence(NullLogger.Instance, ntp, TempCsvLog(), monitorOnly: true); await Assert.ThrowsAnyAsync(() => sequence.RunAsync(cts.Token)); } From fbeaad6d7c61aa514ed6e4bb1b458d79b4012359 Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Thu, 4 Jun 2026 23:17:55 +1200 Subject: [PATCH 3/4] Make log folder configurable on service install --- README.md | 8 +++--- src/OctopusTimeService/Logging/DriftCsvLog.cs | 5 ++-- src/OctopusTimeService/Program.cs | 10 +++++-- src/OctopusTimeService/RegistrySettings.cs | 27 ++++++++++++++++++- src/OctopusTimeService/ServiceInstaller.cs | 12 +++++++++ .../Startup/StartupSequenceTests.cs | 4 +-- 6 files changed, 56 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index 2d819a1..fce8bcc 100644 --- a/README.md +++ b/README.md @@ -43,9 +43,11 @@ the service name. Each log entry has a stable Event ID; the ranges are: Every drift measurement — whether taken at startup (`pre-resync`, `post-resync`, `monitor-only`) or by the steady-state loop — is logged under Event ID **1005** (or **1006** on failure), with the phase named in -the message. The same measurements are also appended to a CSV log at -`C:\Octopus\TimeService\ntp-drift.csv` -(columns: `LocalTime,NtpTime,Drift,MarginOfError`). +the message. The same measurements are also appended to a CSV log named +`ntp-drift.csv` (columns: `LocalTime,NtpTime,Drift,MarginOfError`). The +folder for that file is set at install time with `--logFolder` and stored +in the registry value `LogFolder`; if omitted it defaults to +`C:\Octopus\TimeService`. ## Installation diff --git a/src/OctopusTimeService/Logging/DriftCsvLog.cs b/src/OctopusTimeService/Logging/DriftCsvLog.cs index 6ed0a7e..1501ca1 100644 --- a/src/OctopusTimeService/Logging/DriftCsvLog.cs +++ b/src/OctopusTimeService/Logging/DriftCsvLog.cs @@ -7,11 +7,12 @@ namespace TimeService.Logging; /// Columns: LocalTime, NtpTime (ISO 8601, UTC), Drift, MarginOfError (TimeSpan round-trip format). /// Write failures are logged and swallowed so a locked/unwritable file never disrupts measurement. /// -public sealed class DriftCsvLog(ILogger logger, string filePath = DriftCsvLog.DefaultPath) +public sealed class DriftCsvLog(ILogger logger, string directory) { - public const string DefaultPath = @"C:\Octopus\TimeService\ntp-drift.csv"; + public const string FileName = "ntp-drift.csv"; private const string Header = "LocalTime,NtpTime,Drift,MarginOfError"; + private readonly string filePath = Path.Combine(directory, FileName); private readonly Lock gate = new(); /// diff --git a/src/OctopusTimeService/Program.cs b/src/OctopusTimeService/Program.cs index e8f3ee4..e84408a 100644 --- a/src/OctopusTimeService/Program.cs +++ b/src/OctopusTimeService/Program.cs @@ -49,7 +49,9 @@ static int RunAsService(string[] forwardedArgs) // Information-level drift measurements reach the Windows Event Log. builder.Logging.AddFilter(null, LogLevel.Information); builder.Services.AddSingleton(_ => new NtpClient()); - builder.Services.AddSingleton(sp => new DriftCsvLog(sp.GetRequiredService>())); + builder.Services.AddSingleton(sp => new DriftCsvLog( + sp.GetRequiredService>(), + RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName))); builder.Services.AddSingleton(sp => new StartupSequence( sp.GetRequiredService>(), sp.GetRequiredService(), @@ -64,7 +66,9 @@ static int RunAsConsole(string[] forwardedArgs) { var builder = Host.CreateApplicationBuilder(forwardedArgs); builder.Services.AddSingleton(_ => new NtpClient()); - builder.Services.AddSingleton(sp => new DriftCsvLog(sp.GetRequiredService>())); + builder.Services.AddSingleton(sp => new DriftCsvLog( + sp.GetRequiredService>(), + RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName))); builder.Services.AddSingleton(sp => new StartupSequence( sp.GetRequiredService>(), sp.GetRequiredService(), @@ -90,6 +94,8 @@ static void PrintUsage(TextWriter writer) writer.WriteLine(" --ntpCheckInterval NTP drift-check interval (default: 30)"); writer.WriteLine(" --monitorOnly skip the startup resync/lockdown"); writer.WriteLine(" sequence; just measure and log"); + writer.WriteLine(" --logFolder folder for the drift CSV log"); + writer.WriteLine($" (default: {RegistrySettings.DefaultLogFolder})"); writer.WriteLine(" OctopusTimeService uninstall [flags] Unregister the Windows service."); writer.WriteLine(" --serviceName (default: OctopusTimeService)"); writer.WriteLine(" --dependent target service to strip us from"); diff --git a/src/OctopusTimeService/RegistrySettings.cs b/src/OctopusTimeService/RegistrySettings.cs index 2f9d04d..9843ab3 100644 --- a/src/OctopusTimeService/RegistrySettings.cs +++ b/src/OctopusTimeService/RegistrySettings.cs @@ -13,8 +13,10 @@ internal static class RegistrySettings public const string DependentsValueName = "Dependents"; public const string NtpCheckIntervalSecondsValueName = "NtpCheckIntervalSeconds"; public const string MonitorOnlyValueName = "MonitorOnly"; + public const string LogFolderValueName = "LogFolder"; public const int DefaultNtpCheckIntervalSeconds = 30; + public const string DefaultLogFolder = @"C:\Octopus\TimeService"; private static string KeyPath(string serviceName) => $@"{ServicesRegistryRoot}\{serviceName}"; @@ -81,9 +83,32 @@ public static bool ReadMonitorOnly(string serviceName) return false; } + public static void WriteLogFolder(string serviceName, string folder) + { + using var key = Registry.LocalMachine.OpenSubKey(KeyPath(serviceName), writable: true) + ?? throw new InvalidOperationException( + $@"Registry key HKLM\{KeyPath(serviceName)} does not exist; service was not created."); + key.SetValue(LogFolderValueName, folder, RegistryValueKind.String); + } + + public static string ReadLogFolder(string serviceName) + { + try + { + using var key = Registry.LocalMachine.OpenSubKey(KeyPath(serviceName)); + if (key?.GetValue(LogFolderValueName) is string folder && !string.IsNullOrWhiteSpace(folder)) + return folder; + } + catch + { + // Fall through to default. + } + return DefaultLogFolder; + } + /// /// Removes the service's registry key after sc.exe delete, so any custom values - /// (Dependents, NtpCheckIntervalSeconds) we wrote are not left behind. No-op if missing. + /// (Dependents, NtpCheckIntervalSeconds, LogFolder) we wrote are not left behind. No-op if missing. /// public static void DeleteServiceKey(string serviceName) { diff --git a/src/OctopusTimeService/ServiceInstaller.cs b/src/OctopusTimeService/ServiceInstaller.cs index 3c343b4..63bbd67 100644 --- a/src/OctopusTimeService/ServiceInstaller.cs +++ b/src/OctopusTimeService/ServiceInstaller.cs @@ -14,6 +14,7 @@ public static int Install(ReadOnlySpan args) var dependents = new List(); var ntpCheckIntervalSeconds = RegistrySettings.DefaultNtpCheckIntervalSeconds; var monitorOnly = false; + var logFolder = RegistrySettings.DefaultLogFolder; for (var i = 0; i < args.Length; i++) { @@ -41,6 +42,11 @@ public static int Install(ReadOnlySpan args) case "--monitorOnly": monitorOnly = true; break; + case "--logFolder": + if (!TryGetValue(args, ref i, out var logFolderValue)) return ArgError("--logFolder requires a value"); + if (string.IsNullOrWhiteSpace(logFolderValue)) return ArgError("--logFolder must not be empty."); + logFolder = logFolderValue; + break; default: return ArgError($"Unknown argument: {args[i]}"); } @@ -60,6 +66,10 @@ public static int Install(ReadOnlySpan args) return 1; } + // Normalise the log folder to an absolute path: the service runs under SCM with a + // different working directory, so a relative path would resolve unpredictably at runtime. + logFolder = Path.GetFullPath(logFolder); + // Pre-validate dependents before we make any changes. foreach (var dep in dependents) { @@ -105,8 +115,10 @@ public static int Install(ReadOnlySpan args) RegistrySettings.WriteDependents(serviceName, dependents); RegistrySettings.WriteNtpCheckIntervalSeconds(serviceName, ntpCheckIntervalSeconds); RegistrySettings.WriteMonitorOnly(serviceName, monitorOnly); + RegistrySettings.WriteLogFolder(serviceName, logFolder); Console.WriteLine($" NtpCheckIntervalSeconds = {ntpCheckIntervalSeconds}"); Console.WriteLine($" MonitorOnly = {(monitorOnly ? 1 : 0)}"); + Console.WriteLine($" LogFolder = {logFolder}"); if (dependents.Count > 0) Console.WriteLine($" Dependents = {string.Join(",", dependents)}"); } diff --git a/tests/TimeService.Tests/Startup/StartupSequenceTests.cs b/tests/TimeService.Tests/Startup/StartupSequenceTests.cs index 4c8ccfa..7dcde28 100644 --- a/tests/TimeService.Tests/Startup/StartupSequenceTests.cs +++ b/tests/TimeService.Tests/Startup/StartupSequenceTests.cs @@ -7,11 +7,11 @@ namespace TimeService.Tests.Startup; public class StartupSequenceTests { - // CSV log pointed at a throwaway temp path so the shared measure-and-log path doesn't + // CSV log pointed at a throwaway temp folder so the shared measure-and-log path doesn't // touch the real C:\Octopus location during tests. private static DriftCsvLog TempCsvLog() => new(NullLogger.Instance, - Path.Combine(Path.GetTempPath(), $"octopus-timeservice-tests-{Guid.NewGuid():N}.csv")); + Path.Combine(Path.GetTempPath(), $"octopus-timeservice-tests-{Guid.NewGuid():N}")); [Fact] public async Task Monitor_only_takes_exactly_one_drift_measurement_and_skips_full_startup() From 92c0e951997477251950c758b17362a7f2b743d7 Mon Sep 17 00:00:00 2001 From: Orion Edwards Date: Fri, 5 Jun 2026 09:04:57 +1200 Subject: [PATCH 4/4] Fix gather-oslogs and add plot_drift.py --- Gather-OSLogs.ps1 | 25 ++++++++---- plot_drift.py | 97 +++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 114 insertions(+), 8 deletions(-) create mode 100644 plot_drift.py diff --git a/Gather-OSLogs.ps1 b/Gather-OSLogs.ps1 index a3aa181..37ed56b 100644 --- a/Gather-OSLogs.ps1 +++ b/Gather-OSLogs.ps1 @@ -1,7 +1,7 @@ # Gather-OSLogs.ps1 # # Collects OS-level provisioning / early-boot logs into C:\Octopus\TimeService\OSLogs -# preserving the directory structure relative to %windir%. +# preserving the directory structure relative to $WinDir. # # Compatible with Windows PowerShell (Desktop) 3.0+ on Windows Server 2012, 2016, 2019, 2022. @@ -12,10 +12,10 @@ $ErrorActionPreference = 'Continue' # --------------------------------------------------------------------------- # Configuration # --------------------------------------------------------------------------- -$WinDir = $env:windir # %windir% -$SystemRoot = $env:SystemRoot # %SystemRoot% -- same directory as %windir%, kept separate to mirror Microsoft's notation +$WinDir = $env:windir +$SystemRoot = $env:SystemRoot $BaseDir = 'C:\Octopus\TimeService' -$OutputRoot = Join-Path $BaseDir 'OSLogs' +$OutputRoot = Join-Path $BaseDir 'Windows' $LogFile = Join-Path $BaseDir 'oslog-copy.log' $MaxAttempts = 3 $RetryDelaySeconds = 2 @@ -67,8 +67,8 @@ function Invoke-WithRetry { return $false } -# Maps a source path under %windir% to its destination under $OutputRoot, -# preserving the structure relative to %windir%. +# Maps a source path under $WinDir to its destination under $OutputRoot, +# preserving the structure relative to $WinDir. function Get-DestinationPath { param([string]$SourceFullPath) @@ -77,7 +77,7 @@ function Get-DestinationPath { $SourceFullPath.Substring(0, $base.Length).ToLower() -eq $base.ToLower()) { $relative = $SourceFullPath.Substring($base.Length).TrimStart('\') } else { - # Fallback for anything not under %windir%: strip the drive qualifier. + # Fallback for anything not under $WinDir: strip the drive qualifier. $relative = $SourceFullPath -replace '^[A-Za-z]:[\\/]', '' } @@ -225,7 +225,7 @@ function Copy-SourceItem { } # --------------------------------------------------------------------------- -# Sources to collect (relative to %windir%). +# Sources to collect (relative to $WinDir). # The two .evtx files are given a wevtutil export fallback for when the live # Event Log service holds them open. Panther\UnattendGC lives under Panther; # the de-dupe guard in Copy-OneFile prevents a double copy. @@ -272,4 +272,13 @@ foreach ($entry in $SourceItems) { Write-Log ("INFO Collection finished. Copied={0} Failed={1} Skipped={2}" -f ` $script:Stats.Copied, $script:Stats.Failed, $script:Stats.Skipped) + +# Tell TeamCity to upload the collected logs as a build artifact. +# Uses TeamCity artifact-path syntax 'source => target'; '.zip' target zips it. +# This only has an effect when stdout is read by a TeamCity build agent; +# otherwise it's just a harmless printed line. +$artifactSpec = "$BaseDir => OSLogs.zip" +Write-Host ("##teamcity[publishArtifacts '{0}']" -f $artifactSpec) +Write-Log ("INFO Emitted TeamCity publishArtifacts service message for '{0}'" -f $artifactSpec) + Write-Log "==========================================================" diff --git a/plot_drift.py b/plot_drift.py new file mode 100644 index 0000000..b0633e9 --- /dev/null +++ b/plot_drift.py @@ -0,0 +1,97 @@ +#!/usr/bin/env python3 +"""Plot NTP drift over time from a CSV file. + +The CSV is expected to have a LocalTime column (ISO-8601 timestamps) and a +Drift column (a duration string like "-00:00:00.0032239" = HH:MM:SS.fffffff). +Any other columns (e.g. NtpTime, MarginOfError) are ignored. + +Usage: + python3 plot_drift.py ntp-drift.csv + python3 plot_drift.py ntp-drift.csv -o out.png --x-col LocalTime --y-col Drift +""" +import argparse +import csv +import re +import sys +from datetime import datetime, timezone + + +def parse_timestamp(value): + """Parse an ISO-8601 timestamp, tolerating 7-digit fractional seconds and a 'Z' suffix.""" + text = value.strip() + # Python's fromisoformat (< 3.11) accepts at most 6 fractional digits and no 'Z'. + text = text.replace("Z", "+00:00") + # Trim fractional seconds to 6 digits. + text = re.sub(r"(\.\d{6})\d+", r"\1", text) + return datetime.fromisoformat(text) + + +def parse_duration_seconds(value): + """Parse a "[-]HH:MM:SS.fffffff" duration string into a float number of seconds.""" + text = value.strip() + sign = 1.0 + if text.startswith("-"): + sign = -1.0 + text = text[1:] + elif text.startswith("+"): + text = text[1:] + hours, minutes, seconds = text.split(":") + total = int(hours) * 3600 + int(minutes) * 60 + float(seconds) + return sign * total + + +def load(path, x_col, y_col): + xs, ys = [], [] + with open(path, newline="") as f: + reader = csv.DictReader(f) + if x_col not in reader.fieldnames or y_col not in reader.fieldnames: + sys.exit( + f"error: columns {x_col!r}/{y_col!r} not found. " + f"Available: {reader.fieldnames}" + ) + for row in reader: + xs.append(parse_timestamp(row[x_col])) + ys.append(parse_duration_seconds(row[y_col])) + return xs, ys + + +def main(): + ap = argparse.ArgumentParser(description="Plot NTP drift over time to a PNG.") + ap.add_argument("csv_file", help="Input CSV file") + ap.add_argument("-o", "--output", help="Output PNG path (default: .png)") + ap.add_argument("--x-col", default="LocalTime", help="X-axis column (default: LocalTime)") + ap.add_argument("--y-col", default="Drift", help="Y-axis column (default: Drift)") + ap.add_argument("--unit", choices=["s", "ms", "us"], default="ms", + help="Y-axis unit for drift (default: ms)") + args = ap.parse_args() + + import matplotlib + matplotlib.use("Agg") + import matplotlib.pyplot as plt + import matplotlib.dates as mdates + + xs, ys = load(args.csv_file, args.x_col, args.y_col) + if not xs: + sys.exit("error: no data rows found") + + scale = {"s": 1.0, "ms": 1e3, "us": 1e6}[args.unit] + ys = [y * scale for y in ys] + + output = args.output or (args.csv_file.rsplit(".", 1)[0] + ".png") + + fig, ax = plt.subplots(figsize=(12, 6)) + ax.plot(xs, ys, linewidth=1, color="tab:blue") + ax.axhline(0, color="grey", linewidth=0.8, linestyle="--") + ax.set_xlabel(args.x_col) + ax.set_ylabel(f"{args.y_col} ({args.unit})") + ax.set_title(f"{args.y_col} over {args.x_col}") + ax.grid(True, alpha=0.3) + ax.xaxis.set_major_formatter(mdates.DateFormatter("%H:%M:%S")) + fig.autofmt_xdate() + fig.tight_layout() + fig.savefig(output, dpi=150) + print(f"wrote {output} ({len(xs)} points)") + + +if __name__ == "__main__": + main()