unavailable (14): The RPC has already completed

[ShivamKP-Algoworks]

I am using Bidirectional Stream for sending Audio and other stuff.
Once I login successfully then we initialize the streamer(We initialize the channel and then client)
If I send data using a Bidirectional stream that working fine
Means I use
self.bidiStream?.sendMessage(DialogRequestHandler().createCompositionCreationRequest(), promise: nil)
if I use the app continuously then it's working fine
but if I put the app into the idle mode for more than 10 mins means the app is in the foreground but I am not using it, no action made, After that, I use the App means create any request using the same function
self.bidiStream?.sendMessage(DialogRequestHandler().createCompositionCreationRequest(), promise: nil)

It's giving me an error:-
unavailable (14): The RPC has already completed

and application is getting stuck, I can't use it anymore
Do you have any idea why It's happening?

Even the channel is working fine because I hit ping pong request every 2 sec to check whether the channel working fine or not
and the channel working fine I have checked that.

So Could you help me, how can I get a callback if I receive any error in GRPC So that I can reinitialize the stream?
I am using multiple requests So I need to find a common callback where I can handle GRPC error for all requests.

Thanks !!!

[glbrntt]

In future, please use one of the issue templates when filing an issue.

---

The problem is quite clear: "The RPC has already completed", the question is really why has the RPC already completed?

Without knowing more it's difficult to say. The logs are usually a good place to start; can you attach some? See here: https://github.com/grpc/grpc-swift/blob/main/docs/faqs.md#is-logging-supported on how to configure a logger. Please also set the logger level to trace.

[ShivamKP-Algoworks]

I added the logger and also set the level to trace.

2021-02-03T17:19:45+0530 debug com.queue.logging : request_part=message grpc_request_id=58349A8D-84E2-45CC-A688-EBA0122FD65C grpc_connection_id=0C3F8933-556C-4A43-9296-17B6BD285506/0 unbuffering request part
2021-02-03T17:19:45+0530 trace com.queue.logging : h2_payload=DATA grpc_request_id=58349A8D-84E2-45CC-A688-EBA0122FD65C h2_end_stream=false grpc_connection_id=0C3F8933-556C-4A43-9296-17B6BD285506/0 h2_data_bytes=20 writing HTTP2 frame
2021-02-03T17:29:13+0530 debug com.queue.logging : request_part=metadata call_state=awaitingTransport (0 parts buffered) grpc_request_id=B6B10D26-9D8B-4948-A3F5-2EF6B26CC00B grpc_connection_id=0C3F8933-556C-4A43-9296-17B6BD285506/0 buffering request part
2021-02-03T17:29:13+0530 debug com.queue.logging : grpc_request_id=B6B10D26-9D8B-4948-A3F5-2EF6B26CC00B request_part=message grpc_connection_id=0C3F8933-556C-4A43-9296-17B6BD285506/0 call_state=awaitingTransport (1 parts buffered) buffering request part
2021-02-03T17:29:13+0530 debug com.queue.logging : grpc_connection_id=0C3F8933-556C-4A43-9296-17B6BD285506/0 call_state=awaitingTransport (2 parts buffered) grpc_request_id=B6B10D26-9D8B-4948-A3F5-2EF6B26CC00B request_part=end buffering request part

This is what I am getting.

Thanks !!!

[glbrntt]

Can you add the background activity logger (same docs as above)?

---

You have 2 RPCs here ('grpc_request_id') -- is that expected?

[ShivamKP-Algoworks]

You have 2 RPCs here ('grpc_request_id') -- is that expected?
:- Regarding this

We are creating every time a new request after 2 sec for checking ping pong request success.

Can you add the background activity logger (same docs as above)?

I have added this too.
and some of the more logs are:-

2021-02-03T20:04:36+0530 debug com.queue.logging : call_state=awaitingTransport (0 parts buffered) grpc_connection_id=D3DCAE3E-3BE7-464A-8FFB-9280A2B1EF1D/0 grpc_request_id=2D07D449-6E4A-41FE-8BB1-C6AC25037B5D request_part=metadata buffering request part

2021-02-03T20:04:36+0530 debug com.queue.logging : grpc_request_id=2D07D449-6E4A-41FE-8BB1-C6AC25037B5D grpc_connection_id=D3DCAE3E-3BE7-464A-8FFB-9280A2B1EF1D/0 call_state=awaitingTransport (1 parts buffered) request_part=message buffering request part

2021-02-03T20:04:36+0530 debug com.queue.logging : call_state=awaitingTransport (2 parts buffered) grpc_connection_id=D3DCAE3E-3BE7-464A-8FFB-9280A2B1EF1D/0 grpc_request_id=2D07D449-6E4A-41FE-8BB1-C6AC25037B5D request_part=end buffering request part

[ShivamKP-Algoworks]

Hi @glbrntt

I just run the app and after initializing the stream
I create a request in GRPC then the log is:-

2021-02-04T14:08:53+0530 trace com.queue.logging : h2_payload=DATA h2_end_stream=false grpc_connection_id=BFDA1241-9C41-4561-871F-C9B2FE0688A6/0 h2_data_bytes=21 grpc_request_id=A3839875-1A0E-4B94-9000-342FFA5C311D writing HTTP2 frame

2021-02-04T14:08:53+0530 trace com.queue.logging : h2_data_bytes=47 grpc_request_id=A3839875-1A0E-4B94-9000-342FFA5C311D grpc_connection_id=BFDA1241-9C41-4561-871F-C9B2FE0688A6/0 h2_payload=DATA h2_end_stream=false received HTTP2 frame

That's. fine, But after appx 5mins
I just saw the logs i.e.

2021-02-04T14:13:57+0530 error com.queue.logging : grpc_request_id=A3839875-1A0E-4B94-9000-342FFA5C311D grpc_connection_id=BFDA1241-9C41-4561-871F-C9B2FE0688A6/0 error=StreamClosed(streamID: HTTP2StreamID(3), errorCode: HTTP2ErrorCode<0x0 No Error>, location: "/Users/shivam/Documents/Github/suki/ios/Pods/SwiftNIOHTTP2/Sources/NIOHTTP2/HTTP2StreamChannel.swift:788") grpc client error

2021-02-04T14:13:57+0530 debug com.queue.logging : grpc_request_id=A3839875-1A0E-4B94-9000-342FFA5C311D grpc_connection_id=BFDA1241-9C41-4561-871F-C9B2FE0688A6/0 call_state=closing failing buffered writes

Here you can see the error is coming StreamClosed
and after that, I try to create a request then nothing happens and the app stuck because the stream has been closed.

I hope the above logs will help

Thanks !!!

[glbrntt]

We are creating every time a new request after 2 sec for checking ping pong request success.

Not exactly related to your problem but configuring keepalive may be better than manually sending requests to do the same: https://github.com/grpc/grpc-swift/blob/main/docs/keepalive.md

---

It's a stream closed error with error code 'no error'; this could be the server closing the RPC.

Could you attach all the logs?

---

I try to create a request then nothing happens and the app stuck because the stream has been closed.

The app being stuck I can't help you with: it's up to you to notice that the RPC has ended (by looking at the status on the call object returns from the client).

[ShivamKP-Algoworks]

@glbrntt

Could you attach all the logs?

2021-02-04T16:30:34+0530 trace com.queue.logging : h2_end_stream=false grpc_connection_id=42E332AF-06E1-42DC-AC99-FCA7147156AD/0 h2_data_bytes=21 grpc_request_id=2ADF614E-4480-4AC6-A5CF-DC23A1F96A8C h2_payload=DATA writing HTTP2 frame

2021-02-04T16:30:35+0530 trace com.queue.logging : h2_payload=HEADERS grpc_request_id=2ADF614E-4480-4AC6-A5CF-DC23A1F96A8C h2_headers=[([], ":status", "200"), ([], "content-type", "application/grpc"), ([], "grpc-accept-encoding", "identity,deflate,gzip"), ([], "accept-encoding", "identity,gzip"), ([], "x-content-type-options", "nosniff"), ([], "x-frame-options", "deny"), ([], "x-xss-protection", "1; mode=block"), ([], "strict-transport-security", "max-age=63072000; includeSubDomains; preload;"), ([], "content-security-policy", "default-src 'none'; frame-ancestors 'none';"), ([], "date", "Thu, 04 Feb 2021 11:00:35 GMT"), ([], "server", "envoy")] h2_end_stream=false grpc_connection_id=42E332AF-06E1-42DC-AC99-FCA7147156AD/0 received HTTP2 frame

2021-02-04T16:30:35+0530 trace com.queue.logging : grpc_request_id=2ADF614E-4480-4AC6-A5CF-DC23A1F96A8C h2_data_bytes=7 h2_end_stream=false h2_payload=DATA grpc_connection_id=42E332AF-06E1-42DC-AC99-FCA7147156AD/0 received HTTP2 frame

2021-02-04T16:35:35+0530 error com.queue.logging : grpc_request_id=2ADF614E-4480-4AC6-A5CF-DC23A1F96A8C error=StreamClosed(streamID: HTTP2StreamID(3), errorCode: HTTP2ErrorCode<0x0 No Error>, location: "/Users/shivam/Documents/Github/suki/ios/Pods/SwiftNIOHTTP2/Sources/NIOHTTP2/HTTP2StreamChannel.swift:788") grpc_connection_id=42E332AF-06E1-42DC-AC99-FCA7147156AD/0 grpc client error

2021-02-04T16:35:35+0530 debug com.queue.logging : grpc_request_id=2ADF614E-4480-4AC6-A5CF-DC23A1F96A8C call_state=closing grpc_connection_id=42E332AF-06E1-42DC-AC99-FCA7147156AD/0 failing buffered writes

This is What I am getting.

Thanks !!!

[glbrntt]

I think your background activity logger isn't configured correctly because there would be more logs (i.e. connection state information) if it was. Nevertheless, I don't think that matters here, there are few hints from the logs:

1. the ([], "server", "envoy") header
2. 16:30:35 received HTTP2 frame
3. 16:35:35 stream closed with no error

The 5 minute gap between receiving a frame and the stream closing with no error is almost certainly an Envoy idle timeout, specifically the stream idle timeout which defaults to 5 minutes.

[ShivamKP-Algoworks]

Hi @glbrntt
Sorry for the late reply!

We have changed the Stream idle time out is to infinity (at envoy server).
But also we are getting the same issue means exact after 5 min the stream is getting closed.

Here is the logs:-
2021-02-11T11:28:46+0530 trace com.queue.logging : h2_payload=HEADERS h2_end_stream=false grpc_connection_id=5A3B5209-62DB-4672-9C6E-85DC9A8A6D53/0 h2_headers=[([], ":status", "200"), ([], "content-type", "application/grpc"), ([], "grpc-accept-encoding", "identity,deflate,gzip"), ([], "accept-encoding", "identity,gzip"), ([], "x-content-type-options", "nosniff"), ([], "x-frame-options", "deny"), ([], "x-xss-protection", "1; mode=block"), ([], "strict-transport-security", "max-age=63072000; includeSubDomains; preload;"), ([], "content-security-policy", "default-src 'none'; frame-ancestors 'none';"), ([], "date", "Thu, 11 Feb 2021 05:58:45 GMT"), ([], "server", "envoy")] grpc_request_id=F8EACC1F-0E58-408B-8A12-ADE656FC9C33 received HTTP2 frame

2021-02-11T11:28:46+0530 trace com.queue.logging : h2_payload=DATA h2_data_bytes=7 h2_end_stream=false grpc_connection_id=5A3B5209-62DB-4672-9C6E-85DC9A8A6D53/0 grpc_request_id=F8EACC1F-0E58-408B-8A12-ADE656FC9C33 received HTTP2 frame

2021-02-11T11:33:46+0530 error com.queue.logging : grpc_connection_id=5A3B5209-62DB-4672-9C6E-85DC9A8A6D53/0 error=StreamClosed(streamID: HTTP2StreamID(3), errorCode: HTTP2ErrorCode<0x0 No Error>, location: "/Users/shivam/Documents/Github/suki/ios/Pods/SwiftNIOHTTP2/Sources/NIOHTTP2/HTTP2StreamChannel.swift:788") grpc_request_id=F8EACC1F-0E58-408B-8A12-ADE656FC9C33 grpc client error

2021-02-11T11:33:46+0530 debug com.queue.logging : grpc_connection_id=5A3B5209-62DB-4672-9C6E-85DC9A8A6D53/0 call_state=closing grpc_request_id=F8EACC1F-0E58-408B-8A12-ADE656FC9C33 failing buffered writes

[glbrntt]

Just to check, do you have a deadline set on the RPC? (i.e. set via CallOptions)?

Either way, something appears to still closing the stream early. Is there any other Envoy configuration which might cause this? Are there Envoy logs which you can use to determine what's going on here?