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

Add logging to resolve to indicate resolve is complete #1978

Merged
merged 2 commits into from
Dec 8, 2022

Conversation

JamesNK
Copy link
Member

@JamesNK JamesNK commented Dec 7, 2022

Indicate in logs that the resolve is complete.

Response to flaky test where it appears resolve isn't being triggered because it is still in progress. Extra logging to make it more obvious what is going on. Waiting on resolve task should hopefully deflake.

A total of 1 test files matched the specified pattern.
  Failed HasSubchannels_SubchannelStatusChanges_RefreshResolver [5 s]
  Error Message:
   System.TimeoutException : The operation at /home/runner/work/grpc-dotnet/grpc-dotnet/test/Grpc.Net.Client.Tests/Balancer/RoundRobinBalancerTests.cs:286 timed out after reaching the limit of 5000ms.
  Stack Trace:
     at Grpc.Tests.Shared.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in /home/runner/work/grpc-dotnet/grpc-dotnet/test/Shared/TaskExtensions.cs:line 98
   at Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests.HasSubchannels_SubchannelStatusChanges_RefreshResolver() in /home/runner/work/grpc-dotnet/grpc-dotnet/test/Grpc.Net.Client.Tests/Balancer/RoundRobinBalancerTests.cs:line 286
   at NUnit.Framework.Internal.TaskAwaitAdapter.GenericAdapter`1.BlockUntilCompleted()
   at NUnit.Framework.Internal.MessagePumpStrategy.NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
   at NUnit.Framework.Internal.AsyncToSyncAdapter.Await(Func`1 invoke)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.RunTestMethod(TestExecutionContext context)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.Execute(TestExecutionContext context)
   at NUnit.Framework.Internal.Execution.SimpleWorkItem.<>c__DisplayClass4_0.<PerformWork>b__0()
   at NUnit.Framework.Internal.ContextUtils.<>c__DisplayClass1_0`1.<DoIsolated>b__0(Object _)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at NUnit.Framework.Internal.ContextUtils.DoIsolated(ContextCallback callback, Object state)
   at NUnit.Framework.Internal.ContextUtils.DoIsolated[T](Func`1 func)
   at NUnit.Framework.Internal.Execution.SimpleWorkItem.PerformWork()
  Standard Output Messages:
 0.001s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Client connecting
 0.001s Grpc.Net.Client.Balancer.PollingResolver - Trace: TestResolver refresh requested.
 0.001s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Resolver waiting to continue.
 0.002s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Client waiting for connect to complete.
 0.002s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Resolver creating new sync point.
 0.002s Grpc.Net.Client.Balancer.PollingResolver - Trace: TestResolver result with status code 'OK' and 1 addresses.
 0.002s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1' created with addresses: localhost:80
 0.002s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' state changed registration '1-1' created.
 0.002s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' connection requested.
 0.002s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
 0.002s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' executing state changed registration '1-1'.
 0.002s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Processing subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
 0.002s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
 0.002s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
 0.002s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' connecting to transport.
 0.002s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Transport factory returning state: Ready
 0.003s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1' state changed to Ready. Detail: ''.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' executing state changed registration '1-1'.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Processing subchannel id '1' state changed to Ready. Detail: ''.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Creating ready picker with 1 subchannels: id '1' (localhost:80)
 0.003s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Ready.
 0.003s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Creating ready picker with 1 subchannels: id '1' (localhost:80)
 0.003s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
 0.003s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Transport factory updating state.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1' state changed to Idle. Detail: ''.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' executing state changed registration '1-1'.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Processing subchannel id '1' state changed to Idle. Detail: ''.
 0.003s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
 0.003s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Refreshing resolver because subchannel id '1' is in state Idle.
 0.003s Grpc.Net.Client.Balancer.PollingResolver - Trace: TestResolver refresh requested.
 0.003s Grpc.Net.Client.Balancer.PollingResolver - Trace: TestResolver refresh ignored because resolve is already in progress.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Requesting connection for subchannel id '1' because it is in state Idle.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' connection requested.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' executing state changed registration '1-1'.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Processing subchannel id '1' state changed to Connecting. Detail: 'Connection requested.'.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' connecting to transport.
 0.003s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Transport factory returning state: TransientFailure
 0.003s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1' state changed to TransientFailure. Detail: ''.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' executing state changed registration '1-1'.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Processing subchannel id '1' state changed to TransientFailure. Detail: ''.
 0.003s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to TransientFailure.
 0.003s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
 0.003s Grpc.Net.Client.Balancer.RoundRobinBalancer - Trace: Refreshing resolver because subchannel id '1' is in state TransientFailure.
 0.003s Grpc.Net.Client.Balancer.PollingResolver - Trace: TestResolver refresh requested.
 0.003s Grpc.Net.Client.Balancer.PollingResolver - Trace: TestResolver refresh ignored because resolve is already in progress.
 0.003s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' starting connect backoff of 00:00:00.8878404.
 0.003s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Waiting for sync point in resolver.
 0.891s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Transport factory returning state: TransientFailure
 0.891s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' starting connect backoff of 00:00:01.4079371.
 2.298s Grpc.Net.Client.Tests.Balancer.RoundRobinBalancerTests - Information: Transport factory returning state: TransientFailure
 2.298s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1' starting connect backoff of 00:00:02.7879581.



Failed!  - Failed:     1, Passed:   417, Skipped:     0, Total:   418, Duration: 12 s - Grpc.Net.Client.Tests.dll (net7.0)
     1>Project "/home/runner/work/grpc-dotnet/grpc-dotnet/test/Grpc.Net.Client.Tests/Grpc.Net.Client.Tests.csproj" on node 1 (VSTest target(s)).
     1>DispatchToInnerBuildsWithVSTestTarget:
         Build continuing because "ContinueOnError" on the task "MSBuild" is set to "ErrorAndContinue".
     1>Done Building Project "/home/runner/work/grpc-dotnet/grpc-dotnet/test/Grpc.Net.Client.Tests/Grpc.Net.Client.Tests.csproj" (VSTest target(s)) -- FAILED.

@JamesNK JamesNK merged commit 3ae11a4 into grpc:master Dec 8, 2022
@JamesNK JamesNK deleted the jamesnk/resolver-completion-logging branch December 8, 2022 02:11
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants