Logging and Error Handling Best Practices for Automating Windows Update Installs (MSU) with wusa.exe (And For Logging Any Called Process)

Logging and Error Handling Best Practices for Automating Windows Update Installs (MSU) with wusa.exe (And For Logging Any Called Process)

Darwin Sanoy's photo
Darwin Sanoy
·

16 min read

Table of contents

Automation of Windows Updates is generally done by calling wusa.exe against a .MSU file. When wusa.exe experiences a failure the messages are typically obscure and hard to diagnose. The underlying error messages, however, are frequently easy to understand and resolve.

The secret is to have wusa.exe do verbose logging in it’s standard exported windows event format and then use the PowerShell event message CMDLets to query that log - automatically, everytime you have an error.

Although focused on applying updates with wusa.exe, this article contains most of my logging best practices for automation coding when calling automated sub-processes.

Toolsmithing Perspective

Everything in this post is helpful even if you are the only one who will ever examine the logs of the automation you build. However, you will hear a persistent theme in this post of how it helps “others”. Since I can remember, I have built utility tools that are leveraged by others or supported by a separate support team. In these cases, investments like the ones discussed in this article, have a very high “Team ROI” as well as help to guard the automation developer’s time against unnecessary escalation incidents.

Windows Updates Error Trapping is Not Straight Forward

There are several attributes of wusa.exe execution that make attention to logging all the more valuable:

  1. wusa.exe critical errors do not generate terminating errors in PowerShell
  2. For the same root cause, wusa.exe exit codes are different from logged error codes
  3. For the same root cause, logged error codes are in decimal while the ones that might display interactively when running Windows Update GUI are in hex (but at least the same number when converted).

Examples Of Challenging Messages

0x80240017 / 2149842967 / -2145124329 (Wusa.exe exit code) Log: “Windows update could not be installed because of error 2149842967” Interactive “The update is not applicable to your computer” => Painful - first the logged message is not very helpful. Second, you can get this message if you simply do not have the correct prerequisites - if you can’t find the common causes of not meeting prerequisites for the specific update you are applying, then you have to dissect the windows update to read it’s prerequisites section. See “Dissecting Windows Update Packages” below.

0x80070422 / 2147943458 / 1058 (Wusa.exe exit code) - Windows Update Cannot Check For Updates => Usually means the Windows Update Service is stopped - be careful that it is not stopped for a valid reason (e.g. other long running deployment automation is currently underway.)

0x80070002 / 2147942402 / 2 (Wusa.exe exit code) - The system cannot find the file specified. => The .MSU file is not available at the location passed to wusa.exe. Also occurs in other circumstances.

Additional Common Errors

Logging - The Foundation Of Good Exception Handling and Quicker Resolution of Escalations

When coding automation I a huge advocate of verbose logging for everything my automation invokes (as well as having the automation do it’s own logging) - and to a task specific location when logs can be directed to a custom location.

This is for multiple strategic reasons:

  1. Verbose sub-process logging is super useful in production environemnts, however, it is jaw dropping how often verbose logging helps me while developing automation code.
  2. Once the solution is in production, I get less calls because those who run into problems with my work can frequently solve the problem on their own when the right logging data is in front of them. That makes me, my team and other teams faster and more productive.
  3. When I get calls, I can ask for the logs that I already know exist. That makes me, my team and other teams faster and more productive :)
  4. In production (or test or dev) there is no need to attempt to reproduce the problem AFTER logging has been enabled - so if you have a rare transient problem, you get maximum information on every occurence. That makes me, my team and other teams faster and more productive :)
  5. I have come across many, many interesting edge cases simply by having verbose logging on for development. That allows me to bake in handling of specific issues when merited or to at least document them and their resolution.

Always Run msu.exe With Verbose Logging

While wusa.exe logging is very useful, there a couple nuances about it that are challenging to navigate - especially if you are starting to use the parameter for the first time.

  1. The log output format is “Exported Event Log” - in other words the same type of file as if you exported windows event logs using the event log viewer. Great confusion results if you give it a .log extension because you and others will try to open it in a text editor. A bunch of the productivity benefits I seek are lost if individuals besides myself can’t view the contents without contacting me. To get around this I simply name the log file with the exported event file extension. This causes it to open in the event log viewer if double-clicked and it also cues other people that the file is not a simple text file. I also like to use a file name that communicates a lot of meta data.

    The below example tells exactly what update and exactly when the install happened. If people might send me these in email, I’d probably also embed the computer name, because having the wrong log sent to me is a frequent experience that makes us all less productive:

    $logfilename = "$env:PUBLIC\Logs\ApplyPSH5\PowerShell-Install-W2K12-KB3191565-x64-$(Get-date -format 'yyyyMMddhhmmss')-Log.evtx"

  1. The command line parameter is fussy. Unlike the other parameters for wusa.exe it:

    1. MUST have a colon after it,
    2. must not have whitespace after the colon,
    3. must be enclosed in quotes if there are spaces in the file name
    4. If you break any of these rules, windows update generally runs without errors, it just does not generate a log.

    The above list is an aggregate across multiple versions of Windows - so not all of these sensitivities might be present in a given version of Windows.

    Here is an example of what I use to avoid these problems:

    #Running Directly in CMD or PS1:
wusa.exe W2K12-KB3191565-x64.msu /quiet /norestart /log:"$logfilename"

#Commandline stored in a variable (PS1):
$wusaswitches = "/quiet /norestart /log:`"$logfilename`""
wusa.exe W2K12-KB3191565-x64.msu $wusaswitches

Surface The Fact That You Are Doing Detailed Logging

In addition to being a big advocate of logging of called processes, I am a big advocate of verbose logging for my own automation. It is simply mind boggling how many times I find this truncates the root cause determination phase. I will receive a log and immediately notice things like:

  1. The wrong version of the automation code has been used.
  2. Incorrect parameters were used to call the automation code.
  3. Incorrect parameters were used to call the sub-process.
  4. The code cannot find something which should be a standard part of every environment it was designed to run in.
  5. Exactly what generated “Access Denied”.

This makes me more productive :)

However, another big reason I want to log the fact that I am doing detailed logging on a sub-process is for other professionals to take notice, examine that log and frequently solve the problem on their own - which makes both of us more productive.

Best Practices for Logging The Log Location (and the Calling Command Line)

  1. When I do verbose logging of something like wusa.exe I want to surface that fact in the automation log so that others using the work will notice that there is more detailed logging on a specific call available. By ensuring that verbose log location for subprocesses are logged in the top level log, I will help others to follow the chain of available forensic data in hopes they can solve the problem.
  2. I log the sub-process log location all the time, not just if there is an error. This is because there are situations where an error is thrown somewhere else in the script, but these verbose logs reveal the problem or lead to insights that reveal the problem.
  3. I also ensure that I Log the exact command line used to call the subprocess. When doing this it is helpful to have stored the command line to run in a variable and use the variable for the actual call as well as the log message. If the same variable is not used, the log can end up being misleading when you update the actual command but forget to find and update the logging lines to reflect that update.
  4. In general it is good form to also emit your log messages to the console because if the code runs under any kind of orchestration - that orchestration captures all console output. So for example, if someone is running my code under AWS Cloud Formation - anything emitted in the console is caught up into the general Cloud Formation log - which eliminates one more step in the chain of logs to be followed.
  5. It is best to do this logging before calling the sub-process - then if your call causes a catastrophic failure - the log will contain information on the last call made by the automation code (which likely caused the failure if it is reproducible).

Best Practices for Logging Folder Names and Log File Names

Whenever possible I log to system folder (non-user profile) dedicated to the automation task that is running and use a date time serialized string in the name, among other things this helps with:

  1. with troubleshooting discovery of the logs related to the automation (relevant logs in the same folder)
  2. avoids challenges finding logs when run under different user contexts (run under SYSTEM context or a special user profile for a logged on service)
  3. avoids getting removed in automated temp clean up.
  4. can pick a location that every process can write to and every process and logged on technician can read from.
  5. remote access to a standardized “logroot” is easy to setup because it is in a known location and can be shared as read only.
  6. Serialization of Folder and/or File: Ensuring that multiple subsequent runs of the same automation do NOT overwrite each other - overwritten logs complicate troubleshooting as you never know if you are looking at the exact invocation that caused the problem.
  7. Serialization of Folder and/or File: Better date time correlation when searching for logs.
  8. Serialization of Folder: Allows cumulative logs for logging mechanisms that overwrite a previously existing log by default.
  9. Serialization of File: Communicates more meta data when the log is shared with others out of the context of the folder (e.g. email, copy to network).

A distinct downside to a custom folder rather than a temp folder is that that you usually have to check for the folder and create it before you start logging to it. A downside to serializing log folder names in and file names in a custom folder that logs can accumulate indefinitely.

$env:public is an environment variable that points to the public profile - which all users have write access to. Although this folder is under the user profile root on many systems, it is not a user folder - there is no “public” user. It is used for anything that all users should see and have access to. A subfolder of the $env:public folder can be a great standardized log location, for example $env:public\logs

Example Code

As per the [Testable Reference Pattern Manifesto] (https://MissionImpossibleCode.io/post/back-to-basics-testable-reference-pattern-manifesto-with-testable-sample-code/) all of the below code has been tested. It is also available in a repository to help avoid problems when copying and pasting from web pages: [MissionImpossibleCode] (https://gitlab.com/missionimpossiblecode/MissionImpossibleCode)

Fully Serialized Example of Log Naming (logs never overwritten - retains historical runs)

$LogRoot = "$env:PUBLIC\Logs" ## Non-serialized, globally consistent "logroot" on every machine.
$SerializedStringForThisRun = $(Get-date -format 'yyyyMMddhhmmss')  ## date based serialized string - allows all serialized items to have the same serialization.
$LogFolder = "$LogRoot\InstallPSH5-$SerializedStringForThisRun"  ## date based serialized folder
New-Item -ItemType Directory $LogFolder -Force -ErrorAction SilentlyContinue | Out-Null ## This will create the logroot and specific log folder in one shot
$logfilename = "$logfolder\PowerShell-Install-W2K12-KB3191565-x64-$SerializedStringForThisRun-Log.evtx"  ##date based serialized log filename

$wusaswitches = "/quiet /norestart /log:`"$logfilename`""

Write-Host "Running Windows Update with the following command which generate a verbose log at: $logfilename"  ##Logging the fact that a verbose log is available for the sub-process we are about to call

Write-Host "Initiating command: wusa.exe W2K12-KB3191565-x64.msu $wusaswitches"

$ResultObject = start-process "wusa.exe" -ArgumentList "$pwd\W2K12-KB3191565-x64.msu $wusaswitches" -Wait -PassThru

Non-serialized Example of Log Naming, reset logs to clean everytime (does not retain history)

$LogRoot = "$env:PUBLIC\Logs"
$LogFolder = "$LogRoot\InstallPSH5"
If (Test-Path $LogFolder) {Remove-Item $LogFolder -Recurse -Force -ErrorAction SilentlyContinue}
New-Item -ItemType Directory $LogFolder -Force -ErrorAction SilentlyContinue | Out-Null
$logfilename = "$logfolder\PowerShell-Install-W2K12-KB3191565-x64-Log.evtx"

$wusaswitches = "/quiet /norestart /log:`"$logfilename`""

Write-Host "Running Windows Update with the following command which generate a verbose log at: $logfilename"  ##Logging the fact that a verbose log is available for the sub-process we are about to call
Write-Host "Initiating command: wusa.exe W2K12-KB3191565-x64.msu $wusaswitches"

$ResultObject = start-process "wusa.exe" -ArgumentList "$pwd\W2K12-KB3191565-x64.msu $wusaswitches" -Wait -PassThru

Surface Error Messages (and Warnings If You Wish)

The below snippets show various ways of retrieving and potentially acting upon the messages generated by wusa.exe.

You can creatively mix some of these together - for instance, always re-logging found warnings and errors - but only taking action if ther are actually errors.

Always Show All Messages in Log

This code always re-logs the detailed warnings and errors from the windows uupdate log - this is a good general practice for debugging related errors as well as helping with messages that are classfied as “Warnings” by windows update, which are essentially errors for your deployment scenario.

$WarningMsgs = 3
$ErrorMsgs = 2

$LogRoot = "$env:PUBLIC\Logs"
$SerializedStringForThisRun = $(Get-date -format 'yyyyMMddhhmmss')
$LogFolder = "$LogRoot\InstallPSH5-$SerializedStringForThisRun"
New-Item -ItemType Directory $LogFolder -Force -ErrorAction SilentlyContinue
$logfilename = "$logfolder\PowerShell-Install-W2K12-KB3191565-x64-$SerializedStringForThisRun-Log.evtx"
$wusaswitches = "/quiet /norestart /log:`"$logfilename`""

Write-Host "Running Windows Update with the following command which generate a verbose log at: $logfilename"  ##Logging the fact that a verbose log is available for the sub-process we are about to call
Write-Host "Initiating command: wusa.exe W2K12-KB3191565-x64.msu $wusaswitches"

$ResultObject = start-process "wusa.exe" -ArgumentList "$pwd\W2K12-KB3191565-x64.msu $wusaswitches" -Wait -PassThru

$LogMessagesOfConcern = @(Get-WinEvent -Path "$logfilename" -oldest | where {($_.level -ge $WarningMsgs) -AND ($_.level -le $ErrorMsgs)})
If ($LogMessagesOfConcern.count -gt 0)
{
    Write-Host "Found the following concerning messages in the MSU log `"$logfilename`""
    $LogMessagesOfConcern | Format-List ID, Message | out-string | write-host
}

Using the Existence of an Error in the Verbose Log

The code relies on the windows update to accurately report errors and then consider that there is a problem only if that is true. A downside to this code is that it will not capture malformed wusa.exe command lines or a non-existent .msu.

$WarningMsgs = 3
$ErrorMsgs = 2

$LogRoot = "$env:PUBLIC\Logs"
$SerializedStringForThisRun = $(Get-date -format 'yyyyMMddhhmmss')
$LogFolder = "$LogRoot\InstallPSH5-$SerializedStringForThisRun"
New-Item -ItemType Directory $LogFolder -Force -ErrorAction SilentlyContinue | Out-Null
$logfilename = "$logfolder\PowerShell-Install-W2K12-KB3191565-x64-$SerializedStringForThisRun-Log.evtx"
$wusaswitches = "/quiet /norestart /log:`"$logfilename`""

Write-Host "Running Windows Update with the following command which generate a verbose log at: $logfilename"  ##Logging the fact that a verbose log is available for the sub-process we are about to call
Write-Host "Initiating command: wusa.exe W2K12-KB3191565-x64.msu $wusaswitches"

$ResultObject = start-process "wusa.exe" -ArgumentList "$pwd\W2K12-KB3191565-x64.msu $wusaswitches" -Wait -PassThru

$LogMessagesOfConcern = @(Get-WinEvent -Path "$logfilename" -oldest | where {($_.level -ge $ErrorMsgs) -AND ($_.level -le $WarningMsgs)})
$LogErrorsOnly = @(Get-WinEvent -Path "$logfilename" -oldest | where {$_.level -eq $ErrorMsgs})

If ($LogErrorsOnly.count -gt 0)
{
  Write-Host "Found the following error(s) (and possibly some warnings) in the MSU log `"$logfilename`""
  Throw ($LogMessagesOfConcern | Format-List ID, Message | out-string)
}

Adding Try / Catch - Just Display Errors and Warnings

Try/Catch should be used to capture exceptions that happen because wusa.exe cannot be found or started at all.

$ErrorActionPreference = 'Stop'
$LogRoot = "$env:PUBLIC\Logs"
$SerializedStringForThisRun = $(Get-date -format 'yyyyMMddhhmmss')
$LogFolder = "$LogRoot\Install PSH5-$SerializedStringForThisRun"
New-Item -ItemType Directory $LogFolder -Force -ErrorAction SilentlyContinue
$logfilename = "$logfolder\PowerShell-Install-W2K12-KB3191565-x64-$SerializedStringForThisRun-Log.evtx"

$WarningMsgs = 3
$ErrorMsgs = 2

$wusaswitches = "/quiet /norestart /log:`"$logfilename`""

Write-Host "Running Windows Update with the following command which generate a verbose log at: $logfilename"  ##Logging the fact that a verbose log is available for the sub-process we are about to call
Write-Host "Initiating command: wusa.exe W2K12-KB3191565-x64.msu $wusaswitches"

Try {
  $ResultObject = start-process "wusa.exe" -ArgumentList "$pwd\W2K12-KB3191565-x64.msu $wusaswitches" -Wait -Passthru
  Write-Output "Return code is: $($ResultObject.ExitCode)"
  If (Test-Path "$logfilename")
  {
    $LogMessagesOfConcern = @(Get-WinEvent -Path "$logfilename" -oldest | where {($_.level -ge $ErrorMsgs) -AND ($_.level -le $WarningMsgs)})
    If ($LogMessagesOfConcern.count -gt 0)
    {
      Write-Host "Found the following error(s) and warnings in the MSU log `"$logfilename`""
      $LogMessagesOfConcern | Format-List ID, Message | out-string | write-host
    }
  }
}
catch {
  Throw $_.Exception
}

Acting Upon Specific Messages

The following code shows how to take action depending on the CONTENT of the error in the verbose windows update / wusa.exe log. The action in this case is simply to give a more meaningful error - but if the error is recoverable, you can use the same code block to take action.

$ErrorActionPreference = 'Stop'
$LogRoot = "$env:PUBLIC\Logs"
$SerializedStringForThisRun = $(Get-date -format 'yyyyMMddhhmmss')
$LogFolder = "$LogRoot\Install PSH5-$SerializedStringForThisRun"
New-Item -ItemType Directory $LogFolder -Force -ErrorAction SilentlyContinue
$logfilename = "$logfolder\PowerShell-Install-W2K12-KB3191565-x64-$SerializedStringForThisRun-Log.evtx"

$WarningMsgs = 3
$ErrorMsgs = 2

$wusaswitches = "/quiet /norestart /log:`"$logfilename`""

Write-Host "Running Windows Update with the following command which generate a verbose log at: $logfilename"  ##Logging the fact that a verbose log is available for the sub-process we are about to call
Write-Host "Initiating command: wusa.exe W2K12-KB3191565-x64.msu $wusaswitches"

Try {
  $ResultObject = start-process "wusa.exe" -ArgumentList "$pwd\W2K12-KB3191565-x64.msu $wusaswitches" -Wait -Passthru
  Write-Output "Return code is: $($ResultObject.ExitCode)"
  If (Test-Path "$logfilename")
  {
    $LogMessagesOfConcern = @(Get-WinEvent -Path "$logfilename" -oldest | where {($_.level -ge $ErrorMsgs) -AND ($_.level -le $WarningMsgs)})
    If ($LogMessagesOfConcern.count -gt 0)
    {
      Write-Host "Found the following error(s) and warnings in the MSU log `"$logfilename`""
      $LogMessagesOfConcern | Format-List ID, Message | out-string | write-host
      # Check a given substring against all messages to find and handle a known exception
      If ([bool]($LogMessagesOfConcern | where {$_.message -ilike "*error 2147943458*"}))
        {
          Write-warning "Service could not be started, attempting to fix this situation."
          If ((get-service wuauserv).Starttype -ieq 'Disabled')
          {
            Write-warning "The Windows Update Server was disabled, renenabling..."
            Set-Service wuauserv -StartupType 'Manual'
            #Place code to retry install here.
          }
        }
        If ([bool]($LogMessagesOfConcern | where {$_.message -ilike "*error 2149842967*"}))
        {
          Write-warning "The update is not applicable to this computer - possibilities reasons include: a prerequisite is missing or the update is not for this operating system."
        }
    }
  }
}
catch {
  Throw $_.Exception
}

Dissecting Windows Update Packages

This is most frequently done to attempt to understand the prerequisites or OS targeting of a given update in order to understand why it gets the error 0x80240017 / 2149842967 / -2145124329.

New-Item $env:PUBLIC\Logs\ApplyPSH5\updatefiles -ItemType Directory
expand W2K12-KB3191565-x64.msu -F:* $env:PUBLIC\Logs\ApplyPSH5\updatefiles
Get-Content $env:PUBLIC\Logs\ApplyPSH5\updatefiles\*.txt

This Code In Production

This code is used in the PowerShell for Windows Chocolatey package. It is used to surface better details about why the ugprade failed.

This package has been installed over 1.1 million times - so exposing the underlying errors for others to resolve on their own guards my time and keeps me a lot more productive ;)

Chocolate Package for PowerShell for Windows (see the ‘catch’ statement near the bottom of this script): https://github.com/DarwinJS/ChocoPackages/blob/master/PowerShell/v5.1/tools/ChocolateyInstall.ps1

Updated Code In This Article

The below code’s primary home is on the following repository - where it might be improved upon compared to the below. It is also safer to use the code from the repo rather than copy and paste from this post: https://gitlab.com/missionimpossiblecode/MissionImpossibleCode

Additional Common Errors

0x80070003 / 2147942403 - The system cannot find the file specified. => The .MSU file is not available at the location passed to wusa.exe. Also occurs in other circumstances. Windows Update Troubleshooter

0x800705B4 / 2147943860 => Timeout Period Expired. Troubleshooting Guide, Windows Update Troubleshooter

0x8024200B / 2149851147 => A hardware update (driver) was not able to be installed. Windows Update Troubleshooter

0x80070020 / 2147942432 = The process cannot access the file because it is being used by another process => Windows update is unable to update specific files due to locking or antivirus. Troubleshooting Guide, Windows Update Troubleshooter

0x80073712 / 2147956498 - The Windows Update component manifest is corrupted. Troubleshooting Guide, Windows Update Troubleshooter

0x80004005 / 2147500037 - Corrupt or missing files in the OS. Reseting Windows Update Components, Windows Update Troubleshooter

0x8024402F / 2149859375 - windows update is having trouble contacting Microsoft servers - could be network settings.

0x80070643 / 2147944003 - problems installing .NET framework update. Troubleshooting Guide, Windows Update Troubleshooter

Comprehensive List of Windows Update Errors

Comprehensive Windows Update Error List

Additional Links

PowershellautomationcodeDeep Divetools