Debug `dotnet new` timeouts #32889

dougbu · 2021-05-20T23:42:16Z

hang long enough to grab a dump

This will not help us understand later inability to acquire DotNetNewLock

guessing but this might have something to do w/ the 20 minute default timeout for that acquisition

dougbu · 2021-05-20T23:44:21Z

I don't plan to merge this. Added reviewers partially for awareness and partially because I'll likely need help making heads or tails of whatever dump this captures. Will rerun 'til I hit the failures, perhaps after removing all non-templates non-Helix jobs from the pipeline YAML.

BrennanConroy · 2021-05-20T23:48:17Z

This will not help us understand later inability to acquire DotNetNewLock

Well the reason other tests can't get the lock is because it's global for the process, so when 1 test is hanging on dotnet new, all the other tests are stuck waiting for it to finish.

dougbu · 2021-05-20T23:50:49Z

all the other tests are stuck waiting for it to finish.

You mean one test hangs for 15 minutes and enough tests get backed up waiting that some exceed their 20 minute WaitAsync(...) timeout❔ That seems like a solid explanation.

HaoK · 2021-05-21T00:04:01Z

Why do we need to take a global lock? Can we just change these tests to run sequentially instead? Maybe that would help? I'd imagine those locks were added pre helix days when the templates didn't have an isolated helix machine all to themselves.

dougbu · 2021-05-21T00:08:51Z

@HaoK sequential runs might be fine but we need to figure out the dotnet new timeout first. That part is already serialized by the lock itself.

pranavkm · 2021-05-21T02:09:50Z

Can we just change these tests to run sequentially instead

We used to do that and the tests would take very long to run. @javiercn or @SteveSandersonMS might have more insights about this.

dougbu · 2021-05-21T02:17:08Z

We used to do that and the tests would take very long to run.

Has the math perhaps changed since removing the uninstallation of the default templates❔

dougbu · 2021-05-21T03:11:04Z

/azp run

azure-pipelines · 2021-05-21T03:11:21Z

Azure Pipelines successfully started running 2 pipeline(s).

dougbu · 2021-05-21T05:22:28Z

/azp run

azure-pipelines · 2021-05-21T05:22:46Z

Azure Pipelines successfully started running 2 pipeline(s).

dougbu · 2021-05-21T17:49:55Z

/azp run

azure-pipelines · 2021-05-21T17:50:27Z

Azure Pipelines successfully started running 2 pipeline(s).

dougbu · 2021-05-21T23:02:32Z

/azp run

azure-pipelines · 2021-05-21T23:03:05Z

Azure Pipelines successfully started running 2 pipeline(s).

BrennanConroy · 2021-05-21T23:05:03Z

Heisenbug? 😄

dougbu · 2021-05-21T23:37:39Z

Heisenbug?

I can't tell 😀

dougbu · 2021-05-22T00:46:50Z

/azp run

azure-pipelines · 2021-05-22T00:47:30Z

Azure Pipelines successfully started running 2 pipeline(s).

dougbu · 2021-05-22T20:12:59Z

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-32889-merge-6632ca1f8ec347a89a/ProjectTemplates.Tests--net6.0/dotnet.32172.dmp

May need to lengthen other locks as well. Logs in https://dev.azure.com/dnceng/public/_build/results?buildId=1151130&view=ms.vss-test-web.build-test-results-tab&runId=34807950&resultId=123880&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab make it appear the first failing test timed out after 15 minutes but other tests ran after it, some failing to acquire DotNetNewLock. Also, the "15 minutes" part makes me suspicious my change didn't actually work.

BrennanConroy · 2021-05-25T16:19:16Z

Also, the "15 minutes" part makes me suspicious my change didn't actually work.

Looks like there was another timeout we needed to update
01065ff

dougbu · 2021-05-25T18:05:54Z

Thanks @BrennanConroy. Unfortunately, more Heisenbug behaviour…

BrennanConroy · 2021-05-25T20:52:21Z

/azp run

azure-pipelines · 2021-05-25T20:52:55Z

Azure Pipelines successfully started running 2 pipeline(s).

BrennanConroy · 2021-05-26T18:48:56Z

/azp run

azure-pipelines · 2021-05-26T18:49:33Z

Azure Pipelines successfully started running 2 pipeline(s).

BrennanConroy · 2021-05-26T21:48:43Z

Why is this running quarantined jobs only? Aren't most of the templates tests not quarantined?

dougbu · 2021-05-26T22:11:40Z

Why is this running quarantined jobs only? Aren't most of the templates tests not quarantined?

We saw the timeouts in regular test runs and aspnetcore-quarantined-pr covers the quarantined tests. That said, we don't need another pipeline for this debugging and aspnetcore-quarantined-pr isn't running a focused set of tests.

src/Shared/Process/ProcessEx.cs

HaoK · 2021-06-11T01:53:47Z

Not sure you want to add the blazor templates to this since those will fail a lot due to actual flakiness unrelated to dotnet new, another random datapoint for you, when i was looking at the blazor template with retry runs, occasionally there will be a test run that passes after a little more than 10 minutes, which is an extreme outlier from the normal 1-2 minute runs, that looks like some kind of timeout since its such a round number

dougbu · 2021-06-11T03:58:43Z

Another dotnet publish failure in https://dev.azure.com/dnceng/public/_build/results?buildId=1182397&view=results. The logging is insane; is any of that detail useful❔

Relevant bits may be

Launch host: C:\h\w\B57109AD\p\dotnet-cli\dotnet.exe, app: C:\h\w\B57109AD\p\dotnet-cli\sdk\6.0.100-preview.6.21308.9\dotnet.dll, argc: 5, args: publish,--no-restore,-c,Release,/bl,
--- Begin breadcrumb write
Breadcrumbs will be written using a background thread
Breadcrumb thread write callback...
--- End breadcrumb write 1
Execute managed assembly exit code: 0x1
Waiting for breadcrumb thread to exit...
Done waiting for breadcrumb thread to exit...

and

 | Expected: True
 | Actual:   False
 |    at Xunit.Assert.True(Nullable`1 condition, String userMessage) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\BooleanAsserts.cs:line 95
 |    at Templates.Test.IdentityUIPackageTest.IdentityUIPackage_WorksWithDifferentOptions() in /_/src/ProjectTemplates/test/IdentityUIPackageTest.cs:line 91
 |    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<<InvokeTestMethodAsync>b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 264
 | --- End of stack trace from previous location ---
 |    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 48
 |    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 96

Binary log at https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-pull-32889-merge-6a5d0c1edf6647f58f/ProjectTemplates.Tests--net6.0/AspNet.nniqxrj5imm.binlog may help too.

BrennanConroy · 2021-06-11T17:14:29Z

The logging is insane; is any of that detail useful❔

I turned it on hoping it would be useful, but either it contains nothing for us or I don't know how to find the useful information in it. We should probably turn it off at this point.

dougbu · 2021-06-18T00:31:36Z

/azp run

azure-pipelines · 2021-06-18T00:31:56Z

Pull request contains merge conflicts.

- hang long enough to grab a dump This will _not_ help us understand later inability to acquire `DotNetNewLock` - guessing but this might have something to do w/ the 20 minute default timeout for that acquisition

dougbu · 2021-06-25T02:47:58Z

/azp run

azure-pipelines · 2021-06-25T02:48:26Z

Azure Pipelines successfully started running 1 pipeline(s).

dougbu · 2021-06-25T23:56:45Z

Now that @sebastienros removed $env:COREHOST_TRACE in e03e116, do we need this draft PR❔ I think we had an issue about the timeouts we've been debugging here but can't find it at the moment…

dougbu requested review from pranavkm, javiercn and BrennanConroy May 20, 2021 23:42

ghost added the area-mvc Includes: MVC, Actions and Controllers, Localization, CORS, most templates label May 20, 2021

dougbu mentioned this pull request May 24, 2021

Template tests are run twice azdo + helix #30756

Closed

dougbu commented May 26, 2021

View reviewed changes

src/Shared/Process/ProcessEx.cs Show resolved Hide resolved

dougbu force-pushed the dougbu/template.timeout.debugging branch from e8d9be4 to 0f87949 Compare May 29, 2021 06:17

dougbu force-pushed the dougbu/template.timeout.debugging branch from 0f87949 to db7f554 Compare June 11, 2021 00:20

dougbu force-pushed the dougbu/template.timeout.debugging branch from db7f554 to f36ec2d Compare June 11, 2021 04:04

dougbu and others added 4 commits June 21, 2021 15:35

Debug dotnet new timeouts

2466828

- hang long enough to grab a dump This will _not_ help us understand later inability to acquire `DotNetNewLock` - guessing but this might have something to do w/ the 20 minute default timeout for that acquisition

Only include jobs that run template tests

8f23d5a

Other timeout

62c5a21

!temporary! Disable quarantined-pr pipeline

a29a46c

BrennanConroy force-pushed the dougbu/template.timeout.debugging branch from f36ec2d to a29a46c Compare June 21, 2021 22:37

dougbu mentioned this pull request Jun 25, 2021

Update SDK version #33719

Merged

dougbu closed this Jul 13, 2021

dougbu deleted the dougbu/template.timeout.debugging branch July 13, 2021 17:26

github-actions bot locked and limited conversation to collaborators Dec 8, 2023

Debug dotnet new timeouts #32889

Debug dotnet new timeouts #32889

Conversation

dougbu commented May 20, 2021

dougbu commented May 20, 2021

BrennanConroy commented May 20, 2021

dougbu commented May 20, 2021

HaoK commented May 21, 2021

dougbu commented May 21, 2021

pranavkm commented May 21, 2021

dougbu commented May 21, 2021

dougbu commented May 21, 2021

azure-pipelines bot commented May 21, 2021

dougbu commented May 21, 2021

azure-pipelines bot commented May 21, 2021

dougbu commented May 21, 2021

azure-pipelines bot commented May 21, 2021

dougbu commented May 21, 2021

azure-pipelines bot commented May 21, 2021

BrennanConroy commented May 21, 2021

dougbu commented May 21, 2021

dougbu commented May 22, 2021

azure-pipelines bot commented May 22, 2021

dougbu commented May 22, 2021 • edited Loading

BrennanConroy commented May 25, 2021

dougbu commented May 25, 2021

BrennanConroy commented May 25, 2021

azure-pipelines bot commented May 25, 2021

BrennanConroy commented May 26, 2021

azure-pipelines bot commented May 26, 2021

BrennanConroy commented May 26, 2021

dougbu commented May 26, 2021

HaoK commented Jun 11, 2021

dougbu commented Jun 11, 2021

BrennanConroy commented Jun 11, 2021

dougbu commented Jun 18, 2021

azure-pipelines bot commented Jun 18, 2021

dougbu commented Jun 25, 2021

azure-pipelines bot commented Jun 25, 2021

dougbu commented Jun 25, 2021

Debug `dotnet new` timeouts #32889

Debug `dotnet new` timeouts #32889

dougbu commented May 22, 2021 •

edited

Loading