Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tracking Nuget 429s #10885

Closed
2 tasks
ulisesh opened this issue Sep 15, 2022 · 13 comments
Closed
2 tasks

Tracking Nuget 429s #10885

ulisesh opened this issue Sep 15, 2022 · 13 comments
Assignees

Comments

@ulisesh
Copy link
Contributor

ulisesh commented Sep 15, 2022

Build

https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=12817

Build leg reported

Microsoft.NET.Build.Tests.dll.1.WorkItemExecution

Pull Request

dotnet/sdk#27821

Action required for the engineering services team

To triage this issue (First Responder / @dotnet/dnceng):

  • Open the failing build above and investigate
  • Add a comment explaining your findings

If this is an issue that is causing build breaks across multiple builds and would get benefit from being listed on the build analysis check, follow the next steps:

  1. Add the label "Known Build Error"
  2. Edit this issue and add an error string in the Json below that can help us match this issue with future build breaks. You should use the known issues documentation
{
   "ErrorMessage" : "Response status code does not indicate success: 429",
   "BuildRetry": false
}

Tracking Nuget 429s

Additional information about the issue reported

No response

Report

Build Definition Step Name Console log Pull Request
75273 dotnet/aspnetcore Build shared fx Log dotnet/aspnetcore#44921
72731 dotnet/sdk Run Tests in Helix and non Helix in parallel Log dotnet/sdk#28895
72662 dotnet/sdk Run Tests in Helix Log dotnet/sdk#28888
72722 dotnet/runtime Build managed product components and packages Log dotnet/runtime#77872
72716 dotnet/runtime Build managed product components and packages Log dotnet/runtime#77871
72683 dotnet/runtime Build native test components Log dotnet/runtime#77867
72703 dotnet/runtime Build native test components Log
72697 dotnet/runtime Build native test components Log
72754 dotnet/runtime Build product Log dotnet/runtime#77811
72674 dotnet/aspnetcore Build Log dotnet/aspnetcore#44868
72324 dotnet/runtime Build CoreHost Log dotnet/runtime#62863
72757 dotnet/runtime Build product Log dotnet/runtime#77811
72712 dotnet/runtime Build managed product components and packages Log
72756 dotnet/runtime Build product Log dotnet/runtime#77811
72755 dotnet/runtime Build product Log dotnet/runtime#77811
72661 dotnet/sdk Run Tests in Helix Log dotnet/sdk#28889
72743 dotnet/runtime Build product Log dotnet/runtime#74886
72744 dotnet/runtime Build product Log dotnet/runtime#74886
72745 dotnet/runtime Build product Log dotnet/runtime#74886
72655 dotnet/aspnetcore Build Log dotnet/aspnetcore#44768
72746 dotnet/runtime Build product Log dotnet/runtime#74886
72666 dotnet/sdk Run Tests in Helix Log
72738 dotnet/aspnetcore Build Log
72694 dotnet/sdk Run Tests in Helix Log dotnet/sdk#28892
72643 dotnet/runtime Restore and Build Product Log dotnet/runtime#76740
72724 dotnet/runtime Build product Log dotnet/runtime#77872
72723 dotnet/runtime Build product Log dotnet/runtime#77872
72718 dotnet/runtime Build product Log dotnet/runtime#77871
72717 dotnet/runtime Build product Log dotnet/runtime#77871
72713 dotnet/sdk Run Tests in Helix Log dotnet/sdk#28894
72682 dotnet/installer Build Log
72714 dotnet/runtime Build product Log
72681 dotnet/installer Build Log
72709 dotnet/sdk Build Log dotnet/sdk#28893
72698 dotnet/runtime Restore and Build Product Log dotnet/runtime#77187
72686 dotnet/runtime Build product Log dotnet/runtime#77867
72657 dotnet/sdk Run Tests in Helix Log dotnet/sdk#28811
72631 dotnet/runtime Build managed product components and packages Log dotnet/runtime#75824
72700 dotnet/runtime Build product Log dotnet/runtime#77187
72699 dotnet/runtime Build product Log dotnet/runtime#77187
72702 dotnet/installer Build Log dotnet/installer#14890
72479 dotnet/runtime Build CoreHost Log dotnet/runtime#77858
72498 dotnet/runtime Prepare TestHost with runtime CoreCLR Log dotnet/runtime#77859
72557 dotnet/runtime Prepare TestHost with runtime CoreCLR Log
72672 dotnet/aspnetcore Run build.sh Log dotnet/aspnetcore#44868
72527 dotnet/sdk Build Log dotnet/sdk#28883
72627 dotnet/runtime Build Tests Log
72635 dotnet/sdk Install wasm-tools Workload Log dotnet/sdk#28887
72609 dotnet/runtime Build managed product components and packages Log dotnet/runtime#77465
72637 dotnet/runtime Restore and Build Product Log dotnet/runtime#76740
72640 dotnet/runtime Build product Log dotnet/runtime#76740
72382 dotnet/installer Build Log dotnet/installer#14679
72649 dotnet/runtime Build managed product components and packages Log
72638 dotnet/runtime Build product Log dotnet/runtime#76740
72639 dotnet/runtime Build product Log dotnet/runtime#76740
72593 dotnet/runtime Build managed product components and packages Log dotnet/runtime#77708
72605 dotnet/runtime Build managed product components and packages Log dotnet/runtime#77509
72558 dotnet/runtime Build native test components Log dotnet/runtime#77506
72367 dotnet/installer Build Log dotnet/installer#14890
72632 dotnet/runtime Build product Log dotnet/runtime#75824
72633 dotnet/runtime Build product Log dotnet/runtime#75824
72653 dotnet/aspnetcore Run build.sh Log dotnet/aspnetcore#44768
72587 dotnet/sdk Install wasm-tools Workload Log dotnet/sdk#28886
72652 dotnet/sdk Build Log dotnet/sdk#28885
72610 dotnet/runtime Build product Log dotnet/runtime#77465
72611 dotnet/runtime Build product Log dotnet/runtime#77465
72608 dotnet/runtime Build product Log dotnet/runtime#77509
72596 dotnet/runtime Build product Log dotnet/runtime#77708
72595 dotnet/runtime Build product Log dotnet/runtime#77708
72648 dotnet/runtime Restore and Build Product Log dotnet/runtime#77760
72568 dotnet/installer Build Log
72416 dotnet/runtime Build and Package Log dotnet/runtime#77770
72375 dotnet/runtime Send tests to Helix (Unix) Log dotnet/runtime#77683
72561 dotnet/runtime Build product Log dotnet/runtime#77506
72520 dotnet/sdk Install wasm-tools Workload Log dotnet/sdk#28882
72247 dotnet/installer Build Log
72383 dotnet/runtime Copy native test components to test output folder Log
72517 dotnet/installer Build Log dotnet/installer#14889
72483 dotnet/runtime Build managed product components and packages Log dotnet/runtime#77856
72224 dotnet/installer Build Log
72372 dotnet/runtime Send to Helix Log dotnet/runtime#77283
72508 dotnet/sdk Run Tests in Helix Log dotnet/sdk#28860
72487 dotnet/runtime Build product Log dotnet/runtime#77856
72486 dotnet/runtime Build product Log dotnet/runtime#77856
72480 dotnet/runtime Build product Log dotnet/runtime#77858
72463 dotnet/runtime Build native test components Log
72478 dotnet/runtime Build product Log dotnet/runtime#77811
72471 dotnet/runtime Restore and Build Product Log dotnet/runtime#77852
72514 dotnet/sdk Run Tests in Helix and non Helix in parallel Log
72346 dotnet/runtime Send tests to Helix (Unix) Log
72445 dotnet/runtime Build managed product components and packages Log dotnet/runtime#77857
72331 dotnet/runtime Build and Package Log dotnet/runtime#77353
72530 dotnet/aspnetcore Run build.sh Log
72398 dotnet/runtime Build native test components Log dotnet/runtime#77688
72457 dotnet/runtime Build product Log dotnet/runtime#77770
72369 dotnet/runtime Prepare TestHost with runtime Mono Log dotnet/runtime#77283
72489 dotnet/runtime Build product Log
72476 dotnet/runtime Build product Log dotnet/runtime#77811
72477 dotnet/runtime Build product Log dotnet/runtime#77811
72467 dotnet/aspnetcore Run build.sh Log dotnet/aspnetcore#44653
Displaying 100 of 258 results
Build Definition Test Pull Request
72421 dotnet/sdk Microsoft.DotNet.Cli.New.IntegrationTests.DotnetNewInstallTests.DoNotShowDeprecationMessage_WhenNewCommandIsUsed
65256 dotnet/sdk Microsoft.NET.Restore.Tests.dll.WorkItemExecution dotnet/sdk#28795
65277 dotnet/sdk dotnet.Tests.dll.6.WorkItemExecution dotnet/sdk#28714
65238 dotnet/sdk Microsoft.NET.Build.Tests.dll.4.WorkItemExecution dotnet/sdk#28794
64648 dotnet/installer Microsoft.NET.Publish.Tests.GivenThatWeWantToPublishAFrameworkDependentApp.It_errors_when_using_app_host_with_older_target_framework dotnet/installer#14679
64462 dotnet/sdk Microsoft.DotNet.Cli.New.IntegrationTests.DotnetNewInstallTests.DoNotShowDeprecationMessage_WhenNewCommandIsUsed dotnet/sdk#28784
64335 dotnet/sdk Microsoft.DotNet.Cli.New.IntegrationTests.DotnetNewInstallTests.DoNotShowDeprecationMessage_WhenNewCommandIsUsed dotnet/sdk#28783
64084 dotnet/sdk dotnet.Tests.dll.8.WorkItemExecution dotnet/sdk#28778
63777 dotnet/sdk Microsoft.NET.Sdk.BlazorWebAssembly.Tests.dll.3.WorkItemExecution dotnet/sdk#28774
63761 dotnet/sdk Microsoft.NET.Build.Tests.dll.2.WorkItemExecution dotnet/sdk#28773
64031 dotnet/sdk Microsoft.NET.Publish.Tests.dll.3.WorkItemExecution dotnet/sdk#28690
63759 dotnet/sdk Microsoft.NET.Restore.Tests.dll.WorkItemExecution dotnet/sdk#28771
63795 dotnet/sdk Microsoft.NET.Build.Tests.dll.11.WorkItemExecution dotnet/sdk#28775
63760 dotnet/sdk Microsoft.NET.Build.Tests.dll.1.WorkItemExecution dotnet/sdk#28772
63638 dotnet/sdk Microsoft.NET.Publish.Tests.dll.1.WorkItemExecution dotnet/sdk#28749
63228 dotnet/sdk dotnet.Tests.dll.7.WorkItemExecution dotnet/sdk#28717
63178 dotnet/sdk Microsoft.NET.Pack.Tests.dll.WorkItemExecution dotnet/sdk#28768
62938 dotnet/sdk Microsoft.NET.Build.Tests.dll.7.WorkItemExecution dotnet/sdk#28749
62888 dotnet/sdk Microsoft.DotNet.Cli.Test.Tests.GivenDotnetTestBuildsAndRunsTestFromCsproj.ItBuildsAndTestsAppWhenRestoringToSpecificDirectory dotnet/sdk#28765
62924 dotnet/sdk Microsoft.NET.Build.Tests.dll.4.WorkItemExecution dotnet/sdk#28766
62631 dotnet/sdk dotnet.Tests.dll.9.WorkItemExecution dotnet/sdk#28760
62601 dotnet/sdk Microsoft.NET.Build.Tests.dll.4.WorkItemExecution
61301 dotnet/sdk Microsoft.NET.Build.Tests.dll.10.WorkItemExecution dotnet/sdk#28738
62115 dotnet/sdk Microsoft.NET.Restore.Tests.dll.WorkItemExecution dotnet/sdk#28738
62190 dotnet/sdk Microsoft.NET.Publish.Tests.dll.1.WorkItemExecution
62111 dotnet/sdk dotnet.Tests.dll.8.WorkItemExecution
59376 dotnet/sdk dotnet.Tests.dll.6.WorkItemExecution dotnet/sdk#28707
61375 dotnet/sdk Microsoft.NET.Build.Tests.dll.1.WorkItemExecution dotnet/sdk#28737
61167 dotnet/sdk dotnet.Tests.dll.7.WorkItemExecution dotnet/sdk#28737
60964 dotnet/sdk dotnet.Tests.dll.3.WorkItemExecution dotnet/sdk#28730
61065 dotnet/sdk Microsoft.NET.Build.Tests.dll.2.WorkItemExecution
60986 dotnet/sdk Microsoft.NET.ToolPack.Tests.dll.2.WorkItemExecution dotnet/sdk#28732
60973 dotnet/sdk Microsoft.NET.Sdk.Razor.Tests.dll.2.WorkItemExecution dotnet/sdk#28727
60968 dotnet/sdk dotnet.Tests.dll.8.WorkItemExecution dotnet/sdk#28731
60057 dotnet/sdk Microsoft.NET.Build.Tests.dll.7.WorkItemExecution dotnet/sdk#28722
60054 dotnet/sdk Microsoft.NET.Pack.Tests.dll.WorkItemExecution dotnet/sdk#28721
60044 dotnet/sdk Microsoft.NET.Publish.Tests.dll.1.WorkItemExecution dotnet/sdk#28700
59721 dotnet/sdk Microsoft.NET.Restore.Tests.dll.WorkItemExecution dotnet/sdk#28716
59628 dotnet/sdk Microsoft.NET.Build.Tests.dll.19.WorkItemExecution dotnet/sdk#28705
59270 dotnet/sdk dotnet.Tests.dll.2.WorkItemExecution dotnet/sdk#28703
59235 dotnet/sdk Microsoft.NET.ToolPack.Tests.dll.1.WorkItemExecution dotnet/sdk#28700
59255 dotnet/sdk Microsoft.NET.Sdk.Razor.Tests.dll.3.WorkItemExecution dotnet/sdk#28702
59299 dotnet/sdk Microsoft.NET.Sdk.Razor.Tests.dll.5.WorkItemExecution dotnet/sdk#28707
58387 dotnet/sdk Microsoft.NET.Publish.Tests.dll.6.WorkItemExecution dotnet/sdk#28677
58185 dotnet/sdk Microsoft.NET.Build.Tests.dll.10.WorkItemExecution dotnet/sdk#28677
58186 dotnet/sdk dotnet.Tests.dll.3.WorkItemExecution dotnet/sdk#28680
58173 dotnet/sdk dotnet.Tests.dll.6.WorkItemExecution dotnet/sdk#28679
58163 dotnet/sdk dotnet.Tests.dll.8.WorkItemExecution dotnet/sdk#28678
57850 dotnet/sdk Microsoft.NET.Build.Tests.dll.9.WorkItemExecution dotnet/sdk#28520
57731 dotnet/sdk Microsoft.NET.Build.Tests.dll.11.WorkItemExecution dotnet/sdk#28584
56828 dotnet/sdk Microsoft.NET.Publish.Tests.dll.4.WorkItemExecution dotnet/sdk#28651
52803 dotnet/sdk Microsoft.NET.Publish.Tests.dll.1.WorkItemExecution dotnet/sdk#28591
56800 dotnet/sdk Microsoft.NET.Publish.Tests.dll.1.WorkItemExecution
56804 dotnet/sdk Microsoft.NET.Build.Tests.dll.7.WorkItemExecution
56143 dotnet/sdk dotnet.Tests.dll.8.WorkItemExecution
55937 dotnet/sdk Microsoft.NET.Restore.Tests.dll.WorkItemExecution dotnet/sdk#28260
54898 dotnet/sdk Microsoft.NET.Publish.Tests.dll.4.WorkItemExecution dotnet/sdk#28553
54686 dotnet/sdk Microsoft.NET.Publish.Tests.dll.1.WorkItemExecution dotnet/sdk#28620
54622 dotnet/sdk Microsoft.NET.Build.Tests.dll.7.WorkItemExecution dotnet/sdk#28618

Summary

24-Hour Hit Count 7-Day Hit Count 1-Month Count
0 0 317
@ulisesh
Copy link
Contributor Author

ulisesh commented Oct 24, 2022

Issue on Nuget side NuGet/Home#10558

@MattGal
Copy link
Member

MattGal commented Oct 27, 2022

Created https://portal.microsofticm.com/imp/v3/incidents/details/344927997/home to ask for concurrency limit increases

@MattGal
Copy link
Member

MattGal commented Oct 27, 2022

IcM got us 2x concurrency bump, and no new instances since 12:25 PDT thus far. Will keep an eye on it.

@MattGal
Copy link
Member

MattGal commented Nov 4, 2022

@dougbu noted this hit again yesterday here: https://dev.azure.com/dnceng-public/public/_build/results?buildId=72672&view=logs&jobId=b72e85ab-3386-5aa9-6405-3837662d9688&j=8e9e2812-09db-5a5d-c249-d96adf9f47fa&t=51e8c4b1-e760-5f88-6965-6fecd74b90ed&s=6884a131-87da-5381-61f3-d7acc3b91d76

What we're doing:

  • I am pursuing increasing the limit before 429 again this morning with the packaging team
  • Partner teams are experimenting with trying to remove unused feeds
  • @zivkan is working with us to find viable ways to reduce total usage with new Nuget features while also exploring "retry when you 429" functionality in the client.

@dougbu
Copy link
Member

dougbu commented Nov 4, 2022

/fyi @dotnet/aspnet-build

@zivkan
Copy link
Member

zivkan commented Nov 4, 2022

I just created this PR to actually retry on HTTP 429 responses. But it doesn't (yet) honor the Retry-After header, so I'm not sure if it'll actually make things worse 🤷

Anyway, if anyone would like to provide feedback: NuGet/NuGet.Client#4897

@zivkan
Copy link
Member

zivkan commented Nov 8, 2022

I had another thought. From reading the docs on nuget.config's maxHttpRequestsPerSource setting, it would appear that dotnet restore will not throttle requests to a source at all, given that HttpClient in netcoreapp runtimes don't throttle connections, unlike the .NET Framework runtime. Whatever the maximum number of packages NuGet needs to check in the restore graph in parallel, it will theoretically send out the same number of requests per source.

Therefore, if dotnet/* repos set maxHttpRequestsPerSource in their nuget.config, this may mitigate the amount of traffic individual CI builds send. If tests are run from a subdirectory under the repo root, then the nuget.config will apply to the tests as well, but if tests run elsewhere (like %temp%), then additional effort needs to be made to have the tests also throttle requests (keeping in mind it will be per process, just in case tests shell out to dotnet restore or dotnet build in parallel).

@mmitche
Copy link
Member

mmitche commented Nov 9, 2022

I had another thought. From reading the docs on nuget.config's maxHttpRequestsPerSource setting, it would appear that dotnet restore will not throttle requests to a source at all, given that HttpClient in netcoreapp runtimes don't throttle connections, unlike the .NET Framework runtime. Whatever the maximum number of packages NuGet needs to check in the restore graph in parallel, it will theoretically send out the same number of requests per source.

Therefore, if dotnet/* repos set maxHttpRequestsPerSource in their nuget.config, this may mitigate the amount of traffic individual CI builds send. If tests are run from a subdirectory under the repo root, then the nuget.config will apply to the tests as well, but if tests run elsewhere (like %temp%), then additional effort needs to be made to have the tests also throttle requests (keeping in mind it will be per process, just in case tests shell out to dotnet restore or dotnet build in parallel).

@zivkan This would be an interesting experiment to run. Is there telemetry that could be enabled that would help illuminate the quantity of traffic from NuGet operations?

@zivkan
Copy link
Member

zivkan commented Nov 9, 2022

System.Net.Http (including HttpClient) uses EventSource, and in the future (but not yet, unfortunately) NuGet will as well. So on Windows anything that can record ETW events, like PerfView, can collect the information. Docs say that on .NET Core EventSource uses EventPipe, which supports LTTng, as well as tools like dotnet-counters and dotnet-trace, but I have zero experience with these.

But NuGet doesn't have any relevant telemetry (we only have telemetry in VS, nothing on command line. Even in VS, we need to limit telemetry quantity, so logging every HTTP request is out of the question, only aggregated telemetry is feasible).

@mmitche
Copy link
Member

mmitche commented Nov 9, 2022

I think you'd just be interested in raw totals:

  • Number of gets
  • Number of 404s
  • Number of cache hits (per cache maybe?)
  • Number of downloads

@mmitche
Copy link
Member

mmitche commented Nov 9, 2022

And perhaps total time spent in NuGet related tasks during restore? That would give you a good set of base statistics to determine whether improvements were being made without regressing perf.

@zivkan
Copy link
Member

zivkan commented Nov 9, 2022

With a binlog, or text restore log at normal verbosity, we could calculate the number of gets and 404's with a grep of GET http:// and NotFound http://.

However, I wouldn't expect that maxHttpRequestsPerSource (throttling) would have much of an impact on the total number of requests. It's more about how quickly a single process will hammer a server.

If restore is run as a separate step in CI, then CI logs should tell us how long the restore was. Otherwise, if CI logs the timestamp (to sufficient accuracy) for each line, we could look at the time difference between the "Determining projects to restore" message and the last "Restored c:\path\to\my.csproj" message.

We can (and I have in the past) written a program to use AzDO's REST APIs to download build info, even build logs or build artifacts. But as previously mentioned, we don't have any command line telemetry. So, not super easy to query/do the analysis, certainly nothing "at scale" (across multiple repos/build pipelines).

@ilyas1974
Copy link
Contributor

As it has been a week since we have seen this issue, we believe we have addressed this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants