test: refactor flaky net-error-twice #4062

Trott · 2015-11-29T06:27:05Z

The test was not reliably creating the error event on Windows 2012.

This makes the test more robust by using setTimeout() to delay the
server writing to the socket to give time for socket.destroy() to take
effect.

Fixes: #4057

Trott · 2015-11-29T06:28:42Z

Stress test without this fix:

https://ci.nodejs.org/job/node-stress-single-test/72/nodes=win2012r2/console

Stress test with this fix:

https://ci.nodejs.org/job/node-stress-single-test/86/nodes=win2012r2/console

The test was not reliably creating the error event on Windows 2012. This makes the test more robust by using setImmediate() to delay the server writing to the socket to give time for socket.destroy() to take effect. Fixes: nodejs#4057

Trott · 2015-11-29T06:33:55Z

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

Trott · 2015-11-29T06:52:10Z

The stress test is going OK, but the CI still shows a failure for this test. I'd hate to have to delay the write() with a setTimeout() but that may be the workaround at least in the short term...

Trott · 2015-11-29T16:28:25Z

I added a setTimeout() for Windows only.

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

Stress test: https://ci.nodejs.org/job/node-stress-single-test/87/nodes=win2012r2/

bnoordhuis · 2015-11-30T17:14:17Z

test/parallel/test-net-error-twice.js

+    // Windows-specific handling. See:
+    //   * https://github.com/nodejs/node/pull/4062
+    //   * https://github.com/nodejs/node/issues/4057
+    setTimeout(() => { conn.write(buf); }, 100);


Why is the delay necessary?

@bnoordhuis Concise-but-naive answer: Without the delay, the test is flaky on Windows 2012 r2 on the CI infrastructure.

Less concise and marginally less naive: In this test, conn.write(buf) is supposed to get an error (either EPIPE or ECONNRESET depending on timing). ~~Unfortunately, on Windows 2012 r2 only, it appears that the call to client.destroy() often returns before the socket is set to emit the error.~~ UPDATE: Actually, I think the problem is that the client connection and server connection callbacks fire in an unpredictable order. On Windows 2012 r2 only, the conn.write() would often not trigger an error and the result was assert.equal(errs.length, 1) firing (because errs.length is 0). I tried setImmediate() and that may have improved things but it did not resolve the flakiness. Using the timeout resolved the flakiness. (I did not experiment with a timeout of less than 100 milliseconds.)

As for the cause of this on Windows 2012 r2, I don't know and would certainly be receptive to some guidance on figuring it out (or someone simply doing the work and identifying the source of the issue). Operating system limitation? Bug in libuv? Bug in socket.destroy? I don't know. I don't have easy access to a Windows 2012 r2 machine. (I could try to run one via VirtualBox, but my laptop resources are kind of limited right now and my weak excuse is that it would probably fill up my disk.)

Trott · 2015-12-04T06:04:04Z

Bump. Would like to get this fix in because this test has been failing a lot lately.

Trott · 2015-12-06T22:57:50Z

Bump again, but this time with an @ mention: @nodejs/testing

This continues to fail a lot on Windows and I'd like to get this in as a fix. If this is not going to land, then a different PR can be submitted to at least mark the test as flaky. But I'd rather just see this land...

I suppose the best path would be to identify why this is happening on Windows. As I mention in a previous comment, I don't know if this is an OS issue, libuv issue, socket.destroy() issue, or what.

bnoordhuis · 2015-12-07T10:45:53Z

@nodejs/platform-windows Can you investigate why the timeout fixes the test on Windows?

joaocgreis · 2015-12-07T17:54:22Z

~~I haven't yet been able to reproduce locally.~~ I have only seen this fail on msft machines, has it failed in a rackspace machine yet?

joaocgreis · 2015-12-07T19:24:17Z

This reproduces every time in a fast single-core VM. Slowing down the VM (CPU cap) solves the problem. Only on Windows 2012. This might be a problem with node and not the test.

Trott · 2015-12-09T00:36:52Z

Maybe I was overthinking this. Is it possible that all that's happening is that sometimes the client connection callback is firing before the server connection callback and sometimes vice versa? So sometimes the socket is destroyed (which is what the test expects) and sometimes not?

It seems that all we'd have to do to fix this is wrap the conn.write() in a process.nextTick()... which seems to be working in the stress test. I thought I tried that and/or setImmediate() and it didn't quite work, but maybe I'm mistaken? Or maybe the that's working due to side effects of console logging I added. Let me re-try the stress test without the logging....

@joaocgreis If we change the setTimeout() to a process.nextTick(), does it reliably pass on the Windows machine where it had been reliably failing?

Trott · 2015-12-09T01:11:14Z

Alas, process.nextTick() really doesn't fix it so I really am not losing my mind (although I am filling up the issue tracker with needless walls of text. Sorry...).

Trott · 2015-12-09T03:57:37Z

OK, so back to the "why the timeout" question:

Is it plausible that all that is happening is that the client connection and server connection callbacks fire in an unpredictable order?
If so, then would it be acceptable just to use the setTimeout() (or, if we want to really be safe, a setInterval()) around the conn.write()?
If not, then any other ideas about what we're seeing here?

Trott · 2015-12-09T18:48:46Z

I now have access to a Windows machine and can iterate/test more efficiently. Ordering of callbacks is not the issue. Bummer. Starting to look/feel more and more like an issue with Node itself, as @joaocgreis suggested...

Trott · 2015-12-09T22:47:19Z

Even just introducing a single console.log() statement causes the test to start passing. In case that information helps someone figure this out so I don't have to...

Trott · 2015-12-09T23:23:12Z

Also interesting: If I remove require('common') (and hardcode the instances of common.PORT to 12346), then the test always passes!

Trott · 2015-12-10T00:25:52Z

This is getting weird: It appears that the culprit is adding the console global to the knownGlobals array in common.js on line 260. Comment out that line and set exports.globalCheck to false in line 332, and the test passes every time. (Changing exports.globalCheck alone is not enough. You need to get rid of console from the knownGlobals array.)

Any ideas as to why adding the console global variable to a private array inside the common module would be causing this issue? I understand how it could have side effects. I'm just not coming up with a plausible mechanism of how those side effects translate into this specific failure.

cc @bengl since I roped him in on this in between sessions at Node Interactive...

mscdex · 2015-12-18T08:42:03Z

I think I found a solution that doesn't rely on a timeout, in #4342. Basically it waits until the server connection handler fires to destroy the client socket and write to the server socket. Doing it this way results in a single ECONNRESET every time on win2012r2.

Trott · 2015-12-18T15:09:31Z

I'd still like to know why adding console to an array in common.js causes this problem. That's just totally weird (and it was strangely gratifying to have João more-or-less confirm it independently).

Trott · 2015-12-19T23:45:09Z

Closing. @mscdex resolved it in #4342 and I opened #4358 to address the strange behavior that their fix works around.

MylesBorins · 2015-12-29T23:20:23Z

removing lts watch tag as nothing landed in here

Trott mentioned this pull request Nov 29, 2015

Investigate flaky test-net-error-twice #4057

Closed

test: refactor flaky net-error-twice

6b38a67

The test was not reliably creating the error event on Windows 2012. This makes the test more robust by using setImmediate() to delay the server writing to the socket to give time for socket.destroy() to take effect. Fixes: nodejs#4057

Trott force-pushed the net-error-twice branch from 84990f2 to 6b38a67 Compare November 29, 2015 06:32

mscdex added net Issues and PRs related to the net subsystem. test Issues and PRs related to the tests. labels Nov 29, 2015

fixup: windows-specific handling

c30dc10

bnoordhuis reviewed Nov 30, 2015
View reviewed changes

jasnell added the lts-watch-v4.x label Dec 3, 2015

This was referenced Dec 5, 2015

crypto: ecdh - generate public key when setting private key and more #3511

Closed

doc,fs: keep consistent with fs.link and fs.linkSync #3912

Closed

bnoordhuis added the windows Issues and PRs related to the Windows platform. label Dec 7, 2015

Trott mentioned this pull request Dec 19, 2015

Strange behavior specific to Windows 2012r2 with a single processor #4358

Closed

Trott closed this Dec 19, 2015

MylesBorins removed the lts-watch-v4.x label Dec 29, 2015

Trott deleted the net-error-twice branch January 13, 2022 22:30

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: refactor flaky net-error-twice #4062

test: refactor flaky net-error-twice #4062

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

bnoordhuis Nov 30, 2015

Trott Nov 30, 2015

Trott commented Dec 4, 2015

Trott commented Dec 6, 2015

bnoordhuis commented Dec 7, 2015

joaocgreis commented Dec 7, 2015

joaocgreis commented Dec 7, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 10, 2015

mscdex commented Dec 18, 2015

Trott commented Dec 18, 2015

Trott commented Dec 19, 2015

MylesBorins commented Dec 29, 2015

test: refactor flaky net-error-twice #4062

test: refactor flaky net-error-twice #4062

Conversation

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

Trott commented Nov 29, 2015

bnoordhuis Nov 30, 2015

Choose a reason for hiding this comment

Trott Nov 30, 2015

Choose a reason for hiding this comment

Trott commented Dec 4, 2015

Trott commented Dec 6, 2015

bnoordhuis commented Dec 7, 2015

joaocgreis commented Dec 7, 2015

joaocgreis commented Dec 7, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 9, 2015

Trott commented Dec 10, 2015

mscdex commented Dec 18, 2015

Trott commented Dec 18, 2015

Trott commented Dec 19, 2015

MylesBorins commented Dec 29, 2015