diff --git a/Gather-OSLogs.ps1 b/Gather-OSLogs.ps1
new file mode 100644
index 0000000..37ed56b
--- /dev/null
+++ b/Gather-OSLogs.ps1
@@ -0,0 +1,284 @@
+# 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
+$SystemRoot = $env:SystemRoot
+$BaseDir = 'C:\Octopus\TimeService'
+$OutputRoot = Join-Path $BaseDir 'Windows'
+$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)
+
+# 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/README.md b/README.md
index 4cad2f1..fce8bcc 100644
--- a/README.md
+++ b/README.md
@@ -40,8 +40,14 @@ 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 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/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()
diff --git a/src/OctopusTimeService/Logging/DriftCsvLog.cs b/src/OctopusTimeService/Logging/DriftCsvLog.cs
new file mode 100644
index 0000000..1501ca1
--- /dev/null
+++ b/src/OctopusTimeService/Logging/DriftCsvLog.cs
@@ -0,0 +1,51 @@
+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 directory)
+{
+ 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();
+
+ ///
+ /// 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/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..e84408a 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,7 +49,14 @@ 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 DriftCsvLog(
+ sp.GetRequiredService>(),
+ RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName)));
+ builder.Services.AddSingleton(sp => new StartupSequence(
+ sp.GetRequiredService>(),
+ sp.GetRequiredService(),
+ sp.GetRequiredService(),
+ RegistrySettings.ReadMonitorOnly(ServiceDefaults.ServiceName)));
builder.Services.AddHostedService();
builder.Build().Run();
return 0;
@@ -58,7 +66,14 @@ static int RunAsConsole(string[] forwardedArgs)
{
var builder = Host.CreateApplicationBuilder(forwardedArgs);
builder.Services.AddSingleton(_ => new NtpClient());
- builder.Services.AddSingleton();
+ builder.Services.AddSingleton(sp => new DriftCsvLog(
+ sp.GetRequiredService>(),
+ RegistrySettings.ReadLogFolder(ServiceDefaults.ServiceName)));
+ builder.Services.AddSingleton(sp => new StartupSequence(
+ sp.GetRequiredService>(),
+ sp.GetRequiredService(),
+ sp.GetRequiredService(),
+ RegistrySettings.ReadMonitorOnly(ServiceDefaults.ServiceName)));
builder.Services.AddHostedService();
builder.Build().Run();
return 0;
@@ -79,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/src/OctopusTimeService/Startup/StartupSequence.cs b/src/OctopusTimeService/Startup/StartupSequence.cs
index e320623..8cdc731 100644
--- a/src/OctopusTimeService/Startup/StartupSequence.cs
+++ b/src/OctopusTimeService/Startup/StartupSequence.cs
@@ -8,12 +8,20 @@ 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,
+ DriftCsvLog driftCsvLog,
+ 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,70 +30,75 @@ 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 Worker.MeasureAndLogDriftAsync(
+ logger, ntpClient, driftCsvLog, 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);
- // 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);
- }
+ // Windows Time is required for w32tm /resync to work.
+ var w32TimeRunning = await ops.EnsureRunningAsync(WindowsTimeService, 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);
- }
+ // 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);
+ }
- await MeasureAndLogDriftAsync("post-resync", cancellationToken);
+ if (w32TimeRunning)
+ {
+ await RunW32tmResyncAsync(cancellationToken);
+ }
+ else
+ {
+ Log.SkippingW32tm(logger, WindowsTimeService);
+ }
- Log.StartupComplete(logger);
- }
+ // 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);
+ }
- 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);
+ // 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 Worker.MeasureAndLogDriftAsync(logger, ntpClient, driftCsvLog, "post-resync", cancellationToken);
+
+ Log.StartupComplete(logger);
}
catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested)
{
+ // Host is genuinely shutting down — propagate so the host can abort start.
throw;
}
catch (Exception ex)
{
- Log.ClockDriftPhaseFailed(logger, phase, ntpClient.Server, ex);
+ Log.StartupSequenceFailed(logger, StartupBudget, ex);
}
}
diff --git a/src/OctopusTimeService/Worker.cs b/src/OctopusTimeService/Worker.cs
index 2cffa33..8f28dd6 100644
--- a/src/OctopusTimeService/Worker.cs
+++ b/src/OctopusTimeService/Worker.cs
@@ -7,50 +7,19 @@ namespace TimeService;
public class Worker(
ILogger logger,
NtpClient ntpClient,
- StartupSequence startupSequence) : BackgroundService
+ StartupSequence startupSequence,
+ DriftCsvLog driftCsvLog) : 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);
}
@@ -69,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)
{
@@ -86,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
new file mode 100644
index 0000000..7dcde28
--- /dev/null
+++ b/tests/TimeService.Tests/Startup/StartupSequenceTests.cs
@@ -0,0 +1,75 @@
+using Microsoft.Extensions.Logging.Abstractions;
+using TimeService.Logging;
+using TimeService.Ntp;
+using TimeService.Startup;
+
+namespace TimeService.Tests.Startup;
+
+public class StartupSequenceTests
+{
+ // 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}"));
+
+ [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, TempCsvLog(), 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, TempCsvLog(), 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, TempCsvLog(), 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;
+ }
+ }
+}