diff --git a/host-setup/windows/install-tools.ps1 b/host-setup/windows/install-tools.ps1 index b9dfcbeb7..2ba310256 100644 --- a/host-setup/windows/install-tools.ps1 +++ b/host-setup/windows/install-tools.ps1 @@ -460,8 +460,9 @@ function Invoke-WingetRemove { # Where App Installer keeps every installer log winget asks a package for, named .-.log. $WINGET_LOG_DIRECTORY = Join-Path $env:LOCALAPPDATA 'Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\DiagOutputDir' -# The entries of the installer log one failed winget call wrote that say why it failed, or none where no such log or entry exists. -# All winget reports is that the installer exited non-zero, with a code the installer chose. +# The entries of the installer log one failed winget call wrote, and of winget's own log for that call, that say why it failed. +# Each is none where no such log or entry exists. +# For a package with an installer, all winget reports is that the installer exited non-zero, with a code the installer chose. # So the reason lives in that log and nowhere a person reads by default. # A silent Inno Setup installer, Git for Windows among them, answers its own blocking dialog and logs the dialog's text. # That text is the whole reason. @@ -471,32 +472,54 @@ $WINGET_LOG_DIRECTORY = Join-Path $env:LOCALAPPDATA 'Packages\Microsoft.DesktopA # Whether files were in use is read from every entry before that cap. # An in-use entry is always among those shown, the first one put back where none survived the cap. # So a run of later error and abort lines cannot push the actual reason out of the report. +# A portable or zip package has no installer, so winget's own WinGet-.log for the call holds its reason instead. +# That log is the latest one started since the attempt that names the package id, and only its error lines are kept. +# Only there does an access denial count as files in use, and only one naming a file, as winget reports failing to replace one. +# In an installer log a denial can be a permission failure, which no running process causes. function Get-InstallerFailureReason { param([Parameter(Mandatory)][string]$Id, [Parameter(Mandatory)][datetime]$Since, [string]$Directory = $script:WINGET_LOG_DIRECTORY) - $result = @{ Log = $null; Entries = @(); InUse = $false } + $result = @{ Log = $null; Entries = @(); WingetLog = $null; WingetEntries = @(); InUse = $false } if (-not (Test-Path -LiteralPath $Directory -PathType Container)) { return $result } $log = Get-ChildItem -LiteralPath $Directory -Filter "$Id.*.log" -File -ErrorAction SilentlyContinue | Where-Object { $_.LastWriteTime -ge $Since } | Sort-Object LastWriteTime | Select-Object -Last 1 - if (-not $log) { return $result } - $result.Log = $log.FullName - $entries = [System.Collections.Generic.List[string]]::new() - foreach ($line in (Get-Content -LiteralPath $log.FullName -ErrorAction SilentlyContinue)) { - if (($line -eq '' -or $line -match '^\s') -and $entries.Count -gt 0) { - $entries[$entries.Count - 1] = "$($entries[$entries.Count - 1]) $($line.Trim())".TrimEnd() - } else { - $entries.Add(($line -replace '^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d+\s+', '').Trim()) + if ($log) { + $result.Log = $log.FullName + $entries = [System.Collections.Generic.List[string]]::new() + foreach ($line in (Get-Content -LiteralPath $log.FullName -ErrorAction SilentlyContinue)) { + if (($line -eq '' -or $line -match '^\s') -and $entries.Count -gt 0) { + $entries[$entries.Count - 1] = "$($entries[$entries.Count - 1]) $($line.Trim())".TrimEnd() + } else { + $entries.Add(($line -replace '^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d+\s+', '').Trim()) + } } + $selected = Select-FailureEntry -Entries $entries -Pattern '(?i)suppressed message box|\berror\b|\bfail|\babort|denied|in use|return value 3' + $result.Entries = $selected.Entries + $result.InUse = $selected.InUse + } + $idPattern = "(?i)(? ' } | ForEach-Object { ($_ -replace '^\S+ \S+ \[[^\]]*\]\s*', '').Trim() }) + $selected = Select-FailureEntry -Entries $errors -Pattern '.' -InUsePattern '(?i)in use by|used by another process|access is denied\.?:\s*"' + $result.WingetEntries = $selected.Entries + $result.InUse = $result.InUse -or $selected.InUse } - $inUsePattern = '(?i)process\(es\) use|in use by|used by another process' - $matched = @($entries | Where-Object { $_ -match '(?i)suppressed message box|\berror\b|\bfail|\babort|denied|in use|return value 3' -or $_ -match $inUsePattern }) - $inUse = @($matched | Where-Object { $_ -match $inUsePattern }) - $result.InUse = $inUse.Count -gt 0 + return $result +} + +function Select-FailureEntry { + param([string[]]$Entries, [Parameter(Mandatory)][string]$Pattern, [string]$InUsePattern = '(?i)process\(es\) use|in use by|used by another process') + $matched = @($Entries | Where-Object { $_ -match $Pattern -or $_ -match $InUsePattern }) + $inUse = @($matched | Where-Object { $_ -match $InUsePattern }) $shown = @($matched | Select-Object -Last 4) - if ($result.InUse -and -not ($shown | Where-Object { $_ -match $inUsePattern })) { + if ($inUse.Count -gt 0 -and -not ($shown | Where-Object { $_ -match $InUsePattern })) { $shown = @($inUse[0]) + @($matched | Select-Object -Last 3) } - $result.Entries = $shown - return $result + return @{ Entries = $shown; InUse = $inUse.Count -gt 0 } } # The directory one installed file's package owns, read as the child of the container it was installed into. @@ -564,7 +587,7 @@ function Get-ToolHolder { # What a failed winget call owes its reader: # - winget's code -# - the reason the installer's own log gives +# - the reason the installer's own log gives, and the one winget's own log gives # - the processes that may hold the tool's files # The hex form of the code is the one winget documents its codes under, where the signed decimal matches nothing a search finds. # The log entries pass through the same home folder masking as the log's path, since an installer's reason commonly names a file under the profile. @@ -572,22 +595,28 @@ function Get-ToolHolder { # So the processes running from the tool's install are named only where something says files were in use. # Something says so in one of these ways: # - an installer log entry in Inno Setup's or Windows' own in-use wording +# - an error in winget's own log for the call saying a file was in use or denied # - winget's code being one of its own package-in-use or file-in-use codes, a sharing violation, or an access denial # Anything else names nobody, for this reason. -# A Git upgrade that failed on a download leaves no log and still finds every open Git Bash running from Git's own tree. +# A Git upgrade that failed on a download logs no such entry and still finds every open Git Bash running from Git's own tree. # Blaming those would send the reader after the wrong thing. function Write-InstallFailure { param([Parameter(Mandatory)][string]$ToolName, [Parameter(Mandatory)][string]$Package, [Parameter(Mandatory)][int]$Code, [Parameter(Mandatory)][datetime]$Since, [Parameter(Mandatory)][string]$Probe, [string]$Executable) warn "$ToolName failed on $Package, winget exited $Code ($('0x{0:X8}' -f $Code))" $reason = Get-InstallerFailureReason -Id $Package -Since $Since - if ($reason.Entries.Count -gt 0) { - info 'The installer log says:' - foreach ($entry in $reason.Entries) { - $shown = if ($HOME) { $entry -ireplace [regex]::Escape($HOME), '%USERPROFILE%' } else { $entry } - info " $shown" + foreach ($source in @( + @{ Heading = 'The installer log says:'; Entries = @($reason.Entries); Log = $reason.Log; Label = 'Full installer log' } + @{ Heading = "winget's own log says:"; Entries = @($reason.WingetEntries); Log = $reason.WingetLog; Label = 'Full winget log' } + )) { + if ($source.Entries.Count -gt 0) { + info $source.Heading + foreach ($entry in $source.Entries) { + $shown = if ($HOME) { $entry -ireplace [regex]::Escape($HOME), '%USERPROFILE%' } else { $entry } + info " $shown" + } } + if ($source.Log) { info "$($source.Label): $(Hide-Home $source.Log)" } } - if ($reason.Log) { info "Full installer log: $(Hide-Home $reason.Log)" } $logInUse = [bool]$reason.InUse # 0x8A150101 and 0x8A150103 are winget's own INSTALL_PACKAGE_IN_USE and INSTALL_FILE_IN_USE, which it returns where a manifest maps the installer's exit code to either. # 0x80070020 and 0x80070005 are ERROR_SHARING_VIOLATION and ERROR_ACCESS_DENIED carried as an HRESULT. diff --git a/tests/test_install_tools.py b/tests/test_install_tools.py index 876fe9525..9437d8308 100755 --- a/tests/test_install_tools.py +++ b/tests/test_install_tools.py @@ -817,7 +817,7 @@ def test_the_note_follows_what_dotnet_lists(self) -> None: $tokens = $null $errors = $null $ast = [System.Management.Automation.Language.Parser]::ParseFile($Installer, [ref]$tokens, [ref]$errors) -$wanted = @('Get-InstallerFailureReason', 'Get-InstallRoot', 'Invoke-Utf8Run', 'Get-ToolHolder') +$wanted = @('Get-InstallerFailureReason', 'Select-FailureEntry', 'Get-InstallRoot', 'Invoke-Utf8Run', 'Get-ToolHolder') foreach ($definition in $ast.FindAll({ param($node) $node -is [System.Management.Automation.Language.FunctionDefinitionAst] -and $wanted -contains $node.Name }, $true)) { . ([scriptblock]::Create($definition.Extent.Text)) } @@ -825,7 +825,13 @@ def test_the_note_follows_what_dotnet_lists(self) -> None: $results = [ordered]@{} foreach ($probe in $case.reasons) { $reason = Get-InstallerFailureReason -Id $probe.id -Since ([datetime]$probe.since) -Directory $case.directory - $results["reason $($probe.id) $($probe.since)"] = [ordered]@{ log = [bool]$reason.Log; entries = @($reason.Entries); in_use = $reason.InUse } + $results["reason $($probe.id) $($probe.since)"] = [ordered]@{ + log = [bool]$reason.Log + entries = @($reason.Entries) + winget_log = [bool]$reason.WingetLog + winget_entries = @($reason.WingetEntries) + in_use = $reason.InUse + } } $env:ProgramFiles = 'C:\PF' ${env:ProgramFiles(x86)} = 'C:\PF86' @@ -892,9 +898,12 @@ def test_the_note_follows_what_dotnet_lists(self) -> None: $script:REASON = @{ Log = 'C:\log.log' Entries = @($case.Value.entries | ForEach-Object { $_ -replace '', $HOME.Replace('$', '$$') }) + WingetLog = 'C:\winget.log' + WingetEntries = @(if ($case.Value.PSObject.Properties['winget_entries']) { $case.Value.winget_entries | ForEach-Object { $_ -replace '', $HOME.Replace('$', '$$') } }) InUse = [bool]($case.Value.PSObject.Properties['in_use'] -and $case.Value.in_use) } if ($script:REASON.Entries.Count -eq 0) { $script:REASON.Log = $null } + if ($script:REASON.WingetEntries.Count -eq 0) { $script:REASON.WingetLog = $null } function Get-InstallerFailureReason { param([string]$Id, [datetime]$Since) return $script:REASON } $script:LINES = @() Write-InstallFailure -ToolName 'tool' -Package 'Example.Tool' -Code $case.Value.code -Since (Get-Date) -Probe 'tool' -Executable $case.Value.executable @@ -915,6 +924,31 @@ def test_the_note_follows_what_dotnet_lists(self) -> None: "2026-01-02 03:04:06.002 Deinitializing Setup.", ] +PORTABLE_WINGET_LOG = [ + "2026-01-02 03:04:05.100 [CLI ] WinGet invoked with arguments: 'upgrade' '--id' 'Portable.Tool'", + "2026-01-02 03:04:05.200 [CLI ] Deleting portable exe at: C:\\LAD\\Portable.Tool_x\\tool.exe", + ( + "2026-01-02 03:04:05.300 [CLI ] Caught std::exception: remove: Access is denied.:" + ' "C:\\LAD\\Portable.Tool_x\\tool.exe"' + ), + "2026-01-02 03:04:05.301 [CLI ] Portable installer failed: 2316632067", + "2026-01-02 03:04:05.302 [CLI ] Terminating context: 0x8a150052 at C:\\src\\InstallFlow.cpp:239", +] + +OTHER_WINGET_LOG = [ + "2026-01-02 03:04:05.100 [CLI ] WinGet invoked with arguments: 'upgrade' '--id' 'Portable.Tool.Extra'", + "2026-01-02 03:04:05.300 [CLI ] Caught std::exception: remove: Access is denied.", +] + +UNRELATED_DENIAL_WINGET_LOG = [ + "2026-01-02 03:04:05.100 [CLI ] WinGet invoked with arguments: 'install' '--id' 'Settings.Tool'", + "2026-01-02 03:04:05.300 [CORE] Failed to open the settings store: Access is denied.", +] + +DENIED_LOG = [ + "2026-01-02 03:04:05.100 Error 0x80070005: Access is denied.", +] + BUSY_LOG = [ "2026-01-02 03:04:05.100 The file is being used by another process.", *( @@ -936,6 +970,16 @@ def run_cases(self) -> dict[str, Any]: log.write_text("\r\n".join([*INNO_LOG, ""]), encoding="utf-8", newline="") busy = Path(directory, "Busy.Tool.1.0-26-01-02-03-04-05.log") busy.write_text("\r\n".join([*BUSY_LOG, ""]), encoding="utf-8", newline="") + denied = Path(directory, "Denied.Tool.1.0-26-01-02-03-04-05.log") + denied.write_text("\r\n".join([*DENIED_LOG, ""]), encoding="utf-8", newline="") + for name, lines in ( + ("WinGet-2026-01-02-03-04-05.000.log", PORTABLE_WINGET_LOG), + ("WinGet-2026-01-02-03-04-06.000.log", OTHER_WINGET_LOG), + ("WinGet-2026-01-02-03-04-07.000.log", UNRELATED_DENIAL_WINGET_LOG), + ): + Path(directory, name).write_text( + "\r\n".join([*lines, ""]), encoding="utf-8", newline="" + ) elsewhere = Path(directory, "LAD", "Programs", "Tool", "tool.exe") elsewhere.parent.mkdir(parents=True) elsewhere.write_bytes(b"") @@ -946,6 +990,10 @@ def run_cases(self) -> dict[str, Any]: {"id": "Example.Tool", "since": "2100-01-01"}, {"id": "Other.Tool", "since": "2000-01-01"}, {"id": "Busy.Tool", "since": "2000-01-01"}, + {"id": "Denied.Tool", "since": "2000-01-01"}, + {"id": "Settings.Tool", "since": "2000-01-01"}, + {"id": "Portable.Tool", "since": "2000-01-01"}, + {"id": "Portable.Tool", "since": "2100-01-01"}, ], "roots": [ "C:\\PF\\Git\\cmd\\git.exe", @@ -976,6 +1024,8 @@ def test_the_log_entry_keeps_its_continuation_lines(self) -> None: ), "Failed to proceed to next wizard page; aborting.", ], + "winget_log": False, + "winget_entries": [], "in_use": True, }, ) @@ -991,15 +1041,73 @@ def test_an_in_use_entry_survives_the_cap_on_later_errors(self) -> None: "Error 3: rollback step failed.", "Error 4: rollback step failed.", ], + "winget_log": False, + "winget_entries": [], "in_use": True, }, ) + def test_an_installer_logs_access_denial_alone_is_not_files_in_use(self) -> None: + """An installer's denial can be a permission failure, which no running process causes.""" + self.assertEqual( + self.run_cases()["reason Denied.Tool 2000-01-01"], + { + "log": True, + "entries": ["Error 0x80070005: Access is denied."], + "winget_log": False, + "winget_entries": [], + "in_use": False, + }, + ) + + def test_a_winget_denial_naming_no_file_is_not_files_in_use(self) -> None: + """Only a denial naming a file is winget failing to replace one.""" + self.assertEqual( + self.run_cases()["reason Settings.Tool 2000-01-01"], + { + "log": False, + "entries": [], + "winget_log": True, + "winget_entries": ["Failed to open the settings store: Access is denied."], + "in_use": False, + }, + ) + def test_a_log_older_than_the_attempt_or_for_another_id_is_not_read(self) -> None: results = self.run_cases() - unread = {"log": False, "entries": [], "in_use": False} + unread = { + "log": False, + "entries": [], + "winget_log": False, + "winget_entries": [], + "in_use": False, + } self.assertEqual(results["reason Example.Tool 2100-01-01"], unread) self.assertEqual(results["reason Other.Tool 2000-01-01"], unread) + self.assertEqual(results["reason Portable.Tool 2100-01-01"], unread) + + def test_wingets_own_log_gives_a_portable_packages_reason(self) -> None: + """A package with no installer log has its reason read from winget's own session log. + + A session log naming a longer id that only starts with this one is not read as this one's. + """ + self.assertEqual( + self.run_cases()["reason Portable.Tool 2000-01-01"], + { + "log": False, + "entries": [], + "winget_log": True, + "winget_entries": [ + ( + "Caught std::exception: remove: Access is denied.:" + ' "C:\\LAD\\Portable.Tool_x\\tool.exe"' + ), + "Portable installer failed: 2316632067", + "Terminating context: 0x8a150052 at C:\\src\\InstallFlow.cpp:239", + ], + "in_use": True, + }, + ) @unittest.skipUnless(sys.platform == "win32", "reads this host's own process list") def test_a_same_named_process_outside_the_tree_is_not_a_holder(self) -> None: @@ -1038,6 +1146,7 @@ def test_the_utf8_run_switches_only_for_console_output_and_restores_it(self) -> INSTALLER_FAILED = -1978335226 SHARING_VIOLATION = -2147024864 WINGET_FILE_IN_USE = -1978334973 +WINGET_INSTALL_FAILED = -1978335150 @unittest.skipUnless( @@ -1063,6 +1172,15 @@ def run_cases(self) -> dict[str, list[str]]: }, "no reason": {"entries": [], "code": INSTALLER_FAILED, "executable": ""}, "winget file in use": {"entries": [], "code": WINGET_FILE_IN_USE, "executable": ""}, + "portable in use": { + "entries": [], + "winget_entries": [ + 'Caught std::exception: remove: Access is denied.: "\\Tool_x\\tool.exe"' + ], + "in_use": True, + "code": WINGET_INSTALL_FAILED, + "executable": "", + }, "sharing violation": { "entries": [], "code": SHARING_VIOLATION, @@ -1121,6 +1239,29 @@ def test_wingets_own_file_in_use_code_names_the_holders(self) -> None: ], ) + def test_wingets_own_log_saying_access_denied_names_the_holders(self) -> None: + self.assertEqual( + self.run_cases()["portable in use"], + [ + "WARN tool failed on Example.Tool, winget exited -1978335150 (0x8A150052)", + "INFO winget's own log says:", + ( + "INFO Caught std::exception: remove: Access is denied.:" + ' "%USERPROFILE%\\Tool_x\\tool.exe"' + ), + "INFO Full winget log: LOG", + "HOLDERS tool", + ( + "INFO Running from tool's install, and Windows cannot replace a file a" + " running process holds:" + ), + "INFO helper (process 1234)", + "INFO bash (process 99)", + "INFO Close them, or stop them with the command below, then run this again:", + "INFO Stop-Process -Id 1234, 99", + ], + ) + def test_a_sharing_violation_names_the_holders_from_the_executable_given(self) -> None: lines = self.run_cases()["sharing violation"] self.assertEqual(