TypeError: Cannot read properties of null (reading 'finishWrite')

[alenakhineika]

Something has changed in the latest Insiders so our MongoDB extension CI started to fail with errors (any branch but here is an example):

Cannot read properties of null (reading 'finishWrite'): TypeError: Cannot read properties of null (reading 'finishWrite')
	at JSStreamSocket.finishWrite (node:internal/js_stream_socket:211:12)
	at Immediate.<anonymous> (node:internal/js_stream_socket:196:14)
	at process.processImmediate (node:internal/timers:466:21)

Do you have any idea what might cause it so we can make changes on our side? Might it be something with your dependencies?

[deepak1556]

Runtime has no changes with insiders, this seems like a regression from the recent http proxy changes based on similar errors in upstream. Passing onto @chrmarti

From a quick look the extension relies on https://github.com/mongodb-js/compass/tree/main/packages/data-service package which makes network connection. @alenakhineika it would be great if you can reduce the test case to a minimal extension sample for us to debug this issue further. Thanks!

[alenakhineika]

Unfortunately, we haven't been able to isolate the issue for a minimal extension sample so far.

To reproduce the problem, you can follow these steps:

1. Clone the repository and install the extension.
2. Run the following commands in the terminal:

npm ci
npm run compile
npm test

When running all tests, you may observe multiple failures with the TypeError: Cannot read properties of null (reading 'finishWrite'). However, when running the failed tests separately, they randomly may or may not fail again, which makes it hard to identify the cause of the issue. It is possible that your proxy patches might be the right place to look for further investigation.

[chrmarti]

Maybe a related discussion: nodejs/node#46094

[alenakhineika]

Found it. The place in our code that fails with the latest Insiders is fetch with a biggish timeout. I created a minimal test so you can try it, but here is the code snippet for a quick look:

test('minimal test with fetch', async () => {
    const fetch = require('cross-fetch');
    let unparsedCIDRs;
    try {
      // The uncaught `TypeError: Cannot read properties of null (reading 'finishWrite')`
      // is being thrown for several fetch calls with 5000 timeout:
      // https://github.com/mongodb-js/mongodb-cloud-info/blob/main/index.js#L30
      for (let i = 0; i < 15; i++) {
        unparsedCIDRs = await fetch(CIDRS_URL, { timeout: 5000 }).then((res) =>
          res.json()
        );
      }
    } catch (error) {
      console.log(error);
    }
    assert.notStrictEqual(unparsedCIDRs, null);
});

[chrmarti]

@alenakhineika Thanks for putting together this test!

My investigation so far:

• JSStreamSocket.doClose is called with this._handle === null resulting in the reported error when it calls finishWrite here: https://github.com/nodejs/node/blame/0da3f61a19c05508e437144a3a1dc5959a41d5d1/lib/internal/js_stream_socket.js#L234
• The check at https://github.com/nodejs/node/blame/0da3f61a19c05508e437144a3a1dc5959a41d5d1/lib/net.js#L334 would prevent JSStreamSocket.doClose from being called when this._handle === null, but that is only added with nodejs/node@7f7a899 in Node.js 19.0.0.

Still need to check older versions to see if that check was backported and see if there is a way to test this assessment.

[deepak1556]

nodejs/node@7f7a899 is available in 18.8.0 and 16.18.0, our exploration builds based on Node v18 has this change, @chrmarti you can use the builds from https://builds.code.visualstudio.com/builds/exploration to verify the assessment.

[chrmarti]

The test does not reproduce the issue in the exploration build.

Still trying to understand what is happening (please ignore the above code pointers) by looking at the Node.js code at the v16.17.1 tag. I see the failing call to finishWrite being triggered in doWrite: https://github.com/nodejs/node/blame/6b06e89c7dfccec6792008302af1cee57649445c/lib/internal/js_stream_socket.js#L196

What I don't quite understand is that the callstack to doWrite with this._handle === null comes from Socket._final:

        at JSStreamSocket.doWrite (...)
        at JSStream.onwrite (node:internal/js_stream_socket:33:57)
        at Socket._final (node:net:467:28)
        at callFinal (node:internal/streams/writable:696:27)
        at prefinish (node:internal/streams/writable:725:7)
        at finishMaybe (node:internal/streams/writable:735:5)
        at Writable.end (node:internal/streams/writable:633:5)
        at Socket.end (node:net:655:31)
        at endWritableNT (node:internal/streams/readable:1384:12)
        at process.processTicksAndRejections (node:internal/process/task_queues:82:21)

But Socket._final at that line is supposed to call JSStream.onshutdown not JSStream.onwrite as it appear in the callstack: https://github.com/nodejs/node/blame/6b06e89c7dfccec6792008302af1cee57649445c/lib/net.js#L467

@deepak1556 Could you point me at the Node.js source that went into Electron? I believe that is not the exact same as that at https://github.com/nodejs/node?

[deepak1556]

Electron pulls Node.js source from https://github.com/nodejs/node when building, what you are looking at is the correct one. I think the async stack is missing a trampoline calll, but you are seeing a write after shutdown stack same as nodejs/node#46094 (comment)

[chrmarti]

Thanks @deepak1556. This looks like an upstream issue to me, doWrite should not be called when this._handle is already null. I don't see the change in 18.15.0 (the version the exploration build is using) yet that might have fixed it.

[chrmarti]

We have reverted to the previous way of loading certificates as we are getting close to a release (#189133).

[justinmk3]

We're seeing this again in our macos and Windows CI jobs for VSCode "Insiders" (not current VSCode stable version 1.82.2). Was node or electron updated in the last 2 days on VSCode Insiders?

[deepak1556]

There is fix in upstream for the above scenario, I will backport it to relevant release lines.

[chrmarti]

@justinmk3 Could you confirm that todays Insiders build fixes the problem? Thanks!

[justinmk3]

Confirmed, thanks!