Readable end of a bidirectional stream never ends in Node.js, works in Chrome

[achingbrain]

I've created a demo here - https://github.com/achingbrain/webtransport-readable-never-ends

There's a @fails-components/webtransport server that accepts bidirectional streams. When one opens, it write a small buffer into the writable end of the stream and closes it.

On the client end, it opens the stream, and reads from the readable end until it closes.

On Chrome the buffer is received and the readable end is closed, all good.

On Node.js it receives the buffer but the readable end never closes.

This seems like a very simple use-case but I'm not sure what I'm doing wrong?

[martenrichter]

I may run the code at the end of the weekend. But so far, the code looks like it should work. Can you run it in the meantime with debug logging so that we can see what arrives at the client side? The question is whether the signals for closing the stream arrive.

[martenrichter]

May be add also some debugging output to commitReadBuffer({ buffer, byob, drained, readBytes, fin }) just print all the arguments.

[martenrichter]

I try it short on Windows. But got problems, the examples seems not to work with the v18.15.0 node version, as crypto is not exposed. Error: Cannot get Crypto by name 'default' at CryptoProvider.get (C:\PrivateDaten\Projekte\failscomponents\failslib\thirdpartystuff\bugfixachkingbrain\webtransport-readable-never-ends\node_modules\@peculiar\x509\build\x509.cjs.js:568:19)

[achingbrain]

Aha, crypto is global in Current LTS (e.g. 20.11.1). I've updated the example to work on older maintenance versions, please pull and try again.

I've patched commitReadBuffer like:

  commitReadBuffer({ buffer, byob, drained, readBytes, fin }) {
    console.info('buffer', buffer)
    console.info('byob', byob)
    console.info('drained', drained)
    console.info('readBytes', readBytes)
    console.info('fin', fin)

    //.. rest of function

Here's the debug output I see:

% DEBUG=* DEBUG_TRACE=true node index.js
  webtransport:native(49379) load webtransport binary: ../build/Release/webtransport.node +0ms
CLIENT create session
SERVER new incoming session
SERVER session ready
CLIENT session ready
CLIENT create bidi stream
CLIENT read from stream
SERVER new incoming bidi stream
SERVER await writable ready
SERVER write to writable
SERVER close writeable
buffer Uint8Array(4096) [
  0, 1, 2, 3, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
  0, 0, 0, 0,
  ... 3996 more items
]
byob ReadableStreamBYOBRequest {
  view: Uint8Array(4096) [
    0, 1, 2, 3, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
    0, 0, 0, 0,
    ... 3996 more items
  ],
  controller: ReadableByteStreamController {}
}
drained true
readBytes 4
fin false
  webtransport:http3wtstream(49379):trace commitReadbuffer 4 +0ms
CLIENT got from stream { value: Uint8Array(4) [ 0, 1, 2, 3 ], done: false }
CLIENT read from stream
  webtransport:http3wtstream(49379) callback streamFinal +0ms
  webtransport:http3wtstream(49379):trace networkfinish args { nettask: 'streamFinal' } +1ms
SERVER closed writeable

[martenrichter]

I will try the updated example on the weekend (I am currently away from the dev machine). All I see is that you did not receive a fin (which I think you should...), and the only thing you receive is a streamFinal, which does not touch the current stream. Both points can be the problem; for the last one, I have to look into the spec, and for the other one, I have to tap into the C++ code (so if you can add printf in the stream c++ object where the streamfinal is sent or received and the reading code, it may help). Anyway, I am not sure if I will be able to reproduce it since these issues are often timing-dependent.

[achingbrain]

Putting some extra logging into the C++ layer, I can see that stream_->SendFin() is called successfully by the server when it closes the write end of the stream, but when the client does the second read from the readable, stream_->ReadableBytes() returns 0 so rbuf.setFin() is never called.

Anyway, I am not sure if I will be able to reproduce it since these issues are often timing-dependent.

I don't know, this happens every single time I run the example so I think the problem will present itself.

[martenrichter]

Ok, it also happens on windows..., as a first I will try to write a test for it. And then try to find out in the linux container, where the problem occurs.

[martenrichter]

I assume this was also a problem with Chrome. This commit in quiche changed the behavior https://github.com/google/quiche/commit/75266116f21731354fe44cea6a1aae7eae70441e so adapting it may solve the problem.

[martenrichter]

Can you check the PR to see if it works now? (Preferably also other uses) I did not check the example but converted it to a test. (My coding time for this weekend is over.... as a silly bug while writing the patch consumed too much time)

[achingbrain]

256 seems to resolve the problem, the readable end of the stream now closes. Thanks for looking into it!