grpc / grpc/grpc-node

resolving_call doesn't end, grpc-js client freezes up the whole process

Open
#2,445 3 comments 1 reaction 0 assignees View on GitHub
package: @grpc/grpc-js
Dominant language
TypeScript
Stars
4.8k
Forks
716
Avg merge
2d 3h
Merged PRs (30d)
10

Description

### Problem description

I have an Electron app which creates a grpc-js client in a renderer process. The client communicates with a grpc-js server spun up in a separate, non-renderer process.

I have a very simple unary RPC which doesn't do anything complex on the server side: it creates a new EventEmitter and adds it to a Map that's accessible by the gRPC service.

Sometimes, but not always, when I have two calls to that RPC that are close in time to each other, the second one will never finish and hang up the whole renderer process, i.e. make it impossible to interact with the browser window of the app. The server process doesn't seem to hang, I verified that by adding a `setInterval` with `console.log` to the process which runs the server.

I suspect that it might be grpc-js's fault mostly because when the issue happens it's always the gRPC call that is last logged. I also found a couple of other issues mentioning grpc-js hanging up the process.

### Reproduction steps

I'm sorry but it's hard to specify what exactly the reproduction steps are. The app makes two concurrent calls to the same RPC and appears to hang. I think the logs might tell a better story of what's happening.

I don't use TLS, the client communicates with the server over a socket.

Edit: I might have some reproduction steps tomorrow, as I've just realized how to reliably reproduce it in our open source app.

### Environment
- OS name, version and architecture: macOS 13.3.1 arm64
- Node version: 18.14.0
- Node installation method: shipped with Electron 24.3.0
- Package name and version: grpc-js@1.8.14

### Additional context

I have client and server logs from the moment that the first call to the RPC happens.

The only difference that I managed to spot between the two is that when the client hangs, grpc-message from the first call is empty:

```
2023-05-18T16:48:41.821Z | subchannel_call | [35] Received server trailers:
grpc-status: 0
grpc-message:
```

The logs from the hanging client also include this:

```
2023-05-18T16:48:41.876Z | subchannel_call | [39] received status details string "OK" from server
2023-05-18T16:48:41.876Z | subchannel_call | [39] close http2 stream with code 0
```

but are missing this part which is present when everything goes okay:

```
2023-05-18T16:53:01.587Z | resolving_call | [37] Received status
2023-05-18T16:53:01.587Z | resolving_call | [37] ended with status: code=0 details="OK"
```

Logs when the client hangs

Server logs

```
2023-05-18T16:48:41.820Z | server | (1) Received call to method /PtyHost/CreatePtyProcess at address null
2023-05-18T16:48:41.821Z | server_call | Request to /PtyHost/CreatePtyProcess received headers {"grpc-accept-encoding":["identity,deflate,gzip"],"accept-encoding":["identity"],"user-agent":["grpc-node-js/1.8.14"],"content-type":["application/grpc"],"te":["trailers"]}
2023-05-18T16:48:41.825Z | server_call | Request to method /PtyHost/CreatePtyProcess ended with status code: OK details: OK
2023-05-18T16:48:41.826Z | server_call | Request to method /PtyHost/CreatePtyProcess stream closed with rstCode 0
2023-05-18T16:48:41.876Z | server | (1) Received call to method /PtyHost/CreatePtyProcess at address null
2023-05-18T16:48:41.876Z | server_call | Request to /PtyHost/CreatePtyProcess received headers {"grpc-accept-encoding":["identity,deflate,gzip"],"accept-encoding":["identity"],"user-agent":["grpc-node-js/1.8.14"],"content-type":["application/grpc"],"te":["trailers"]}
```

Client logs

```
2023-05-18T16:48:40.007Z | index | Loading @grpc/grpc-js version 1.8.14

2023-05-18T16:48:41.814Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createResolvingCall [36] method="/PtyHost/CreatePtyProcess", deadline=Infinity
2023-05-18T16:48:41.814Z | resolving_call | [36] Created
2023-05-18T16:48:41.814Z | resolving_call | [36] Deadline: Infinity
2023-05-18T16:48:41.814Z | resolving_call | [36] start called
2023-05-18T16:48:41.814Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket IDLE -> CONNECTING
2023-05-18T16:48:41.814Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:48:41.814Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket IDLE -> CONNECTING
2023-05-18T16:48:41.815Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
2023-05-18T16:48:41.815Z | resolving_call | [36] startRead called
2023-05-18T16:48:41.816Z | resolving_call | [36] write() called with message of length 10585
2023-05-18T16:48:41.816Z | resolving_call | [36] halfClose called
2023-05-18T16:48:41.816Z | pick_first | Connect to address list /Users/rav/Library/Application Support/Electron/shared.socket
2023-05-18T16:48:41.816Z | subchannel | (8) /Users/rav/Library/Application Support/Electron/shared.socket Subchannel constructed with options {}
2023-05-18T16:48:41.816Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 0 -> 1
2023-05-18T16:48:41.816Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 1 -> 2
2023-05-18T16:48:41.816Z | pick_first | Start connecting to subchannel with address /Users/rav/Library/Application Support/Electron/shared.socket
2023-05-18T16:48:41.816Z | pick_first | IDLE -> CONNECTING
2023-05-18T16:48:41.816Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:48:41.816Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0
2023-05-18T16:48:41.816Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:48:41.817Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:48:41.817Z | subchannel | (8) /Users/rav/Library/Application Support/Electron/shared.socket IDLE -> CONNECTING
2023-05-18T16:48:41.817Z | pick_first | CONNECTING -> CONNECTING
2023-05-18T16:48:41.817Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:48:41.817Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:48:41.817Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:48:41.817Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createRetryingCall [37] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:48:41.817Z | resolving_call | [36] Created child [37]
2023-05-18T16:48:41.817Z | retrying_call | [37] start called
2023-05-18T16:48:41.817Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createLoadBalancingCall [38] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:48:41.817Z | retrying_call | [37] Created child call [38] for attempt 1
2023-05-18T16:48:41.817Z | load_balancing_call | [38] start called
2023-05-18T16:48:41.817Z | load_balancing_call | [38] Pick called
2023-05-18T16:48:41.817Z | load_balancing_call | [38] Pick result: QUEUE subchannel: null status: undefined undefined
2023-05-18T16:48:41.818Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
2023-05-18T16:48:41.818Z | retrying_call | [37] startRead called
2023-05-18T16:48:41.818Z | load_balancing_call | [38] startRead called
2023-05-18T16:48:41.818Z | retrying_call | [37] write() called with message of length 10590
2023-05-18T16:48:41.818Z | load_balancing_call | [38] write() called with message of length 10590
2023-05-18T16:48:41.818Z | retrying_call | [37] halfClose called
2023-05-18T16:48:41.819Z | subchannel | (8) /Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> READY
2023-05-18T16:48:41.819Z | pick_first | Pick subchannel with address /Users/rav/Library/Application Support/Electron/shared.socket
2023-05-18T16:48:41.819Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 2 -> 3
2023-05-18T16:48:41.819Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 3 -> 2
2023-05-18T16:48:41.819Z | pick_first | CONNECTING -> READY
2023-05-18T16:48:41.819Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> READY
2023-05-18T16:48:41.819Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:48:41.819Z | load_balancing_call | [38] Pick called
2023-05-18T16:48:41.819Z | load_balancing_call | [38] Pick result: COMPLETE subchannel: (8) /Users/rav/Library/Application Support/Electron/shared.socket status: undefined undefined
2023-05-18T16:48:41.819Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> READY
2023-05-18T16:48:41.819Z | transport_flowctrl | (9) /Users/rav/Library/Application Support/Electron/shared.socket local window size: 65535 remote window size: 65535
2023-05-18T16:48:41.819Z | transport_internals | (9) /Users/rav/Library/Application Support/Electron/shared.socket session.closed=false session.destroyed=false session.socket.destroyed=false
2023-05-18T16:48:41.819Z | load_balancing_call | [38] Created child call [39]
2023-05-18T16:48:41.819Z | subchannel_call | [39] write() called with message of length 10590
2023-05-18T16:48:41.819Z | subchannel_call | [39] sending data chunk of length 10590
2023-05-18T16:48:41.820Z | load_balancing_call | [38] halfClose called
2023-05-18T16:48:41.820Z | subchannel_call | [39] end() called
2023-05-18T16:48:41.820Z | subchannel_call | [39] calling end() on HTTP/2 stream
2023-05-18T16:48:41.820Z | subchannel_call | [35] Received server headers:
:status: 200
content-type: application/grpc
2023-05-18T16:48:41.820Z | load_balancing_call | [33] Received metadata
2023-05-18T16:48:41.820Z | retrying_call | [32] Received metadata from child [33]
2023-05-18T16:48:41.820Z | retrying_call | [32] Committing call [33] at index 0
2023-05-18T16:48:41.820Z | resolving_call | [29] Received metadata
2023-05-18T16:48:41.820Z | subchannel_call | [35] receive HTTP/2 data frame of length 334
2023-05-18T16:48:41.820Z | subchannel_call | [35] parsed message of length 334
2023-05-18T16:48:41.820Z | subchannel_call | [35] pushing to reader message of length 334
2023-05-18T16:48:41.820Z | load_balancing_call | [33] Received message
2023-05-18T16:48:41.820Z | retrying_call | [32] Received message from child [33]
2023-05-18T16:48:41.820Z | resolving_call | [29] Received message
2023-05-18T16:48:41.820Z | resolving_call | [29] Finished filtering received message
2023-05-18T16:48:41.821Z | subchannel_call | [35] Received server trailers:
grpc-status: 0
grpc-message:
2023-05-18T16:48:41.821Z | subchannel_call | [35] received status code 0 from server
2023-05-18T16:48:41.821Z | subchannel_call | [35] received status details string "" from server
2023-05-18T16:48:41.821Z | subchannel_call | [35] close http2 stream with code 0
2023-05-18T16:48:41.821Z | subchannel_call | [35] ended with status: code=0 details=""
2023-05-18T16:48:41.821Z | load_balancing_call | [33] Received status
2023-05-18T16:48:41.821Z | load_balancing_call | [33] ended with status: code=0 details=""
2023-05-18T16:48:41.821Z | retrying_call | [32] Received status from child [33]
2023-05-18T16:48:41.821Z | retrying_call | [32] state=COMMITTED handling status with progress PROCESSED from child [33] in state ACTIVE
2023-05-18T16:48:41.821Z | retrying_call | [32] ended with status: code=0 details=""
2023-05-18T16:48:41.821Z | resolving_call | [29] Received status
2023-05-18T16:48:41.822Z | resolving_call | [29] ended with status: code=0 details=""
2023-05-18T16:48:41.822Z | subchannel_call | [35] HTTP/2 stream closed with code 0
2023-05-18T16:48:41.867Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createResolvingCall [40] method="/PtyHost/CreatePtyProcess", deadline=Infinity
2023-05-18T16:48:41.867Z | resolving_call | [40] Created
2023-05-18T16:48:41.867Z | resolving_call | [40] Deadline: Infinity
2023-05-18T16:48:41.867Z | resolving_call | [40] start called
2023-05-18T16:48:41.868Z | resolving_call | [40] startRead called
2023-05-18T16:48:41.868Z | resolving_call | [40] write() called with message of length 10662
2023-05-18T16:48:41.868Z | resolving_call | [40] halfClose called
2023-05-18T16:48:41.869Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createRetryingCall [41] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:48:41.869Z | resolving_call | [40] Created child [41]
2023-05-18T16:48:41.869Z | retrying_call | [41] start called
2023-05-18T16:48:41.869Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createLoadBalancingCall [42] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:48:41.869Z | retrying_call | [41] Created child call [42] for attempt 1
2023-05-18T16:48:41.869Z | load_balancing_call | [42] start called
2023-05-18T16:48:41.869Z | load_balancing_call | [42] Pick called
2023-05-18T16:48:41.870Z | load_balancing_call | [42] Pick result: COMPLETE subchannel: (8) /Users/rav/Library/Application Support/Electron/shared.socket status: undefined undefined
2023-05-18T16:48:41.870Z | retrying_call | [41] startRead called
2023-05-18T16:48:41.870Z | load_balancing_call | [42] startRead called
2023-05-18T16:48:41.870Z | transport_flowctrl | (9) /Users/rav/Library/Application Support/Electron/shared.socket local window size: 65535 remote window size: 54945
2023-05-18T16:48:41.870Z | transport_internals | (9) /Users/rav/Library/Application Support/Electron/shared.socket session.closed=false session.destroyed=false session.socket.destroyed=false
2023-05-18T16:48:41.870Z | load_balancing_call | [42] Created child call [43]
2023-05-18T16:48:41.870Z | retrying_call | [41] write() called with message of length 10667
2023-05-18T16:48:41.870Z | load_balancing_call | [42] write() called with message of length 10667
2023-05-18T16:48:41.871Z | subchannel_call | [43] write() called with message of length 10667
2023-05-18T16:48:41.871Z | subchannel_call | [43] sending data chunk of length 10667
2023-05-18T16:48:41.871Z | retrying_call | [41] halfClose called
2023-05-18T16:48:41.875Z | transport | (9) /Users/rav/Library/Application Support/Electron/shared.socket local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
2023-05-18T16:48:41.875Z | subchannel_call | [39] Received server headers:
:status: 200
content-type: application/grpc+proto
grpc-accept-encoding: identity,deflate,gzip
grpc-encoding: identity
date: Thu, 18 May 2023 16:48:41 GMT
2023-05-18T16:48:41.875Z | load_balancing_call | [38] Received metadata
2023-05-18T16:48:41.875Z | retrying_call | [37] Received metadata from child [38]
2023-05-18T16:48:41.875Z | retrying_call | [37] Committing call [38] at index 0
2023-05-18T16:48:41.875Z | resolving_call | [36] Received metadata
2023-05-18T16:48:41.875Z | subchannel_call | [39] receive HTTP/2 data frame of length 28
2023-05-18T16:48:41.875Z | subchannel_call | [39] parsed message of length 28
2023-05-18T16:48:41.875Z | subchannel_call | [39] pushing to reader message of length 28
2023-05-18T16:48:41.875Z | load_balancing_call | [38] Received message
2023-05-18T16:48:41.875Z | retrying_call | [37] Received message from child [38]
2023-05-18T16:48:41.875Z | resolving_call | [36] Received message
2023-05-18T16:48:41.876Z | resolving_call | [36] Finished filtering received message
2023-05-18T16:48:41.876Z | subchannel_call | [39] Received server trailers:
grpc-status: 0
grpc-message: OK
2023-05-18T16:48:41.876Z | subchannel_call | [39] received status code 0 from server
2023-05-18T16:48:41.876Z | subchannel_call | [39] received status details string "OK" from server
2023-05-18T16:48:41.876Z | subchannel_call | [39] close http2 stream with code 0
```

Logs when the client doesn't hang

Server logs

```
2023-05-18T16:53:01.575Z | server | (1) Received call to method /PtyHost/CreatePtyProcess at address null
2023-05-18T16:53:01.576Z | server_call | Request to /PtyHost/CreatePtyProcess received headers {"grpc-accept-encoding":["identity,deflate,gzip"],"accept-encoding":["identity"],"user-agent":["grpc-node-js/1.8.14"],"content-type":["application/grpc"],"te":["trailers"]}
2023-05-18T16:53:01.576Z | server | (1) Received call to method /PtyHost/CreatePtyProcess at address null
2023-05-18T16:53:01.576Z | server_call | Request to /PtyHost/CreatePtyProcess received headers {"grpc-accept-encoding":["identity,deflate,gzip"],"accept-encoding":["identity"],"user-agent":["grpc-node-js/1.8.14"],"content-type":["application/grpc"],"te":["trailers"]}
2023-05-18T16:53:01.581Z | server_call | Request to method /PtyHost/CreatePtyProcess ended with status code: OK details: OK
2023-05-18T16:53:01.584Z | server_call | Request to method /PtyHost/CreatePtyProcess ended with status code: OK details: OK
2023-05-18T16:53:01.585Z | server_call | Request to method /PtyHost/CreatePtyProcess stream closed with rstCode 0
2023-05-18T16:53:01.585Z | server_call | Request to method /PtyHost/CreatePtyProcess stream closed with rstCode 0
```

Client logs

```
2023-05-18T16:53:01.565Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createResolvingCall [36] method="/PtyHost/CreatePtyProcess", deadline=Infinity
2023-05-18T16:53:01.566Z | resolving_call | [36] Created
2023-05-18T16:53:01.566Z | resolving_call | [36] Deadline: Infinity
2023-05-18T16:53:01.566Z | resolving_call | [36] start called
2023-05-18T16:53:01.566Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket IDLE -> CONNECTING
2023-05-18T16:53:01.566Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:53:01.566Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket IDLE -> CONNECTING
2023-05-18T16:53:01.566Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
2023-05-18T16:53:01.566Z | resolving_call | [36] startRead called
2023-05-18T16:53:01.568Z | resolving_call | [36] write() called with message of length 10585
2023-05-18T16:53:01.568Z | resolving_call | [36] halfClose called
2023-05-18T16:53:01.568Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createResolvingCall [37] method="/PtyHost/CreatePtyProcess", deadline=Infinity
2023-05-18T16:53:01.568Z | resolving_call | [37] Created
2023-05-18T16:53:01.568Z | resolving_call | [37] Deadline: Infinity
2023-05-18T16:53:01.568Z | resolving_call | [37] start called
2023-05-18T16:53:01.569Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.ref | configSelectionQueue.length=2 pickQueue.length=0
2023-05-18T16:53:01.569Z | resolving_call | [37] startRead called
2023-05-18T16:53:01.569Z | resolving_call | [37] write() called with message of length 10662
2023-05-18T16:53:01.569Z | resolving_call | [37] halfClose called
2023-05-18T16:53:01.570Z | pick_first | Connect to address list /Users/rav/Library/Application Support/Electron/shared.socket
2023-05-18T16:53:01.570Z | subchannel | (8) /Users/rav/Library/Application Support/Electron/shared.socket Subchannel constructed with options {}
2023-05-18T16:53:01.570Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 0 -> 1
2023-05-18T16:53:01.570Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 1 -> 2
2023-05-18T16:53:01.570Z | pick_first | Start connecting to subchannel with address /Users/rav/Library/Application Support/Electron/shared.socket
2023-05-18T16:53:01.570Z | pick_first | IDLE -> CONNECTING
2023-05-18T16:53:01.570Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:53:01.570Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=2 pickQueue.length=0
2023-05-18T16:53:01.570Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:53:01.570Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:53:01.570Z | subchannel | (8) /Users/rav/Library/Application Support/Electron/shared.socket IDLE -> CONNECTING
2023-05-18T16:53:01.570Z | pick_first | CONNECTING -> CONNECTING
2023-05-18T16:53:01.570Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:53:01.570Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:53:01.570Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> CONNECTING
2023-05-18T16:53:01.571Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createRetryingCall [38] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:53:01.571Z | resolving_call | [36] Created child [38]
2023-05-18T16:53:01.571Z | retrying_call | [38] start called
2023-05-18T16:53:01.571Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createLoadBalancingCall [39] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:53:01.571Z | retrying_call | [38] Created child call [39] for attempt 1
2023-05-18T16:53:01.571Z | load_balancing_call | [39] start called
2023-05-18T16:53:01.571Z | load_balancing_call | [39] Pick called
2023-05-18T16:53:01.571Z | load_balancing_call | [39] Pick result: QUEUE subchannel: null status: undefined undefined
2023-05-18T16:53:01.571Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
2023-05-18T16:53:01.571Z | retrying_call | [38] startRead called
2023-05-18T16:53:01.571Z | load_balancing_call | [39] startRead called
2023-05-18T16:53:01.571Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createRetryingCall [40] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:53:01.571Z | resolving_call | [37] Created child [40]
2023-05-18T16:53:01.571Z | retrying_call | [40] start called
2023-05-18T16:53:01.571Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket createLoadBalancingCall [41] method="/PtyHost/CreatePtyProcess"
2023-05-18T16:53:01.571Z | retrying_call | [40] Created child call [41] for attempt 1
2023-05-18T16:53:01.571Z | load_balancing_call | [41] start called
2023-05-18T16:53:01.571Z | load_balancing_call | [41] Pick called
2023-05-18T16:53:01.572Z | load_balancing_call | [41] Pick result: QUEUE subchannel: null status: undefined undefined
2023-05-18T16:53:01.572Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=2
2023-05-18T16:53:01.572Z | retrying_call | [40] startRead called
2023-05-18T16:53:01.572Z | load_balancing_call | [41] startRead called
2023-05-18T16:53:01.572Z | retrying_call | [38] write() called with message of length 10590
2023-05-18T16:53:01.572Z | load_balancing_call | [39] write() called with message of length 10590
2023-05-18T16:53:01.572Z | retrying_call | [38] halfClose called
2023-05-18T16:53:01.572Z | retrying_call | [40] write() called with message of length 10667
2023-05-18T16:53:01.572Z | load_balancing_call | [41] write() called with message of length 10667
2023-05-18T16:53:01.572Z | retrying_call | [40] halfClose called
2023-05-18T16:53:01.573Z | subchannel | (8) /Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> READY
2023-05-18T16:53:01.573Z | pick_first | Pick subchannel with address /Users/rav/Library/Application Support/Electron/shared.socket
2023-05-18T16:53:01.573Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 2 -> 3
2023-05-18T16:53:01.573Z | subchannel_refcount | (8) /Users/rav/Library/Application Support/Electron/shared.socket refcount 3 -> 2
2023-05-18T16:53:01.574Z | pick_first | CONNECTING -> READY
2023-05-18T16:53:01.574Z | resolving_load_balancer | unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> READY
2023-05-18T16:53:01.574Z | channel | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
2023-05-18T16:53:01.574Z | load_balancing_call | [39] Pick called
2023-05-18T16:53:01.574Z | load_balancing_call | [39] Pick result: COMPLETE subchannel: (8) /Users/rav/Library/Application Support/Electron/shared.socket status: undefined undefined
2023-05-18T16:53:01.574Z | load_balancing_call | [41] Pick called
2023-05-18T16:53:01.574Z | load_balancing_call | [41] Pick result: COMPLETE subchannel: (8) /Users/rav/Library/Application Support/Electron/shared.socket status: undefined undefined
2023-05-18T16:53:01.574Z | connectivity_state | (2) unix:///Users/rav/Library/Application Support/Electron/shared.socket CONNECTING -> READY
2023-05-18T16:53:01.574Z | transport_flowctrl | (9) /Users/rav/Library/Application Support/Electron/shared.socket local window size: 65535 remote window size: 65535
2023-05-18T16:53:01.574Z | transport_internals | (9) /Users/rav/Library/Application Support/Electron/shared.socket session.closed=false session.destroyed=false session.socket.destroyed=false
2023-05-18T16:53:01.574Z | load_balancing_call | [39] Created child call [42]
2023-05-18T16:53:01.574Z | subchannel_call | [42] write() called with message of length 10590
2023-05-18T16:53:01.574Z | subchannel_call | [42] sending data chunk of length 10590
2023-05-18T16:53:01.575Z | transport_flowctrl | (9) /Users/rav/Library/Application Support/Electron/shared.socket local window size: 65535 remote window size: 65535
2023-05-18T16:53:01.575Z | transport_internals | (9) /Users/rav/Library/Application Support/Electron/shared.socket session.closed=false session.destroyed=false session.socket.destroyed=false
2023-05-18T16:53:01.575Z | load_balancing_call | [41] Created child call [43]
2023-05-18T16:53:01.575Z | subchannel_call | [43] write() called with message of length 10667
2023-05-18T16:53:01.575Z | subchannel_call | [43] sending data chunk of length 10667
2023-05-18T16:53:01.576Z | load_balancing_call | [39] halfClose called
2023-05-18T16:53:01.576Z | subchannel_call | [42] end() called
2023-05-18T16:53:01.576Z | subchannel_call | [42] calling end() on HTTP/2 stream
2023-05-18T16:53:01.576Z | load_balancing_call | [41] halfClose called
2023-05-18T16:53:01.577Z | subchannel_call | [43] end() called
2023-05-18T16:53:01.577Z | subchannel_call | [43] calling end() on HTTP/2 stream
2023-05-18T16:53:01.577Z | transport | (9) /Users/rav/Library/Application Support/Electron/shared.socket local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
2023-05-18T16:53:01.584Z | subchannel_call | [42] Received server headers:
:status: 200
content-type: application/grpc+proto
grpc-accept-encoding: identity,deflate,gzip
grpc-encoding: identity
date: Thu, 18 May 2023 16:53:01 GMT
2023-05-18T16:53:01.584Z | load_balancing_call | [39] Received metadata
2023-05-18T16:53:01.584Z | retrying_call | [38] Received metadata from child [39]
2023-05-18T16:53:01.584Z | retrying_call | [38] Committing call [39] at index 0
2023-05-18T16:53:01.584Z | resolving_call | [36] Received metadata
2023-05-18T16:53:01.585Z | subchannel_call | [43] Received server headers:
:status: 200
content-type: application/grpc+proto
grpc-accept-encoding: identity,deflate,gzip
grpc-encoding: identity
date: Thu, 18 May 2023 16:53:01 GMT
2023-05-18T16:53:01.585Z | load_balancing_call | [41] Received metadata
2023-05-18T16:53:01.585Z | retrying_call | [40] Received metadata from child [41]
2023-05-18T16:53:01.585Z | retrying_call | [40] Committing call [41] at index 0
2023-05-18T16:53:01.585Z | resolving_call | [37] Received metadata
2023-05-18T16:53:01.585Z | subchannel_call | [42] receive HTTP/2 data frame of length 28
2023-05-18T16:53:01.585Z | subchannel_call | [42] parsed message of length 28
2023-05-18T16:53:01.585Z | subchannel_call | [42] pushing to reader message of length 28
2023-05-18T16:53:01.585Z | load_balancing_call | [39] Received message
2023-05-18T16:53:01.585Z | retrying_call | [38] Received message from child [39]
2023-05-18T16:53:01.585Z | resolving_call | [36] Received message
2023-05-18T16:53:01.585Z | resolving_call | [36] Finished filtering received message
2023-05-18T16:53:01.585Z | subchannel_call | [43] receive HTTP/2 data frame of length 28
2023-05-18T16:53:01.585Z | subchannel_call | [43] parsed message of length 28
2023-05-18T16:53:01.585Z | subchannel_call | [43] pushing to reader message of length 28
2023-05-18T16:53:01.586Z | load_balancing_call | [41] Received message
2023-05-18T16:53:01.586Z | retrying_call | [40] Received message from child [41]
2023-05-18T16:53:01.586Z | resolving_call | [37] Received message
2023-05-18T16:53:01.586Z | resolving_call | [37] Finished filtering received message
2023-05-18T16:53:01.586Z | subchannel_call | [42] Received server trailers:
grpc-status: 0
grpc-message: OK
2023-05-18T16:53:01.586Z | subchannel_call | [42] received status code 0 from server
2023-05-18T16:53:01.586Z | subchannel_call | [42] received status details string "OK" from server
2023-05-18T16:53:01.586Z | subchannel_call | [42] close http2 stream with code 0
2023-05-18T16:53:01.586Z | subchannel_call | [43] Received server trailers:
grpc-status: 0
grpc-message: OK
2023-05-18T16:53:01.586Z | subchannel_call | [43] received status code 0 from server
2023-05-18T16:53:01.586Z | subchannel_call | [43] received status details string "OK" from server
2023-05-18T16:53:01.586Z | subchannel_call | [43] close http2 stream with code 0
2023-05-18T16:53:01.586Z | subchannel_call | [42] ended with status: code=0 details="OK"
2023-05-18T16:53:01.586Z | subchannel_call | [43] ended with status: code=0 details="OK"
2023-05-18T16:53:01.586Z | load_balancing_call | [39] Received status
2023-05-18T16:53:01.586Z | load_balancing_call | [39] ended with status: code=0 details="OK"
2023-05-18T16:53:01.586Z | retrying_call | [38] Received status from child [39]
2023-05-18T16:53:01.587Z | retrying_call | [38] state=COMMITTED handling status with progress PROCESSED from child [39] in state ACTIVE
2023-05-18T16:53:01.587Z | retrying_call | [38] ended with status: code=0 details="OK"
2023-05-18T16:53:01.587Z | load_balancing_call | [41] Received status
2023-05-18T16:53:01.587Z | load_balancing_call | [41] ended with status: code=0 details="OK"
2023-05-18T16:53:01.587Z | retrying_call | [40] Received status from child [41]
2023-05-18T16:53:01.587Z | retrying_call | [40] state=COMMITTED handling status with progress PROCESSED from child [41] in state ACTIVE
2023-05-18T16:53:01.587Z | retrying_call | [40] ended with status: code=0 details="OK"
2023-05-18T16:53:01.587Z | resolving_call | [36] Received status
2023-05-18T16:53:01.587Z | resolving_call | [36] ended with status: code=0 details="OK"
2023-05-18T16:53:01.587Z | subchannel_call | [42] HTTP/2 stream closed with code 0
2023-05-18T16:53:01.587Z | resolving_call | [37] Received status
2023-05-18T16:53:01.587Z | resolving_call | [37] ended with status: code=0 details="OK"
2023-05-18T16:53:01.587Z | subchannel_call | [43] HTTP/2 stream closed with code 0
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.