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

Picker poisoning after calling Listener(...) and PickAsync(...) in parallell #2407

Open
kolonist opened this issue Apr 3, 2024 · 8 comments
Labels
bug Something isn't working

Comments

@kolonist
Copy link

kolonist commented Apr 3, 2024

@JamesNK Hi!

We have a problem with using PollingResolver and SubchannelsLoadBalancer. There is a case (occuring mainly under very intensive use) when ConnectionManager.PickAsync(...) become poisoned and always returns ErrorPicker result even if there are valid addresses.

Below I tried to described when it could happen.

What happened:

  1. If picker user often enough there could be case when called ConnectionManager.PickAsync(...), it started to execute and it calls await ConnectionManager.GetPickerAsync(...).
  2. GetPickerAsync(...) finishes execution, returns _nextPickerTcs.Task.WaitAsync(...) which then awaited inside PickAsync(...).
  3. Then before awaited task completed we have new balancer addresses (e.g. from service discovery) and we call PollingResolver.Listener(...) with new addresses. If addresses are really new then new subchannels will be created and at least one of them can get TransientFailure when trying to connect.
  4. And if all of these cases happened (I mean when Listener(...) with new addresses called just after GetPickerAsync(...) returns but before returned task completed and one of sunchannels has TransientFailure state) then Picker become poisoned forever. It will always return ErrorPicker and currentPicker.Pick(...).Type will be PickResultType.Fail.

For this situation to happen there should be client side balancing enabled with custom resolver, ConnectionManager.PickAsync(...) calls should be often, connections should sometimes be broken. Even if it seems to be rare case nevertheless it happened often enough under high load and intensive use.

Reproducing

I've made a test in my fork of this repository to reproduce this case: kolonist#1
Feel free to take and use that code as you wish.

About system:

We use grpc-dotnet v2.61, but the problem exists also in v2.62.x
It could be reproduced at least under Linux and MacOS (ARM CPU)
I used .NET SDK 8.0.202 and runtime 8.0.3 to reproduce it but I don't think it matters.

I couldn't find exact place where it could be fixed quickly so I really hoping on you to lookup the problem and fix it.

Best regards

@kolonist kolonist added the bug Something isn't working label Apr 3, 2024
@kalduzov
Copy link

kalduzov commented Apr 9, 2024

@JamesNK Hi. Please look at this issue.

@JamesNK
Copy link
Member

JamesNK commented Apr 11, 2024

Hi

I took at the sample. When I ran the new test, it eventually failed but I didn't see it go into a state where the picker stops working forever.

The picker switches between one that is successful to one that is failing a number of times until eventually there are 50 failing calls and then the test fails.

https://github.com/kolonist/grpc-dotnet/pull/1/files#diff-5f8d8f24f3c065e5d6e231116ec0ead4c2ab587a412d83a7b98dd914334d8da4R651

What do I need to do to the test to make it have the problem? What does it look like when the error is reproduced?

Log output:

 PickAsync_ErrorWhenInParallelWithUpdateChannelState
   Source: ResolverTests.cs line 556
   Duration: 2.8 sec

  Message: 
Grpc.Core.RpcException : Status(StatusCode="Internal", Detail="")

  Stack Trace: 
ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) line 341
<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() line 621
--- End of stack trace from previous location ---
ResolverTests.PickAsync_ErrorWhenInParallelWithUpdateChannelState() line 658
GenericAdapter`1.BlockUntilCompleted()
NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaiter)
AsyncToSyncAdapter.Await(Func`1 invoke)
TestMethodCommand.RunTestMethod(TestExecutionContext context)
TestMethodCommand.Execute(TestExecutionContext context)
<>c__DisplayClass4_0.<PerformWork>b__0()
<>c__DisplayClass1_0`1.<DoIsolated>b__0(Object _)
ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
ContextUtils.DoIsolated(ContextCallback callback, Object state)
ContextUtils.DoIsolated[T](Func`1 func)
SimpleWorkItem.PerformWork()

  Standard Output: 
0.045s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
0.052s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' created with addresses: test_addr_01:4242, test_addr_02:4242
0.053s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' state changed registration '1-1-1' created.
0.055s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
0.056s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connection requested.
0.058s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
0.058s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
0.059s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
0.060s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
0.060s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver refresh requested.
0.061s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connecting to transport.
0.061s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
0.062s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Ready. Detail: ''.
0.062s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
0.062s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Ready. Detail: ''.
0.062s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver resolve task completed.
0.062s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Ready.
0.062s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
0.086s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.088s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.090s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 1 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.117s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.117s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.117s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 2 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.148s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.148s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.148s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 3 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.180s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.180s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.180s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 4 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.211s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.211s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.211s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 5 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.242s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.242s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.242s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 6 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.273s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.273s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.273s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 7 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.304s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.305s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.305s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 8 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.336s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.336s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.336s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 9 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.368s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.368s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.368s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 10 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.399s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.399s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.399s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 11 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.430s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.430s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.430s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 12 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.461s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.461s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.461s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 13 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.493s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.493s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.493s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 14 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.523s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.523s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.523s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 15 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.554s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.554s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
0.554s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
0.554s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 16 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
0.554s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' current address 'test_addr_01:4242' is not in the updated addresses.
0.555s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
0.555s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
0.555s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
0.555s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver refresh requested.
0.555s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Idle.
0.555s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
0.555s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connection requested.
0.555s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
0.555s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
0.555s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
0.555s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
0.555s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
0.555s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
0.555s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connecting to transport.
0.555s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver resolve task completed.
0.555s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to TransientFailure. Detail: ''.
0.555s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
0.555s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to TransientFailure. Detail: ''.
0.555s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to TransientFailure.
0.555s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
0.557s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' starting connect backoff of 00:00:01.1166834.
0.585s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.587s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.588s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 17 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.648s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.648s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.648s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 18 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.678s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.678s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.679s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 19 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.710s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.710s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.710s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 20 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.742s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.742s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.742s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 21 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.772s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.772s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.772s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 22 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.803s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.803s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.803s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 23 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.834s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.834s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.834s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 24 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.866s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.866s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.866s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 25 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.897s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.897s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.897s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 26 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.928s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.928s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.928s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 27 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.960s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.960s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.960s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 28 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
0.991s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
0.991s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
0.991s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 29 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.022s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.022s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.022s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 30 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.053s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.053s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.053s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
1.053s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 31 ] PickAsync Error
1.053s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' is connecting when its addresses are updated. Restarting connect.
1.053s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' canceling connect.
1.053s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
1.053s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
1.053s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.053s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver refresh requested.
1.053s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Idle.
1.053s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
1.053s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connection requested.
1.053s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
1.053s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
1.053s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
1.053s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
1.053s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
1.054s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connecting to transport.
1.054s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Ready. Detail: ''.
1.054s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
1.054s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Ready. Detail: ''.
1.054s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Ready.
1.054s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
1.054s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
1.054s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver resolve task completed.
1.084s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.084s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.084s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 32 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.115s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.115s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.115s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 33 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.146s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.146s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.146s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 34 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.178s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.178s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.178s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 35 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.211s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.211s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.211s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 36 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.242s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.242s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.242s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 37 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.273s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.273s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.273s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 38 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.304s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.304s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.304s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 39 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.335s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.335s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.335s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 40 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.367s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.367s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.367s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 41 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.399s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.399s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.399s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 42 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.431s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.431s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.431s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 43 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.462s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.462s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.462s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 44 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.493s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.493s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.493s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 45 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.525s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.525s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_01:4242. Transport status: Passive
1.525s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 46 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_01:4242, test_addr_02:4242, State: Ready, Current address: test_addr_01:4242`, address = `test_addr_01:4242`
1.541s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
1.541s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' current address 'test_addr_01:4242' is not in the updated addresses.
1.541s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
1.541s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
1.541s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
1.541s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver refresh requested.
1.541s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Idle.
1.541s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
1.541s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connection requested.
1.541s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
1.541s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
1.541s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
1.541s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
1.541s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
1.541s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connecting to transport.
1.541s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
1.541s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Ready. Detail: ''.
1.541s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
1.541s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver resolve task completed.
1.541s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Ready. Detail: ''.
1.541s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Ready.
1.541s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
1.556s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.556s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_03:4242. Transport status: Passive
1.556s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 47 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_03:4242, test_addr_04:4242, State: Ready, Current address: test_addr_03:4242`, address = `test_addr_03:4242`
1.588s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.588s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_03:4242. Transport status: Passive
1.588s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 48 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_03:4242, test_addr_04:4242, State: Ready, Current address: test_addr_03:4242`, address = `test_addr_03:4242`
1.620s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.620s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_03:4242. Transport status: Passive
1.620s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 49 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_03:4242, test_addr_04:4242, State: Ready, Current address: test_addr_03:4242`, address = `test_addr_03:4242`
1.651s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.651s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_03:4242. Transport status: Passive
1.651s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 50 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_03:4242, test_addr_04:4242, State: Ready, Current address: test_addr_03:4242`, address = `test_addr_03:4242`
1.683s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.683s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_03:4242. Transport status: Passive
1.683s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 51 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_03:4242, test_addr_04:4242, State: Ready, Current address: test_addr_03:4242`, address = `test_addr_03:4242`
1.684s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to TransientFailure. Detail: ''.
1.684s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
1.684s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to TransientFailure. Detail: ''.
1.684s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to TransientFailure.
1.684s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
1.684s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connect canceled.
1.715s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.715s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.715s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 52 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.746s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.746s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.746s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 53 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.777s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.777s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.777s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 54 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.807s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.807s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.807s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 55 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.838s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.838s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.838s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 56 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.870s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.870s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.870s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 57 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.901s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.901s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.901s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 58 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.932s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.932s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.932s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 59 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.963s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.963s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.963s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 60 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
1.994s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
1.994s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
1.994s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 61 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.025s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.025s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.025s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 62 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.041s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
2.041s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' is connecting when its addresses are updated. Restarting connect.
2.041s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
2.041s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
2.041s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
2.041s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver refresh requested.
2.041s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Idle.
2.041s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
2.041s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connection requested.
2.041s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
2.041s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
2.041s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
2.041s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
2.041s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
2.041s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connecting to transport.
2.041s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
2.041s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to TransientFailure. Detail: ''.
2.041s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
2.041s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to TransientFailure. Detail: ''.
2.041s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to TransientFailure.
2.041s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
2.041s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver resolve task completed.
2.041s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' starting connect backoff of 00:00:00.8259291.
2.057s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.057s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.057s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 63 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.087s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.087s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.087s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 64 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.118s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.118s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.118s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 65 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.150s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.150s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.150s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 66 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.181s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.181s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.181s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 67 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.212s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.212s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.212s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 68 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.243s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.243s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.243s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 69 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.274s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.274s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.274s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 70 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.306s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.306s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.306s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 71 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.337s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.337s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.337s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 72 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.367s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.367s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.367s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 73 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.399s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.399s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.399s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 74 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.431s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.431s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.431s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 75 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.462s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.462s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.462s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 76 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.493s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.493s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.493s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 77 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.525s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.525s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.525s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 78 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.540s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
2.540s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' is connecting when its addresses are updated. Restarting connect.
2.540s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' canceling connect.
2.540s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
2.540s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
2.540s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Idle. Detail: 'Disconnected.'.
2.540s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver refresh requested.
2.540s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Idle.
2.540s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
2.540s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connection requested.
2.540s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
2.540s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
2.540s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Connecting. Detail: 'Connection requested.'.
2.540s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Connecting.
2.540s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
2.540s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connecting to transport.
2.540s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to TransientFailure. Detail: ''.
2.540s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver result with status code 'OK' and 2 addresses.
2.540s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
2.540s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to TransientFailure. Detail: ''.
2.540s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to TransientFailure.
2.540s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
2.540s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' starting connect backoff of 00:00:01.0104665.
2.540s Grpc.Net.Client.Balancer.PollingResolver - Trace: CustomResolver resolve task completed.
2.556s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.556s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.556s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 79 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.587s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.587s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.587s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 80 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.617s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.617s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.617s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 81 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.648s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.648s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.648s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 82 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.681s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.681s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.681s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 83 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.712s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.712s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.712s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 84 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.744s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.744s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.744s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 85 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.775s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.775s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.775s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 86 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621
2.806s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
2.806s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
2.806s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 87 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass15_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 621

@JamesNK
Copy link
Member

JamesNK commented Apr 11, 2024

I updated the test slightly to reset the error count when there is a successful pick, and to increase the number of allowed concurrent errors.

JamesNK@6134120

I made these changes with the assumption that the problem shows up when the channel goes into an error state forever.

After these changes the test passes for me.

@kolonist
Copy link
Author

kolonist commented Apr 11, 2024

Hi!

Call to Listener(...) with new addresses can fix Picker, errors will happen until you call it.

After you changed the test you count 5 errors in line 638 and then start doing Listener() calls in lines 648-649. When Listener() call with new addresses made, then Picker restores valid state and exceptionsCounter flushes to 0. Then it repeats again with the very beginning and again, and again until 3000 or any other number of PickAsync() calls happened.

But if you change left interval border on line 648 (> LEFT_BORDER and < (LEFT_BORDER + 50), i.e. > 150 and < 200, > 500 and < 550, etc.) you could see in logs that there are as many errors as you just written in left border. (I took 50 just for example, even one length interval should be enough)

@JamesNK
Copy link
Member

JamesNK commented Apr 14, 2024

Sorry, I still don't understand what the bug is your test is showing.

While looking at this I noticed a bug about a pending connection attempt not being canceled when subchannel addresses were updated. While fixing that, I added some more logging. PR: #2410

I rebased your changes on top of that PR and increased time between resolver calls, and total number of calls and errors allowed. These are the logs:
grpc-poison-logs.txt

I don't see anything unexpected in the logs. If a resolver provides new results and the subchannel has a transient error when trying to connect, then the connection is retried with a backoff. Eventually the connection suceeds with a retry and the subchannel goes back to a ready state.

For example, a subchannel that is erroring and then the backoff is complete, TryConnectAsync is called again, and this time it succeeds so the picker goes back to a ready state:

27.252s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
27.252s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
27.252s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 877 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass17_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 751
27.284s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
27.284s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Picked failure with status: Status(StatusCode="Internal", Detail="")
27.284s Grpc.Net.Client.Tests.Balancer.ResolverTests - Error: [ 878 ] PickAsync Error
Grpc.Core.RpcException: Status(StatusCode="Internal", Detail="")
   at Grpc.Net.Client.Balancer.Internal.ConnectionManager.PickAsync(PickContext context, Boolean waitForReady, CancellationToken cancellationToken) in C:\Development\Source\grpc-dotnet\src\Grpc.Net.Client\Balancer\Internal\ConnectionManager.cs:line 341
   at Grpc.Net.Client.Tests.Balancer.ResolverTests.<>c__DisplayClass17_0.<<PickAsync_ErrorWhenInParallelWithUpdateChannelState>b__1>d.MoveNext() in C:\Development\Source\grpc-dotnet\test\Grpc.Net.Client.Tests\Balancer\ResolverTests.cs:line 751
27.299s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' connect backoff complete.
27.299s Grpc.Net.Client.Balancer.Subchannel - Debug: Subchannel id '1-1' state changed to Ready. Detail: ''.
27.299s Grpc.Net.Client.Balancer.Subchannel - Trace: Subchannel id '1-1' executing state changed registration '1-1-1'.
27.299s Grpc.Net.Client.Balancer.PickFirstBalancer - Trace: Processing subchannel id '1-1' state changed to Ready. Detail: ''.
27.299s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel state updated to Ready.
27.299s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Channel picker updated.
27.315s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
27.315s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_03:4242. Transport status: Passive
27.315s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 879 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_03:4242, test_addr_04:4242, State: Ready, Current address: test_addr_03:4242`, address = `test_addr_03:4242`
27.347s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Trace: Pick started.
27.347s Grpc.Net.Client.Balancer.Internal.ConnectionManager - Debug: Successfully picked subchannel id '1-1' with address test_addr_03:4242. Transport status: Passive
27.347s Grpc.Net.Client.Tests.Balancer.ResolverTests - Information: [ 880 ] PickAsync result: subchannel = `Id: 1-1, Addresses: test_addr_03:4242, test_addr_04:4242, State: Ready, Current address: test_addr_03:4242`, address = `test_addr_03:4242`

@kolonist
Copy link
Author

Hi! It seems that with your fix it works better and errors stop quickly after they started.

Could you please tell when it goes to release?

@JamesNK
Copy link
Member

JamesNK commented Apr 17, 2024

Reconnect and connection backoff is already there. It's been a feature for years.

I fixed what I think might be an unrelated bug here - #2410 - when investigating this issue but that's it.

You're welcome to get the latest package from the nightly feed and try again.

@kolonist
Copy link
Author

Yes, I mean fix #2410
Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants