Refactor and Log NTP drift measurements to a local CSV file

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 "=========================================================="

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
 

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: <input>.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()