TB

MoppleIT Tech Blog

Welcome to my personal blog where I share thoughts, ideas, and experiences.

Actionable Verbose Logging in PowerShell: Clean Output, Clear Diagnostics, Faster Debugging

Verbose logging lets you make scripts explain themselves without cluttering the data your tools and pipelines rely on. In PowerShell, you can achieve this by enabling advanced functions, sending diagnostics to the verbose stream, and keeping your actual results clean on stdout. The result: clearer diagnostics, predictable pipelines, and faster debugging.

Why Verbose Logging Matters (and How Streams Work)

PowerShell has multiple output streams. The most important for day-to-day scripting are:

  • Success output (stdout, stream 1): your actual data objects. Keep this clean.
  • Error (stream 2): terminating and non-terminating errors.
  • Warning (stream 3): user-visible warnings that should stand out.
  • Verbose (stream 4): step-level context, progress notes, and timings.
  • Debug (stream 5): deep, developer-focused details for troubleshooting.
  • Information (stream 6): structured messages with opt-in handling.

By placing diagnostics on the verbose stream and keeping return data on stdout, you preserve clean pipelines and gain powerful routing options like redirecting verbose output to a file with 4> or merging it only when needed with 4>&1.

Implementing Verbose Logging in Your Functions

Enable CmdletBinding to support -Verbose

To opt into PowerShells common parameters (including -Verbose), declare your function as an advanced function using [CmdletBinding()]. This adds -Verbose transparently, without your function needing to parse it manually.

function Invoke-Thing {
  [CmdletBinding()]  # Enables -Verbose, -ErrorAction, -WarningAction, etc.
  param(
    [Parameter(Mandatory)]
    [string]$Name
  )

  Write-Verbose "Starting Invoke-Thing for $Name"
  # Do work here
  Write-Verbose "Completed Invoke-Thing for $Name"
}

# Usage
# Invoke-Thing -Name 'example' -Verbose

Use Write-Verbose for step-level context and timings

Verbose messages should explain what youre doing and how long it takes. This preserves intent and makes performance issues obvious.

$sw = [Diagnostics.Stopwatch]::StartNew()
Write-Verbose ("[{0} ms] Initializing..." -f $sw.ElapsedMilliseconds)
# ... some operation
Write-Verbose ("[{0} ms] Completed step A" -f $sw.ElapsedMilliseconds)

Keep data on stdout; keep diagnostics in the verbose stream

Return objects via the pipeline or Write-Output (implicit), and reserve Write-Verbose for context. That way, consumers can pipe results to further commands, serialize to JSON, or export to CSV without being polluted by log text.

Complete example: Get-DirectoryStats

The following function scans a directory, logs step-level context and timings using the verbose stream, and returns a clean object for further processing. It keeps stdout clean while giving you optional, detailed diagnostics.

function Get-DirectoryStats {
  [CmdletBinding()]
  param(
    [Parameter(Mandatory)]
    [string]$Path
  )
  $sw = [Diagnostics.Stopwatch]::StartNew()
  Write-Verbose ("Scanning: {0}" -f $Path)
  $files = Get-ChildItem -Path $Path -File -Recurse -ErrorAction Stop
  Write-Verbose ("Files: {0}" -f $files.Count)
  $size = ($files | Measure-Object -Property Length -Sum).Sum
  $sw.Stop()
  Write-Verbose ("Elapsed: {0} ms" -f $sw.ElapsedMilliseconds)
  [pscustomobject]@{
    Path   = (Resolve-Path -Path $Path).Path
    Files  = $files.Count
    SizeMB = [math]::Round($size/1MB, 2)
  }
}
# Usage
# Get-DirectoryStats -Path './logs' -Verbose

This approach yields a predictable, scriptable object while keeping on-demand diagnostics available via -Verbose.

Advanced Patterns and Tooling

Control verbosity globally or per-call

  • Per-call: Get-DirectoryStats -Path ./logs -Verbose
  • Redirect to a file: Get-DirectoryStats -Path ./logs -Verbose 4> verbose.log
  • Merge verbose into stdout (e.g., for single capture): Get-DirectoryStats -Path ./logs -Verbose 4>&1 (use sparingly)
  • Session-wide default: $PSDefaultParameterValues["*:Verbose"] = $true
  • Preference variable: $VerbosePreference = 'Continue' (affects the current scope)

Choose the right stream for the right message

  • Write-Verbose: step descriptions, durations, counts, resource paths, decision reasons.
  • Write-Warning: non-fatal issues that the user should notice.
  • Write-Error: real failures; consider throw for terminating errors.
  • Write-Debug: low-level developer details; generally off unless -Debug or $DebugPreference is set.
  • Write-Information: structured messages that can be routed with -InformationAction and captured via -InformationVariable.

In most cases, prefer verbose for diagnostics so they are opt-in and easily redirected without touching your data stream.

Add timestamps and correlation details

When debugging automation in CI/CD or distributed systems, add timestamps and correlation IDs to your verbose messages for easier traceability.

$corr = [guid]::NewGuid().ToString()
$sw = [Diagnostics.Stopwatch]::StartNew()

function Write-TSVerbose {
  param([string]$Message)
  Write-Verbose ("[{0:o}] [{1}] {2}" -f (Get-Date), $corr, $Message)
}

Write-TSVerbose "Starting job"
# ... work
Write-TSVerbose ("Completed step A at {0} ms" -f $sw.ElapsedMilliseconds)

Return rich objects; format later

Your function should return data as objects, not formatted strings. When you need human-readable display, rely on formatting (e.g., Format-Table) outside the function, or attach a custom .ps1xml view. Verbose logs can include the human context and decisions without polluting stdout.

Integrate with CI/CD

  • Turn on verbose in PR builds: Add -Verbose in critical steps for faster triage.
  • Capture diagnostics: Redirect verbose to a file artifact: 4> logs/verbose.txt.
  • Keep output parsable: If your step emits JSON for downstream jobs, do not merge verbose into stdout.
  • Redact secrets: Never emit secrets in verbose; treat verbose logs as potentially collectible artifacts.

Handle errors predictably

Pair verbose logs with consistent error handling. Use -ErrorAction Stop for cmdlets that must fail fast, then catch and enrich errors with context via throw or Write-Error. Add a verbose breadcrumb before and after risky operations for pinpointing the failure site.

try {
  Write-Verbose "Downloading input..."
  Invoke-WebRequest -Uri $Uri -OutFile $Path -ErrorAction Stop
  Write-Verbose "Download complete"
}
catch {
  Write-Error -Message "Failed to download from $Uri to $Path: $($_.Exception.Message)" -ErrorAction Stop
}

Test your verbose behavior

When writing Pester tests, you can enable verbose to validate that key steps log as expected without altering the returned object shape.

# Example snippet (Pester v5 style)
It "emits useful verbose messages" {
  $output = & { Get-DirectoryStats -Path . -Verbose 4>&1 }
  $output -join "`n" | Should -Match "Scanning:"
  $output -join "`n" | Should -Match "Elapsed:" 
}

Common Pitfalls and a Quick Checklist

  • Dont write informational text to stdout. Use Write-Verbose or Write-Information instead.
  • Dont concatenate strings for data. Return objects; serialize downstream if needed.
  • Do include timings and counts. They make performance issues obvious.
  • Do use [CmdletBinding()]. Get -Verbose and other common parameters for free.
  • Do keep messages actionable. Prefer messages like Searching 12 files for pattern 'ERROR over Starting.
  • Do route logs smartly in automation. Use 4> to capture verbose to dedicated files.
  • Do avoid secrets in logs. Treat verbose as collectible diagnostics.

Putting It All Together

With advanced functions, Write-Verbose, and a little timing and context, you can keep data on stdout and diagnostics in the verbose stream. Your scripts will be easier to reason about, pipelines will be more reliable, and debugging will be faster.

Sharpen your logging discipline in PowerShell and keep learning advanced patterns. Explore the PowerShell Advanced CookBook  https://www.amazon.com/PowerShell-Advanced-Cookbook-scripting-advanced-ebook/dp/B0D5CPP2CQ/

← All Posts Home →