search

NuGet / Home

Repo for NuGet Client issues
Other
1.5k stars 252 forks source link

NuGet push fails (timeout) with innocuous changes to C# source code #5219

Open lshearer opened 7 years ago

lshearer commented 7 years ago

Our team at Hudl has encountered an odd issue after adding a new feature to one our of .NET Core packages. The result is that although the assembly builds fine, runs correctly, and packages without error, it fails with a timeout when pushing to a NuGet server.

Although we first encountered this issue while pushing to our private Nexus server installation, the behavior is consistent with other NuGet servers, including http://nuget.org, http://myget.org, and a Docker-ized PHP version.

After investigating the push failures, it became apparent that the amount of C# code included in the package seems to be causing the failure (adding embedded resources to the assembly didn't have the same effect). I am able to consistently reproduce the push failures with various code changes that have no effect on the package information/metadata or anything else that would seem to have potential issues related to the NuGet packaging/pushing process. These changes can be found in a somewhat stripped-down version of the repo.

I don't understand why this particular package is experiencing issues. The package is quite small (~50KB) and we have other much larger .NET Core packages using the same publishing pipeline. Yet, it feels as though no matter what changes I've tried to make to the project, we are hitting a sort of threshold that is limiting the amount of compiled instructions we can include. Because the built DLL can be executed successfully (it's a command-line app) for all branches—regardless of whether it can be successfully pushed to NuGet—I've filed this issue here, instead of with the dotnet build tools.

This issue has become a blocker for proper development on this project while we try workarounds like splitting the codebase into separate NuGet packages. Any help in diagnosing and resolving this issue is greatly appreciated.

Details about Problem

NuGet product used (NuGet.exe | VS UI | Package Manager Console | dotnet.exe): dotnet nuget (in combination with dotnet restore, dotnet pack, etc.)

NuGet version (x.x.x.xxx): 4.0.0.0

dotnet.exe --version (if appropriate): 1.0.4

VS version (if appropriate): N/A

OS version (i.e. win10 v1607 (14393.321)): macOS v10.12.4

The behavior is also seen on our AWS build agent:

dotnet --info
.NET Command Line Tools (1.0.1)

Product Information:
  Version:            1.0.1
  Commit SHA-1 hash:  005db40cd1

 Runtime Environment:
  OS Name:     amzn
  OS Version:  2016.03
  OS Platform: Linux
  RID:         rhel.7.2-x64
  Base Path:   /opt/dotnet/sdk/1.0.1

Worked before? If so, with which NuGet version: N/A

Detailed repro steps so we can see the same problem

The behavior can be reproduced using the repro project I published here. I am still working on testing this behavior on Windows, so the repro scripts used might not work there but the equivalent commands are straightforward. There are repro instructions in the README as well, but essentially:

  1. Clone the repo.

  2. From the repo root, start the Docker test NuGet server (requires Bash and Docker): 

    ./start-server.sh

  3. Run the publish script (or equivalent commands) to clean, build, execute, pack, and push the project:

    ./test-publish.sh

  4. Branch names starting with succeeds should push to NuGet without issue. Branch names starting with fails should fail with a timeout like the log below.

Other suggested things

Verbose Logs

Log from nuget push against the repro project

+ dotnet nuget -v Debug push ./build/NugetPushIssueRepro.3.0.0-publishtest13961.nupkg --api-key 1234 --source http://localhost:5000/api/v2/package
trace: NuGet Command Line Version: 4.0.0.0
info : Pushing NugetPushIssueRepro.3.0.0-publishtest13961.nupkg to 'http://localhost:5000/api/v2/package'...
info :   PUT http://localhost:5000/api/v2/package/
info : An error was encountered when fetching 'PUT http://localhost:5000/api/v2/package/'. The request will now be retried.
info : An error occurred while sending the request.
info :   Server returned nothing (no headers, no data)
info :   PUT http://localhost:5000/api/v2/package/
info : An error was encountered when fetching 'PUT http://localhost:5000/api/v2/package/'. The request will now be retried.
info : An error occurred while sending the request.
info :   Server returned nothing (no headers, no data)
info :   PUT http://localhost:5000/api/v2/package/
error: An error occurred while sending the request.
error:   Server returned nothing (no headers, no data)
trace: System.AggregateException: One or more errors occurred. (An error occurred while sending the request.) ---> System.Net.Http.HttpRequestException: An error occurred while sending the reques
t. ---> System.Net.Http.CurlException: Server returned nothing (no headers, no data)
trace:    at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
trace:    at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)
trace:    --- End of inner exception stack trace ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpSourceAuthenticationHandler.<SendAsync>d__9.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
trace:    at System.Net.Http.HttpClient.<FinishSendAsync>d__58.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
trace:    at NuGet.Protocol.TimeoutUtility.<StartWithTimeout>d__0`1.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpRetryHandler.<SendAsync>d__0.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpSource.<GetThrottledResponse>d__16.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpSource.<ProcessResponseAsync>d__14`1.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<PushPackageToServer>d__19.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<PushPackageCore>d__13.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<PushPackage>d__12.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<Push>d__8.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Commands.PushRunner.<Run>d__0.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.CommandLine.XPlat.PushCommand.<>c__DisplayClass0_0.<<Register>b__1>d.MoveNext()
trace:    --- End of inner exception stack trace ---
trace:    at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
trace:    at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
trace:    at Microsoft.Extensions.CommandLineUtils.CommandLineApplication.<>c__DisplayClass79_0.<OnExecute>b__0()
trace:    at Microsoft.Extensions.CommandLineUtils.CommandLineApplication.Execute(String[] args)
trace:    at NuGet.CommandLine.XPlat.Program.MainInternal(String[] args, CommandOutputLogger log)
trace: ---> (Inner Exception #0) System.Net.Http.HttpRequestException: An error occurred while sending the request. ---> System.Net.Http.CurlException: Server returned nothing (no headers, no dat
a)
trace:    at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
trace:    at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)
trace:    --- End of inner exception stack trace ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpSourceAuthenticationHandler.<SendAsync>d__9.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
trace:    at System.Net.Http.HttpClient.<FinishSendAsync>d__58.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
trace:    at NuGet.Protocol.TimeoutUtility.<StartWithTimeout>d__0`1.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpRetryHandler.<SendAsync>d__0.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpSource.<GetThrottledResponse>d__16.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.HttpSource.<ProcessResponseAsync>d__14`1.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<PushPackageToServer>d__19.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<PushPackageCore>d__13.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<PushPackage>d__12.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Protocol.Core.Types.PackageUpdateResource.<Push>d__8.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.Commands.PushRunner.<Run>d__0.MoveNext()
trace: --- End of stack trace from previous location where exception was thrown ---
trace:    at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
trace:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
trace:    at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
trace:    at NuGet.CommandLine.XPlat.PushCommand.<>c__DisplayClass0_0.<<Register>b__1>d.MoveNext()<---

Sample Project

https://github.com/lshearer/NuGetPushFailRepro

rexlam0630 commented 7 years ago

Same problem!

It persists on my Mac

dotnet version: 1.0.1 NuGet Command Line: 4.0.0.0

also dotnet docker images

1.1-sdk 2.0-sdk

Tried following nuget provider/server

NuGet.org MyGet.org NuGet.Server ProGet server

rexlam0630 commented 7 years ago

Further details -

Environment: macOS 10.12.4 dotnet SDK 1.0.1 mono 5.0.0.100 (2017-02/9667aa6 Fri May 5 09:12:57 EDT 2017)

Attached is Wireshark package capture mono-nuget-41.pcapng - Successfully push using mono + nuget.exe 4.1.0.2450 dotnet-nuget-4.0.pcapng - Unsuccessful push using dotnet nuget CLI 4.0.0.0

WS.zip

rexlam0630 commented 7 years ago

I'm not sure, but feels like related to this issue: https://github.com/NuGet/Home/issues/3251

codeimpossible commented 7 years ago

tl;dr - just uncompress and recompress your packages (or manually create them in the first place) if you are on a *nix system until this issue is figured out

Update from some more testing that @lshearer and I did today:

It looks like the pack command is not producing a proper zip file on OSX and some linux distros (amazon linux being the other environment we've seen this on). We ran the repro example in both Windows and Windows linux-subsystem (ubuntu 14.04) and the publish succeeded in both scenarios.

After this, we copies the nupkg from the OSX system and tried to publish it. It failed with the same timeout issue above. 💡 So we unzipped it and re-zipped it and then tried to publish it. It succeeded 🎉.

We're not sure why pack is not creating a "good" nupkg file in these cases but we've identified a decent enough workaround for the issue: just uncompress and recompress your packages (or manually create them in the first place) if you are on a *nix system until this issue is figured out.

Here is the nupkg that fails to upload

Here is the re-zipped version of the same nupkg that succeeds

lshearer commented 7 years ago

I've dockerized the repro and workaround and added the output from the workaround test runs.

Note that the workaround—extracting the package contents and then re-archiving them—does not work using the default zip/unzip utilities. I had to use 7-Zip (via the p7zip port) for the push to succeed.

lshearer commented 7 years ago

As it turns out, the recompressing workaround only worked for some packages. The root cause appears to be deeper in the Mac/Linux implementations (or underlying native libraries) of some .NET Core libraries, particularly around sending of the HTTP PUT request. We didn't pinpoint the exact problem, but subtle variations in the package contents appear to result in the request not completing (the tool used to compress and/or level of compression was one example of the differences).

For a more stable workaround, we've abandoned using dotnet nuget push and have opted for using a Node.js approach using a script based on this npm package. So far, this has proven to push the otherwise problematic package versions to the NuGet API without issue.