Warn instead of logging "tweak completed" after a tweak step error (#5090)

* Warn instead of logging tweak completed after a step error

Invoke-WinUtilTweaks wrote "Apply tweak completed" unconditionally, even
when Invoke-WinUtilScript or another helper had just logged an ERROR for
that tweak. The job layer already counts those errors, so snapshot the
count after the header line and compare at the end: log a WARN line with
the error count when it grew, otherwise the existing completed line.

Two Pester cases run the real logger and script runner against a temp
log file to pin both outcomes.

* Count tweak step errors from the shared log list

The job error counter only increments inside a Start-WinUtilJob worker.
Toggle switches call Invoke-WinUtilTweaks directly on the UI thread, so
a failing toggle still logged "tweak completed" after its ERROR line.

Every ERROR line is added to $sync.LoggedErrors from any runspace, and
Invoke-WinUtilAutoRun already reads it as a before/after delta, so the
tweak runner now does the same. The completion-status tests run without
the worker flag and seed an earlier unrelated error, and a new case
covers a failing UndoScript.

* Count tweak errors on the logging runspace, not the shared list

Diffing $sync.LoggedErrors charged a toggle with errors a concurrent
job logged from its own runspace. Global scope is per runspace, so the
logger now bumps the runspace counter for every headline error and the
tweak status diffs that. Job workers still reset the counter at start
and end, so job results are unchanged.
This commit is contained in:
Malin Fossum
2026-09-29 10:58:32 -05:00
committed by GitHub
parent 6f1266eb86
commit d0d39d6478
4 changed files with 97 additions and 5 deletions
+9 -1
View File
@@ -23,6 +23,9 @@ function Invoke-WinUtilTweaks {
$action = if ($undo) { "Undo" } else { "Apply" }
Write-WinUtilLog -Component "Tweaks" -Message "$action tweak: $CheckBox"
# The counter lives in this runspace, so an error a concurrent job logs from its own
# runspace cannot be charged to a toggle flipped on the UI thread
$errorsBefore = [int]$global:WinUtilJobErrorCount
if ($undo) {
$Values = @{
@@ -81,5 +84,10 @@ function Invoke-WinUtilTweaks {
Remove-WinUtilProvisionedAPPX -PackageList $sync.configs.tweaks.$CheckBox.appx
}
}
Write-WinUtilLog -Component "Tweaks" -Message "$action tweak completed: $CheckBox"
$errorCount = [int]$global:WinUtilJobErrorCount - $errorsBefore
if ($errorCount -gt 0) {
Write-WinUtilLog -Level "WARN" -Component "Tweaks" -Message "$action tweak finished with $errorCount error(s): $CheckBox"
} else {
Write-WinUtilLog -Component "Tweaks" -Message "$action tweak completed: $CheckBox"
}
}
+4 -1
View File
@@ -42,7 +42,10 @@ function Write-WinUtilLog {
$null = $sync.LoggedErrors.Add("[$Component] $Message")
}
if ($Level -eq "ERROR" -and -not $Detail -and $global:WinUtilIsJobWorker) {
# Global scope is per runspace, so this counter only ever sees errors logged by the
# runspace that owns it: a job worker reads its own, and a tweak on the UI thread reads the
# UI thread's
if ($Level -eq "ERROR" -and -not $Detail) {
$global:WinUtilJobErrorCount++
}
+3 -3
View File
@@ -131,7 +131,7 @@ Describe "Write-WinUtilLog" {
Should -Invoke -CommandName Write-Warning -Times 0 -Exactly
}
It "counts only headline errors written by the active job worker" {
It "counts headline errors in the logging runspace whether or not it is a job worker" {
$script:sync = [hashtable]::Synchronized(@{
winutildir = $script:testRoot
LoggedErrors = [System.Collections.ArrayList]::Synchronized([System.Collections.ArrayList]::new())
@@ -142,9 +142,9 @@ Describe "Write-WinUtilLog" {
Write-WinUtilLog -Level "ERROR" -Component "Test" -Message "job error"
Write-WinUtilLog -Level "ERROR" -Detail -Component "Test" -Message "error detail"
$global:WinUtilIsJobWorker = $false
Write-WinUtilLog -Level "ERROR" -Component "UI" -Message "unrelated error"
Write-WinUtilLog -Level "ERROR" -Component "UI" -Message "toggle error"
$global:WinUtilJobErrorCount | Should -Be 1
$global:WinUtilJobErrorCount | Should -Be 2
$script:sync.LoggedErrors.Count | Should -Be 2
}
+81
View File
@@ -179,6 +179,87 @@ Describe "Invoke-WinUtilTweaks" {
}
}
Describe "Invoke-WinUtilTweaks completion status" {
BeforeAll {
. (Join-Path $script:repoRoot "functions\private\Write-WinUtilLog.ps1")
. (Join-Path $script:repoRoot "functions\private\Invoke-WinUtilScript.ps1")
}
BeforeEach {
$script:testRoot = Join-Path ([System.IO.Path]::GetTempPath()) "winutil-tweaks-$([guid]::NewGuid())"
$script:logPath = Join-Path $script:testRoot "logs\winutil_2026-09-15_12-00-00.log"
$script:sync = [Hashtable]::Synchronized(@{
logPath = $script:logPath
configs = @{
tweaks = [pscustomobject]@{
WPFTweaksFailing = [pscustomobject]@{
InvokeScript = @("throw 'simulated icacls failure'")
UndoScript = @("throw 'simulated icacls undo failure'")
}
WPFTweaksClean = [pscustomobject]@{
InvokeScript = @("Write-Output 'apply tweak'")
}
# A job worker logging an error from its own runspace lands in the shared
# list without passing through this runspace's logger
WPFTweaksDuringJob = [pscustomobject]@{
InvokeScript = @("`$null = `$sync.LoggedErrors.Add('[Job] error from a concurrent job'); Write-Output 'apply tweak'")
}
}
}
# Seeded with an earlier error: only errors logged during this tweak may count
LoggedErrors = [System.Collections.ArrayList]::Synchronized([System.Collections.ArrayList]::new(@("[UI] earlier unrelated failure")))
})
# Toggle switches run the tweak on the UI thread, outside any job worker. The runspace
# counter starts non-zero: only errors logged during this tweak may count
Remove-Variable -Name WinUtilIsJobWorker -Scope Global -ErrorAction SilentlyContinue
$global:WinUtilJobErrorCount = 3
Mock Write-Host { }
Mock Write-Warning { }
}
AfterEach {
Remove-Variable -Name sync -Scope Script -ErrorAction SilentlyContinue
Remove-Variable -Name WinUtilJobErrorCount -Scope Global -ErrorAction SilentlyContinue
Remove-Item -Path $script:testRoot -Recurse -Force -ErrorAction SilentlyContinue
}
It "warns instead of reporting completion when a tweak step logged an error" {
Invoke-WinUtilTweaks -CheckBox "WPFTweaksFailing"
$log = Get-Content -Path $script:logPath -Raw
$log | Should -Match "\[ERROR\] \[Script\] Runtime exception while running script for WPFTweaksFailing"
$log | Should -Match "\[WARN\] \[Tweaks\] Apply tweak finished with 1 error\(s\): WPFTweaksFailing"
$log | Should -Not -Match "tweak completed: WPFTweaksFailing"
}
It "warns when an undo step logged an error" {
Invoke-WinUtilTweaks -CheckBox "WPFTweaksFailing" -undo $true
$log = Get-Content -Path $script:logPath -Raw
$log | Should -Match "\[ERROR\] \[Script\] Runtime exception while running script for WPFTweaksFailing"
$log | Should -Match "\[WARN\] \[Tweaks\] Undo tweak finished with 1 error\(s\): WPFTweaksFailing"
$log | Should -Not -Match "tweak completed: WPFTweaksFailing"
}
It "reports completion when every tweak step succeeded" {
Invoke-WinUtilTweaks -CheckBox "WPFTweaksClean"
$log = Get-Content -Path $script:logPath -Raw
$log | Should -Match "\[INFO\] \[Tweaks\] Apply tweak completed: WPFTweaksClean"
$log | Should -Not -Match "\[WARN\]"
$log | Should -Not -Match "\[ERROR\]"
}
It "ignores an error another runspace logged while the tweak ran" {
Invoke-WinUtilTweaks -CheckBox "WPFTweaksDuringJob"
$log = Get-Content -Path $script:logPath -Raw
$log | Should -Match "\[INFO\] \[Tweaks\] Apply tweak completed: WPFTweaksDuringJob"
$log | Should -Not -Match "tweak finished with"
}
}
Describe "Invoke-WPFtweaksbutton" {
BeforeEach {
$script:sync = [Hashtable]::Synchronized(@{