Regression: Wrong value in bytesWritten for net.Socket

[patrickjuchli]

There is a regression since v9.7.0 (Darwin-x64) until and including v9.9.0:

If I send data with a net.Socket, the property bytesWritten won't reflect the correct number of bytes
written, it's always too low. I have verified this on the receiving end – data is written/sent as expected, only bytesWritten is incorrect.

This works correctly until v9.6.1 (Darwin-x64).

[patrickjuchli]

I'm using a stream to send data like so:

myReadableStream.pipe(mySocket)

The value of mySocket.bytesWritten after the stream has ended is too low.

[gireeshpunathil]

Unable to reproduce on mac with this code. Can you review and see where is the difference between our approaches?

#cat 19562.js

const n = require('net')
const v = n.createServer((s) => {
  s.end(Buffer.alloc(process.argv[2] - 0).fill('g'), () => {
    console.log(s.bytesWritten)
  })
}).listen(8124, () => {
  const c = n.connect(8124, () => {})
  c.on('close', () => {v.close()})
})

#node 19562.js 1
1
#node 19562.js 32
32
#node 19562.js 128
128
#node 19562.js 512
512
#node 19562.js 1024
1024

#node -v
v9.8.0

[patrickjuchli]

#node 19562.js 600000
338324

[gireeshpunathil]

what is your /etc/sysctl.conf looking like? Mine is:

kern.ipc.maxsockbuf=16777216
net.inet.tcp.sendspace=1048576
net.inet.tcp.recvspace=2097152

[patrickjuchli]

I don't seem to have that on my system (MacOS 10.13.3).

[patrickjuchli]

I have added an /etc/sysctl.conf with the same lines. It then works for 600000 Bytes, but continues to fail for e.g. 2600000. Again, all of this works fine with v9.6.1.

#node 19562.js 2600000
1159456

[richardlau]

If it regressed between v9.6.1 and v9.7.0 then possibly the libuv update (1.19.2)? Maybe related to libuv/libuv#1739?

[gireeshpunathil]

thanks @patrickjuchli - following your hint I am able to reproduce in my system too, thought with different data volume, which does not matter.
#cat 19562.js

const n = require('net')
let count = 0
const v = n.createServer((s) => {
  s.end(Buffer.alloc(process.argv[2] - 0).fill('g'), () => {
    console.log(`server: bytes written: ${s.bytesWritten}`)
  })
}).listen(8124, () => {
  const c = n.connect(8124, () => {})
  c.on('data', (d) => {count += d.length})
  c.on('close', () => {
    console.log(`client: data received: ${count}`)
    v.close()
  })
})

#node 19562.js 99999
server: bytes written: 99999
client: data received: 99999
#node 19562.js 999999
server: bytes written: 999999
client: data received: 999999
#node 19562.js 9999999
server: bytes written: 8611363
client: data received: 9999999
#

[gireeshpunathil]

I tested with changes undone from libuv/libuv#1739 , but it did not solve this.

[gireeshpunathil]

Used git bisect for the first time, and became a fan of it! It brought up 9169449 . I will manually verify it.
/cc @addaleax

[gireeshpunathil]

confirmed.

[addaleax]

@gireeshpunathil thanks for investigating, and thanks for the ping!

I think the issue is that req.bytes now only reports the write queue size in some cases, when a write completed only partially synchronously.

The already-open #19551 should fix this particular issue with bytesWritten, too; so I’ve added a regression test there + a commit that makes sure .bytes now refers to what it originally was supposed to refer to.

[patrickjuchli]

Thanks so much, @gireeshpunathil and @addaleax.

[gireeshpunathil]

I verified that #19551 indeed fixes this issue.