fix(ext/node): send data frame with end_stream flag on _final call

[satyarohith]

We previously ended the http2 stream by sending trailers which should have been only used if waitForTrailers option is set on the http2session. This patch updates it and ends the stream by sending an empty data frame with end_stream flag set or by emitting 'wantTrailers' event if waitForTrailers option is set.

Hard to create an unit test as this requires that a test server needs to ack end of stream flag and then process a request. The example from #24058 works.

Closes #24058

[rnbguy]

Just wanted to report:

1. somehow this still doesn't work when I use deno run npm:@informalsystems/quint. Is there anything I need to take care of when I am using @grpc/grpc-js inside an npm package?
2. I still get warning: Warning: Not implemented: Http2Session.socket.

Otherwise, it works with my provided deno script: ping_apalache.ts. ✨

I will try to port @informalsystems/quint to deno and release it at jsr 🙌 Thanks for addressing the issue 🙏

[satyarohith]

1. somehow this still doesn't work when I use deno run npm:@informalsystems/quint. Is there anything I need to take care of when I am using @grpc/grpc-js inside an npm package?

Can you open a separate issue with debug (use GRPC_VERBOSITY=debug GRPC_TRACE=all to enable them) logs? We're happy to look into it.

2. I still get warning: Warning: Not implemented: Http2Session.socket.

gRPC package depends on .socket for debug/trace information. It doesn't effect the core functionality so you can ignore the warning.

[rnbguy]

Thanks for your reply. This is the log from deno run npm:@informalsystems/quint

...
Warning: Not implemented: Http2Session.socket
D 2024-06-10T09:26:54.639Z | v1.10.8 627447 | transport_internals | (1) 127.0.0.1:8822 session.closed=false session.destroyed=false session.socket.destroyed=undefined
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | load_balancing_call | [6] Created child call [7]
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | retrying_call | [5] write() called with message of length 990524
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | load_balancing_call | [6] write() called with message of length 990524
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | subchannel_call | [7] write() called with message of length 990524
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | subchannel_call | [7] sending data chunk of length 990524
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | retrying_call | [5] halfClose called
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | load_balancing_call | [6] halfClose called
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | subchannel_call | [7] end() called
D 2024-06-10T09:26:54.640Z | v1.10.8 627447 | subchannel_call | [7] calling end() on HTTP/2 stream
D 2024-06-10T09:26:54.642Z | v1.10.8 627447 | subchannel_call | [3] Received server trailers:
                grpc-status: 0

D 2024-06-10T09:26:54.642Z | v1.10.8 627447 | subchannel_call | [3] received status code 0 from server
D 2024-06-10T09:26:54.643Z | v1.10.8 627447 | subchannel_call | [3] ended with status: code=0 details=""
D 2024-06-10T09:26:54.644Z | v1.10.8 627447 | load_balancing_call | [2] Received status
D 2024-06-10T09:26:54.644Z | v1.10.8 627447 | load_balancing_call | [2] ended with status: code=0 details="" start time=2024-06-10T09:26:54.601Z
D 2024-06-10T09:26:54.644Z | v1.10.8 627447 | retrying_call | [1] Received status from child [2]
D 2024-06-10T09:26:54.644Z | v1.10.8 627447 | retrying_call | [1] state=COMMITTED handling status with progress PROCESSED from child [2] in state ACTIVE
D 2024-06-10T09:26:54.644Z | v1.10.8 627447 | retrying_call | [1] ended with status: code=0 details="" start time=2024-06-10T09:26:54.600Z
D 2024-06-10T09:26:54.644Z | v1.10.8 627447 | resolving_call | [0] Received status
D 2024-06-10T09:26:54.644Z | v1.10.8 627447 | resolving_call | [0] ended with status: code=0 details=""
D 2024-06-10T09:26:56.523Z | v1.10.8 627447 | subchannel_call | [7] Received server headers:
                :status: 200
                content-type: application/grpc
                grpc-encoding: identity
                grpc-accept-encoding: gzip

D 2024-06-10T09:26:56.523Z | v1.10.8 627447 | load_balancing_call | [6] Received metadata
D 2024-06-10T09:26:56.523Z | v1.10.8 627447 | retrying_call | [5] Received metadata from child [6]
D 2024-06-10T09:26:56.523Z | v1.10.8 627447 | retrying_call | [5] Committing call [6] at index 0
D 2024-06-10T09:26:56.523Z | v1.10.8 627447 | resolving_call | [4] Received metadata
D 2024-06-10T09:26:56.525Z | v1.10.8 627447 | subchannel_call | [7] receive HTTP/2 data frame of length 16384
D 2024-06-10T09:26:56.527Z | v1.10.8 627447 | subchannel_call | [7] receive HTTP/2 data frame of length 16384
D 2024-06-10T09:26:56.528Z | v1.10.8 627447 | subchannel_call | [7] receive HTTP/2 data frame of length 16384
D 2024-06-10T09:26:56.530Z | v1.10.8 627447 | subchannel_call | [7] receive HTTP/2 data frame of length 15502
D 2024-06-10T09:26:56.531Z | v1.10.8 627447 | subchannel_call | [7] receive HTTP/2 data frame of length 881
D 2024-06-10T09:27:04.606Z | v1.10.8 627447 | subchannel_refcount | (2) [::1]:8822 refcount 1 -> 0

(hangs)

I am also pasting the similar section of the log from the working ping_apalache.ts,

...
D 2024-06-10T09:27:51.975Z | subchannel_call | [7] Received server headers:
                :status: 200
                content-type: application/grpc
                grpc-encoding: identity
                grpc-accept-encoding: gzip

D 2024-06-10T09:27:51.975Z | load_balancing_call | [6] Received metadata
D 2024-06-10T09:27:51.975Z | retrying_call | [5] Received metadata from child [6]
D 2024-06-10T09:27:51.975Z | retrying_call | [5] Committing call [6] at index 0
D 2024-06-10T09:27:51.975Z | resolving_call | [4] Received metadata
D 2024-06-10T09:27:51.976Z | subchannel_call | [7] receive HTTP/2 data frame of length 1747
D 2024-06-10T09:27:51.976Z | subchannel_call | [7] parsed message of length 1747
D 2024-06-10T09:27:51.976Z | subchannel_call | [7] pushing to reader message of length 1747
D 2024-06-10T09:27:51.976Z | load_balancing_call | [6] Received message
D 2024-06-10T09:27:51.976Z | retrying_call | [5] Received message from child [6]
D 2024-06-10T09:27:51.976Z | resolving_call | [4] Received message
D 2024-06-10T09:27:51.976Z | subchannel_call | [7] Received server trailers:
                grpc-status: 0
...
(teminates)

[bartlomieju]

LGTM

[rnbguy]

I looked into the issue that I posted earlier. It seems that when there are multiple chunks in the response, Deno is getting stuck here after the last chunk.

deno/ext/node/polyfills/http2.ts

Lines 1009 to 1012 in 8cbf81c

	const [chunk, finished, cancelled] =
	await op_http2_client_get_response_body_chunk(
	this[kDenoResponse].bodyRid,
	);

That means, the trailer response is never ready here.

deno/ext/node/ops/http2.rs

Lines 455 to 477 in 8cbf81c

	fn poll_data_or_trailers(
	cx: &mut std::task::Context,
	body: &mut RecvStream,
	) -> Poll<Result<DataOrTrailers, h2::Error>> {
	loop {
	if let Poll::Ready(trailers) = body.poll_trailers(cx) {
	if let Some(trailers) = trailers? {
	return Poll::Ready(Ok(DataOrTrailers::Trailers(trailers)));
	} else {
	return Poll::Ready(Ok(DataOrTrailers::Eof));
	}
	}
	if let Poll::Ready(data) = body.poll_data(cx) {
	if let Some(data) = data {
	return Poll::Ready(Ok(DataOrTrailers::Data(data?)));
	}
	// If data is None, loop one more time to check for trailers
	continue;
	}
	// Return pending here as poll_data will keep the waker
	return Poll::Pending;
	}
	}