Idle connections are broken/closed, and not detected properly, in some environments (e.g. AWS Lambda)

[cprice404]

Problem description

When writing an AWS lambda it is often considered a reasonable practice to store client objects (database clients etc.) in a global variable so that they can be re-used by subsequent lambda invocations.

If this approach is used with a grpc-js client/channel, and the lambda is idle for an extended period of time, when it is resumed the connection may no longer be usable (e.g. the connection may have been closed by the server due to an idle timeout). However, the getConnectivityState still reports it as "ready" (2) and attempts to use it.

The first request that is issued via this channel after this immediately fails with a grpc status 14 (UNAVAILABLE). If we immediately retry the request via an interceptor, the retry hangs until the client-side deadline is exceeded and then the request fails with DEADLINE_EXCEEDED (4).

Keepalive settings do not help in an AWS Lambda environment because the runtime is suspended between lambda invocations, and thus the keepalive pings are never sent by the client.

Reproduction steps

In my case the server side of the gRPC channel is going through an AWS Network Load Balancer. The NLB has an idle timeout of 350s: https://docs.aws.amazon.com/elasticloadbalancing/latest/network/network-load-balancers.html#connection-idle-timeout

So the repro involves:

• Instantiating a client/channel that connects to a gRPC service through an AWS NLB
• Making a few (successful) requests
• Leaving the client idle for 6+ minutes
• Attempting to make another request and observing that the client/channel are no longer usable even though the channel reports ConnectivityState 0 or 2.

I haven't yet been able to repro this using a standalone node.js program. The simplest reproducer I've come up with has been via SST. Following their quickstart guide and creaging a "minimal/typescript" project, I have been able to reproduce this reliably:

• Create a minimal typescript project
• Modify the lambda code to create a global variable that contains a grpc client/channel so that on the first load, the connection is established through the NLB
• Consume the client to try to make requests from within the lambda body
• run npx sst start to launch the local development mode
• Use the SST console to invoke the lambda a few times and observe the successful gRPC requests
• wait for 6+ minutes
• Use the SST console to invoke the lambda again and observe that you get UNAVAILABLE and/or DEADLINE_EXCEEDED.

I have also been able to reproduce this directly in the deployed AWS lambda, by:

• deploying the lambda
• Setting up "provisioned capacity" for it so that the lambda runtime will be re-used across multiple invocations
• Invoke it successfully a few times
• Wait 6+ minutes
• Invoke it again and watch the gRPC connection issue recur

I would be happy to provide client code to reproduce this but the server I'm hitting is proprietary. If there is a toy service that we could use to reproduce it I don't mind trying to stand up the NLB in front of it to help make this easier to repro/debug.

Environment

• OS name, version and architecture: Mac OS 12.5 + SST, or AWS Lambda node.js environment
• Node version [e.g. 8.10.0]: AWS Lambda node.js 16.x runtime; on laptop: node 16.15.0
• Node installation method [e.g. nvm]: AWS Lambda, and on laptop nodenv.
• If applicable, compiler version [e.g. clang 3.8.0-2ubuntu4] N/A
• Package name and version [e.g. gRPC@1.12.0] @grpc/grpc-js v1.5.10 and v1.7.3

Additional context

These logs probably aren't very useful since they are generated by our app, but:

21:48:32.922
{"level":20,"time":1669844912922,"pid":61312,"hostname":"neutraljanet.local","name":"RetryInterceptor","msg":"Request path: /cache_client.Scs/Set; response status code: 14; number of retries (0) is less than max (3), retrying."}
21:49:22.914
TimeoutError: 4 DEADLINE_EXCEEDED: undefined
at cacheServiceErrorMapper (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:28189:14)
at Object.callback (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:28623:20)
at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9829:30)
at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7386:31
at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9425:9)
at InterceptingListenerImpl.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7382:23)
at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7386:31
at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:28049:23)
at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9644:140)
at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9612:175)

[murgatroid99]

This behavior is definitely incorrect. Once the client detects that it does not have a connection, it should reconnect and subsequent attempts should succeed.

The initial UNAVAILABLE is expected because the client detects that the connection no longer exists after the point where it can try again on a different connection. This will be improved in many cases by the upcoming retry feature.

The DEADLINE_EXCEEDED error is the concerning part. The client should usually be able to reconnect and successfully make the request within a reasonable time limit.

If you need an alternate service to test, it should be possible to reproduce this with the hello world example.

It would help to have a trace log from the client running on Lambda, if possible. It will be output to stderr if you set the environment variables GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG.

[cprice404]

Thanks for the reply. We are working around this in our code for now by tracking the last time that the client was accessed, and if it exceeds a certain idle timeout then we just forcefully close and restart it. Not ideal but it fixes the issue for us for now.

I will try to find some time to set up a reproducer with the hello world example, but not sure whether I'll have bandwidth.

I can do another run with those GRPC env vars set to get those logs though, that's easy enough.

[murgatroid99]

The suggestion about running the hello world example was just a response to

I would be happy to provide client code to reproduce this but the server I'm hitting is proprietary. If there is a toy service that we could use to reproduce it I don't mind trying to stand up the NLB in front of it to help make this easier to repro/debug.

It's not a high priority. I think the log should have the relevant information.

[cprice404]

Here's a log from SST environment. I'll push it up to lambda and get one there next.

d5fe8810-e29a-4288-b191-39e5f21d24ea REQUEST dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh [functions/lambda.handler] invoked
EVENT IS: {}
EVENT REQUEST CONTEXT: {
  "callbackWaitsForEmptyEventLoop": true,
  "functionVersion": "$LATEST",
  "functionName": "dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh",
  "memoryLimitInMB": "1024",
  "clientContext": {},
  "identity": {},
  "invokedFunctionArn": "arn:aws:lambda:us-west-2:266697619022:function:dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh",
  "awsRequestId": "d5fe8810-e29a-4288-b191-39e5f21d24ea"
}
{"level":10,"time":1669925539622,"pid":97231,"hostname":"neutraljanet.local","name":"_MomentoCache","msg":"Issuing 'get' request; key: foooooo"}
Current channel state: 0
D 2022-12-01T20:12:19.622Z | channel | (6) dns:server.momentohq.com createCall [5] method="/cache_client.Scs/Get", deadline=Thu Dec 01 2022 12:13:09 GMT-0800 (Pacific Standard Time)
D 2022-12-01T20:12:19.622Z | call_stream | [5] Sending metadata
D 2022-12-01T20:12:19.623Z | dns_resolver | Looking up DNS hostname server.momentohq.com
D 2022-12-01T20:12:19.623Z | resolving_load_balancer | dns:server.momentohq.com IDLE -> CONNECTING
D 2022-12-01T20:12:19.623Z | connectivity_state | (6) dns:server.momentohq.com IDLE -> CONNECTING
D 2022-12-01T20:12:19.623Z | resolving_load_balancer | dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.623Z | connectivity_state | (6) dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.623Z | channel | (6) dns:server.momentohq.com callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2022-12-01T20:12:19.623Z | call_stream | [5] write() called with message of length 9
D 2022-12-01T20:12:19.623Z | call_stream | [5] end() called
D 2022-12-01T20:12:19.623Z | call_stream | [5] deferring writing data chunk of length 14
D 2022-12-01T20:12:19.661Z | dns_resolver | Resolved addresses for target dns:server.momentohq.com: [54.186.170.81:443]
D 2022-12-01T20:12:19.661Z | pick_first | Connect to address list 54.186.170.81:443
D 2022-12-01T20:12:19.661Z | subchannel | (18) 54.186.170.81:443 Subchannel constructed with options {
  "grpc-node.max_session_memory": 256,
  "grpc.use_local_subchannel_pool": 1
}
D 2022-12-01T20:12:19.661Z | subchannel_refcount | (18) 54.186.170.81:443 refcount 0 -> 1
D 2022-12-01T20:12:19.661Z | pick_first | Start connecting to subchannel with address 54.186.170.81:443
D 2022-12-01T20:12:19.661Z | pick_first | IDLE -> CONNECTING
D 2022-12-01T20:12:19.661Z | resolving_load_balancer | dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.661Z | channel | (6) dns:server.momentohq.com callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0
D 2022-12-01T20:12:19.661Z | connectivity_state | (6) dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.661Z | subchannel | (18) 54.186.170.81:443 IDLE -> CONNECTING
D 2022-12-01T20:12:19.661Z | pick_first | CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.661Z | resolving_load_balancer | dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.661Z | connectivity_state | (6) dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.661Z | channel | (6) dns:server.momentohq.com Pick result for call [5]: QUEUE subchannel: null status: undefined undefined
D 2022-12-01T20:12:19.661Z | channel | (6) dns:server.momentohq.com callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-12-01T20:12:19.661Z | subchannel | (18) 54.186.170.81:443 creating HTTP/2 session
D 2022-12-01T20:12:19.687Z | subchannel | (18) 54.186.170.81:443 CONNECTING -> READY
D 2022-12-01T20:12:19.687Z | pick_first | Pick subchannel with address 54.186.170.81:443
D 2022-12-01T20:12:19.687Z | pick_first | CONNECTING -> READY
D 2022-12-01T20:12:19.687Z | resolving_load_balancer | dns:server.momentohq.com CONNECTING -> READY
D 2022-12-01T20:12:19.687Z | channel | (6) dns:server.momentohq.com callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-12-01T20:12:19.687Z | channel | (6) dns:server.momentohq.com Pick result for call [5]: COMPLETE subchannel: (18) 54.186.170.81:443 status: undefined undefined
D 2022-12-01T20:12:19.687Z | connectivity_state | (6) dns:server.momentohq.com CONNECTING -> READY
D 2022-12-01T20:12:19.687Z | subchannel_refcount | (18) 54.186.170.81:443 refcount 1 -> 2
D 2022-12-01T20:12:19.687Z | subchannel_refcount | (18) 54.186.170.81:443 refcount 2 -> 1
D 2022-12-01T20:12:19.687Z | call_stream | Starting stream [5] on subchannel (18) 54.186.170.81:443 with headers
		cache: default-cache
		authorization: REDACTED
		grpc-timeout: 49935m
		grpc-accept-encoding: identity,deflate,gzip
		accept-encoding: identity
		:authority: server.momentohq.com
		user-agent: grpc-node-js/1.5.10
		content-type: application/grpc
		:method: POST
		:path: /cache_client.Scs/Get
		te: trailers

D 2022-12-01T20:12:19.687Z | subchannel_flowctrl | (18) 54.186.170.81:443 local window size: 65535 remote window size: 65535
D 2022-12-01T20:12:19.687Z | subchannel_internals | (18) 54.186.170.81:443 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2022-12-01T20:12:19.687Z | call_stream | [5] attachHttp2Stream from subchannel 54.186.170.81:443
D 2022-12-01T20:12:19.687Z | subchannel_refcount | (18) 54.186.170.81:443 callRefcount 0 -> 1
D 2022-12-01T20:12:19.687Z | call_stream | [5] sending data chunk of length 14 (deferred)
D 2022-12-01T20:12:19.687Z | call_stream | [5] calling end() on HTTP/2 stream
D 2022-12-01T20:12:19.699Z | subchannel | (18) 54.186.170.81:443 new settings received: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":1048576,"maxFrameSize":16384,"maxConcurrentStreams":100,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
D 2022-12-01T20:12:19.699Z | subchannel | (18) 54.186.170.81:443 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
D 2022-12-01T20:12:19.702Z | call_stream | [5] Received server headers:
		:status: 200
		content-type: application/grpc
		grpc-encoding: identity
		grpc-accept-encoding: gzip
		x-envoy-upstream-service-time: 2
		momento_ver: 3.3.4
		date: Thu, 01 Dec 2022 20:12:19 GMT
		server: envoy

D 2022-12-01T20:12:19.702Z | call_stream | [5] receive HTTP/2 data frame of length 23
D 2022-12-01T20:12:19.702Z | call_stream | [5] parsed message of length 23
D 2022-12-01T20:12:19.702Z | call_stream | [5] filterReceivedMessage of length 23
D 2022-12-01T20:12:19.702Z | call_stream | [5] pushing to reader message of length 18
D 2022-12-01T20:12:19.702Z | call_stream | [5] Received server trailers:
		grpc-status: 0

D 2022-12-01T20:12:19.703Z | call_stream | [5] received status code 0 from server
D 2022-12-01T20:12:19.703Z | call_stream | [5] close http2 stream with code 0
D 2022-12-01T20:12:19.703Z | call_stream | [5] ended with status: code=0 details=""
D 2022-12-01T20:12:19.703Z | subchannel_refcount | (18) 54.186.170.81:443 callRefcount 1 -> 0
D 2022-12-01T20:12:19.703Z | call_stream | [5] HTTP/2 stream closed with code 0
D 2022-12-01T20:12:19.703Z | channel | (1) dns:server.momentohq.com createCall [6] method="/cache_client.Scs/Set", deadline=Thu Dec 01 2022 12:13:09 GMT-0800 (Pacific Standard Time)
D 2022-12-01T20:12:19.703Z | call_stream | [6] Sending metadata
{"level":10,"time":1669925539703,"pid":97231,"hostname":"neutraljanet.local","name":"RetryInterceptor","msg":"Request path: /cache_client.Scs/Get; response status code: 0; not eligible for retry."}
D 2022-12-01T20:12:19.703Z | channel | (1) dns:server.momentohq.com Pick result for call [6]: COMPLETE subchannel: (8) 54.186.170.81:443 status: undefined undefined
D 2022-12-01T20:12:19.703Z | call_stream | [6] write() called with message of length 25
D 2022-12-01T20:12:19.703Z | call_stream | [6] end() called
D 2022-12-01T20:12:19.704Z | call_stream | Starting stream [6] on subchannel (8) 54.186.170.81:443 with headers
		cache: default-cache
		authorization: REDACTED
		grpc-timeout: 49999m
		grpc-accept-encoding: identity,deflate,gzip
		accept-encoding: identity
		:authority: server.momentohq.com
		user-agent: grpc-node-js/1.5.10
		content-type: application/grpc
		:method: POST
		:path: /cache_client.Scs/Set
		te: trailers

D 2022-12-01T20:12:19.704Z | subchannel_flowctrl | (8) 54.186.170.81:443 local window size: 65512 remote window size: 1048562
D 2022-12-01T20:12:19.704Z | subchannel_internals | (8) 54.186.170.81:443 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2022-12-01T20:12:19.704Z | call_stream | [6] attachHttp2Stream from subchannel 54.186.170.81:443
D 2022-12-01T20:12:19.704Z | subchannel_refcount | (8) 54.186.170.81:443 callRefcount 0 -> 1
D 2022-12-01T20:12:19.704Z | call_stream | [6] sending data chunk of length 30
D 2022-12-01T20:12:19.704Z | call_stream | [6] calling end() on HTTP/2 stream
{"level":10,"time":1669925539703,"pid":97231,"hostname":"neutraljanet.local","name":"_MomentoCache","msg":"'get' request result: MISS"}
{"level":10,"time":1669925539703,"pid":97231,"hostname":"neutraljanet.local","name":"_MomentoCache","msg":"Issuing 'set' request; key: foooooo, value length: 10, ttl: null"}
D 2022-12-01T20:12:19.716Z | call_stream | [6] Node error event: message=read ECONNRESET code=ECONNRESET errno=Unknown system error -54 syscall=read
D 2022-12-01T20:12:19.716Z | subchannel | (8) 54.186.170.81:443 connection closed with error read ECONNRESET
D 2022-12-01T20:12:19.716Z | subchannel | (8) 54.186.170.81:443 connection closed
D 2022-12-01T20:12:19.716Z | subchannel | (8) 54.186.170.81:443 READY -> IDLE
D 2022-12-01T20:12:19.716Z | subchannel_refcount | (8) 54.186.170.81:443 refcount 1 -> 0
D 2022-12-01T20:12:19.716Z | pick_first | READY -> IDLE
D 2022-12-01T20:12:19.716Z | resolving_load_balancer | dns:server.momentohq.com READY -> IDLE
D 2022-12-01T20:12:19.716Z | connectivity_state | (1) dns:server.momentohq.com READY -> IDLE
D 2022-12-01T20:12:19.716Z | call_stream | [6] HTTP/2 stream closed with code 2
D 2022-12-01T20:12:19.717Z | call_stream | [6] ended with status: code=14 details="read ECONNRESET"
D 2022-12-01T20:12:19.717Z | subchannel_refcount | (8) 54.186.170.81:443 callRefcount 1 -> 0
D 2022-12-01T20:12:19.717Z | channel | (1) dns:server.momentohq.com createCall [7] method="/cache_client.Scs/Set", deadline=Thu Dec 01 2022 12:13:09 GMT-0800 (Pacific Standard Time)
D 2022-12-01T20:12:19.717Z | call_stream | [7] Sending metadata
D 2022-12-01T20:12:19.717Z | channel | (1) dns:server.momentohq.com Pick result for call [7]: QUEUE subchannel: null status: undefined undefined
D 2022-12-01T20:12:19.717Z | channel | (1) dns:server.momentohq.com callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-12-01T20:12:19.717Z | pick_first | Connect to address list 54.186.170.81:443
D 2022-12-01T20:12:19.717Z | subchannel_refcount | (8) 54.186.170.81:443 refcount 0 -> 1
D 2022-12-01T20:12:19.717Z | pick_first | Start connecting to subchannel with address 54.186.170.81:443
D 2022-12-01T20:12:19.717Z | pick_first | IDLE -> CONNECTING
D 2022-12-01T20:12:19.717Z | resolving_load_balancer | dns:server.momentohq.com IDLE -> CONNECTING
D 2022-12-01T20:12:19.717Z | channel | (1) dns:server.momentohq.com callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-12-01T20:12:19.717Z | channel | (1) dns:server.momentohq.com Pick result for call [7]: QUEUE subchannel: null status: undefined undefined
D 2022-12-01T20:12:19.717Z | channel | (1) dns:server.momentohq.com callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-12-01T20:12:19.718Z | connectivity_state | (1) dns:server.momentohq.com IDLE -> CONNECTING
D 2022-12-01T20:12:19.718Z | subchannel | (8) 54.186.170.81:443 IDLE -> CONNECTING
D 2022-12-01T20:12:19.718Z | pick_first | CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.718Z | resolving_load_balancer | dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.718Z | channel | (1) dns:server.momentohq.com callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-12-01T20:12:19.718Z | channel | (1) dns:server.momentohq.com Pick result for call [7]: QUEUE subchannel: null status: undefined undefined
D 2022-12-01T20:12:19.718Z | channel | (1) dns:server.momentohq.com callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2022-12-01T20:12:19.718Z | connectivity_state | (1) dns:server.momentohq.com CONNECTING -> CONNECTING
D 2022-12-01T20:12:19.718Z | subchannel | (8) 54.186.170.81:443 creating HTTP/2 session
{"level":20,"time":1669925539717,"pid":97231,"hostname":"neutraljanet.local","name":"RetryInterceptor","msg":"Request path: /cache_client.Scs/Set; response status code: 14; number of retries (0) is less than max (3), retrying."}
D 2022-12-01T20:12:19.752Z | subchannel | (8) 54.186.170.81:443 CONNECTING -> READY
D 2022-12-01T20:12:19.752Z | pick_first | Pick subchannel with address 54.186.170.81:443
D 2022-12-01T20:12:19.752Z | pick_first | CONNECTING -> READY
D 2022-12-01T20:12:19.752Z | resolving_load_balancer | dns:server.momentohq.com CONNECTING -> READY
D 2022-12-01T20:12:19.752Z | channel | (1) dns:server.momentohq.com callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2022-12-01T20:12:19.752Z | channel | (1) dns:server.momentohq.com Pick result for call [7]: COMPLETE subchannel: (8) 54.186.170.81:443 status: undefined undefined
D 2022-12-01T20:12:19.752Z | connectivity_state | (1) dns:server.momentohq.com CONNECTING -> READY
D 2022-12-01T20:12:19.752Z | subchannel_refcount | (8) 54.186.170.81:443 refcount 1 -> 2
D 2022-12-01T20:12:19.752Z | subchannel_refcount | (8) 54.186.170.81:443 refcount 2 -> 1
D 2022-12-01T20:12:19.753Z | call_stream | Starting stream [7] on subchannel (8) 54.186.170.81:443 with headers
		cache: default-cache
		authorization:  REDACTED
		grpc-accept-encoding: identity,deflate,gzip
		accept-encoding: identity
		:authority: REDACTED
		user-agent: grpc-node-js/1.5.10
		content-type: application/grpc
		:method: POST
		:path: /cache_client.Scs/Set
		te: trailers

D 2022-12-01T20:12:19.753Z | subchannel_flowctrl | (8) 54.186.170.81:443 local window size: 65535 remote window size: 65535
D 2022-12-01T20:12:19.753Z | subchannel_internals | (8) 54.186.170.81:443 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2022-12-01T20:12:19.753Z | call_stream | [7] attachHttp2Stream from subchannel 54.186.170.81:443
D 2022-12-01T20:12:19.753Z | subchannel_refcount | (8) 54.186.170.81:443 callRefcount 0 -> 1
D 2022-12-01T20:12:19.764Z | subchannel | (8) 54.186.170.81:443 new settings received: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":1048576,"maxFrameSize":16384,"maxConcurrentStreams":100,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
D 2022-12-01T20:12:19.764Z | subchannel | (8) 54.186.170.81:443 local settings acknowledged by remote: {"headerTableSize":4096,"enablePush":true,"initialWindowSize":65535,"maxFrameSize":16384,"maxConcurrentStreams":4294967295,"maxHeaderListSize":4294967295,"maxHeaderSize":4294967295,"enableConnectProtocol":false}
D 2022-12-01T20:13:09.704Z | call_stream | [7] cancelWithStatus code: 4 details: "Deadline exceeded"
D 2022-12-01T20:13:09.704Z | call_stream | [7] ended with status: code=4 details="Deadline exceeded"
D 2022-12-01T20:13:09.704Z | subchannel_refcount | (8) 54.186.170.81:443 callRefcount 1 -> 0
D 2022-12-01T20:13:09.704Z | call_stream | [7] close http2 stream with code 8
d5fe8810-e29a-4288-b191-39e5f21d24ea ERROR TimeoutError: 4 DEADLINE_EXCEEDED: undefined
 TimeoutError: 4 DEADLINE_EXCEEDED: undefined
    at cacheServiceErrorMapper (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:28189:14)
    at Object.callback (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:28623:20)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9829:30)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7386:31
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9425:9)
    at InterceptingListenerImpl.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7382:23)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7386:31
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:28049:23)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9644:140)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9612:175)
D 2022-12-01T20:13:09.706Z | call_stream | [7] HTTP/2 stream closed with code 8
d5fe8810-e29a-4288-b191-39e5f21d24ea-1669925539061 Failed to send a response because the Lambda Function timed out. If this happens again, you can increase the function timeout or use the --increase-timeout option with "sst start". Read more about the option here: https://docs.sst.dev/packages/cli#options

Note that we have our own custom retry interceptor in play here; you can see a log message near the bottom where it sees the 14 and then retries:

{"level":20,"time":1669925539717,"pid":97231,"hostname":"neutraljanet.local","name":"RetryInterceptor","msg":"Request path: /cache_client.Scs/Set; response status code: 14; number of retries (0) is less than max (3), retrying."}

However, I am still hitting basically the same behavior if I turn off our retry interceptor; first request gets a 14, one of the next few requests times out.

[murgatroid99]

OK, that's not what I was expecting. The log shows that the client does reconnect to the server, but it looks like the server just doesn't respond to the request.

There's a good chance that upgrading the gRPC library will help here, or at least give better logs. I notice that the logs don't show the client redoing DNS resolution after the connection dropped. That looks like a bug that was fixed in a version after the one you are using, and it might be related to the problem you are seeing.

[cprice404]

Here's what happens in local SST environment with grpc-js upgraded to 1.7.3 and my retry interceptor disabled:

ff91e571-7375-4408-a60a-ed15f3fc6483 REQUEST dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh [functions/lambda.handler] invoked
EVENT IS: {}
EVENT REQUEST CONTEXT: {
  "callbackWaitsForEmptyEventLoop": true,
  "functionVersion": "$LATEST",
  "functionName": "dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh",
  "memoryLimitInMB": "1024",
  "clientContext": {},
  "identity": {},
  "invokedFunctionArn": "arn:aws:lambda:us-west-2:266697619022:function:dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh",
  "awsRequestId": "ff91e571-7375-4408-a60a-ed15f3fc6483"
}
{"level":10,"time":1669930841166,"pid":99356,"hostname":"neutraljanet.local","name":"_MomentoCache","msg":"Issuing 'get' request; key: foooooo"}
Current channel state: 2
D 2022-12-01T21:40:41.167Z | channel | (2) dns:server.momentohq.com createCall [7] method="/cache_client.Scs/Get", deadline=Thu Dec 01 2022 13:41:31 GMT-0800 (Pacific Standard Time)
D 2022-12-01T21:40:41.167Z | call_stream | [7] Sending metadata
D 2022-12-01T21:40:41.167Z | channel | (2) dns:server.momentohq.com Pick result for call [7]: COMPLETE subchannel: (10) 54.186.170.81:443 status: undefined undefined
D 2022-12-01T21:40:41.167Z | call_stream | [7] write() called with message of length 9
D 2022-12-01T21:40:41.167Z | call_stream | [7] end() called
D 2022-12-01T21:40:41.168Z | call_stream | Starting stream [7] on subchannel (10) 54.186.170.81:443 with headers
		cache: default-cache
		authorization: REDACTED
		grpc-timeout: 50000m
		grpc-accept-encoding: identity,deflate,gzip
		accept-encoding: identity
		:authority: server.momentohq.com
		user-agent: grpc-node-js/1.7.3
		content-type: application/grpc
		:method: POST
		:path: /cache_client.Scs/Get
		te: trailers

D 2022-12-01T21:40:41.168Z | subchannel_flowctrl | (10) 54.186.170.81:443 local window size: 65528 remote window size: 1048546
D 2022-12-01T21:40:41.168Z | subchannel_internals | (10) 54.186.170.81:443 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2022-12-01T21:40:41.168Z | call_stream | [7] attachHttp2Stream from subchannel 54.186.170.81:443
D 2022-12-01T21:40:41.168Z | subchannel_refcount | (10) 54.186.170.81:443 callRefcount 0 -> 1
D 2022-12-01T21:40:41.168Z | call_stream | [7] sending data chunk of length 14
D 2022-12-01T21:40:41.168Z | call_stream | [7] calling end() on HTTP/2 stream
D 2022-12-01T21:40:41.180Z | call_stream | [7] Node error event: message=read ECONNRESET code=ECONNRESET errno=Unknown system error -54 syscall=read
D 2022-12-01T21:40:41.180Z | subchannel | (10) 54.186.170.81:443 connection closed with error read ECONNRESET
D 2022-12-01T21:40:41.181Z | subchannel | (10) 54.186.170.81:443 connection closed
D 2022-12-01T21:40:41.181Z | subchannel | (10) 54.186.170.81:443 READY -> IDLE
D 2022-12-01T21:40:41.181Z | subchannel_refcount | (10) 54.186.170.81:443 refcount 2 -> 1
D 2022-12-01T21:40:41.181Z | pick_first | READY -> IDLE
D 2022-12-01T21:40:41.181Z | resolving_load_balancer | dns:server.momentohq.com READY -> IDLE
D 2022-12-01T21:40:41.181Z | connectivity_state | (2) dns:server.momentohq.com READY -> IDLE
D 2022-12-01T21:40:41.181Z | call_stream | [7] HTTP/2 stream closed with code 2
D 2022-12-01T21:40:41.181Z | call_stream | [7] ended with status: code=14 details="read ECONNRESET"
D 2022-12-01T21:40:41.181Z | subchannel_refcount | (10) 54.186.170.81:443 callRefcount 1 -> 0
ff91e571-7375-4408-a60a-ed15f3fc6483 ERROR InternalServerError: 14 UNAVAILABLE: read ECONNRESET
 Error: 14 UNAVAILABLE: read ECONNRESET
    at Object.callErrorFromStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9236:21)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9849:46)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7369:31
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9431:9)
    at InterceptingListenerImpl.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7365:23)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9650:140)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9618:175)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7428:77
    at processTicksAndRejections (node:internal/process/task_queues:78:11)
for call at
    at ScsClient.makeUnaryRequest (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9820:34)
    at ScsClient.Get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:10129:19)
    at ScsClient.Get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29266:20)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29483:38
    at new Promise (<anonymous>)
    at _MomentoCache.sendGet (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29481:18)
    at _MomentoCache.get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29472:31)
    at SimpleCacheClient.get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29651:25)
    at getCacheValue (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29839:41)
    at Runtime.handler (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29872:29)
Background task running! Counter is: 152
Background task running! Counter is: 153
D 2022-12-01T21:40:50.286Z | subchannel_refcount | (10) 54.186.170.81:443 refcount 1 -> 0
f0fa380b-88f2-4915-8c04-38d269aa4c12 REQUEST dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh [functions/lambda.handler] invoked
EVENT IS: {}
EVENT REQUEST CONTEXT: {
  "callbackWaitsForEmptyEventLoop": true,
  "functionVersion": "$LATEST",
  "functionName": "dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh",
  "memoryLimitInMB": "1024",
  "clientContext": {},
  "identity": {},
  "invokedFunctionArn": "arn:aws:lambda:us-west-2:266697619022:function:dev-my-sst-app-MyStack-apiLambdaGET2D5CB7A7-kd9VbLCGPlkh",
  "awsRequestId": "f0fa380b-88f2-4915-8c04-38d269aa4c12"
}
{"level":10,"time":1669930850913,"pid":99356,"hostname":"neutraljanet.local","name":"_MomentoCache","msg":"Issuing 'get' request; key: foooooo"}
Current channel state: 2
D 2022-12-01T21:40:50.913Z | channel | (3) dns:server.momentohq.com createCall [8] method="/cache_client.Scs/Get", deadline=Thu Dec 01 2022 13:41:40 GMT-0800 (Pacific Standard Time)
D 2022-12-01T21:40:50.914Z | call_stream | [8] Sending metadata
D 2022-12-01T21:40:50.914Z | channel | (3) dns:server.momentohq.com Pick result for call [8]: COMPLETE subchannel: (12) 54.186.170.81:443 status: undefined undefined
D 2022-12-01T21:40:50.914Z | call_stream | [8] write() called with message of length 9
D 2022-12-01T21:40:50.914Z | call_stream | [8] end() called
D 2022-12-01T21:40:50.915Z | call_stream | Starting stream [8] on subchannel (12) 54.186.170.81:443 with headers
		cache: default-cache
		authorization: REDACTED
		grpc-timeout: 49999m
		grpc-accept-encoding: identity,deflate,gzip
		accept-encoding: identity
		:authority: server.momentohq.com
		user-agent: grpc-node-js/1.7.3
		content-type: application/grpc
		:method: POST
		:path: /cache_client.Scs/Get
		te: trailers

D 2022-12-01T21:40:50.915Z | subchannel_flowctrl | (12) 54.186.170.81:443 local window size: 65516 remote window size: 1048562
D 2022-12-01T21:40:50.915Z | subchannel_internals | (12) 54.186.170.81:443 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2022-12-01T21:40:50.915Z | call_stream | [8] attachHttp2Stream from subchannel 54.186.170.81:443
D 2022-12-01T21:40:50.915Z | subchannel_refcount | (12) 54.186.170.81:443 callRefcount 0 -> 1
D 2022-12-01T21:40:50.915Z | call_stream | [8] sending data chunk of length 14
D 2022-12-01T21:40:50.915Z | call_stream | [8] calling end() on HTTP/2 stream
D 2022-12-01T21:40:50.927Z | call_stream | [8] Node error event: message=read ECONNRESET code=ECONNRESET errno=Unknown system error -54 syscall=read
D 2022-12-01T21:40:50.927Z | subchannel | (12) 54.186.170.81:443 connection closed with error read ECONNRESET
D 2022-12-01T21:40:50.927Z | subchannel | (12) 54.186.170.81:443 connection closed
D 2022-12-01T21:40:50.927Z | subchannel | (12) 54.186.170.81:443 READY -> IDLE
D 2022-12-01T21:40:50.927Z | subchannel_refcount | (12) 54.186.170.81:443 refcount 2 -> 1
D 2022-12-01T21:40:50.927Z | pick_first | READY -> IDLE
D 2022-12-01T21:40:50.927Z | resolving_load_balancer | dns:server.momentohq.com READY -> IDLE
D 2022-12-01T21:40:50.927Z | connectivity_state | (3) dns:server.momentohq.com READY -> IDLE
D 2022-12-01T21:40:50.927Z | call_stream | [8] HTTP/2 stream closed with code 2
D 2022-12-01T21:40:50.927Z | call_stream | [8] ended with status: code=14 details="read ECONNRESET"
D 2022-12-01T21:40:50.927Z | subchannel_refcount | (12) 54.186.170.81:443 callRefcount 1 -> 0
f0fa380b-88f2-4915-8c04-38d269aa4c12 ERROR InternalServerError: 14 UNAVAILABLE: read ECONNRESET
 Error: 14 UNAVAILABLE: read ECONNRESET
    at Object.callErrorFromStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9236:21)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9849:46)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7369:31
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9431:9)
    at InterceptingListenerImpl.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7365:23)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9650:140)
    at Object.onReceiveStatus (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9618:175)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:7428:77
    at processTicksAndRejections (node:internal/process/task_queues:78:11)
for call at
    at ScsClient.makeUnaryRequest (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:9820:34)
    at ScsClient.Get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:10129:19)
    at ScsClient.Get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29266:20)
    at file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29483:38
    at new Promise (<anonymous>)
    at _MomentoCache.sendGet (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29481:18)
    at _MomentoCache.get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29472:31)
    at SimpleCacheClient.get (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29651:25)
    at getCacheValue (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29839:41)
    at Runtime.handler (file:///Users/cprice/git/momento/client-sdk-javascript/examples/sst/my-sst-app/.sst/artifacts/dev-my-sst-app-MyStack-api-Lambda_GET_-/services/functions/lambda.js:29872:29)

So you're right that the behavior changed - it fails fast now and it's consistently UNAVAILABLE. I think I probably would have expected the connection to be refreshed automatically in this scenario but it is an improvement.

[murgatroid99]

That last log shows that the two requests were made on separate channels, with separate connections. Each one of them seems to be going through the first part of the process I described earlier, where they try to make a request, discover that the connection no longer exists, and drop the connection. But that means that we are not seeing any reconnection attempts that might happen after that. In the original log, the two failing requests are made on the same channel by the retry interceptor, which explains why we did see a reconnect attempt in that case.

The two channels already exist before the log starts, and they do not share the connection even though they have the same target, so I am guessing that your code does round robin over a channel pool that is deliberately avoids channel sharing. If so, after a long idle period this will happen once with each channel in the pool.

Can you make a second request attempt with a single channel, either by disabling the channel pooling (if that's what this is) or by making enough requests to go around the whole pool.

[cprice404]

You're correct that we have a pool. I'll reduce the size to 1 and run it again. Thanks for catching that.

[cprice404]

Okay, after getting rid of the pool the observations are:

• With no retry interceptor, the first request after the timeout fails fast with UNAVAILABLE and subsequent requests succeed.
• With the retry interceptor, the first request after the timeout fails fast with UNAVAILABLE but is retried by the interceptor, and there it still hangs until a client-side DEADLINE_EXCEEDED is hit. Subsequent requests succeed.

Is this the expected behavior?

[murgatroid99]

The first one is the expected behavior. If you are seeing additional failures only when using the retry interceptor, it seems likely that the interceptor itself is causing the problem.

Looking again at the first log you shared, the following lines are present in the request that fails with UNAVAILABLE, but the corresponding lines are not present in the request that fails with DEADLINE_EXCEEDED:

D 2022-12-01T20:12:19.703Z | call_stream | [6] write() called with message of length 25
D 2022-12-01T20:12:19.703Z | call_stream | [6] end() called

It looks to me like the retry interceptor is starting a second attempt, but not re-sending the message or half close. I would expect this to cause DEADLINE_EXCEEDED errors because the server is waiting to receive those things before responding.

[cprice404]

Interesting. Our retry interceptor was mostly just copied from something we found as a top answer on stackoverflow or similar. So we are just calling nextCall, etc. Is there a state of the art example for how you recommend to handle retries? You mentioned that it might be bundled in an upcoming release?

Thanks so much for your help diagnosing this. Since it's more and more starting to look like PEBKAC I really appreciate the time you've spent to help root cause it.

[murgatroid99]

I believe that the retry interceptor in #284 (comment) works, but I haven't tested it much myself.

The built in retry implementation should be out this week assuming everything goes well. The spec for that feature is here, and you might want to check it out to see if it will serve your use case.

[cprice404]

Thanks. Comparing our interceptor to the one that you linked, it looks like we might have copy/pasted from an older version of it that was missing a few things. I'll compare our code with that code, and look at the spec.

Thanks again for your help. I'll close this for now and re-open or open a new ticket if this doesn't resolve things for us.