Chocolatey reporting success when install fails with 503 error

[Ewynne]

Hi,

I experienced a silent failure while installing the dotnetfx package. I don't think the problem is with the package, as it appears to be a network failure and I managed to install the package successfully on the next run. The issue here is that I see a 'The remote server returned an error: (503) Server Unavailable. Service Unavailable' and the package was not installed, but the exit code was 0 so it reported success. This is most likely not relevant to the issue, but I am installing using the ansible win_chocolatey module. Here is the log from the failure.

16:53:30 "Chocolatey v0.10.9", 16:53:30 "Chocolatey is running on Windows v 6.3.9600.0", 16:53:30 "Attempting to delete file \"C:/ProgramData/chocolatey/choco.exe.old\".", 16:53:30 "Attempting to delete file \"C:\ProgramData\chocolatey\choco.exe.old\".", 16:53:30 "Command line: \"C:\ProgramData\chocolatey\choco.exe\" install -dv --no-progress -y dotnetfx --timeout 2700 --failonunfound --whatif --installargs \"--norestart --quiet --version 4.7.2 -my\"", 16:53:30 "Received arguments: install -dv --no-progress -y dotnetfx --timeout 2700 --failonunfound --whatif --installargs --norestart --quiet --version 4.7.2 -my", 16:53:30 "RemovePendingPackagesTask is now ready and waiting for PreRunMessage.", 16:53:30 "Sending message 'PreRunMessage' out if there are subscribers...", 16:53:30 "[Pending] Removing all pending packages that should not be considered installed...", 16:53:30 "The source 'https://chocolatey.org/api/v2/' evaluated to a 'normal' source type", 16:53:30 "", 16:53:30 "NOTE: Hiding sensitive configuration data! Please double and triple ", 16:53:30 " check to be sure no sensitive data is shown, especially if copying ", 16:53:30 " output to a gist for review.", 16:53:30 "Configuration: CommandName='install'|", 16:53:30 "CacheLocation='C:\Users\svc-hudson\AppData\Local\Temp\chocolatey'|", 16:53:30 "ContainsLegacyPackageInstalls='True'|", 16:53:30 "CommandExecutionTimeoutSeconds='2700'|WebRequestTimeoutSeconds='30'|", 16:53:30 "Sources='https://chocolatey.org/api/v2/'|SourceType='normal'|", 16:53:30 "Debug='True'|Verbose='True'|Trace='False'|Force='False'|Noop='True'|", 16:53:30 "HelpRequested='False'|UnsuccessfulParsing='False'|RegularOutput='True'|", 16:53:30 "QuietOutput='False'|PromptForConfirmation='False'|AcceptLicense='True'|", 16:53:30 "AllowUnofficialBuild='False'|Input='dotnetfx --failonunfound'|", 16:53:30 "AllVersions='False'|SkipPackageInstallProvider='False'|", 16:53:30 "PackageNames='dotnetfx'|Prerelease='False'|ForceX86='False'|", 16:53:30 "InstallArguments='--norestart --quiet --version 4.7.2 -my'|", 16:53:30 "OverrideArguments='False'|NotSilent='False'|", 16:53:30 "ApplyPackageParametersToDependencies='False'|", 16:53:30 "ApplyInstallArgumentsToDependencies='False'|IgnoreDependencies='False'|", 16:53:30 "AllowMultipleVersions='False'|AllowDowngrade='False'|", 16:53:30 "ForceDependencies='False'|Information.PlatformType='Windows'|", 16:53:30 "Information.PlatformVersion='6.3.9600.0'|", 16:53:30 "Information.PlatformName='Windows Server 2012 R2'|", 16:53:30 "Information.ChocolateyVersion='0.10.9.0'|", 16:53:30 "Information.ChocolateyProductVersion='0.10.9'|", 16:53:30 "Information.FullName='choco, Version=0.10.9.0, Culture=neutral, PublicKeyToken=79d02ea9cad655eb'|", 16:53:30 "", 16:53:30 "Information.Is64BitOperatingSystem='True'|", 16:53:30 "Information.Is64BitProcess='True'|Information.IsInteractive='False'|", 16:53:30 "Information.UserName='svc-hudson'|", 16:53:30 "Information.UserDomainName='GREENWICH'|", 16:53:30 "Information.IsUserAdministrator='True'|", 16:53:30 "Information.IsUserSystemAccount='False'|", 16:53:30 "Information.IsUserRemoteDesktop='False'|", 16:53:30 "Information.IsUserRemote='True'|", 16:53:30 "Information.IsProcessElevated='True'|", 16:53:30 "Information.IsLicensedVersion='False'|Information.LicenseType='Foss'|", 16:53:30 "Features.AutoUninstaller='True'|Features.ChecksumFiles='True'|", 16:53:30 "Features.AllowEmptyChecksums='False'|", 16:53:30 "Features.AllowEmptyChecksumsSecure='True'|", 16:53:30 "Features.FailOnAutoUninstaller='False'|", 16:53:30 "Features.FailOnStandardError='False'|Features.UsePowerShellHost='True'|", 16:53:30 "Features.LogEnvironmentValues='False'|Features.LogWithoutColor='False'|", 16:53:30 "Features.VirusCheck='False'|", 16:53:30 "Features.FailOnInvalidOrMissingLicense='False'|", 16:53:30 "Features.IgnoreInvalidOptionsSwitches='True'|", 16:53:30 "Features.UsePackageExitCodes='True'|", 16:53:30 "Features.UseFipsCompliantChecksums='False'|", 16:53:30 "Features.ShowNonElevatedWarnings='True'|", 16:53:30 "Features.ShowDownloadProgress='False'|", 16:53:30 "Features.StopOnFirstPackageFailure='False'|", 16:53:30 "Features.UseRememberedArgumentsForUpgrades='False'|", 16:53:30 "Features.IgnoreUnfoundPackagesOnUpgradeOutdated='False'|", 16:53:30 "Features.RemovePackageInformationOnUninstall='False'|", 16:53:30 "Features.ScriptsCheckLastExitCode='False'|", 16:53:30 "ListCommand.LocalOnly='False'|", 16:53:30 "ListCommand.IdOnly='False'|ListCommand.IncludeRegistryPrograms='False'|", 16:53:30 "ListCommand.PageSize='25'|ListCommand.Exact='False'|", 16:53:30 "ListCommand.ByIdOnly='False'|ListCommand.ByTagOnly='False'|", 16:53:30 "ListCommand.IdStartsWith='False'|ListCommand.OrderByPopularity='False'|", 16:53:30 "ListCommand.ApprovedOnly='False'|", 16:53:30 "ListCommand.DownloadCacheAvailable='False'|", 16:53:30 "ListCommand.NotBroken='False'|", 16:53:30 "ListCommand.IncludeVersionOverrides='False'|", 16:53:30 "UpgradeCommand.FailOnUnfound='False'|", 16:53:30 "UpgradeCommand.FailOnNotInstalled='False'|", 16:53:30 "UpgradeCommand.NotifyOnlyAvailableUpgrades='False'|", 16:53:30 "UpgradeCommand.ExcludePrerelease='False'|", 16:53:30 "NewCommand.AutomaticPackage='False'|", 16:53:30 "NewCommand.UseOriginalTemplate='False'|SourceCommand.Command='unknown'|", 16:53:30 "SourceCommand.Priority='0'|SourceCommand.BypassProxy='False'|", 16:53:30 "SourceCommand.AllowSelfService='False'|", 16:53:30 "SourceCommand.VisibleToAdminsOnly='False'|", 16:53:30 "FeatureCommand.Command='unknown'|ConfigCommand.Command='unknown'|", 16:53:30 "PinCommand.Command='unknown'|OutdatedCommand.IgnorePinned='False'|", 16:53:30 "Proxy.BypassOnLocal='True'|", 16:53:30 " Chocolatey:ChocolateyInstallCommand - Noop Mode ", 16:53:30 "Chocolatey would have used NuGet to install packages (if they are not already installed):", 16:53:30 "dotnetfx", 16:53:30 "Attempting to create directory \"C:\Users\svc-hudson\AppData\Local\Temp\chocolatey\Chocolatey\TempInstalls_20180627_165329_3857\".", 16:53:30 "[NuGet] Attempting to resolve dependency 'KB2919355 (≥ 1.0.20160915)'.", 16:53:30 "[NuGet] Attempting to resolve dependency 'KB2919442 (≥ 1.0.20160915)'.", 16:53:30 "dotnetfx not installed. An error occurred during installation:", 16:53:30 " The remote server returned an error: (503) Server Unavailable. Service Unavailable", 16:53:30 "Attempting to delete directory \"C:\Users\svc-hudson\AppData\Local\Temp\chocolatey\Chocolatey\TempInstalls_20180627_165329_3857\".", 16:53:30 "", 16:53:30 "Enjoy using Chocolatey? Explore more amazing features to take your", 16:53:30 "experience to the next level at", 16:53:30 " https://chocolatey.org/compare", 16:53:30 "Sending message 'PostRunMessage' out if there are subscribers...", 16:53:30 "Exiting with 0"

[bcurran3]

@ewilde you're .2 versions behind. Have you tried with the latest release? I don't know if it will make a difference (and I just looked at the release notes), but it's worth a shot.

[thomasvdb]

@Ewynne Can you still reproduce this issue? Can you provide some steps to reproduce?

[Ewynne]

I don't have the ability to reproduce since the problem The remote server returned an error: (503) Server Unavailable. Service Unavailable came from an external resource that the dotnetfx chocolatey package needed. When the server/service came back online the error went away. The problem here is that this turned into a silent failure on chocolatey's part. How did chocolatey exit with a status code 0?

[ferventcoder]

@Ewynne something we'll need to look closer at - unsure what would have caused it to ignore the issue, but it could be that the 503 came from the error from nuget attempting to contact an unavailable repository. Those don't flow all the way up like they should, so I'm going to tag this as a bug.

[shejri]

Happened to me yesterday with two openjdk packages in a packer build, resulting with a successful build.

    amazon-ebs: Chocolatey v0.10.15
    amazon-ebs: Installing the following packages:
    amazon-ebs: openjdk12
    amazon-ebs: By installing you accept licenses for the packages.
    amazon-ebs: openjdk12 not installed. An error occurred during installation:
    amazon-ebs:  The remote server returned an error: (503) Server Unavailable. Service Unavailable
    amazon-ebs: openjdk12 package files install completed. Performing other installation steps.
    amazon-ebs: The install of openjdk12 was NOT successful.
    amazon-ebs: openjdk12 not installed. An error occurred during installation:
    amazon-ebs:  The remote server returned an error: (503) Server Unavailable. Service Unavailable
    amazon-ebs:
    amazon-ebs: Chocolatey installed 0/1 packages. 1 packages failed.
    amazon-ebs:  See the log for details (C:\ProgramData\chocolatey\logs\chocolatey.log).
    amazon-ebs:
    amazon-ebs: Failures
    amazon-ebs:  - openjdk12 (exited 1) - openjdk12 not installed. An error occurred during installation:
    amazon-ebs:  The remote server returned an error: (503) Server Unavailable. Service Unavailable
    amazon-ebs: Chocolatey v0.10.15
    amazon-ebs: Installing the following packages:
    amazon-ebs: nodejs

[jpluimers]

37 (currently titled "Receive messages (like maintenance messages) from servers") might be related.

Please all upvote the first comment there so it gets more traction as the goal is to make the choco client be more informative of ongoing maintenance (and hopefully also about outages).