choco.exe.manifest is ignored because it is extracted AFTER first choco.exe access

[Outek]

What You Are Seeing?

If i try to push a package to the nuget server with the parameter -debug the wrong os version is logged.

What is Expected?

Platformversion = 10.x
Platformname = Windows Server 2016 or something similar

How Did You Get This To Happen? (Steps to Reproduce)

choco push --api-key= -source -debug

Output Log

~~~sh
onfiguration: CommandName='push'|
CacheLocation=''|
ContainsLegacyPackageInstalls='True'|
CommandExecutionTimeoutSeconds='2700'|WebRequestTimeoutSeconds='30'|
Sources=''|
SourceType='normal'|Debug='True'|Verbose='False'|Trace='False'|
Force='False'|Noop='False'|HelpRequested='False'|
UnsuccessfulParsing='False'|RegularOutput='True'|QuietOutput='False'|
PromptForConfirmation='True'|AcceptLicense='False'|
AllowUnofficialBuild='False'|Input=''|
AllVersions='False'|SkipPackageInstallProvider='False'|
Prerelease='False'|ForceX86='False'|OverrideArguments='False'|
NotSilent='False'|ApplyPackageParametersToDependencies='False'|
ApplyInstallArgumentsToDependencies='False'|IgnoreDependencies='False'|
AllowMultipleVersions='False'|AllowDowngrade='False'|
ForceDependencies='False'|Information.PlatformType='Windows'|
Information.PlatformVersion='6.2.9200.0'|
Information.PlatformName='Windows Server 2012'|
Information.ChocolateyVersion='0.10.5.0'|
Information.ChocolateyProductVersion='0.10.5'|
Information.FullName='choco, Version=0.10.5.0, Culture=neutral, PublicKeyToken=79d02ea9cad655eb'|

Information.Is64BitOperatingSystem='True'|
Information.Is64BitProcess='True'|Information.IsInteractive='True'|
Information.IsUserAdministrator='True'|
Information.IsProcessElevated='True'|
Information.IsLicensedVersion='False'|Information.LicenseType='Foss'|
Features.AutoUninstaller='True'|Features.ChecksumFiles='True'|
Features.AllowEmptyChecksums='False'|
Features.AllowEmptyChecksumsSecure='True'|
Features.FailOnAutoUninstaller='False'|
Features.FailOnStandardError='False'|Features.UsePowerShellHost='True'|
Features.LogEnvironmentValues='False'|Features.VirusCheck='False'|
Features.FailOnInvalidOrMissingLicense='False'|
Features.IgnoreInvalidOptionsSwitches='True'|
Features.UsePackageExitCodes='True'|
Features.UseFipsCompliantChecksums='False'|
Features.ShowNonElevatedWarnings='True'|
Features.ShowDownloadProgress='True'|
Features.StopOnFirstPackageFailure='False'|
Features.UseRememberedArgumentsForUpgrades='False'|
Features.ScriptsCheckLastExitCode='False'|
ListCommand.LocalOnly='False'|
ListCommand.IncludeRegistryPrograms='False'|ListCommand.PageSize='25'|
ListCommand.Exact='False'|ListCommand.ByIdOnly='False'|
ListCommand.IdStartsWith='False'|ListCommand.OrderByPopularity='False'|
ListCommand.ApprovedOnly='False'|
ListCommand.DownloadCacheAvailable='False'|
ListCommand.NotBroken='False'|
ListCommand.IncludeVersionOverrides='False'|
UpgradeCommand.FailOnUnfound='False'|
UpgradeCommand.FailOnNotInstalled='False'|
UpgradeCommand.NotifyOnlyAvailableUpgrades='False'|
UpgradeCommand.ExcludePrerelease='False'|
NewCommand.AutomaticPackage='False'|
NewCommand.UseOriginalTemplate='False'|SourceCommand.Command='unknown'|
SourceCommand.Priority='0'|SourceCommand.BypassProxy='False'|
SourceCommand.AllowSelfService='False'|
FeatureCommand.Command='unknown'|
ConfigCommand.Command='unknown'|PinCommand.Command='unknown'|
Proxy.BypassOnLocal='True'|
_ Chocolatey:ChocolateyPushCommand - Normal Run Mode _
Attempting to push *.nupkg to https://servername:port/api/v2/package
Chocolatey had an error occur:
System.Net.WebException: The underlying connection was closed: An unexpected error occurred on a send. ---> System.IO.IOException: The handshake failed due to an unexpected packet format.
at System.Net.Security.SslState.StartReadFrame(Byte[] buffer, Int32 readBytes, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslState.ForceAuthentication(Boolean receiveFirst, Byte[] buffer, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslState.ProcessAuthentication(LazyAsyncResult lazyResult)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Net.TlsStream.ProcessAuthentication(LazyAsyncResult result)
at System.Net.TlsStream.Write(Byte[] buffer, Int32 offset, Int32 size)
at System.Net.ConnectStream.WriteHeaders(Boolean async)
--- End of inner exception stack trace ---
at System.Net.HttpWebRequest.GetResponse()
at NuGet.RequestHelper.GetResponse()
at NuGet.RedirectedHttpClient.GetResponseUri(HttpClient client)
at NuGet.RedirectedHttpClient.EnsureClient()
at System.Lazy1.CreateValue() at System.Lazy1.LazyInitValue()
at NuGet.MemoryCache.GetOrAddT
at chocolatey.infrastructure.app.nuget.NugetPush.push_package(ChocolateyConfiguration config, String nupkgFilePath)
at chocolatey.infrastructure.app.services.NugetService.push_run(ChocolateyConfiguration config)
at chocolatey.infrastructure.app.services.ChocolateyPackageService.push_run(ChocolateyConfiguration config)
at chocolatey.infrastructure.app.runners.GenericRunner.run(ChocolateyConfiguration config, Container container, Boolean isConsole, Action`1 parseArgs)
at chocolatey.infrastructure.app.runners.ConsoleApplication.run(String[] args, ChocolateyConfiguration config, Container container)
at chocolatey.console.Program.Main(String[] args)
Exiting with 1

~~~

[ferventcoder]

This is likely related to https://github.com/chocolatey/choco/issues/1178, which had a fix for Windows 10.

[ferventcoder]

~
Information.PlatformVersion='6.2.9200.0'|
Information.PlatformName='Windows Server 2012'|
~

I believe that you are likely running from Windows 2016, but for some reason it is coming back as 6.2.

What does the following run in PowerShell give you?

~powershell
~

[Outek]

PS C:\Windows\system32> [System.Environment]::OSVersion.Version

Major Minor Build Revision

---

10 0 14393 0

[Outek]

On the same Server after upgrading from .3 to .5:

Information.PlatformVersion='10.0.14393.0'|
Information.PlatformName='Windows'|
Information.ChocolateyVersion='0.10.3.0'|
Information.ChocolateyProductVersion='0.10.3

Information.PlatformVersion='6.2.9200.0'|
Information.PlatformName='Windows Server 2012'|
Information.ChocolateyVersion='0.10.5.0'|
Information.ChocolateyProductVersion='0.10.5'

[ferventcoder]

In Chocolatey v0.10.4, we externalized the app.manifest - https://github.com/chocolatey/choco/issues/1054.

I wonder why it comes back incorrectly with choco...

We added the compatibility into the app.manifest so it would show correctly quite a long time ago - https://msdn.microsoft.com/en-us/library/windows/desktop/aa374191(v=vs.85).aspx | https://github.com/chocolatey/choco/blob/2f588e755e33e4476f5170494c097932a23e1554/src/chocolatey.console/choco.exe.manifest#L39

Can you verify that this file exists: C:\ProgramData\Chocolatey\choco.exe.manifest?

[ferventcoder]

The .NET Framework calls https://msdn.microsoft.com/en-us/library/windows/desktop/ms724833(v=vs.85).aspx and https://msdn.microsoft.com/en-us/library/windows/desktop/ms724834(v=vs.85).aspx which should come back with the right information.

[ferventcoder]

Actually, I'm guessing that the manifest isn't getting applied for some reason - can you verify this is correct?

[Outek]

~~~sh



















~~~

[Outek]

How can i verify if the manifest is getting applied or not?

[ferventcoder]

Put an error in the file.

Like "1" at the very start of the file and save it.

I just did that and I got the following:

~~~sh
choco

Unhandled Exception: System.ComponentModel.Win32Exception: The application has failed to start because its side-by-side configuration is incorrect. Please see the application event log or use the command-line sxstrace.exe tool for more detail
at System.Diagnostics.Process.StartWithCreateProcess(ProcessStartInfo startInfo)
at shim.CommandExecutor.execute(String process, String arguments, String working_directory, Boolean is_gui, Boolean wait_for_exit, Boolean requires_elevation)
at shim.ShimProgram.Main(String[] args)
~~~

[Outek]

~~~sh
1



















~~~

C:>choco list -localonly
Chocolatey v0.10.5
chocolatey 0.10.5
googlechrome 57.0.2987.110
npp 7.3.3
3 packages installed.

There is no error..

[ferventcoder]

If you can do that and verify, that will help.

If it is getting applied but that section is being ignored, that is going to require a LOT more research.

Of note, one article turned up a timestamp possibly causing the issue (but the timestamp changes when the file is built):

• http://csi-windows.com/blog/all/27-csi-news-general/245-find-out-why-your-external-manifest-is-being-ignored

[ferventcoder]

What do you get for these next two commands?

• where.exe choco
• choco list -lo --shimgen-log

[Outek]

C:>where.exe choco
C:\ProgramData\chocolatey\bin\choco.exe

[Outek]

C:>choco list -lo --shimgen-log
path to executable: C:\ProgramData\chocolatey\choco.exe
working directory: C:\
is gui? False
wait for exit? True
command (optional):
Chocolatey v0.10.5
chocolatey 0.10.5
googlechrome 57.0.2987.110
npp 7.3.3
3 packages installed.

[ferventcoder]

Well it means it is completely ignoring that file. Can you verify the casing of the manifest and the exe are exactly the same?

[Outek]

I don't know what you mean, please explain...

[ferventcoder]

In C:\ProgramData\chocolatey, take a screen shot and paste that here.

[Outek]

[ferventcoder]

@Outek That manifest file looks suspect - please turn on "Show file extensions" and ensure that file doesn't end in ".txt".

[ferventcoder]

Better yet, provide the output of:

dir C:\ProgramData\chocolatey

Thanks

[Outek]

dir C:\ProgramData\chocolatey
Volume in drive C has no label.
Volume Serial Number is B8F8-C245

Directory of C:\ProgramData\chocolatey

12.05.2017 23:04

.
12.05.2017 23:04 ..
12.05.2017 23:03 bin
12.05.2017 23:02 7'499'400 choco.exe
12.05.2017 23:02 0 choco.exe.ignore
12.05.2017 23:45 2'626 choco.exe.manifest
12.05.2017 23:04 config
12.05.2017 23:03 helpers
27.03.2017 22:02 lib
12.05.2017 23:02 670 LICENSE.txt
27.03.2017 20:42 logs
12.05.2017 23:03 redirects
12.05.2017 23:03 tools
4 File(s) 7'502'696 bytes
9 Dir(s) 27'873'824'768 bytes free

[ferventcoder]

This is very strange

[ferventcoder]

@Outek can you prove the output of the following:

• ls HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\SideBySide
• Get-ItemProperty HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\SideBySide

[Outek]

PS C:> ls HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\SideBySide
Hive: HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\SideBySide
Name Property
---- --------
Configuration
Winners

PS C:> Get-ItemProperty HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\SideBySide
PublisherPolicyChangeTime : 131370422642971529
MaintenanceFlags : 2147549203
LastSuccessfullScavenge : 131389742135672126
LastScavengingStarvationSQMReport : 131385276016212865
LastScavengeCookie : 131370422642971529
LastScavengeFlags : 39
PSPath : Microsoft.PowerShell.Core\Registry::HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\SideBySid
e
PSParentPath : Microsoft.PowerShell.Core\Registry::HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion
PSChildName : SideBySide
PSDrive : HKLM
PSProvider : Microsoft.PowerShell.Core\Registry

[ferventcoder]

Nothing there looks out of line. We are looking into options in #1307 and may embed the manifest back into choco.

[jberezanski]

@ferventcoder

one article turned up a timestamp possibly causing the issue (but the timestamp changes when the file is built)

Here are links where a Microsoft developer writes about caching of the manifest information: https://blogs.msdn.microsoft.com/junfeng/2006/10/25/touch-the-exe-after-you-added-a-manifest-for-it-in-vista/
https://blogs.msdn.microsoft.com/junfeng/2007/10/01/windows-vista-sxs-activation-context-cache/

The issue is caused by the way choco.exe.manifest is deployed. Currently, it is unpacked by choco.exe itself, not by the Chocolatey installation script. This leads to the following sequence of events:

1. the user does not have Chocolatey installed or installed Chocolatey is 0.10.3 or earlier
   0.a. %ChocolateyInstall%\choco.exe.manifest does not exist
   0.b. the last modified time of %ChocolateyInstall%\choco.exe is T0 (if it exists)
2. the user installs Chocolatey 0.10.4+
   1.a. Chocolatey install script creates/updates %ChocolateyInstall%\choco.exe - its last modified time changes to T1
3. the user runs choco.exe for the first time
   2.a. the OS loader checks for the existence of a manifest
   2.a.1. the OS loader looks at the last modified time of %ChocolateyInstall%choco.exe - it is T1
   2.a.2. the OS loader does not have any cached manifest info for "%ChocolateyInstall%choco.exe with last modified time T1"
   2.a.3. the OS loader checks for an embedded manifest - there is none
   2.a.4. the OS loader checks for the presence of %ChocolateyInstall%choco.exe.manifest - it does not exist
   2.a.5. the OS loader caches the info that "%ChocolateyInstall%choco.exe with last modified time T1 does not have a manifest"
   2.b. the OS loader starts choco.exe with the default permission level
   2.c. choco.exe runs and executes AssemblyFileExtractor.extract_all_resources_to_relative_directory()
   2.c.1. choco.exe creates %ChocolateyInstall%choco.exe.manifest
4. the user runs choco.exe for the second time
   3.a. the OS loader checks for the existence of a manifest
   3.a.1. the OS loader looks at the last modified time of %ChocolateyInstall%choco.exe - it is T1
   3.a.2. the OS loader remembers that "%ChocolateyInstall%choco.exe with last modified time T1 does not have a manifest"
   3.b. the OS loader starts choco.exe with the default permission level

And, possibly, later:

1. the user upgrades Chocolatey to vNext or changes the last modified time of choco.exe manually (using touch.exe, for example)
   4.a. the last modified time of %ChocolateyInstall%choco.exe changes to T2
2. the user runs choco.exe
   5.a. the OS loader checks for the existence of a manifest
   5.a.1. the OS loader looks at the last modified time of %ChocolateyInstall%choco.exe - it is T2
   5.a.2. the OS loader does not have any cached manifest info for "%ChocolateyInstall%choco.exe with last modified time T2"
   5.a.3. the OS loader checks for an embedded manifest - there is none
   5.a.4. the OS loader checks for the presence of %ChocolateyInstall%choco.exe.manifest - it exists
   5.a.5. the OS loader caches the info that "%ChocolateyInstall%choco.exe with last modified time T2 does have a manifest"
   5.b. the OS loader reads the manifest
   5.c. the OS loader starts choco.exe with the permission level specified in the manifest

The solution is to move the manifest deployment logic to the install script.

To avoid unconditionally overwriting the existing manifest upon chocolatey.nupkg extraction, the file in the nupkg could be named, for example, choco.exe.manifest.original. The install script would copy it to choco.exe.manifest (and possibly perform some overwriting decision logic).

[jberezanski]

What has apparently changed from Vista times (when those blog posts were written) is that the cache seems to survive reboots.

[ferventcoder]

I think we have a bug:

2.a.5. the OS loader caches the info that "%ChocolateyInstall%choco.exe with last modified time T1 does not have a manifest"
2.b. the OS loader starts choco.exe with the default permission level
2.c. choco.exe runs and executes AssemblyFileExtractor.extract_all_resources_to_relative_directory()

The file should be already set. I think you have found a bug.

[ferventcoder]

@Outek can you confirm if you change the last modified time of choco.exe that it starts working appropriately?

[Outek]

Yes, i can confirm this.

After the last modified time is altered:

ForceDependencies='False'|Information.PlatformType='Windows'|
Information.PlatformVersion='10.0.14393.0'|
Information.PlatformName='Windows Server 2016'|
Information.ChocolateyVersion='0.10.5.0'|
Information.ChocolateyProductVersion='0.10.5'|

[ferventcoder]

@Outek awesome. Thank you!

[DarwinJS]

Sorry - just getting wind of this now.

I believe this is a bug in windows manifest caching (because the SDK says it should not get stuck like this) and I found changing the EXE modified date is the least destructive away around it.

Blogged it ages ago: http://csi-windows.com/blog/all/27-csi-news-general/245-find-out-why-your-external-manifest-is-being-ignored