Crash in list command

[ajkWare]

Brief description of your issue

I upgraded from v1.3.1251-preview to v1.31681 (rc1) and winget now crashes.

I tried other versions - v1.3.1391-preview works but v1.3.1611-preview fails.

The failure occurs when the program examined the installed programs e.g. list command.

The same or very similar failure occurred in earlier versions of the program I tried on this installation; v1.3.1251-preview was the first version I tried that was able to list installed programs. So it appears that v1.3.1611-preview has regressed and the correction included in v1.3.1251-preview seems to have been lost.

Steps to reproduce

The crash occurs on one particular machine whenever a list command is issued.

Expected behavior

A list of installed programs displayed.

Actual behavior

The crash is an access violation and is reported in Security and Maintenance with the following details listed:

Faulting application name: winget.exe, version: 1.18.2206.10001, time stamp: 0x62a3cb5a
Faulting module name: WindowsPackageManager.dll, version: 1.18.2206.10001, time stamp: 0x62a3cb32
Exception code: 0xc0000005
Fault offset: 0x0000000000146d0d
Faulting process id: 0x52b8
Faulting application start time: 0x01d88637bf09aae0
Faulting application path: C:\Program Files\WindowsApps\Microsoft.DesktopAppInstaller_1.18.1611.0_x64__8wekyb3d8bbwe\winget.exe
Faulting module path: C:\Program Files\WindowsApps\Microsoft.DesktopAppInstaller_1.18.1611.0_x64__8wekyb3d8bbwe\WindowsPackageManager.dll
Report Id: 9bcc9e14-9e17-45d2-8ff4-cfaca593645c
Faulting package full name: Microsoft.DesktopAppInstaller_1.18.1611.0_x64__8wekyb3d8bbwe
Faulting package-relative application ID: winget

The log ends:

...
2022-06-22 13:58:23.228 [REPO] Creating PredefinedInstalledSource with filter [None]
2022-06-22 13:58:23.228 [REPO] Creating new SQLite Index [4294967295.4294967295] at ':memory:'
2022-06-22 13:58:23.228 [SQL ] Opening SQLite connection: ':memory:' [6, 0]
2022-06-22 13:58:23.268 [REPO] Examining ARP entries for Machine | X64
2022-06-22 13:58:23.296 [REPO] Examining ARP entries for Machine | X86
2022-06-22 13:58:23.341 [REPO] Examining ARP entries for User | X64
2022-06-22 13:58:23.345 [FAIL] D:\a\_work\1\s\external\pkg\src\AppInstallerRepositoryCore\Microsoft\Schema\1_0\Interface_1_0.cpp(192)\WindowsPackageManager.dll!00007FFBF9DD0BD5: (caller: 00007FFBF9DCA0D1) Exception(1) tid(2238) 800700B7 Cannot create a file when that file already exists.
2022-06-22 13:58:23.345 [REPO] Ignoring duplicate ARP entry User|X64|SumatraPDF [SumatraPDF]
2022-06-22 13:58:23.615 [REPO] Opening SQLite Index for ReadWrite at 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\StoreEdgeFD\installed.db'
2022-06-22 13:58:23.615 [SQL ] Opening SQLite connection: 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\StoreEdgeFD\installed.db' [2, 0]
2022-06-22 13:58:23.616 [REPO] Opened SQLite Index with version [1.4], last write [2022-03-12 16:23:31.000]
2022-06-22 13:58:23.664 [REPO] Opening SQLite Index for ReadWrite at 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\Microsoft.Winget.Source_8wekyb3d8bbwe\installed.db'
2022-06-22 13:58:23.664 [SQL ] Opening SQLite connection: 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\Microsoft.Winget.Source_8wekyb3d8bbwe\installed.db' [2, 0]
2022-06-22 13:58:23.665 [REPO] Opened SQLite Index with version [1.4], last write [2022-06-17 16:18:39.000]
2022-06-22 13:58:23.727 [REPO] Did not find a Version {  }
2022-06-22 13:58:23.727 [REPO] Did not find a Version {  }

The log from a successful run is the same but continues:

...
2022-06-22 13:59:37.310 [REPO] Creating PredefinedInstalledSource with filter [None]
2022-06-22 13:59:37.310 [REPO] Creating new SQLite Index [4294967295.4294967295] at ':memory:'
2022-06-22 13:59:37.310 [SQL ] Opening SQLite connection: ':memory:' [6, 0]
2022-06-22 13:59:37.348 [REPO] Examining ARP entries for Machine | X64
2022-06-22 13:59:37.373 [REPO] Examining ARP entries for Machine | X86
2022-06-22 13:59:37.414 [REPO] Examining ARP entries for User | X64
2022-06-22 13:59:37.416 [FAIL] D:\a\_work\1\s\external\pkg\src\AppInstallerRepositoryCore\Microsoft\Schema\1_0\Interface_1_0.cpp(192)\WindowsPackageManager.dll!00007FFBF8CFBF45: (caller: 00007FFBF8CF7A01) Exception(1) tid(43fc) 800700B7 Cannot create a file when that file already exists.
2022-06-22 13:59:37.417 [REPO] Ignoring duplicate ARP entry User|X64|SumatraPDF [SumatraPDF]
2022-06-22 13:59:37.706 [REPO] Opening SQLite Index for ReadWrite at 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\StoreEdgeFD\installed.db'
2022-06-22 13:59:37.706 [SQL ] Opening SQLite connection: 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\StoreEdgeFD\installed.db' [2, 0]
2022-06-22 13:59:37.708 [REPO] Opened SQLite Index with version [1.4], last write [2022-03-12 16:23:31.000]
2022-06-22 13:59:37.756 [REPO] Opening SQLite Index for ReadWrite at 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\Microsoft.Winget.Source_8wekyb3d8bbwe\installed.db'
2022-06-22 13:59:37.756 [SQL ] Opening SQLite connection: 'C:\Users\msajk\AppData\Local\Packages\Microsoft.DesktopAppInstaller_8wekyb3d8bbwe\LocalState\Microsoft.Winget.Source_8wekyb3d8bbwe\installed.db' [2, 0]
2022-06-22 13:59:37.758 [REPO] Opened SQLite Index with version [1.4], last write [2022-06-17 16:18:39.000]
2022-06-22 13:59:37.814 [REPO] Did not find a Version {  }
2022-06-22 13:59:37.814 [REPO] Did not find a Version {  }
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> log from failing version stopped here...
2022-06-22 13:59:37.814 [REPO] Did not find a Version {  }
2022-06-22 13:59:37.815 [REPO] CompositeSource: The installed version of the package '' was null and is being dropped from the results.
2022-06-22 13:59:37.970 [REPO] Found multiple matches for installed package [Mozilla Firefox 101.0.1 (x64 en-US)] in source [Microsoft.Winget.Source_8wekyb3d8bbwe] when searching for [Query:[none] Include:ProductCode='mozilla firefox 101.0.1 (x64 en-us)'[Exact] Include:NormalizedNameAndPublisher='mozillafirefox'+'mozilla'[Exact]]
2022-06-22 13:59:37.971 [REPO]   Checking match with package id: Mozilla.Firefox.Beta
2022-06-22 13:59:37.971 [REPO]   Checking match with package id: Mozilla.Firefox
2022-06-22 13:59:37.971 [REPO]   Appropriate available package could not be determined
2022-06-22 13:59:38.044 [REPO] Found multiple matches for installed package [{042d26ef-3dbe-4c25-95d3-4c1b11b235a7}] in tracking catalog for source [Microsoft.Winget.Source_8wekyb3d8bbwe] when searching for [Query:[none] Include:ProductCode='{042d26ef-3dbe-4c25-95d3-4c1b11b235a7}'[Exact] Include:NormalizedNameAndPublisher='microsoftvisualc2013redistributable'+'microsoft'[Exact]]
2022-06-22 13:59:38.045 [REPO]   Checking match with package id: Microsoft.VC++2013Redist-x64
2022-06-22 13:59:38.045 [REPO]   Checking match with package id: Microsoft.VC++2013Redist-x86
...

Environment

WinGet, version [1.3.1611-preview], activity [{9149E05B-F815-4315-B4BA-E72B953CD382}]
OS: Windows.Desktop v10.0.19044.1766
System Architecture: X64
Command line Args: winget  list
Package: Microsoft.DesktopAppInstaller v1.18.1611.0

[denelon]

@ajkajk,

Thank you for reporting this. Would you be willing to submit a report using Feedback Hub and provide the link to the report so we can review the additional logs provided?

[JohnMcPMS]

It would be better if you had the failure bucket from the crash event; that makes it very easy to find the crash dumps in the back end. But Feedback Hub probably won't help much here.

[JohnMcPMS]

After some investigation, there are likely no crash dumps but it might help understand the root problem here if you could provide the log file from a crashing winget list --verbose-logs (or whatever the command was + --verbose-logs). I'm going to mitigate the issue again, hopefully more permanently than last time, but I still don't understand why this is happening.

And now in the middle of writing this, I think the issue might be that the DisplayVersion for the ARP entry in question is resulting in an embedded null character. Working backward to exactly which entry that is and having you verify it is going to be complicated. But from reading about it, it fits exactly with the strange failure that is needed where we find all versions, sort them, then fail to find the latest version from the data we just pulled.

Given that your successful log shows this:

CompositeSource: The installed version of the package '' was null and is being dropped from the results.

With no value for the package id that is failing suggests that the id might also have an embedded null character, or isn't properly being converted from UTF-16 to UTF-8.

[ajkWare]

Right. I hoped that narrowing it down to the working/failed versions would get us there. Anyway, given the feedback hub won't help much, instead I've

1. (re)installed 1.3.1681 release candidate and
2. run winget list --verbose-logs - I attach a zip the resulting log.
3. I've also taken a mini dump of the crash (using sysinternals procdump) and attach a zip of that too.

If needed I could get a full dump. Hope this helps in tracking down this regression. As I said before, the first release versions of winget exhibited the same symptoms on this machine, and the bug was apparently fixed for awhile during v1.3 development.

winget.exe_220624_163606.dmp.zip
WinGet-2022-06-24-14-55-54.437.failed.log.zip

[denelon]

@ajkajk thank you so much for going above and beyond to help us build a better product.

[JohnMcPMS]

I made a fix that should mitigate the issue, but it is hard to know for sure. This is a store signed package, same as the rest on the releases. If you could verify that it does mitigate the issue for you, that would help a lot. I'm going to look at your files to confirm my theory on the root cause.

[Remove the .zip extension]
Microsoft.DesktopAppInstaller.msixbundle.zip

[JohnMcPMS]

That didn't take long, found a null byte in a version string immediately.

Adding manifest for [Adobe Photoshop Elements 9, 9.0.3.0 VersionM] at relative path [Adobe Photoshop Elements 9]
                                                        | I'm a null byte, not a space 

So the mitigation should work, but it will mean that Photoshop Elements here won't be in list because of the null. I'm going to work on a larger fix that probably won't be able to ship with 1.3.

[ajkWare]

Tried that build and winget list now runs to completion on the troublesome machine.

As you expected, Photoshop Elements is not in the list. It wasn't in the list produced by v1.3.1391-preview either. Elements does appear OK in the Windows 10 Settings/Apps list.

Thanks for the fix - I'll look forward to the full fix.

Please close this issue whenever your process suggests.

[denelon]

Windows Package Manager 1.3 release candidate (2)