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

Connecting to shutdown servers hangs client a randomly time to emit error 14 UNAVAILABLE #2031

Closed
NormandoHall opened this issue Jan 26, 2022 · 9 comments

Comments

@NormandoHall
Copy link

NormandoHall commented Jan 26, 2022

Problem description

I have configured 4 clients, to make unary calls to 4 servers. Each client is an instance from a class, and stored in a js Map. Some calls need to do on all servers, and another calls only calls one. Because few servers are shutdown, I send the same call (with each client corresponding to the instance with the ip:port of each server) and get for those are shutdown error 14 UNAVAILABLE. That's fine! But randomly some clients hangs waiting for the connection error. So, every call to a shutdown server giveme error 14 at randomly time, from miliseconds, to 30 seconds!!! Why? I suppose the error should emited instantaneous. This cause me issues, because I need to check all servers before continue with de application code.

Reproduction steps

Create a simple grpc client and try to make an unary call to any no existent server ip:port. You get and error 14. Repeat the same call few times, and you will see that sometimes client hangs for seconds.

Environment

  • OS name, version and architecture: Linux Centos 7 64bits
  • Node Version 14.18.0
  • Node installation method: Binary
  • Package name and version @grpc/grpc-js@1.5.1 (tested with 1.5.3 also)

Additional context

I was simplified my client to only one to reproduce the same issue. I think this issue is relate with those are around there suche as #1591 #1815 or https://stackoverflow.com/questions/61565913/why-does-my-node-js-grpc-client-take-3-seconds-to-send-a-request-to-my-python-gr

Of course, I was setup a deadline for the client to avoid hangs waiting for the error 14, but this is a workaround. A 1 second deadline is ok, but it is not a fix.

This is the console output. As you can see, there is 30 seconds waiting to connect. I want to fail instantly

D 2022-01-25T23:35:05.884Z | channel | (1) dns:192.168.10.20:50051 createCall [11] method="/dvdriver.DriverService/GetAffiliation", deadline=Infinity
D 2022-01-25T23:35:05.885Z | call_stream | [11] Sending metadata
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-25T23:35:05.885Z | call_stream | [11] write() called with message of length 27
D 2022-01-25T23:35:05.885Z | call_stream | [11] end() called
D 2022-01-25T23:35:05.885Z | resolving_load_balancer | dns:192.168.10.20:50051 IDLE -> CONNECTING
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-25T23:35:05.885Z | connectivity_state | (1) dns:192.168.10.20:50051 IDLE -> CONNECTING
D 2022-01-25T23:35:05.885Z | resolving_load_balancer | dns:192.168.10.20:50051 CONNECTING -> CONNECTING
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-25T23:35:05.885Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-25T23:35:05.886Z | connectivity_state | (1) dns:192.168.10.20:50051 CONNECTING -> CONNECTING
D 2022-01-25T23:35:05.886Z | call_stream | [11] deferring writing data chunk of length 32

<--------------- 3 SECONDS LATER ------------->
D 2022-01-25T23:35:08.852Z | subchannel_refcount | (16) 192.168.10.20:50051 refcount 1 -> 0



<--------------- 27 SECONDS LATER ------------->
D 2022-01-25T23:35:32.889Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50051
D 2022-01-25T23:35:32.890Z | pick_first | Connect to address list 192.168.10.20:50051
D 2022-01-25T23:35:32.890Z | subchannel | (19) 192.168.10.20:50051 Subchannel constructed with options {}
D 2022-01-25T23:35:32.890Z | subchannel_refcount | (19) 192.168.10.20:50051 refcount 0 -> 1
D 2022-01-25T23:35:32.890Z | subchannel_refcount | (19) 192.168.10.20:50051 refcount 1 -> 2
D 2022-01-25T23:35:32.890Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50051
D 2022-01-25T23:35:32.890Z | pick_first | IDLE -> CONNECTING
D 2022-01-25T23:35:32.890Z | resolving_load_balancer | dns:192.168.10.20:50051 CONNECTING -> CONNECTING
D 2022-01-25T23:35:32.890Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-25T23:35:32.890Z | channel | (1) dns:192.168.10.20:50051 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-25T23:35:32.890Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-25T23:35:32.890Z | connectivity_state | (1) dns:192.168.10.20:50051 CONNECTING -> CONNECTING
D 2022-01-25T23:35:32.891Z | subchannel | (19) 192.168.10.20:50051 IDLE -> CONNECTING
D 2022-01-25T23:35:32.891Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-25T23:35:32.891Z | resolving_load_balancer | dns:192.168.10.20:50051 CONNECTING -> CONNECTING
D 2022-01-25T23:35:32.891Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-25T23:35:32.891Z | channel | (1) dns:192.168.10.20:50051 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-25T23:35:32.891Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-25T23:35:32.891Z | connectivity_state | (1) dns:192.168.10.20:50051 CONNECTING -> CONNECTING
D 2022-01-25T23:35:32.891Z | channel | (1) dns:192.168.10.20:50051 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-25T23:35:32.891Z | subchannel | (19) 192.168.10.20:50051 creating HTTP/2 session
D 2022-01-25T23:35:32.895Z | subchannel | (19) 192.168.10.20:50051 connection closed with error connect EHOSTUNREACH 192.168.10.20:50051
D 2022-01-25T23:35:32.895Z | subchannel | (19) 192.168.10.20:50051 connection closed
D 2022-01-25T23:35:32.895Z | subchannel | (19) 192.168.10.20:50051 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-25T23:35:32.895Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-25T23:35:32.895Z | resolving_load_balancer | dns:192.168.10.20:50051 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-25T23:35:32.895Z | channel | (1) dns:192.168.10.20:50051 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-25T23:35:32.895Z | call_stream | [11] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-25T23:35:32.895Z | call_stream | [11] ended with status: code=14 details="No connection established"
D 2022-01-25T23:35:32.895Z | connectivity_state | (1) dns:192.168.10.20:50051 CONNECTING -> TRANSIENT_FAILURE

<-------- FINALLY GET ERROR 14!!!! --------------->

Only for reference, this is the console output when I instanciate the client class:

D 2022-01-26T03:31:29.762Z | index | Loading @grpc/grpc-js version 1.5.1
D 2022-01-26T03:31:29.976Z | resolving_load_balancer | dns:192.168.10.10:50050 IDLE -> IDLE
D 2022-01-26T03:31:29.976Z | connectivity_state | (1) dns:192.168.10.10:50050 IDLE -> IDLE
D 2022-01-26T03:31:29.977Z | dns_resolver | Resolver constructed for target dns:192.168.10.10:50050
D 2022-01-26T03:31:29.978Z | channel | (1) dns:192.168.10.10:50050 Channel constructed with options {}

Thanks for the help and this module!

Regards,
Normando

@murgatroid99
Copy link
Member

Can you share the full log that you took those excerpts from? There may be information in other parts of it that will help understand what exactly is happening here.

@NormandoHall
Copy link
Author

NormandoHall commented Jan 26, 2022

@murgatroid99 I splitted the log in two sections, to note de hang time of 5 seconds in this example. But there are times that hangs 30 seconds and more frequently than this. Sorry for the long log. I tried to connect lot of times, as you can see:

First part

D 2022-01-26T21:09:36.324Z | index | Loading @grpc/grpc-js version 1.5.3
D 2022-01-26T21:09:36.495Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> IDLE
D 2022-01-26T21:09:36.496Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> IDLE
D 2022-01-26T21:09:36.497Z | dns_resolver | Resolver constructed for target dns:192.168.10.20:50052
D 2022-01-26T21:09:36.498Z | channel | (1) dns:192.168.10.20:50052 Channel constructed with options {}
D 2022-01-26T21:09:38.858Z | channel | (1) dns:192.168.10.20:50052 createCall [0] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:09:48 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:38.860Z | call_stream | [0] Sending metadata
D 2022-01-26T21:09:38.860Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:09:38.861Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:38.861Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:38.861Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:38.861Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:38.861Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2022-01-26T21:09:38.863Z | call_stream | [0] write() called with message of length 27
D 2022-01-26T21:09:38.863Z | call_stream | [0] end() called
D 2022-01-26T21:09:38.864Z | call_stream | [0] deferring writing data chunk of length 32
D 2022-01-26T21:09:38.865Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:09:38.865Z | subchannel | (2) 192.168.10.20:50052 Subchannel constructed with options {}
D 2022-01-26T21:09:38.866Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 0 -> 1
D 2022-01-26T21:09:38.866Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:09:38.866Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:09:38.866Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:09:38.867Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:38.867Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0
D 2022-01-26T21:09:38.867Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:38.867Z | subchannel | (2) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:38.868Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:09:38.868Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:38.868Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:38.869Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:38.869Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:38.869Z | subchannel | (2) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:09:38.877Z | subchannel | (2) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:09:38.877Z | subchannel | (2) 192.168.10.20:50052 connection closed
D 2022-01-26T21:09:38.877Z | subchannel | (2) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:38.877Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:38.878Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:38.878Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:38.878Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:38.878Z | call_stream | [0] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:38.878Z | call_stream | [0] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:38.878Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:39.867Z | subchannel | (2) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:39.868Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:09:39.868Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:39.868Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:39.868Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:39.939Z | channel | (1) dns:192.168.10.20:50052 createCall [1] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:09:49 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:39.939Z | call_stream | [1] Sending metadata
D 2022-01-26T21:09:39.939Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:39.939Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:39.939Z | call_stream | [1] write() called with message of length 27
D 2022-01-26T21:09:39.939Z | call_stream | [1] end() called
D 2022-01-26T21:09:39.940Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:09:39.940Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:39.940Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:39.940Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:39.940Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:39.940Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:39.940Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:39.940Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:39.940Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:39.940Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:39.940Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:39.941Z | call_stream | [1] deferring writing data chunk of length 32
D 2022-01-26T21:09:39.941Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:09:39.941Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:09:39.941Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:09:39.941Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:09:39.941Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:39.941Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:39.941Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:39.942Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:39.942Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:39.942Z | subchannel | (2) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:39.942Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:09:39.942Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:39.942Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:39.942Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:39.942Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:39.942Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:39.942Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:39.942Z | subchannel | (2) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:09:39.945Z | subchannel | (2) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:09:39.945Z | subchannel | (2) 192.168.10.20:50052 connection closed
D 2022-01-26T21:09:39.945Z | subchannel | (2) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:39.945Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:39.945Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:39.945Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:39.945Z | call_stream | [1] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:39.945Z | call_stream | [1] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:39.945Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:40.772Z | channel | (1) dns:192.168.10.20:50052 createCall [2] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:09:50 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:40.773Z | call_stream | [2] Sending metadata
D 2022-01-26T21:09:40.773Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:40.773Z | call_stream | [2] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:40.773Z | call_stream | [2] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:40.773Z | call_stream | [2] write() called with message of length 27
D 2022-01-26T21:09:40.773Z | call_stream | [2] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:40.774Z | call_stream | [2] deferring writing data chunk of length 32
D 2022-01-26T21:09:41.282Z | subchannel | (2) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:41.282Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:09:41.282Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:41.283Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:41.283Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:43.277Z | channel | (1) dns:192.168.10.20:50052 createCall [3] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:09:53 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:43.277Z | call_stream | [3] Sending metadata
D 2022-01-26T21:09:43.277Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:43.277Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:43.278Z | call_stream | [3] write() called with message of length 27
D 2022-01-26T21:09:43.278Z | call_stream | [3] end() called
D 2022-01-26T21:09:43.278Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:09:43.278Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:43.278Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:43.278Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:43.278Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:43.278Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:43.278Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:43.278Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:43.278Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:43.279Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:43.279Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:43.279Z | call_stream | [3] deferring writing data chunk of length 32
D 2022-01-26T21:09:43.279Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:09:43.279Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:09:43.279Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:09:43.279Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:09:43.279Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:43.279Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:43.279Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:43.279Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:43.279Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:43.279Z | subchannel | (2) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:43.280Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:09:43.280Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:43.280Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:43.280Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:43.280Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:43.280Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:43.280Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:43.280Z | subchannel | (2) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:09:43.282Z | subchannel | (2) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:09:43.282Z | subchannel | (2) 192.168.10.20:50052 connection closed
D 2022-01-26T21:09:43.282Z | subchannel | (2) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:43.282Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:43.282Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:43.282Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:43.282Z | call_stream | [3] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:43.282Z | call_stream | [3] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:43.282Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:44.576Z | channel | (1) dns:192.168.10.20:50052 createCall [4] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:09:54 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:44.576Z | call_stream | [4] Sending metadata
D 2022-01-26T21:09:44.577Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:44.577Z | call_stream | [4] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:44.577Z | call_stream | [4] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:44.577Z | call_stream | [4] write() called with message of length 27
D 2022-01-26T21:09:44.577Z | call_stream | [4] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:44.578Z | call_stream | [4] deferring writing data chunk of length 32
D 2022-01-26T21:09:45.740Z | subchannel | (2) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:45.741Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:09:45.741Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:45.741Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:45.741Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:48.865Z | subchannel_refcount | (2) 192.168.10.20:50052 refcount 1 -> 0
D 2022-01-26T21:09:49.569Z | channel | (1) dns:192.168.10.20:50052 createCall [5] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:09:59 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:49.569Z | call_stream | [5] Sending metadata
D 2022-01-26T21:09:49.570Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:49.570Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:49.570Z | call_stream | [5] write() called with message of length 27
D 2022-01-26T21:09:49.570Z | call_stream | [5] end() called
D 2022-01-26T21:09:49.570Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:09:49.570Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:49.570Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:49.571Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:49.571Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:49.571Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:49.571Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:49.571Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:49.571Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:49.571Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:49.571Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:49.571Z | call_stream | [5] deferring writing data chunk of length 32
D 2022-01-26T21:09:49.571Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:09:49.571Z | subchannel | (6) 192.168.10.20:50052 Subchannel constructed with options {}
D 2022-01-26T21:09:49.571Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 0 -> 1
D 2022-01-26T21:09:49.571Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:09:49.572Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:09:49.572Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:09:49.572Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:49.572Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:49.572Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:49.572Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:49.572Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:49.572Z | subchannel | (6) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:49.572Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:09:49.572Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:49.572Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:49.572Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:49.572Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:49.572Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:49.573Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:49.573Z | subchannel | (6) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:09:49.575Z | subchannel | (6) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:09:49.575Z | subchannel | (6) 192.168.10.20:50052 connection closed
D 2022-01-26T21:09:49.575Z | subchannel | (6) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:49.575Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:49.575Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:49.576Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:49.576Z | call_stream | [5] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:49.576Z | call_stream | [5] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:49.576Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:50.573Z | subchannel | (6) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:50.573Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:09:50.573Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:50.573Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:50.573Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:52.403Z | channel | (1) dns:192.168.10.20:50052 createCall [6] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:02 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:52.403Z | call_stream | [6] Sending metadata
D 2022-01-26T21:09:52.403Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:52.403Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:52.403Z | call_stream | [6] write() called with message of length 27
D 2022-01-26T21:09:52.404Z | call_stream | [6] end() called
D 2022-01-26T21:09:52.404Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:52.404Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:52.404Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:52.404Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:52.404Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:52.404Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:52.404Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:52.404Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:52.404Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:52.404Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:52.404Z | call_stream | [6] deferring writing data chunk of length 32
D 2022-01-26T21:09:52.813Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:09:52.814Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:09:52.814Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:09:52.814Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:09:52.814Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:09:52.814Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:52.814Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:52.814Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:52.814Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:52.814Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:52.814Z | subchannel | (6) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:52.815Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:09:52.815Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:52.815Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:09:52.815Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:09:52.815Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:52.815Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:52.815Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:09:52.815Z | subchannel | (6) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:09:52.817Z | subchannel | (6) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:09:52.817Z | subchannel | (6) 192.168.10.20:50052 connection closed
D 2022-01-26T21:09:52.817Z | subchannel | (6) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:52.817Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:52.817Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:52.817Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:52.817Z | call_stream | [6] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:52.817Z | call_stream | [6] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:52.817Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:54.129Z | subchannel | (6) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:54.129Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:09:54.129Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:54.129Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:54.130Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:09:58.310Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:09:58.310Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:09:58.311Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:09:58.311Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:09:58.311Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:09:58.311Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:58.311Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:58.311Z | subchannel | (6) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:09:58.311Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:09:58.311Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:58.311Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:09:58.311Z | subchannel | (6) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:09:58.313Z | subchannel | (6) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:09:58.314Z | subchannel | (6) 192.168.10.20:50052 connection closed
D 2022-01-26T21:09:58.314Z | subchannel | (6) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:58.314Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:58.314Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:58.314Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:09:59.835Z | channel | (1) dns:192.168.10.20:50052 createCall [7] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:09 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:09:59.836Z | call_stream | [7] Sending metadata
D 2022-01-26T21:09:59.836Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:09:59.836Z | call_stream | [7] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:09:59.837Z | call_stream | [7] ended with status: code=14 details="No connection established"
D 2022-01-26T21:09:59.838Z | call_stream | [7] write() called with message of length 27
D 2022-01-26T21:09:59.838Z | call_stream | [7] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:09:59.838Z | call_stream | [7] deferring writing data chunk of length 32
D 2022-01-26T21:10:00.322Z | subchannel | (6) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:00.322Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:10:00.322Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:00.322Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:00.322Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:00.656Z | channel | (1) dns:192.168.10.20:50052 createCall [8] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:10 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:00.656Z | call_stream | [8] Sending metadata
D 2022-01-26T21:10:00.656Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:00.656Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:00.656Z | call_stream | [8] write() called with message of length 27
D 2022-01-26T21:10:00.657Z | call_stream | [8] end() called
D 2022-01-26T21:10:00.657Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:10:00.657Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:00.657Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:00.657Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:00.657Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:00.657Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:00.657Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:00.657Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:00.657Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:00.657Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:00.658Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:00.658Z | call_stream | [8] deferring writing data chunk of length 32
D 2022-01-26T21:10:00.658Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:10:00.658Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:10:00.658Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:10:00.658Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:10:00.658Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:00.658Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:00.658Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:00.659Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:00.659Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:00.659Z | subchannel | (6) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:00.659Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:10:00.659Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:00.659Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:00.659Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:00.659Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:00.659Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:00.659Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:00.659Z | subchannel | (6) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:10:00.661Z | subchannel | (6) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:10:00.661Z | subchannel | (6) 192.168.10.20:50052 connection closed
D 2022-01-26T21:10:00.662Z | subchannel | (6) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:00.662Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:00.662Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:00.662Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:00.662Z | call_stream | [8] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:00.662Z | call_stream | [8] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:00.662Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:01.551Z | channel | (1) dns:192.168.10.20:50052 createCall [9] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:11 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:01.551Z | call_stream | [9] Sending metadata
D 2022-01-26T21:10:01.552Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:01.552Z | call_stream | [9] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:01.552Z | call_stream | [9] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:01.552Z | call_stream | [9] write() called with message of length 27
D 2022-01-26T21:10:01.552Z | call_stream | [9] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:01.553Z | call_stream | [9] deferring writing data chunk of length 32
D 2022-01-26T21:10:02.656Z | channel | (1) dns:192.168.10.20:50052 createCall [10] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:12 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:02.656Z | call_stream | [10] Sending metadata
D 2022-01-26T21:10:02.656Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:02.656Z | call_stream | [10] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:02.656Z | call_stream | [10] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:02.656Z | call_stream | [10] write() called with message of length 27
D 2022-01-26T21:10:02.657Z | call_stream | [10] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:02.657Z | call_stream | [10] deferring writing data chunk of length 32
D 2022-01-26T21:10:04.277Z | subchannel | (6) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:04.277Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:10:04.277Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:04.277Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:04.278Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:04.576Z | channel | (1) dns:192.168.10.20:50052 createCall [11] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:14 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:04.576Z | call_stream | [11] Sending metadata
D 2022-01-26T21:10:04.577Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:04.577Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:04.577Z | call_stream | [11] write() called with message of length 27
D 2022-01-26T21:10:04.577Z | call_stream | [11] end() called
D 2022-01-26T21:10:04.577Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:04.577Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:04.577Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:04.577Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:04.577Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:04.578Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:04.578Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:04.578Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:04.578Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:04.578Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:04.578Z | call_stream | [11] deferring writing data chunk of length 32
D 2022-01-26T21:10:05.747Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:10:05.748Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:10:05.748Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:10:05.748Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:10:05.748Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:10:05.748Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:05.749Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:05.749Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:05.749Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:05.749Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:05.749Z | subchannel | (6) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:05.749Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:10:05.749Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:05.749Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:05.749Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:05.749Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:05.749Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:05.749Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:05.750Z | subchannel | (6) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:10:05.751Z | subchannel | (6) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:10:05.751Z | subchannel | (6) 192.168.10.20:50052 connection closed
D 2022-01-26T21:10:05.751Z | subchannel | (6) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:05.752Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:05.752Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:05.752Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:05.752Z | call_stream | [11] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:05.752Z | call_stream | [11] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:05.752Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:10.652Z | subchannel | (6) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:10.652Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:10:10.652Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:10.652Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:10.653Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:13.985Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:10:13.986Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:10:13.986Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:10:13.986Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:10:13.986Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:10:13.986Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:13.986Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:13.986Z | subchannel | (6) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:13.986Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:10:13.987Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:13.987Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:13.987Z | subchannel | (6) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:10:13.988Z | subchannel | (6) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:10:13.989Z | subchannel | (6) 192.168.10.20:50052 connection closed
D 2022-01-26T21:10:13.989Z | subchannel | (6) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:13.989Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:13.989Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:13.989Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:15.739Z | channel | (1) dns:192.168.10.20:50052 createCall [12] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:25 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:15.740Z | call_stream | [12] Sending metadata
D 2022-01-26T21:10:15.740Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:15.740Z | call_stream | [12] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:15.740Z | call_stream | [12] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:15.740Z | call_stream | [12] write() called with message of length 27
D 2022-01-26T21:10:15.740Z | call_stream | [12] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:15.740Z | call_stream | [12] deferring writing data chunk of length 32
D 2022-01-26T21:10:16.609Z | channel | (1) dns:192.168.10.20:50052 createCall [13] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:26 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:16.609Z | call_stream | [13] Sending metadata
D 2022-01-26T21:10:16.609Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:16.609Z | call_stream | [13] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:16.610Z | call_stream | [13] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:16.610Z | call_stream | [13] write() called with message of length 27
D 2022-01-26T21:10:16.610Z | call_stream | [13] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:16.610Z | call_stream | [13] deferring writing data chunk of length 32
D 2022-01-26T21:10:17.940Z | channel | (1) dns:192.168.10.20:50052 createCall [14] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:27 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:17.940Z | call_stream | [14] Sending metadata
D 2022-01-26T21:10:17.940Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:17.940Z | call_stream | [14] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:17.940Z | call_stream | [14] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:17.940Z | call_stream | [14] write() called with message of length 27
D 2022-01-26T21:10:17.940Z | call_stream | [14] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:17.941Z | call_stream | [14] deferring writing data chunk of length 32
D 2022-01-26T21:10:18.761Z | channel | (1) dns:192.168.10.20:50052 createCall [15] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:28 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:18.761Z | call_stream | [15] Sending metadata
D 2022-01-26T21:10:18.761Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:18.761Z | call_stream | [15] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:18.761Z | call_stream | [15] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:18.761Z | call_stream | [15] write() called with message of length 27
D 2022-01-26T21:10:18.761Z | call_stream | [15] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:18.762Z | call_stream | [15] deferring writing data chunk of length 32
D 2022-01-26T21:10:19.573Z | channel | (1) dns:192.168.10.20:50052 createCall [16] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:29 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:19.573Z | call_stream | [16] Sending metadata
D 2022-01-26T21:10:19.573Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:19.574Z | call_stream | [16] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:19.574Z | call_stream | [16] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:19.574Z | call_stream | [16] write() called with message of length 27
D 2022-01-26T21:10:19.574Z | call_stream | [16] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:19.575Z | call_stream | [16] deferring writing data chunk of length 32
D 2022-01-26T21:10:20.336Z | channel | (1) dns:192.168.10.20:50052 createCall [17] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:30 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:20.337Z | call_stream | [17] Sending metadata
D 2022-01-26T21:10:20.337Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:20.337Z | call_stream | [17] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:20.337Z | call_stream | [17] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:20.337Z | call_stream | [17] write() called with message of length 27
D 2022-01-26T21:10:20.337Z | call_stream | [17] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:20.337Z | call_stream | [17] deferring writing data chunk of length 32
D 2022-01-26T21:10:21.090Z | channel | (1) dns:192.168.10.20:50052 createCall [18] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:31 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:21.090Z | call_stream | [18] Sending metadata
D 2022-01-26T21:10:21.090Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:21.090Z | call_stream | [18] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:21.090Z | call_stream | [18] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:21.090Z | call_stream | [18] write() called with message of length 27
D 2022-01-26T21:10:21.091Z | call_stream | [18] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:21.091Z | call_stream | [18] deferring writing data chunk of length 32
D 2022-01-26T21:10:21.819Z | channel | (1) dns:192.168.10.20:50052 createCall [19] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:31 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:21.819Z | call_stream | [19] Sending metadata
D 2022-01-26T21:10:21.819Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:21.819Z | call_stream | [19] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:21.819Z | call_stream | [19] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:21.820Z | call_stream | [19] write() called with message of length 27
D 2022-01-26T21:10:21.820Z | call_stream | [19] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:21.820Z | call_stream | [19] deferring writing data chunk of length 32
D 2022-01-26T21:10:22.612Z | channel | (1) dns:192.168.10.20:50052 createCall [20] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:32 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:22.613Z | call_stream | [20] Sending metadata
D 2022-01-26T21:10:22.613Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:22.613Z | call_stream | [20] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:22.613Z | call_stream | [20] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:22.613Z | call_stream | [20] write() called with message of length 27
D 2022-01-26T21:10:22.613Z | call_stream | [20] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:22.614Z | call_stream | [20] deferring writing data chunk of length 32
D 2022-01-26T21:10:22.805Z | subchannel | (6) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:22.806Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:10:22.806Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:22.806Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:22.806Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:24.247Z | channel | (1) dns:192.168.10.20:50052 createCall [21] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:34 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:24.248Z | call_stream | [21] Sending metadata
D 2022-01-26T21:10:24.248Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:24.248Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:24.248Z | call_stream | [21] write() called with message of length 27
D 2022-01-26T21:10:24.248Z | call_stream | [21] end() called
D 2022-01-26T21:10:24.248Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:10:24.248Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:24.248Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:24.248Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:24.249Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:24.249Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:24.249Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:24.249Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:24.249Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:24.249Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:24.249Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:24.249Z | call_stream | [21] deferring writing data chunk of length 32
D 2022-01-26T21:10:24.249Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:10:24.249Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:10:24.250Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:10:24.250Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:10:24.250Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:24.250Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:24.250Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:24.250Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:24.250Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:24.250Z | subchannel | (6) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:24.250Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:10:24.250Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:24.250Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:24.250Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:24.250Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:24.251Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:24.251Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:24.251Z | subchannel | (6) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:10:24.253Z | subchannel | (6) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:10:24.253Z | subchannel | (6) 192.168.10.20:50052 connection closed
D 2022-01-26T21:10:24.254Z | subchannel | (6) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:24.254Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:24.254Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:24.254Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:24.254Z | call_stream | [21] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:24.254Z | call_stream | [21] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:24.254Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:25.057Z | channel | (1) dns:192.168.10.20:50052 createCall [22] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:35 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:25.057Z | call_stream | [22] Sending metadata
D 2022-01-26T21:10:25.057Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:25.057Z | call_stream | [22] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:25.057Z | call_stream | [22] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:25.057Z | call_stream | [22] write() called with message of length 27
D 2022-01-26T21:10:25.057Z | call_stream | [22] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:25.058Z | call_stream | [22] deferring writing data chunk of length 32
D 2022-01-26T21:10:25.793Z | channel | (1) dns:192.168.10.20:50052 createCall [23] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:35 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:25.793Z | call_stream | [23] Sending metadata
D 2022-01-26T21:10:25.793Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:25.793Z | call_stream | [23] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:25.793Z | call_stream | [23] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:25.793Z | call_stream | [23] write() called with message of length 27
D 2022-01-26T21:10:25.794Z | call_stream | [23] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:25.794Z | call_stream | [23] deferring writing data chunk of length 32
D 2022-01-26T21:10:26.506Z | channel | (1) dns:192.168.10.20:50052 createCall [24] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:36 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:26.507Z | call_stream | [24] Sending metadata
D 2022-01-26T21:10:26.507Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:26.507Z | call_stream | [24] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:26.507Z | call_stream | [24] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:26.507Z | call_stream | [24] write() called with message of length 27
D 2022-01-26T21:10:26.507Z | call_stream | [24] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:26.508Z | call_stream | [24] deferring writing data chunk of length 32
D 2022-01-26T21:10:27.288Z | channel | (1) dns:192.168.10.20:50052 createCall [25] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:37 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:27.288Z | call_stream | [25] Sending metadata
D 2022-01-26T21:10:27.288Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:27.288Z | call_stream | [25] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:27.288Z | call_stream | [25] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:27.288Z | call_stream | [25] write() called with message of length 27
D 2022-01-26T21:10:27.288Z | call_stream | [25] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:27.289Z | call_stream | [25] deferring writing data chunk of length 32
D 2022-01-26T21:10:31.310Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:10:33.197Z | channel | (1) dns:192.168.10.20:50052 createCall [26] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:43 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:33.197Z | call_stream | [26] Sending metadata
D 2022-01-26T21:10:33.197Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:33.198Z | call_stream | [26] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:33.198Z | call_stream | [26] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:33.198Z | call_stream | [26] write() called with message of length 27
D 2022-01-26T21:10:33.198Z | call_stream | [26] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:33.198Z | call_stream | [26] deferring writing data chunk of length 32
D 2022-01-26T21:10:34.002Z | channel | (1) dns:192.168.10.20:50052 createCall [27] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:44 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:34.003Z | call_stream | [27] Sending metadata
D 2022-01-26T21:10:34.003Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:34.003Z | call_stream | [27] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:34.003Z | call_stream | [27] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:34.003Z | call_stream | [27] write() called with message of length 27
D 2022-01-26T21:10:34.003Z | call_stream | [27] end() called
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:34.004Z | call_stream | [27] deferring writing data chunk of length 32
D 2022-01-26T21:10:36.452Z | subchannel | (6) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:36.452Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:10:36.452Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:36.452Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:36.453Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:39.578Z | subchannel_refcount | (6) 192.168.10.20:50052 refcount 1 -> 0
D 2022-01-26T21:10:47.525Z | channel | (1) dns:192.168.10.20:50052 createCall [28] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:57 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:47.525Z | call_stream | [28] Sending metadata
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:47.526Z | call_stream | [28] write() called with message of length 27
D 2022-01-26T21:10:47.526Z | call_stream | [28] end() called
D 2022-01-26T21:10:47.526Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:10:47.526Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:47.526Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:47.526Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:47.526Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:47.527Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:47.527Z | call_stream | [28] deferring writing data chunk of length 32
D 2022-01-26T21:10:47.527Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:10:47.527Z | subchannel | (14) 192.168.10.20:50052 Subchannel constructed with options {}
D 2022-01-26T21:10:47.527Z | subchannel_refcount | (14) 192.168.10.20:50052 refcount 0 -> 1
D 2022-01-26T21:10:47.527Z | subchannel_refcount | (14) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:10:47.527Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:10:47.527Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:10:47.528Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:47.528Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:47.528Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:47.528Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:47.528Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:47.528Z | subchannel | (14) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:47.528Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:10:47.528Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:47.528Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:47.528Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:47.528Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:47.528Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:47.528Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:47.529Z | subchannel | (14) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:10:47.533Z | subchannel | (14) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:10:47.533Z | subchannel | (14) 192.168.10.20:50052 connection closed
D 2022-01-26T21:10:47.533Z | subchannel | (14) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:47.533Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:47.533Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:47.533Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:47.534Z | call_stream | [28] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:47.534Z | call_stream | [28] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:47.534Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:48.529Z | subchannel | (14) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:48.529Z | subchannel_refcount | (14) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:10:48.529Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:48.529Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:48.529Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:49.959Z | channel | (1) dns:192.168.10.20:50052 createCall [29] method="/dvdriver.DriverService/GetAffiliation", deadline=Wed Jan 26 2022 18:10:59 GMT-0300 (Argentina Standard Time)
D 2022-01-26T21:10:49.959Z | call_stream | [29] Sending metadata
D 2022-01-26T21:10:49.959Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:49.959Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:49.959Z | call_stream | [29] write() called with message of length 27
D 2022-01-26T21:10:49.959Z | call_stream | [29] end() called
D 2022-01-26T21:10:49.959Z | resolving_load_balancer | dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:49.960Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:49.960Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:49.962Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:49.962Z | connectivity_state | (1) dns:192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:49.962Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:49.962Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:49.962Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:49.962Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:49.962Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:49.963Z | call_stream | [29] deferring writing data chunk of length 32

Hangs here !!!! 5 seconds later continue...

Second part 5 seconds later

D 2022-01-26T21:10:54.718Z | dns_resolver | Returning IP address for target dns:192.168.10.20:50052
D 2022-01-26T21:10:54.719Z | pick_first | Connect to address list 192.168.10.20:50052
D 2022-01-26T21:10:54.719Z | subchannel_refcount | (14) 192.168.10.20:50052 refcount 1 -> 2
D 2022-01-26T21:10:54.719Z | pick_first | Start connecting to subchannel with address 192.168.10.20:50052
D 2022-01-26T21:10:54.719Z | pick_first | IDLE -> CONNECTING
D 2022-01-26T21:10:54.719Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:54.719Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:54.719Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:54.719Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:54.719Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:54.719Z | subchannel | (14) 192.168.10.20:50052 IDLE -> CONNECTING
D 2022-01-26T21:10:54.719Z | pick_first | CONNECTING -> CONNECTING
D 2022-01-26T21:10:54.719Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:54.719Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-01-26T21:10:54.720Z | channel | (1) dns:192.168.10.20:50052 Pick result: QUEUE subchannel: undefined status: undefined undefined
D 2022-01-26T21:10:54.720Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:54.720Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> CONNECTING
D 2022-01-26T21:10:54.720Z | channel | (1) dns:192.168.10.20:50052 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-01-26T21:10:54.720Z | subchannel | (14) 192.168.10.20:50052 creating HTTP/2 session
D 2022-01-26T21:10:54.721Z | subchannel | (14) 192.168.10.20:50052 connection closed with error connect EHOSTUNREACH 192.168.10.20:50052
D 2022-01-26T21:10:54.721Z | subchannel | (14) 192.168.10.20:50052 connection closed
D 2022-01-26T21:10:54.721Z | subchannel | (14) 192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:54.721Z | pick_first | CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:54.721Z | resolving_load_balancer | dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
D 2022-01-26T21:10:54.721Z | channel | (1) dns:192.168.10.20:50052 Pick result: TRANSIENT_FAILURE subchannel: undefined status: 14 No connection established
D 2022-01-26T21:10:54.721Z | call_stream | [29] cancelWithStatus code: 14 details: "No connection established"
D 2022-01-26T21:10:54.721Z | call_stream | [29] ended with status: code=14 details="No connection established"
D 2022-01-26T21:10:54.721Z | connectivity_state | (1) dns:192.168.10.20:50052 CONNECTING -> TRANSIENT_FAILURE
Company ID 1 : 14 UNAVAILABLE: No connection established
{}
D 2022-01-26T21:10:56.095Z | subchannel | (14) 192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:56.095Z | subchannel_refcount | (14) 192.168.10.20:50052 refcount 2 -> 1
D 2022-01-26T21:10:56.095Z | pick_first | TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:56.095Z | resolving_load_balancer | dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:56.095Z | connectivity_state | (1) dns:192.168.10.20:50052 TRANSIENT_FAILURE -> IDLE
D 2022-01-26T21:10:57.528Z | subchannel_refcount | (14) 192.168.10.20:50052 refcount 1 -> 0

@murgatroid99
Copy link
Member

I think there is a bug there but it's hard to tell what the problem is exactly from the logs. Can you share your test code so that I can run it through a debugger?

@NormandoHall
Copy link
Author

NormandoHall commented Jan 26, 2022

Yes, sure. I was simplified the code to only one client, because causes the same issue.

dvdriverClientClass.js

const grpc = require('@grpc/grpc-js');
const protoLoader = require('@grpc/proto-loader');
const { promisify } = require('util');

function promisifyAll(client) {
  const to = {};
  for (var k in client) {
      if (typeof client[k] != 'function') continue;
      to[k] = promisify(client[k].bind(client));
  }
  return to;
}

class DVDriverClient {
  constructor(serverURL, protoPath) {
    const packageDefinition = protoLoader.loadSync(
      protoPath,
      {
        keepCase: true,
        longs: String,
        enums: String,
        defaults: true,
        oneofs: true
      });

    const dvdriver = grpc.loadPackageDefinition(packageDefinition).dvdriver;

    this.client = new dvdriver.DriverService(serverURL,
      grpc.credentials.createInsecure()
    );

    // Convert gRPC's callback APIs to await friendly promises
    const {
      getCompany,
      getAffiliation,
      addAffiliation,
      deleteAffiliation,
      sendCommand
    } = promisifyAll(this.client);

    this.srvGetCompany = getCompany;
    this.srvGetAffiliation = getAffiliation;
    this.srvAddAffiliation = addAffiliation;
    this.srvDeleteAffiliation = deleteAffiliation;
    this.srvSendCommand = sendCommand;

  }

  async getCompany(params) {
    return await this.srvGetCompany(params);
  }

  async getAffiliation(params) {
    return await this.srvGetAffiliation(params);
  }

  async addAffiliation(params) {
    return await this.srvAddAffiliation(params);
  }

  async deleteAffiliation(params) {
    return await this.srvDeleteAffiliation(params);
  }

  async sendCommand(params) {
    return await this.srvSendCommand(params);
  }

}

module.exports = {DVDriverClient};

index.js

const PROTO_PATH = __dirname + '/protos/dvdriver.proto';
const {DVDriverClient} = require('./dvdriverClientClass');
const clients = new Map();

const GRPC = {

  loadClients: function () {
    return new Promise((resolve, reject) => {

      // here I was simplified this to only one company (server), 
      // because it's the same for testing purposes
      
      const client = new DVDriverClient('192.168.10.20:50052', PROTO_PATH);
      clients.set(1, client);
      resolve()
    });
  },

  // Itera por todas las empresas
  broadcastRequest: async (companyId, method, params) => {
    try {
      if (clients.has(companyId)) {
        //console.log('Query', companyId)
        const response = await clients.get(companyId)[method](params);
        //console.log('OK', companyId)
        return response;
      }
    } catch (error) {
      console.log('Company ID', companyId, ':', error.message)
    }
  },

  getCompanies: async () => {
    const output = {};
    for (const companyId of clients.keys()) {
      output[companyId] = await GRPC.broadcastRequest(companyId, 'getCompany', null);
    }
    return output;
  },

  getAffiliations: async (appid) => {
    const output = {}
    for (const companyId of clients.keys()) {
      output[companyId] = await GRPC.broadcastRequest(companyId, 'getAffiliation', appid);
    }
    return output
  }
}

module.exports = GRPC;

Then in another file I require grpc/index and call method loadClients()

const grpcClient = require('../../grpc');

grpcClient.loadClients();

In this file I receive requests from an API REST, to call various grpc unary calls. So the client is load once. Then I do calls to grpc, such as:

const companiesSettings = await grpcClient.getCompanies()
console.log(companiesSettings)
const affiliations = await grpcClient.getAffiliations({appid: appid});
console.log(affiliations)

and so on.

This is my proto:

// Proto file para comunicar dvdriver con cada nodo (empresa)
// dvdriver es el servidor, y los nodos los clientes

syntax = "proto3";

option optimize_for = SPEED;

package dvdriver;

message Empty {}

message Company {
  bool modulo_despacho = 1;
  bool modulo_taximetro = 2;
  bool modulo_q_r = 3;
  bool taximetro_auto = 4;
  bool libre_ocupado_externo = 5;
  bool panico_externo = 6;
  bool agregarse_base = 7;
  bool boton_cancelar_despacho = 8;
  bool boton_pasajero_a_bordo = 9;
  string whatsapp = 10;
}

message AffiliationQuery {
  string appid = 1;
}

message AffiliationResponse {
  message Affiliation {
    Company company = 1;
	uint32 affiliated = 2;
    bool locked = 3;
    message Link {
      bool free = 1;
      string alias = 2;
      string movil = 3;
    }
    repeated Link links = 4;
  }
  Affiliation affiliation = 1;
}

message AffiliationRequest {
  uint32 id = 1;
  map<string, string> info = 2;
}

message AffiliationDelete {
  uint32 id = 1;
  string appid = 2;
}

message Command {
  uint32 id = 1;
  string command = 2;
  string appid = 3;
  map<string, string> options = 4;

}

service DriverService {
  rpc GetCompany (Empty) returns (Company) {}
  rpc GetAffiliation (AffiliationQuery) returns (AffiliationResponse) {}
  rpc AddAffiliation (AffiliationRequest) returns (Empty) {}
  rpc DeleteAffiliation (AffiliationDelete) returns (Empty) {}
  rpc SendCommand (Command) returns (Empty) {}
}

For testing you need to do lot of calls (ex await grpcClient.getCompanies()). Sometimes hangs at 4 try, but other times hangs at 60 tries. The time between tris is around 2 seconds, and varies. It is totally randomly

EDIT: Removed deadlines in code for testing purposes

@murgatroid99
Copy link
Member

Your code sets a two second deadline for the methods you mentioned. It is never going to hang.

@NormandoHall
Copy link
Author

NormandoHall commented Jan 27, 2022

Your code sets a two second deadline for the methods you mentioned. It is never going to hang.

Ignore these deadlines. These are there only to stop the hang as a workaround. Please, test it without these deadlines.

EDIT: I edited the code and removed the deadlines. Sorry

@NormandoHall
Copy link
Author

Hello @murgatroid99 . Were you able to reproduce the issue?

@murgatroid99
Copy link
Member

I was not able to reproduce it, but fortunately I think I found the bug anyway. I published @grpc/grpc-js version 1.5.4 with a change that I think fixes this bug. Can you try it out?

@NormandoHall
Copy link
Author

Well, I can confirm that 1.5.4 fix this issue! I tested a lot of times with 1.5.3 and 1.5.4. Seams also that 1.5.3 fails only when I try to connect to an IP, not a FQDN. But I am not sure 100% about this. But definitely 1.5.4 fix this issue, and also the 14 error response is more fastest.

Thanks!

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

No branches or pull requests

2 participants