test: fix flaky test-tls-wrap-timeout #7857

Trott · 2016-07-23T21:15:43Z

Checklist

make -j4 test (UNIX), or vcbuild test nosign (Windows) passes
commit message follows commit guidelines

Affected core subsystem(s)

test tls

Description of change

Competing timers were causing a race condition and thus the test was
flaky. Instead, we check an object property on process exit.

Fixes: #7650

/cc @indutny @nodejs/testing @SomeKittens

Trott · 2016-07-23T21:17:40Z

The fix for this test is in io.js 1.3 and absent in io.js 1.2. So I modified the test a bit so that it would work on those versions to confirm that the test still passes in 1.3 and fails in 1.2. That form of the test can be found at https://gist.github.com/Trott/e4110c64314b9666185c3018dbb33b5c

Trott · 2016-07-25T02:54:39Z

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

indutny · 2016-07-25T02:58:01Z

Hm... doesn't really LGTM. The test was about server timeout, not client's.

indutny · 2016-07-25T02:58:03Z

Sorry!

Trott · 2016-07-25T03:50:19Z

@indutny I don't understand. Both this version of the test and the current one check the same object (socket in the code).

The old version made sure that socket.setTimeout() handler never fired. That makes sense in theory but is subject to race conditions in practice.

It was introduced in 9b6b0555. Prior to that, the timeout was firing (incorrectly) because socket._idleTimeout and related properties were not being updated correctly. (They were being updated on TLSSocket but not the parent, which in this case is socket. Or at least, that's my understanding.)

This new proposed version removes the race condition by checking that socket._idleTimeout gets set to -1 after TLSSocket is closed. Prior to 9b6b0555, this wasn't happening. After 9b6b0555, it's the expected state upon exiting.

Maybe it would be better to also check that socket._idleStart is being updated after the write/read on the socket. That would (further) guarantee that the socket timeout is working as expected and won't fire erroneously.

Trott · 2016-07-25T14:38:32Z

(Failure that this PR is supposed to address happened again on FreeBSD in CI: https://ci.nodejs.org/job/node-test-commit-freebsd/3427/nodes=freebsd10-64/console )

Trott · 2016-07-26T21:21:04Z

@indutny I put back the timer (now setImmediate()) to do a write and an assert to check that _idleStart is being updated. PTAL

Trott · 2016-07-27T16:40:08Z

New version of test is failing on some platforms. More work to be done...

Trott · 2016-07-27T16:45:43Z

OK, let's try again: https://ci.nodejs.org/job/node-test-pull-request/3437/

EDIT: OK, that's looking much better so far.

Trott · 2016-07-29T04:26:54Z

Previous CI failures look CI infra related and not an issue with this test, but uh, let's run it again anyway: https://ci.nodejs.org/job/node-test-pull-request/3450/

Trott · 2016-07-29T06:23:04Z

Ci again again: https://ci.nodejs.org/job/node-test-pull-request/3452/

jasnell · 2016-07-29T15:51:46Z

~~LGTM~~ ... I take that back... looks like there are CI failures

Trott · 2016-07-29T16:31:42Z

@jasnell All the CI failures are build related. None are related to this test. But I do love green, so let's do CI again again again: https://ci.nodejs.org/job/node-test-pull-request/3455/

Trott · 2016-07-29T16:32:39Z

I am eager to get this fix in for this test because the version currently on master is failing a fair amount on FreeBSD. Here's another one from this morning:

not ok 1032 parallel/test-tls-wrap-timeout
# /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-tls-wrap-timeout.js:32
#       throw new Error('timeout');
#       ^
# 
# Error: timeout
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-tls-wrap-timeout.js:32:13)
#     at Socket.g (events.js:286:16)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:228:11)
#     at Timer.listOnTimeout (timers.js:202:5)
  ---
  duration_ms: 0.632

jasnell · 2016-07-29T16:39:42Z

LGTM with green-ish CI then ;-)

Trott · 2016-07-29T17:02:58Z

Last CI is green! ✅

Trott · 2016-07-30T03:55:07Z

Another failure on FreeBSD with current master. Definitely eager to land this fix.

https://ci.nodejs.org/job/node-test-commit-freebsd/3506/nodes=freebsd10-64/console

not ok 1032 parallel/test-tls-wrap-timeout
# /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-tls-wrap-timeout.js:32
#       throw new Error('timeout');
#       ^
# 
# Error: timeout
#     at Socket.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-tls-wrap-timeout.js:32:13)
#     at Socket.g (events.js:286:16)
#     at emitNone (events.js:86:13)
#     at Socket.emit (events.js:185:7)
#     at Socket._onTimeout (net.js:333:8)
#     at tryOnTimeout (timers.js:228:11)
#     at Timer.listOnTimeout (timers.js:202:5)
  ---
  duration_ms: 1.37

santigimeno · 2016-07-30T12:45:03Z

test/parallel/test-tls-wrap-timeout.js

-    var tsocket = tls.connect({
+    lastIdleStart = socket._idleStart;
+
+    const tsocket = tls.connect({


Maybe adding here

assert.notStrictEqual(socket._idleTimeout, -1);

@santigimeno Good idea. Added!

santigimeno · 2016-07-30T12:55:52Z

I like that with this change we don't rely on timers. I'm not too sold on relying on implementation details (i.e:_idleTimeout and _idleStart) though.

Competing timers were causing a race condition and thus the test was flaky. Instead, we check an object property on process exit. Fixes: nodejs#7650

Trott · 2016-07-31T04:21:08Z

@santigimeno Yeah, I'd welcome a better way. For what it's worth, there is at least one other test where we do something similar (test-timers-active.js) and AFAIK it has never been flaky, so it does have at least that going for it.

santigimeno · 2016-07-31T07:03:11Z

@Trott FWIW I gave this a try and found a way that, at least, seems less flaky than the current one: santigimeno@3df3f47.

I run a couple of stress tests and didn't fail:

https://ci.nodejs.org/job/node-stress-single-test/840/ (9999 times)
https://ci.nodejs.org/job/node-stress-single-test/838/ (1000 times)

whereas current master did fail:

https://ci.nodejs.org/job/node-stress-single-test/839/ (9999 times --> 4 failures)
https://ci.nodejs.org/job/node-stress-single-test/837/ (1000 times --> 1 failure)

The problem is that still relies on timers and the number of tests run doesn't seem representative enough to consider it non-flaky.

santigimeno · 2016-07-31T07:11:38Z

Also, I looked to the original issue: nodejs/node-v0.x-archive#9242, and by the looks of the sample code pasted there, it seems that the timer associated with the socket is unref-ed as it doesn't keep the loop running even though the timer is already running. This test would have been so much easier to implement if the timer were ref-ed...

Trott · 2016-07-31T15:22:36Z

@santigimeno I'm inclined to think that using _idleTimeout/_idleStart is an indication of a missing API. It should be possible to query a socket to find out if it has any timeouts set or not. Our use case is for testing, but I'm sure there are other use cases. On the surface, at least, it seems like this would be easily done by adding a getter that returns _idleTimeout !== -1.

Trott · 2016-07-31T16:11:20Z

@indutny @santigimeno @jasnell Maybe something like d76bb07a19d890d95e71329da504187f3e4462f2 is sufficiently minimal a change to have everyone feel better about it? (Haven't actually stress tested or run it on the old versions and so on, but you get the idea of the approach.)

indutny · 2016-07-31T18:32:48Z

Gosh, looks like I was thinking about different test all the time. LGTM. Sorry!

santigimeno · 2016-07-31T18:38:46Z

@Trott, after your explanation, I'm fine with this PR, and I think I prefer this to the new one. LGTM

Competing timers were causing a race condition and thus the test was flaky. Instead, we check an object property on process exit. Fixes: nodejs#7650 PR-URL: nodejs#7857 Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: jasnell - James M Snell <[email protected]>

Trott · 2016-07-31T20:33:10Z

Landed in bc464a8. Thanks, everyone!

Competing timers were causing a race condition and thus the test was flaky. Instead, we check an object property on process exit. Fixes: #7650 PR-URL: #7857 Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: jasnell - James M Snell <[email protected]>

Competing timers were causing a race condition and thus the test was flaky. Instead, we check an object property on process exit. Fixes: nodejs#7650 PR-URL: nodejs#7857 Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: jasnell - James M Snell <[email protected]>

Competing timers were causing a race condition and thus the test was flaky. Instead, we check an object property on process exit. Fixes: #7650 Backport-PR-URL: #12567 PR-URL: #7857 Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: jasnell - James M Snell <[email protected]>

Trott added tls Issues and PRs related to the tls subsystem. test Issues and PRs related to the tests. labels Jul 23, 2016

Trott mentioned this pull request Jul 23, 2016

Investigate flaky test-tls-wrap-timeout on FreeBSD #7650

Closed

Trott force-pushed the wrap branch from 75db303 to db0abb3 Compare July 26, 2016 19:53

Trott force-pushed the wrap branch from f0dbb96 to 471cb0d Compare July 27, 2016 16:40

santigimeno reviewed Jul 30, 2016
View reviewed changes

Trott added 4 commits July 30, 2016 21:14

test: fix flaky test-tls-wrap-timeout

2b17997

Competing timers were causing a race condition and thus the test was flaky. Instead, we check an object property on process exit. Fixes: nodejs#7650

squash: add _idleStart check

6185e4b

squash: moar ticks, later asserts

84ed1ea

squash: additional assertion

58d3fbf

Trott force-pushed the wrap branch from 85545c5 to 58d3fbf Compare July 31, 2016 04:18

Trott mentioned this pull request Jul 31, 2016

test: fix flaky test-tls-wrap-timeout #7926

Closed

2 tasks

Trott closed this Jul 31, 2016

cjihrig mentioned this pull request Aug 8, 2016

v6.4.0 Release Proposal #8020

Closed

cjihrig mentioned this pull request Aug 11, 2016

v6.4.0 Proposal #8070

Merged

Trott added the lts-watch-v4.x label Sep 9, 2016

MylesBorins added dont-land-on-v4.x and removed lts-watch-v4.x labels Oct 10, 2016

BethGriggs mentioned this pull request Apr 21, 2017

backport v4.x: test: fix flaky test-tls-wrap-timeout #12567

Closed

2 tasks

MylesBorins mentioned this pull request May 2, 2017

v4.8.3 proposal #12499

Merged

Trott deleted the wrap branch October 14, 2021 12:26

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: fix flaky test-tls-wrap-timeout #7857

test: fix flaky test-tls-wrap-timeout #7857

Trott commented Jul 23, 2016

Trott commented Jul 23, 2016

Trott commented Jul 25, 2016

indutny commented Jul 25, 2016

indutny commented Jul 25, 2016

Trott commented Jul 25, 2016

Trott commented Jul 25, 2016

Trott commented Jul 26, 2016

Trott commented Jul 27, 2016

Trott commented Jul 27, 2016 •

edited

Loading

Trott commented Jul 29, 2016

Trott commented Jul 29, 2016

jasnell commented Jul 29, 2016 •

edited

Loading

Trott commented Jul 29, 2016

Trott commented Jul 29, 2016

jasnell commented Jul 29, 2016

Trott commented Jul 29, 2016

Trott commented Jul 30, 2016

santigimeno Jul 30, 2016

Trott Jul 31, 2016

santigimeno commented Jul 30, 2016

Trott commented Jul 31, 2016

santigimeno commented Jul 31, 2016

santigimeno commented Jul 31, 2016

Trott commented Jul 31, 2016

Trott commented Jul 31, 2016

indutny commented Jul 31, 2016

santigimeno commented Jul 31, 2016

Trott commented Jul 31, 2016

test: fix flaky test-tls-wrap-timeout #7857

test: fix flaky test-tls-wrap-timeout #7857

Conversation

Trott commented Jul 23, 2016

Checklist

Affected core subsystem(s)

Description of change

Trott commented Jul 23, 2016

Trott commented Jul 25, 2016

indutny commented Jul 25, 2016

indutny commented Jul 25, 2016

Trott commented Jul 25, 2016

Trott commented Jul 25, 2016

Trott commented Jul 26, 2016

Trott commented Jul 27, 2016

Trott commented Jul 27, 2016 • edited Loading

Trott commented Jul 29, 2016

Trott commented Jul 29, 2016

jasnell commented Jul 29, 2016 • edited Loading

Trott commented Jul 29, 2016

Trott commented Jul 29, 2016

jasnell commented Jul 29, 2016

Trott commented Jul 29, 2016

Trott commented Jul 30, 2016

santigimeno Jul 30, 2016

Choose a reason for hiding this comment

Trott Jul 31, 2016

Choose a reason for hiding this comment

santigimeno commented Jul 30, 2016

Trott commented Jul 31, 2016

santigimeno commented Jul 31, 2016

santigimeno commented Jul 31, 2016

Trott commented Jul 31, 2016

Trott commented Jul 31, 2016

indutny commented Jul 31, 2016

santigimeno commented Jul 31, 2016

Trott commented Jul 31, 2016

Trott commented Jul 27, 2016 •

edited

Loading

jasnell commented Jul 29, 2016 •

edited

Loading