net: fix bufferSize

[ronag]

bufferSize should only look at writableLength otherwise it will always show more than what is actually pending.

I'm not familiar with this code but it just looks wrong/suspicious to me.

Tests seem to pass with changes.

Maybe someone more familiar could take a look at determine whether this seems reasonable and what a good test could be?

Refs: #34078

Checklist

• make -j4 test (UNIX), or vcbuild test (Windows) passes
• tests and/or benchmarks are included
• documentation is changed or added
• commit message follows commit guidelines

[ronag]

@nodejs/net

[ronag]

writableLength won't get subtracted until the write actually completes. Not sure what the purpose of kLastWriteQueueSize is here.

[lpinca]

This is my understanding: assume there is nothing buffered so writableLength is zero and there is a write in progress, socket.bufferSize should report the number of bytes that are currently being written and not zero.

[ronag]

I don't think writableLength is zero here, it becomes non zero as soon as you do write() and won't become zero again unless all writes have finished

should report the number of bytes that are currently being writte

writableLength does exactly that as far as I can tell

[lpinca]

Ok, can you check when this was originally added? The original commit might shed some light.

[lpinca]

Perhaps at that time writableLength wasn't working like this? I don't know.

[ronag]

unclear...

[ronag]

The only explanation I can think of is if the callback is called before the write has actually completed... which would be a bit weird.

[addaleax]

Right, I don’t think that that’s what happens (but I guess it could be checked easily enough through verifying that the write queue size is 0 when we get the callback from libuv?)

[ronag]

Seems like handle.writeQueueSize is not zero before invoking the callback. Which is kind of confusing.

[ronag]

@addaleax the following assertion will fail when running the test suite:

diff --git a/lib/internal/stream_base_commons.js b/lib/internal/stream_base_commons.js
index fdf540a47e..4c7049bf51 100644
--- a/lib/internal/stream_base_commons.js
+++ b/lib/internal/stream_base_commons.js
@@ -30,6 +30,7 @@ const {
 } = require('internal/timers');
 const { isUint8Array } = require('internal/util/types');
 const { clearTimeout } = require('timers');
+const assert = require('assert');
 
 const kMaybeDestroy = Symbol('kMaybeDestroy');
 const kUpdateTimer = Symbol('kUpdateTimer');
@@ -104,6 +105,8 @@ function onWriteComplete(status) {
   stream[kUpdateTimer]();
   stream[kAfterAsyncWrite](this);
 
+  assert(this.handle.writeQueueSize === 0);
+
   if (typeof this.callback === 'function')
     this.callback(null);
 }

[addaleax]

This code seemed a bit suspicious to me as well, but anytime I changed something, CI broke, so … I’ll kick off CI 😄

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32120/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32121/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32122/

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32123/

[ronag]

So from what I can tell writeQueueSize is not zero when the callback is invoked, i.e. the handle has some kind of internal buffer that is not always flushed before the callback is invoked. Which kind of makes write(chunk, callback) lie in regards to whether the write was successful or not.

Furthermore, this causes a problem since writableLength also includes parts of writeQueueSize. Basically what we want is bufferSize = writableLength + writeQueueSize - dispatchedLength where dispatchedLength is the current size of whatever was sent to writeGeneric.

[addaleax]

@ronag Maybe the problem is a discrepancy between handle.writeQueueSize and the write_queue_size property as reported by libuv?

This diff doesn’t result in any obvious crashes:

--- a/src/stream_wrap.cc
+++ b/src/stream_wrap.cc
@@ -400,6 +400,7 @@ void LibuvStreamWrap::AfterUvWrite(uv_write_t* req, int status) {
   CHECK_NOT_NULL(req_wrap);
   HandleScope scope(req_wrap->env()->isolate());
   Context::Scope context_scope(req_wrap->env()->context());
+  CHECK_EQ(static_cast<LibuvStreamWrap*>(req_wrap->stream())->stream()->write_queue_size, 0);
   req_wrap->Done(status);
 }
 

[addaleax]

What is writeQueueSize and where does it come from?

My understanding is that it is the size of the currently active write. This is not necessarily equivalent to the size of the last scheduled write, because sometimes a large write is only partially written and then the rest of it. libuv communicated that through write_queue_size. We use this for timeout tracking – if write_queue_size has decreased since the last time, it means that data has been written in the background by libuv, without any action from Node.js, hence we can infer that the socket is active and not timing out.

I seem to get a writeQueueSize of 80 even when nothing has been written to the socket.

Are you talking about a net.Socket? Do you have a repro? This sounds very wrong. 😄

[ronag]

@addaleax

diff --git a/test/parallel/test-tls-streamwrap-buffersize.js b/test/parallel/test-tls-streamwrap-buffersize.js
index 984cc51e50..6ec028c621 100644
--- a/test/parallel/test-tls-streamwrap-buffersize.js
+++ b/test/parallel/test-tls-streamwrap-buffersize.js
@@ -52,6 +52,7 @@ const net = require('net');
         socket,
         rejectUnauthorized: false,
       }, common.mustCall(() => {
+        assert.strictEqual(client._handle.writeQueueSize, 0);
         assert.strictEqual(client.bufferSize, 0);
 
         for (let i = 1; i < iter; i++) {

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

80 !== 0

    at TLSSocket.<anonymous> (/Users/ronagy/GitHub/nxtedition/node/test/parallel/test-tls-streamwrap-buffersize.js:55:16)
    at TLSSocket.<anonymous> (/Users/ronagy/GitHub/nxtedition/node/test/common/index.js:365:15)
    at Object.onceWrapper (events.js:420:28)
    at TLSSocket.emit (events.js:314:20)
    at TLSSocket.onConnectSecure (_tls_wrap.js:1523:10)
    at TLSSocket.emit (events.js:314:20)
    at TLSSocket._finishInit (_tls_wrap.js:933:8)
    at TLSWrap.ssl.onhandshakedone (_tls_wrap.js:707:12)
    at DuplexSocket.ondata (internal/js_stream_socket.js:77:22)
    at DuplexSocket.emit (events.js:314:20) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: 80,
  expected: 0,
  operator: 'strictEqual'
}

[ronag]

@addaleax Are we in agreement on bufferSize === writableLength should be true or am I missing something?

[ronag]

Are you talking about a net.Socket? Do you have a repro? This sounds very wrong. 😄

Maybe something to do with tls handshake or something?

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32128/

[ronag]

@addaleax Regarding writeQueueSize, I'm curious where exactly it is implemented?

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32135/ ✅

[ronag]

are deprecations always semver-major?

[richardlau]

are deprecations always semver-major?

Generally yes (for non-doc-only deprecations) unless the TSC make an exception: https://github.com/nodejs/node/blob/master/doc/guides/collaborator-guide.md#deprecations

[ronag]

Landed in 8f4b4f2...0edeeec