search

microsoft / winget-cli

WinGet is the Windows Package Manager. This project includes a CLI (Command Line Interface), PowerShell modules, and a COM (Component Object Model) API (Application Programming Interface).
https://learn.microsoft.com/windows/package-manager/
MIT License
22.96k stars 1.43k forks source link

Installation fails with no output message #4692

Open chhoumann opened 1 month ago

chhoumann commented 1 month ago

Brief description of your issue

Winget will respond normally to many commands, but refuses to do any installations. Anytime I wrote, for example, winget upgrade --all, it would simply display a spinner for a bit, and then exit with no error message.

Logs

I checked the logs, which look like this:

2024-07-31 09:15:59.151 [CORE] WinGet, version [1.8.1911], activity [{EAE8B4B6-154D-42E2-AA82-50B6F9F43277}]
2024-07-31 09:15:59.151 [CORE] OS: Windows.Desktop v10.0.22631.3958
2024-07-31 09:15:59.151 [CORE] Command line Args: "C:\Program Files\WindowsApps\Microsoft.DesktopAppInstaller_1.23.1911.0_x64__8wekyb3d8bbwe\WindowsPackageManagerServer.exe" -Embedding
2024-07-31 09:15:59.151 [CORE] Package: Microsoft.DesktopAppInstaller v1.23.1911.0
2024-07-31 09:15:59.151 [CORE] IsCOMCall:1; Caller: C:\Windows\explorer.exe
2024-07-31 09:15:59.163 [CORE] Default proxy is not set
2024-07-31 09:15:59.163 [REPO] REST HTTP Client helper does not use proxy
2024-07-31 09:15:59.171 [REPO] REST HTTP Client helper does not use proxy
2024-07-31 09:15:59.177 [REPO] Sending http GET request to: https://storeedgefd.dsx.mp.microsoft.com/v9.0/information
2024-07-31 09:15:59.307 [REPO] Response status: 200
2024-07-31 09:15:59.307 [REPO] Authentication node not found. Assuming authentication type none.
2024-07-31 09:15:59.307 [REPO] Sending http GET request to: https://storeedgefd.dsx.mp.microsoft.com/v9.0/information
2024-07-31 09:15:59.325 [REPO] Response status: 200
2024-07-31 09:15:59.325 [REPO] Authentication node not found. Assuming authentication type none.
2024-07-31 09:15:59.328 [REPO] Creating new SQLite Index with version [Latest] at ':memory:'
2024-07-31 09:15:59.364 [REPO] Reading MSI UpgradeCodes
2024-07-31 09:15:59.600 [REPO] Reading MSI UpgradeCodes
2024-07-31 09:16:00.089 [REPO] Opening database for ReadWrite at 'C:\Users\chhou\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\StoreEdgeFD\installed.db'
2024-07-31 09:16:00.090 [REPO] Opened SQLite Index with version [1.3], last write [2022-05-24 11:15:13.000]
2024-07-31 09:16:00.117 [REPO] Sending http POST request to: https://storeedgefd.dsx.mp.microsoft.com/v9.0/manifestSearch
2024-07-31 09:16:00.137 [REPO] Response status: 200
2024-07-31 09:16:00.191 [REPO] Opening database for ReadWrite at 'C:\Users\chhou\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\Microsoft.Winget.Source_8wekyb3d8bbwe\installed.db'
2024-07-31 09:16:00.192 [REPO] Opened SQLite Index with version [1.3], last write [2024-07-04 15:39:58.000]

However, sometimes the following line will appear at the bottom:

2024-07-31 09:16:49.294 [REPO] Did not find Id [calibre.calibre] in tracked source: winget

I was able to successfully examine the SQLite database file, and nothing stood out as missing or wrong at a glance. I also checked the other directories in %LOCALAPPDATA%\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\, but found nothing notable.

Manual solution

I had previously tried uninstalling and reinstalling before abandoning the issue. That did not work. I even tried reinstalling App Installer. This time, I decided to just rename the entire %LOCALAPPDATA%\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe to %LOCALAPPDATA%\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe.bak. When I tried to re-run winget upgrade --all, everything finally worked. I still have the backup if you need additional information.

Steps to reproduce

I do not know how my winget got into the state it was in for the bug to appear. I haven't manually modified any of its files (until I found the solution mentioned above) - at least not intentionally.

Running commands like winget upgrade --all would simply exit with no error message. That is, nothing was printed to the terminal after running the command.

Expected behavior

I expect the installer to proceed with upgrading/installing, not simply exit with no message.

Actual behavior

I expect the installer to proceed with upgrading/installing, not simply exit with no message.

Environment

[winget --info]
Windows Package Manager v1.8.1911
Copyright (c) Microsoft Corporation. All rights reserved.

Windows: Windows.Desktop v10.0.22631.3958
System Architecture: X64
Package: Microsoft.DesktopAppInstaller v1.23.1911.0

Winget Directories
-------------------------------------------------------------------------------------------------------------------------------
Logs                               %LOCALAPPDATA%\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\DiagOutputDir
User Settings                      %LOCALAPPDATA%\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\settings.json
Portable Links Directory (User)    %LOCALAPPDATA%\Microsoft\WinGet\Links
Portable Links Directory (Machine) C:\Program Files\WinGet\Links
Portable Package Root (User)       %LOCALAPPDATA%\Microsoft\WinGet\Packages
Portable Package Root              C:\Program Files\WinGet\Packages
Portable Package Root (x86)        C:\Program Files (x86)\WinGet\Packages
Installer Downloads                %USERPROFILE%\Downloads

Links
---------------------------------------------------------------------------
Privacy Statement   https://aka.ms/winget-privacy
License Agreement   https://aka.ms/winget-license
Third Party Notices https://aka.ms/winget-3rdPartyNotice
Homepage            https://aka.ms/winget
Windows Store Terms https://www.microsoft.com/en-us/storedocs/terms-of-sale

Admin Setting                             State
--------------------------------------------------
LocalManifestFiles                        Disabled
BypassCertificatePinningForMicrosoftStore Disabled
InstallerHashOverride                     Disabled
LocalArchiveMalwareScanOverride           Disabled
ProxyCommandLineOptions                   Disabled
DefaultProxy                              Disabled
github-actions[bot] commented 1 month ago

Hi I'm an AI powered bot that finds similar issues based off the issue title.

Please view the issues below to see if they solve your problem, and if the issue describes your problem please consider closing this one and thumbs upping the other issue to help us prioritize it. Thank you!

Open similar issues:

Closed similar issues:

Note: You can give me feedback by thumbs upping or thumbs downing this comment.

chhoumann commented 1 month ago

In #2677, the solution was to reinstall the system from iso. This is not a good solution for most people!

4219 is closed, but the issue persists.

I did not try the solution that was presented in that issue, but it sounds promising. The fix that was mentioned being released in https://github.com/microsoft/winget-cli/releases/tag/v1.7.10661 did not seem to resolve this issue, as I was running version 1.8.1911 while having the issue.

denelon commented 1 month ago

Did you have any of the experimental features enabled? winget features will show which features are enabled.

chhoumann commented 1 month ago

I've never explicitly enabled any, no.

Output says as much ("This is a stable release...").

florelis commented 1 month ago

Sounds like an error is thrown when reading the database. Which winget should be more resilient to, or at least show a proper error...

If you run with --verbose-logs, the logs may show what was being queried when the error happened, which could narrow down the cause.

chhoumann commented 1 month ago

Sounds plausible, yeah.

Now that I did the manual fix, the logs show something different, despite using the old directory. I'd be happy to provide them, but winget upgrade --all --verbose-logs is over 7k lines long. Without --verbose-logs it's 280 lines. It still doesn't actually output anything in the terminal, but I'm unsure if that's because I've already updated everything to the latest version.

Looking at the new logs, it seems to be able to search the DB, as it finds entries that it looks for updates for. Unsure if my setup just got into some weird state or something.

florelis commented 1 month ago

is over 7k lines long.

I'd be mostly interested in knowing where it is crashing, that should be something we can see with just the last section of the file. Probably a couple dozen lines would be enough.

It still doesn't actually output anything in the terminal, but I'm unsure if that's because I've already updated everything to the latest version.

If everything is up to date, winget would output some message about it, although I can't remember what it is. So if there is no output at all, I think it is still crashing.

chhoumann commented 1 month ago

Head

2024-07-31 20:45:11.675 [CORE] WinGet, version [1.8.1911], activity [{A8DF6291-C085-46E5-81C0-572DC597DF5D}]
2024-07-31 20:45:11.675 [CORE] OS: Windows.Desktop v10.0.22631.3958
2024-07-31 20:45:11.675 [CORE] Command line Args: "C:\Users\chhou\AppData\Local\Microsoft\WindowsApps\winget.exe" upgrade --all --verbose-logs
2024-07-31 20:45:11.675 [CORE] Package: Microsoft.DesktopAppInstaller v1.23.1911.0
2024-07-31 20:45:11.675 [CORE] IsCOMCall:0; Caller: winget-cli
2024-07-31 20:45:11.682 [CLI ] WinGet invoked with arguments: 'upgrade' '--all' '--verbose-logs'
2024-07-31 20:45:11.682 [CLI ] Found subcommand: upgrade
2024-07-31 20:45:11.682 [CLI ] Leaf command to execute: root:upgrade
2024-07-31 20:45:11.684 [CORE] Setting action: Get, Type: Secure, Name: admin_settings
2024-07-31 20:45:11.684 [CORE] Admin settings was not found
2024-07-31 20:45:11.684 [CORE] Setting action: Get, Type: Secure, Name: admin_settings
2024-07-31 20:45:11.684 [CORE] Admin settings was not found
2024-07-31 20:45:11.684 [CORE] Setting action: Get, Type: Secure, Name: admin_settings
2024-07-31 20:45:11.684 [CORE] Admin settings was not found
2024-07-31 20:45:11.684 [CORE] Setting action: Get, Type: Secure, Name: admin_settings
2024-07-31 20:45:11.684 [CORE] Admin settings was not found
2024-07-31 20:45:11.684 [CORE] Setting action: Get, Type: Secure, Name: admin_settings
2024-07-31 20:45:11.684 [CORE] Admin settings was not found
2024-07-31 20:45:11.684 [CLI ] Executing command: upgrade
2024-07-31 20:45:11.685 [REPO] Additional sources GP is not enabled.
2024-07-31 20:45:11.685 [CORE] Setting action: Get, Type: Secure, Name: user_sources
2024-07-31 20:45:11.685 [CORE] Setting action: Get, Type: Secure, Name: admin_settings
2024-07-31 20:45:11.685 [CORE] Admin settings was not found

Tail

2024-07-31 20:45:14.449 [REPO]  ... searching source: msstore [StoreEdgeFD]
2024-07-31 20:45:14.449 [REPO] Performing search: Query:[none] Include:PackageFamilyName='notepadplusplus_7njy0v32s6xk6'[Exact]
2024-07-31 20:45:14.450 [REPO]  ... searching source: winget [Microsoft.Winget.Source_8wekyb3d8bbwe]
2024-07-31 20:45:14.450 [REPO] Performing search: Query:[none] Include:PackageFamilyName='notepadplusplus_7njy0v32s6xk6'[Exact]
2024-07-31 20:45:14.450 [REPO] Performing search: Query:[none] Include:PackageFamilyName='notepadplusplus_7njy0v32s6xk6'[Exact]
2024-07-31 20:45:14.451 [REPO] Finding available package from installed package using system reference search: Query:[none] Include:PackageFamilyName='shiftyjelly.pocketcastsdesktop_jr8twj5yc2snp'[Exact]
2024-07-31 20:45:14.451 [REPO]  ... searching source: msstore [StoreEdgeFD]
2024-07-31 20:45:14.451 [REPO] Performing search: Query:[none] Include:PackageFamilyName='shiftyjelly.pocketcastsdesktop_jr8twj5yc2snp'[Exact]
2024-07-31 20:45:14.451 [REPO]  ... searching source: winget [Microsoft.Winget.Source_8wekyb3d8bbwe]
2024-07-31 20:45:14.451 [REPO] Performing search: Query:[none] Include:PackageFamilyName='shiftyjelly.pocketcastsdesktop_jr8twj5yc2snp'[Exact]
2024-07-31 20:45:14.452 [REPO] Performing search: Query:[none] Include:PackageFamilyName='shiftyjelly.pocketcastsdesktop_jr8twj5yc2snp'[Exact]
2024-07-31 20:45:14.452 [REPO] Finding available package from installed package using system reference search: Query:[none] Include:PackageFamilyName='thebrowsercompany.arc_ttt1ap7aakyb4'[Exact]
2024-07-31 20:45:14.452 [REPO]  ... searching source: msstore [StoreEdgeFD]
2024-07-31 20:45:14.452 [REPO] Performing search: Query:[none] Include:PackageFamilyName='thebrowsercompany.arc_ttt1ap7aakyb4'[Exact]
2024-07-31 20:45:14.453 [REPO]  ... searching source: winget [Microsoft.Winget.Source_8wekyb3d8bbwe]
2024-07-31 20:45:14.453 [REPO] Performing search: Query:[none] Include:PackageFamilyName='thebrowsercompany.arc_ttt1ap7aakyb4'[Exact]
2024-07-31 20:45:14.453 [REPO] Performing search: Query:[none] Include:PackageFamilyName='thebrowsercompany.arc_ttt1ap7aakyb4'[Exact]
2024-07-31 20:45:14.453 [REPO]  ... adding available package: TheBrowserCompany.Arc
2024-07-31 20:45:14.454 [REPO] Finding available package from installed package using system reference search: Query:[none] Include:PackageFamilyName='winrar.shellextension_s4jet1zx4n14a'[Exact]
2024-07-31 20:45:14.454 [REPO]  ... searching source: msstore [StoreEdgeFD]
2024-07-31 20:45:14.454 [REPO] Performing search: Query:[none] Include:PackageFamilyName='winrar.shellextension_s4jet1zx4n14a'[Exact]
2024-07-31 20:45:14.454 [REPO]  ... searching source: winget [Microsoft.Winget.Source_8wekyb3d8bbwe]
2024-07-31 20:45:14.454 [REPO] Performing search: Query:[none] Include:PackageFamilyName='winrar.shellextension_s4jet1zx4n14a'[Exact]
2024-07-31 20:45:14.454 [REPO] Performing search: Query:[none] Include:PackageFamilyName='winrar.shellextension_s4jet1zx4n14a'[Exact]