A log write killed the job it was logging, and the exit code still said 0

The symptom

A scheduled-style job stopped partway through its work and reported success. It did roughly half of what it was supposed to do, exited, and the exit code said everything was fine. Nothing downstream noticed. The only reason it surfaced at all was that the output was short.

The cause

At the top of the script, as recommended by essentially every PowerShell article ever written:

$ErrorActionPreference = "Stop"

The advice behind that line is sound. PowerShell’s default is to print a red error and keep going, which is how you get a script that reports success after failing every meaningful step. Stop fixes that.

What the advice usually leaves out is the scope. Under Stop, every non-terminating error, anywhere, becomes terminating, including inside a statement whose failure could not matter less.

Here, that statement was the logger:

Add-Content -Path $LogFile -Value "[$(Get-Date -f o)] processed $name"

Something else had the log file open. In my case a tail -f from an earlier debugging session. An editor with the file in a tab does it. So does a search indexer, and so does antivirus, mid-scan.

Windows refused the write:

The process cannot access the file 'C:\...\run.log'
because it is being used by another process.

Under Stop, that is terminating. The runspace unwound from a line that writes a log message, in the middle of the work the job exists to do.

Why the exit code lied

The termination unwound cleanly out of the script body. Nothing rethrew, nothing set $LASTEXITCODE, nothing called exit 1. From the outside, the process ended without a failure signal, which is exactly what a successful run looks like.

A crash that reports failure gets fixed. A crash that reports success gets scheduled daily and rots for months.

The fix

The logger is not essential work, so it should not be able to end the run. Bound the retry, then give up quietly:

function Write-Log {
  param([string]$Message)
  $line = "[$(Get-Date -Format o)] $Message"
  for ($i = 0; $i -lt 5; $i++) {
    try {
      Add-Content -Path $LogFile -Value $line -ErrorAction Stop
      return
    } catch {
      Start-Sleep -Milliseconds 100
    }
  }
  # Give up. A lost log line is never worth a lost run.
}

Five attempts over half a second clears a transient lock. A persistent one costs you a line of log and nothing else.

The inner call needs its own -ErrorAction Stop for the try to be reliable across the different error shapes: catch only fires for terminating errors, so under a different global preference the same code silently catches nothing.

Proving it

An A/B against a file deliberately opened with FileShare.None:

$h = [System.IO.File]::Open($LogFile, 'Open', 'Write', 'None')

• Old version: exits 1, never reaches the statement after the log call.
• New version: exits 0, reaches the next statement, log line missing.

The work completed and the only casualty was a line of logging.

The same bug, three times in two days

1. Add-Content to a locked log file, promoted to terminating.
2. 2>&1 on a native executable, promoting a harmless stderr warning to terminating.
3. An npm-generated .ps1 shim doing the same thing one level down, where the redirect could not reach it to be fixed.

Under Stop, any side effect that is not the point of the script can abort the part that is: logging, telemetry, progress output, cleanup, a cosmetic warning from a tool you shelled out to.

Keep Stop as the default. Then go through the script and give every side effect that is not its purpose permission to fail.

The smaller trap

My first instinct was to blame the writer: buffering, encoding, a handle the script itself had left open.

The tail process had outlived the terminal that started it and was still holding the file. The script was innocent, and I spent real time reading it anyway.

When a file is locked, identify the holder before reading the writer:

# Sysinternals
handle64.exe -a C:\path\to\run.log