Skip to content

[Templating] Build hang on AspNetProcess.GetListeningUri #15048

New issue
New issue
Closed
Closed
[Templating] Build hang on AspNetProcess.GetListeningUri#15048
Assignees
javiercn
Labels
DoneThis issue has been fixedarea-mvcIncludes: MVC, Actions and Controllers, Localization, CORS, most templatesbugThis issue describes a behavior which is not expected - a bug.
Milestone
3.1.0-preview2
@javiercn

Description

@javiercn
javiercn
opened on Oct 16, 2019

We've been seeing some build hangs on the CI lately, and it can be traced down to this call stack below.

Seems that what is happening is that we are waiting indefinitely for new messages to show up in the console while we try to find the listen urls for the application. This can be due to two reasons:

  • The underlying application is blocked and doesn't display log messages to the console.
    • We need to capture a dump of the underlying child application at that point.
  • The process infrastructure is failing to capture log messages appropriately and we miss the message that prints the url to the output.

Whatever the underlying cause is (though we should capture a dump for the child process) we should find a better strategy to find out the listening urls for the application.

0000000FB6B7DA80 00007ffe25af5886 (MethodDesc 00007ffe254d5780 + 0x76 System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout(Int32, UInt32, System.Threading.CancellationToken))
0000000FB6B7DB70 00007ffe25af5886 (MethodDesc 00007ffe254d5780 + 0x76 System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout(Int32, UInt32, System.Threading.CancellationToken))
0000000FB6B7DBC0 00007ffe259aec0f (MethodDesc 00007ffe254d5768 + 0x16f System.Threading.SemaphoreSlim.Wait(Int32, System.Threading.CancellationToken))
0000000FB6B7DC10 00007ffe259e69f5 (MethodDesc 00007ffe256ff0a0 + 0x385 System.Collections.Concurrent.BlockingCollection`1[[System.__Canon, System.Private.CoreLib]].TryTakeWithNoTimeValidation(System.__Canon ByRef, Int32, System.Threading.CancellationToken, System.Threading.CancellationTokenSource))
0000000FB6B7DC60 00007ffe259e675d (MethodDesc 00007ffe256ff0a0 + 0xed System.Collections.Concurrent.BlockingCollection`1[[System.__Canon, System.Private.CoreLib]].TryTakeWithNoTimeValidation(System.__Canon ByRef, Int32, System.Threading.CancellationToken, System.Threading.CancellationTokenSource))
0000000FB6B7DC70 00007ffe25cb07bd (MethodDesc 00007ffe250f7560 + 0xad System.Threading.CancellationTokenSource.CreateLinkedTokenSource(System.Threading.CancellationToken, System.Threading.CancellationToken))
0000000FB6B7DCA0 00007ffe259e4e18 (MethodDesc 00007ffe256fef20 + 0x18 System.Collections.Concurrent.BlockingCollection`1[[System.__Canon, System.Private.CoreLib]].get_IsCompleted())
0000000FB6B7DCD0 00007ffe259e6598 (MethodDesc 00007ffe25ad4240 + 0xb8 System.Collections.Concurrent.BlockingCollection`1+<GetConsumingEnumerable>d__68[[System.__Canon, System.Private.CoreLib]].MoveNext())
0000000FB6B7DD20 00007ffe259e62b8 (MethodDesc 00007ffe25126540 + 0xf8 System.Linq.Enumerable+WhereEnumerableIterator`1[[System.__Canon, System.Private.CoreLib]].MoveNext())
0000000FB6B7DD30 00007ffe259e6b53 (MethodDesc 00007ffe254004c8 + 0x13 Templates.Test.Helpers.AspNetProcess+<>c.<GetListeningUri>b__12_1(System.String))
0000000FB6B7DD60 00007ffe25d22b5d (MethodDesc 00007ffe2510b428 + 0x11d System.Linq.Enumerable.TryGetFirst[[System.__Canon, System.Private.CoreLib]](System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Func`2<System.__Canon,Boolean>, Boolean ByRef))
0000000FB6B7DD80 00007ffeb856958d (MethodDesc 00007ffe256ff270 + 0x6d System.Collections.Concurrent.BlockingCollection`1[[System.__Canon, System.Private.CoreLib]].GetConsumingEnumerable(System.Threading.CancellationToken))
0000000FB6B7DDE0 00007ffe25d26000 (MethodDesc 00007ffe250fd8e0 + 0x40 System.Linq.Enumerable.FirstOrDefault[[System.__Canon, System.Private.CoreLib]](System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Func`2<System.__Canon,Boolean>))
0000000FB6B7DE30 00007ffe259dfec8 (MethodDesc 00007ffe253a35e8 + 0x188 Templates.Test.Helpers.AspNetProcess.GetListeningUri(Xunit.Abstractions.ITestOutputHelper))
0000000FB6B7DF10 00007ffe25d23f92 (MethodDesc 00007ffe253a3560 + 0x302 Templates.Test.Helpers.AspNetProcess..ctor(Xunit.Abstractions.ITestOutputHelper, System.String, System.String, System.Collections.Generic.IDictionary`2<System.String,System.String>, Boolean, Boolean))
0000000FB6B7E020 00007ffe259e3722 (MethodDesc 00007ffe253a4070 + 0x192 Templates.Test.Helpers.Project.StartPublishedProjectAsync(Boolean))
0000000FB6B7E0B0 00007ffe259a670f (MethodDesc 00007ffe253aeca0 + 0x15bf Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9.MoveNext())
0000000FB6B7E530 00007ffe259bba1e (MethodDesc 00007ffe25a547d8 + 0x3e System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9, ProjectTemplates.Tests]].ExecutionContextCallback(System.Object))
0000000FB6B7E570 00007ffe257ad1bc (MethodDesc 00007ffe252e0c40 + 0x8c System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0000000FB6B7E5E0 00007ffe259bb8b4 (MethodDesc 00007ffe25a54818 + 0xa4 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9, ProjectTemplates.Tests]].MoveNext(System.Threading.Thread))
0000000FB6B7E630 00007ffe259bb529 (MethodDesc 00007ffe25a54808 + 0x19 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Templates.Test.SpaTemplateTest.SpaTemplateTestBase+<SpaTemplateImplAsync>d__9, ProjectTemplates.Tests]].MoveNext())
0000000FB6B7E660 00007ffe259b40d9 (MethodDesc 00007ffe256a8390 + 0x49 System.Threading.Tasks.AwaitTaskContinuation.RunCallback(System.Threading.ContextCallback, System.Object, System.Threading.Tasks.Task ByRef))
0000000FB6B7E6B0 00007ffe257acb43 (MethodDesc 00007ffe250f6660 + 0x123 System.Threading.Tasks.Task.RunContinuations(System.Object))
0000000FB6B7E700 00007ffe259af791 (MethodDesc 00007ffe250ff020 + 0xa1 System.Text.StringBuilder.ToString())
0000000FB6B7E770 00007ffe259b312f (MethodDesc 00007ffe255fc748 + 0x8f System.Threading.Tasks.Task`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib]].TrySetResult(System.Threading.Tasks.VoidTaskResult))
0000000FB6B7E7B0 00007ffe25cf742a (MethodDesc 00007ffe25406950 + 0x34a Templates.Test.Helpers.AspNetProcess+<AssertStatusCode>d__17.MoveNext())
0000000FB6B7E880 00007ffe257ad1bc (MethodDesc 00007ffe252e0c40 + 0x8c System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0000000FB6B7E8F0 00007ffe25d14ca6 (MethodDesc 00007ffe25ad6ba0 + 0x66 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[Templates.Test.Helpers.AspNetProcess+<AssertStatusCode>d__17, ProjectTemplates.Tests]].MoveNext(System.Threading.Thread))
0000000FB6B7E920 00007ffe257ad428 (MethodDesc 00007ffe2540d360 + 0x18 System.Threading.SynchronizationContext.get_Current())
0000000FB6B7E950 00007ffe259b40d9 (MethodDesc 00007ffe256a8390 + 0x49 System.Threading.Tasks.AwaitTaskContinuation.RunCallback(System.Threading.ContextCallback, System.Object, System.Threading.Tasks.Task ByRef))
0000000FB6B7E9A0 00007ffe257acb43 (MethodDesc 00007ffe250f6660 + 0x123 System.Threading.Tasks.Task.RunContinuations(System.Object))
0000000FB6B7EA60 00007ffe259c1291 (MethodDesc 00007ffe25357de8 + 0x91 System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon))
0000000FB6B7EAB0 00007ffe259d4cf8 (MethodDesc 00007ffe25407148 + 0x58 System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, System.Private.CoreLib]].SetResult(System.__Canon))
0000000FB6B7EAF0 00007ffe259e14d6 (MethodDesc 00007ffe25ad4a10 + 0x3a6 Templates.Test.Helpers.AspNetProcess+<RequestWithRetries>d__11`1[[System.__Canon, System.Private.CoreLib]].MoveNext())
0000000FB6B7EB70 00007ffe257ad1bc (MethodDesc 00007ffe252e0c40 + 0x8c System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0000000FB6B7EBE0 00007ffe25ce8bfc (MethodDesc 00007ffe25ad6450 + 0xac System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.__Canon, System.Private.CoreLib],[Templates.Test.Helpers.AspNetProcess+<RequestWithRetries>d__11`1[[System.__Canon, System.Private.CoreLib]], ProjectTemplates.Tests]].MoveNext(System.Threading.Thread))
0000000FB6B7EC20 00007ffe257ad428 (MethodDesc 00007ffe2540d360 + 0x18 System.Threading.SynchronizationContext.get_Current())
0000000FB6B7EC50 00007ffe259be836 (MethodDesc 00007ffe25612dd0 + 0x56 Xunit.Sdk.MaxConcurrencySyncContext.RunOnSyncContext(System.Threading.SendOrPostCallback, System.Object))
0000000FB6B7ECA0 00007ffe257ad1bc (MethodDesc 00007ffe252e0c40 + 0x8c System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0000000FB6B7ED10 00007ffe25548284 (MethodDesc 00007ffe25612db8 + 0xe4 Xunit.Sdk.MaxConcurrencySyncContext.WorkerThreadProc())
0000000FB6B7ED60 00007ffe2520e852 (MethodDesc 00007ffe254a2ee0 + 0x52 Xunit.Sdk.XunitWorkerThread+<>c.<QueueUserWorkItem>b__5_0(System.Object))
0000000FB6B7EDB0 00007ffe84387bb4 (MethodDesc 00007ffe250f63c8 + 0x34 System.Threading.Tasks.Task.InnerInvoke())
0000000FB6B7EDF0 00007ffe84387b72 (MethodDesc 00007ffe250f8b30 + 0x12 System.Threading.Tasks.Task+<>c.<.cctor>b__274_0(System.Object))
0000000FB6B7EE20 00007ffe84388a36 (MethodDesc 00007ffe252e0c40 + 0x76 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0000000FB6B7EEA0 00007ffe843877e3 (MethodDesc 00007ffe250f63b0 + 0xe3 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread))
0000000FB6B7EF40 00007ffe843876a3 (MethodDesc 00007ffe250f6380 + 0x53 System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread))
0000000FB6B7EF80 00007ffe8439190b (MethodDesc 00007ffe254a6298 + 0x1b System.Threading.Tasks.ThreadPoolTaskScheduler+<>c.<.cctor>b__10_0(System.Object))
0000000FB6B7EFB0 00007ffe8439187d (MethodDesc 00007ffe254a63c8 + 0x3d System.Threading.ThreadHelper.ThreadStart_Context(System.Object))
0000000FB6B7EFE0 00007ffe84388a36 (MethodDesc 00007ffe252e0c40 + 0x76 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))
0000000FB6B7F060 00007ffe8439180c (MethodDesc 00007ffe254a63f8 + 0x3c System.Threading.ThreadHelper.ThreadStart(System.Object))

I was able to retrieve the logs from the captured dump:

dbug: Microsoft.AspNetCore.Hosting.Diagnostics[3]
      Hosting starting
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using 'C:\Users\vsagent\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
dbug: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[37]
      Reading data from file 'C:\Users\vsagent\AppData\Local\ASP.NET\DataProtection-Keys\key-ab7d5c38-0e9e-4050-8a98-7740412d0478.xml'.
dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[18]
      Found key {ab7d5c38-0e9e-4050-8a98-7740412d0478}.
dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.DefaultKeyResolver[13]
      Considering key {ab7d5c38-0e9e-4050-8a98-7740412d0478} with expiration date 2020-01-13 17:28:26Z as default key.
dbug: Microsoft.AspNetCore.DataProtection.TypeForwardingActivator[0]
      Forwarded activator type request from Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor, Microsoft.AspNetCore.DataProtection, Version=3.1.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
dbug: Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor[51]
      Decrypting secret element using Windows DPAPI.
dbug: Microsoft.AspNetCore.DataProtection.TypeForwardingActivator[0]
      Forwarded activator type request from Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Version=3.1.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
dbug: Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.CngCbcAuthenticatedEncryptorFactory[4]
      Opening CNG algorithm 'AES' from provider '(null)' with chaining mode CBC.
dbug: Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.CngCbcAuthenticatedEncryptorFactory[3]
      Opening CNG algorithm 'SHA256' from provider '(null)' with HMAC.
dbug: Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingProvider[2]
      Using key {ab7d5c38-0e9e-4050-8a98-7740412d0478} as the default key.
dbug: Microsoft.AspNetCore.DataProtection.Internal.DataProtectionHostedService[0]
      Key ring with default key {ab7d5c38-0e9e-4050-8a98-7740412d0478} was loaded during application startup.
dbug: Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer[2]
      Failed to locate the development https certificate at '(null)'.
dbug: Microsoft.AspNetCore.Server.Kestrel.Core.KestrelServer[0]
      Using development certificate: CN=localhost (Thumbprint: D3D2779C07D515CFC0BD0EB823961396E49809F0)
Hosting environment: Production
Content root path: F:\workspace\_work\1\s\src\ProjectTemplates\test\bin\Release\netcoreapp3.1\TestTemplates\AspNet.angularnoauth.u1e4za05bip\bin\Release\netcoreapp3.1\publish
dbugNow listening on: http://127.0.0.1:12857
: Microsoft.AspNetCore.Hosting.Diagnostics[4]
      Hosting started
dbugNow listening on: https://127.0.0.1:12858
Application started. Press Ctrl+C to shut down.
: Microsoft.AspNetCore.Hosting.Diagnostics[0]
      Loaded hosting startup assembly AspNet.angularnoauth.u1e4za05bip

Metadata

Metadata

Assignees

Labels

DoneThis issue has been fixedarea-mvcIncludes: MVC, Actions and Controllers, Localization, CORS, most templatesbugThis issue describes a behavior which is not expected - a bug.

Type

No type

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions