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

satyarohith · 2024-06-08T07:29:29Z

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 · 2024-06-09T19:56:55Z

Just wanted to report:

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?
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 · 2024-06-10T04:24:34Z

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.

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 · 2024-06-10T09:33:05Z

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

…24147)

rnbguy · 2024-07-12T12:40:11Z

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; 

 } 

 }

satyarohith added 2 commits June 8, 2024 12:57

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

e0da904

fix tests

8739e48

satyarohith requested a review from bartlomieju June 8, 2024 13:02

satyarohith enabled auto-merge (squash) June 10, 2024 11:50

bartlomieju approved these changes Jun 10, 2024

View reviewed changes

satyarohith merged commit 4fd3d5a into denoland:main Jun 10, 2024
17 checks passed

satyarohith deleted the fix_grpc_24058 branch June 11, 2024 14:08

satyarohith mentioned this pull request Jun 11, 2024

Not implemented: Http2Session.socket #20903

Open

nathanwhit pushed a commit that referenced this pull request Jun 13, 2024

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

702235b

…24147)

rnbguy mentioned this pull request Jul 12, 2024

large multi-chunk GRPC responses get stuck #24552

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

satyarohith commented Jun 8, 2024 •

edited

Loading

rnbguy commented Jun 9, 2024

satyarohith commented Jun 10, 2024

rnbguy commented Jun 10, 2024

bartlomieju left a comment

rnbguy commented Jul 12, 2024 •

edited

Loading

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

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

Conversation

satyarohith commented Jun 8, 2024 • edited Loading

rnbguy commented Jun 9, 2024

satyarohith commented Jun 10, 2024

rnbguy commented Jun 10, 2024

bartlomieju left a comment

Choose a reason for hiding this comment

rnbguy commented Jul 12, 2024 • edited Loading

satyarohith commented Jun 8, 2024 •

edited

Loading

rnbguy commented Jul 12, 2024 •

edited

Loading