Questions about grpc-node client streaming

244 views
Skip to first unread message

Kyaw Thit Lwin

unread,
Jan 3, 2024, 1:47:56 AMJan 3
to grpc.io
Hi guys, I have some confusions about grpc-js client streaming. Sorry for the long question.
 
    I have encountered multiple errors, 13 INTERNAL: Received RST_STREAM with code 2 triggered by internal client error: Session closed with error code 2 during the load testing. May I know what could trigger this error?
 
    I have the following grpc server and client implementation, referencing from https://github.com/grpc/grpc-node/blob/master/examples/metadata/server.js.
Client
function clientStreamingWithMetadata(client, message) {
return new Promise((resolve, reject) => {
const requestMetadata = new grpc.Metadata();
requestMetadata.set('timestamp', new Date().toISOString());
const call = client.clientStreamingEcho(requestMetadata, (error, value) => {
if (error) {
console.log(`Received error ${error}`);
return;
}
});
call.on('status', status => {
const timestamps = status.metadata.get('timestamp');
if (timestamps.length == 0) {
console.error("timestamp expected but doesn't exist in trailer");
}
resolve();
});
for (let i = 0; i < STREAMING_COUNT; i++) {
call.write({message});
}
call.end();
});
}

Server
function clientStreamingEcho(call, callback) {
const incomingTimestamps = call.metadata.get('timestamp');
if (incomingTimestamps.length > 0) {
console.log('Timestamp from metadata:');
for (const [index, value] of incomingTimestamps.entries()) {
console.log(` ${index}. ${value}`);
}
}

let lastReceivedMessage = '';
call.on('data', value => {
console.log(`Received request ${JSON.stringify(value)}`);
lastReceivedMessage = value.message;
});
call.on('end', () => {
console.log("Call end!")
const outgoingTrailers = new grpc.Metadata();
outgoingTrailers.set('timestamp', new Date().toISOString());
callback(null, {message: lastReceivedMessage}, outgoingTrailers);
});
}

May I also know that do I really need to listen back to the server callback on stream end initiated by client side?

I tried running the code by removing the server callback on stream end event and remove the call.on('status') listener on the client side. Then the client stream doesn't seem to be ended even after call.end() and keep pinging the server. These are the logs from server and client.

Client
D 2024-01-03T04:11:09.279Z | v1.9.13 354656 | subchannel_call | [3] write() called with message of length 32
D 2024-01-03T04:11:09.279Z | v1.9.13 354656 | subchannel_call | [3] sending data chunk of length 32
D 2024-01-03T04:11:09.279Z | v1.9.13 354656 | load_balancing_call | [2] halfClose called
D 2024-01-03T04:11:09.279Z | v1.9.13 354656 | subchannel_call | [3] end() called
D 2024-01-03T04:11:09.279Z | v1.9.13 354656 | subchannel_call | [3] calling end() on HTTP/2 stream
D 2024-01-03T04:11:10.277Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Sending ping with timeout 20000ms
D 2024-01-03T04:11:10.277Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Received ping response
D 2024-01-03T04:11:10.277Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Starting keepalive timer for 1000ms
D 2024-01-03T04:11:11.278Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Sending ping with timeout 20000ms
D 2024-01-03T04:11:11.278Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Received ping response
D 2024-01-03T04:11:11.278Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Starting keepalive timer for 1000ms
D 2024-01-03T04:11:12.279Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Sending ping with timeout 20000ms
D 2024-01-03T04:11:12.279Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Received ping response
D 2024-01-03T04:11:12.279Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Starting keepalive timer for 1000ms
D 2024-01-03T04:11:13.281Z | v1.9.13 354656 | keepalive | (3) 127.0.0.1:50052 Sending ping with timeout 20000ms

Server
D 2024-01-03T04:11:09.278Z | v1.9.13 352893 | server_call | Received message of length 27
Received request {"message":"this is examples/metadata"}
D 2024-01-03T04:11:09.279Z | v1.9.13 352893 | server_call | Received message of length 27
Received request {"message":"this is examples/metadata"}
D 2024-01-03T04:11:09.279Z | v1.9.13 352893 | server_call | Received message of length 27
Received request {"message":"this is examples/metadata"}
D 2024-01-03T04:11:09.279Z | v1.9.13 352893 | server_call | Received end of stream
Call end!
D 2024-01-03T04:11:26.004Z | v1.9.13 352893 | server_call | Request to method /grpc.examples.echo.Echo/ClientStreamingEcho stream closed with rstCode 8


Thank you so much and appreciated any explanation.

Michael Lumish

unread,
Jan 3, 2024, 4:52:50 PMJan 3
to Kyaw Thit Lwin, grpc.io
You do need to call the callback on the server to end the call. If I am understanding correctly that those trace logs are from the test where you removed that call. In that case they will not be helpful. It would be helpful to have the logs that show the original error you were experiencing.

On the client side, you do need to pass a function for the callback parameter, but it doesn't need to do anything.

--
You received this message because you are subscribed to the Google Groups "grpc.io" group.
To unsubscribe from this group and stop receiving emails from it, send an email to grpc-io+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/9b6662fe-d368-45de-a454-a0273f0c1c09n%40googlegroups.com.

Kyaw Thit Lwin

unread,
Jan 4, 2024, 12:33:23 PMJan 4
to grpc.io
Hi,
    first of all, thank you so much for your response and sorry for the late reply.

    The below are the logs from client and server regarding to the original error, 13 INTERNAL: Received RST_STREAM with code 2 triggered by internal client error: Session closed with error code 2.

Client
D 2024-01-04T15:33:21.496Z | v1.9.13 965056 | subchannel_call | [4139] sending data chunk of length 22
D 2024-01-04T15:33:21.496Z | v1.9.13 965056 | load_balancing_call | [4138] write() called with message of length 22
D 2024-01-04T15:33:21.496Z | v1.9.13 965056 | subchannel_call | [4139] write() called with message of length 22
D 2024-01-04T15:33:21.496Z | v1.9.13 965056 | subchannel_call | [4139] sending data chunk of length 22
D 2024-01-04T15:33:21.496Z | v1.9.13 965056 | load_balancing_call | [4138] halfClose called
D 2024-01-04T15:33:21.496Z | v1.9.13 965056 | subchannel_call | [4139] end() called
D 2024-01-04T15:33:21.496Z | v1.9.13 965056 | subchannel_call | [4139] calling end() on HTTP/2 stream
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | transport | (3) 127.0.0.1:50052 connection closed by GOAWAY with code 2 and data undefined
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | subchannel | (2) 127.0.0.1:50052 READY -> IDLE
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | subchannel_refcount | (2) 127.0.0.1:50052 refcount 2 -> 1
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | pick_first | READY -> IDLE
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | resolving_load_balancer | dns:localhost:50052 READY -> IDLE
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | connectivity_state | (1) dns:localhost:50052 READY -> IDLE
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | dns_resolver | resolution update delayed by "min time between resolutions" rate limit
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | resolving_load_balancer | dns:localhost:50052 IDLE -> CONNECTING
D 2024-01-04T15:33:21.497Z | v1.9.13 965056 | connectivity_state | (1) dns:localhost:50052 IDLE -> CONNECTING
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | subchannel_call | [4139] Node error event: message=Session closed with error code 2 code=ERR_HTTP2_SESSION_ERROR errno=Unknown system error undefined syscall=undefined
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | subchannel_call | [4139] HTTP/2 stream closed with code 2
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | subchannel_call | [4139] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: Session closed with error code 2"
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | load_balancing_call | [4138] Received status
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | load_balancing_call | [4138] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: Session closed with error code 2"
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | retrying_call | [4137] Received status from child [4138]
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | retrying_call | [4137] state=TRANSPARENT_ONLY handling status with progress PROCESSED from child [4138] in state ACTIVE
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | retrying_call | [4137] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: Session closed with error code 2"
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | resolving_call | [4136] Received status
D 2024-01-04T15:33:21.498Z | v1.9.13 965056 | resolving_call | [4136] ended with status: code=13 details="Received RST_STREAM with code 2 triggered by internal client error: Session closed with error code 2"
Received error Error: 13 INTERNAL: Received RST_STREAM with code 2 triggered by internal client error: Session closed with error code 2

timestamp expected but doesn't exist in trailer

Server
D 2024-01-04T15:33:21.495Z | v1.9.13 964523 | server_call | Received message of length 17
Received request {"message":"hello metatdata"}
D 2024-01-04T15:33:21.495Z | v1.9.13 964523 | server_call | Received message of length 17
Received request {"message":"hello metatdata"}
D 2024-01-04T15:33:21.495Z | v1.9.13 964523 | server_call | Received message of length 17
Received request {"message":"hello metatdata"}
D 2024-01-04T15:33:21.495Z | v1.9.13 964523 | server_call | Received end of stream
Call end!
D 2024-01-04T15:33:21.495Z | v1.9.13 964523 | server_call | Request to method /grpc.examples.echo.Echo/ClientStreamingEcho ended with status code: OK details: OK
D 2024-01-04T15:33:21.495Z | v1.9.13 964523 | server_call | Request to method /grpc.examples.echo.Echo/ClientStreamingEcho stream closed with rstCode 0
D 2024-01-04T15:33:21.496Z | v1.9.13 964523 | server | (1) Received call to method /grpc.examples.echo.Echo/ClientStreamingEcho at address null
D 2024-01-04T15:33:21.496Z | v1.9.13 964523 | server_call | Request to /grpc.examples.echo.Echo/ClientStreamingEcho received headers {"timestamp":["2024-01-04T15:33:21.496Z"],"grpc-accept-encoding":["identity,deflate,gzip"],"accept-encoding":["identity"],"user-agent":["grpc-node-js/1.9.13"],"content-type":["application/grpc"],"te":["trailers"]}
Timestamp from metadata:
 0. 2024-01-04T15:33:21.496Z
D 2024-01-04T15:33:21.496Z | v1.9.13 964523 | server_call | Received message of length 17
Received request {"message":"hello metatdata"}
D 2024-01-04T15:33:21.497Z | v1.9.13 964523 | server_call | Request to method /grpc.examples.echo.Echo/ClientStreamingEcho stream closed with rstCode 7


And from your reply, On the client side, you do need to pass a function for the callback parameter, but it doesn't need to do anything, it means that I don't necessarily need to listen to `status` event on the client side, right?

Thank you so much.

Michael Lumish

unread,
Jan 4, 2024, 12:40:08 PMJan 4
to Kyaw Thit Lwin, grpc.io
From that trace log, it looks like this is the same error as in https://github.com/grpc/grpc-node/issues/2625. It would be helpful to consolidate further discussions of this error in that issue.

You do need a 'status' event handler if you want to always see trailers, and it looks like you do want that in your code.

Kyaw Thit Lwin

unread,
Jan 4, 2024, 2:30:31 PMJan 4
to grpc.io
Hi,
Thank you so much for the responses. I will be following up with that github issue regarding to the Session closed with error code 2 .
For the stream end and server callback, I think I understand enough from your replies.
Thanks a lot! 
Reply all
Reply to author
Forward
0 new messages