fix test-readline-interface by Trott · Pull Request #14681 · nodejs/node

Trott · 2017-08-08T00:23:56Z

~~First commit is from #14677 and I will remove it and rebase if that PR lands before this one (which I imagine it will).~~

~~Second~~ First commit (h/t @addaleax):

lib: use Timer.now() in readline module
Using Date.now() introduces problems when operating under load or
otherwise with constrained resources. Use Timer.now() to mitigate.
Refs: https://github.com/nodejs/node/issues/14674

~~Third~~ Second commit:

test: split out load-sensitive readline tests
Two test cases in `test-readline-interface` are sensitive to resource
constraints (probably due to `\r` and `\n` not arriving within the
appropriate delay to be treated as a single line ending). Move those
tests to `sequential`.
Fixes: https://github.com/nodejs/node/issues/14674

Checklist

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

Affected core subsystem(s)

test readline

Trott · 2017-08-08T00:26:56Z

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

cjihrig

LGTM pending CI

Trott · 2017-08-08T01:54:01Z

arm-fanned is green! Ci is effectively green. (Only failure is that vexing C++ test failure on armv7-wheezy.)

refack

I starting to RC Collaborators, since our review process is getting watered down.

refack · 2017-08-08T11:50:10Z

Please comment what this tests, and why is it in /sequential/.

Comment added.

// These test cases are in `sequential` rather than the analogous test file in // `parallel` because they become unrelaible under load. The unreliability under // load was determined empirically when the test cases were in `parallel` by // running: // tools/test.py -j 96 --repeat 192 test/parallel/test-readline-interface.js

AFAIK it should be in the code, not just in GitHub 🤔

That's puzzling. I must have force-pushed it out at some point...

Argh! I overwrote the commit message change I did for @bnoordhuis too. The joys of having two laptops and forgetting to fetch before starting work, I imagine...

OK, all fixes have been re-fixed.

addaleax · 2017-08-08T12:00:44Z

@Trott is moving to sequential actually necessary after the first adjustments? I think we might not need that, libuv’s now() should work well with synchronous input

bnoordhuis · 2017-08-08T12:45:52Z

Using Date.now() introduces problems when operating under load or otherwise with constrained resources.

Could use more detail. What problems, what load or constrained resources?

Trott · 2017-08-08T13:28:16Z

@Trott is moving to sequential actually necessary after the first adjustments? I think we might not need that, libuv’s now() should work well with synchronous input

@addaleax Without the third commit, here's the sorts of failures those two test cases get (that were moved to sequential) when resource-constrained:

Details

$ tools/test.py -j 96 --repeat 192 test/parallel/test-readline-interface.js === release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bat' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:262:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bat' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bat' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'baz' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'baz' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'baz' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1032 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:287:10) at Interface._line (readline.js:642:8) at Interface._ttyWrite (readline.js:929:16) at FakeInput.onkeypress (readline.js:165:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js[00:09|% 100|+ 160|- 32]: Done 
$

The changes to lib/readline.js solved a bunch of other issues in the test, but I think the above problems are an artifact of the way those two test cases are written. High load makes them unreliable because subsequent .write() calls do not happen quickly enough. At least, that's what seems to be happening to me.

Trott · 2017-08-08T13:34:01Z

Could use more detail. What problems, what load or constrained resources?

@bnoordhuis The problem was diagnosed (and the solution prposed) by @addaleax in #14674 (comment):

the delay between processing \r and \n is so long that readline thinks they are actually separate line endings.
I do think it’s problematic that this happens even for synchronously emitted input. Maybe we should be using process.binding('timer_wrap').Timer.now() instead of Date.now()?

As for load, I tend to simulate by running many test processes simultaneously which seems to pretty reliably predict (or retroactively "predict") what tests are unreliable in CI:

$ tools/test.py -j 96 --repeat 192 test/parallel/test-foo-bar.js

bnoordhuis · 2017-08-08T13:58:12Z

Right, I mean the commit log could go into more detail. I kind of gleaned what you wrote from the linked issue but it's better for the commit log to document that.

Trott · 2017-08-08T13:59:59Z

@bnoordhuis Updated commit message.

lib: use Timer.now() in readline module
Using Date.now() introduces problems when operating under load or
otherwise with constrained resources. Use Timer.now() to mitigate.
The problem was identified in `test-readline-interface` where under
heavy load, `\r` and `\n` were received so far apart that they were
treated as separate line endings rather than a single line ending.
Switching to `Timer.now()` prevented this from happening.
Refs: https://github.com/nodejs/node/issues/14674

refack · 2017-08-08T18:07:33Z

@Trott after f11379d is it still falky (I assume yes, but do we have empirical evidance)?

Using Date.now() introduces problems when operating under load or otherwise with constrained resources. Use Timer.now() to mitigate. The problem was identified in `test-readline-interface` where under heavy load, `\r` and `\n` were received so far apart that they were treated as separate line endings rather than a single line ending. Switching to `Timer.now()` prevented this from happening. Refs: nodejs#14674

Two test cases in `test-readline-interface` are sensitive to resource constraints (probably due to `\r` and `\n` not arriving within the appropriate delay to be treated as a single line ending). Move those tests to `sequential`. Fixes: nodejs#14674

Trott · 2017-08-08T20:03:59Z

@Trott after f11379d is it still falky (I assume yes, but do we have empirical evidance)?

@refack f11379d seems to fix the flakiness on Raspberry Pi 1 in CI, but there is still unreliability when the test is run under load, which is what this PR addresses.

Details

$ tools/test.py -j 96 --repeat 192 test/parallel/test-readline-interface.js === release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:262:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfaceassert.js:42 throw new errors.AssertionError({ ^AssertionError [ERR_ASSERTION]: 2 === 1 at Timeout.common.mustCall (/Users/trott/io.js/test/parallel/test-readline-interface.js:349:14) at Timeout._onTimeout (/Users/trott/io.js/test/common/index.js:509:15) at ontimeout (timers.js:469:11) at tryOnTimeout (timers.js:304:5) at Timer.listOnTimeout (timers.js:264:5)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:262:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:262:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js=== release test-readline-interface === Path: parallel/test-readline-interfacereadline.js:1030 throw err; ^AssertionError [ERR_ASSERTION]: '' === 'bar' at Interface.<anonymous> (/Users/trott/io.js/test/parallel/test-readline-interface.js:245:14) at emitOne (events.js:115:13) at Interface.emit (events.js:210:7) at Interface._onLine (readline.js:285:10) at Interface._line (readline.js:640:8) at Interface._ttyWrite (readline.js:927:16) at FakeInput.onkeypress (readline.js:163:10) at emitTwo (events.js:125:13) at FakeInput.emit (events.js:213:7) at emitKeys (internal/readline.js:420:14)Command: out/Release/node --expose_internals /Users/trott/io.js/test/parallel/test-readline-interface.js[00:08|% 100|+ 176|- 16]: Done 
$

(With the changes in this PR, the test passes with the above command line.)

Trott · 2017-08-10T01:50:41Z

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

Trott · 2017-08-10T04:29:35Z

AIX failure is almost certainly unrelated, but just in case...

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

Using Date.now() introduces problems when operating under load or otherwise with constrained resources. Use Timer.now() to mitigate. The problem was identified in `test-readline-interface` where under heavy load, `\r` and `\n` were received so far apart that they were treated as separate line endings rather than a single line ending. Switching to `Timer.now()` prevented this from happening. PR-URL: nodejs#14681 Refs: nodejs#14674 Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

Two test cases in `test-readline-interface` are sensitive to resource constraints (probably due to `\r` and `\n` not arriving within the appropriate delay to be treated as a single line ending). Move those tests to `sequential`. PR-URL: nodejs#14681Fixes: nodejs#14674 Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

Trott · 2017-08-10T06:00:57Z

Landed in fe54bc7 and c7a9a2e

Using Date.now() introduces problems when operating under load or otherwise with constrained resources. Use Timer.now() to mitigate. The problem was identified in `test-readline-interface` where under heavy load, `\r` and `\n` were received so far apart that they were treated as separate line endings rather than a single line ending. Switching to `Timer.now()` prevented this from happening. PR-URL: #14681 Refs: #14674 Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

Two test cases in `test-readline-interface` are sensitive to resource constraints (probably due to `\r` and `\n` not arriving within the appropriate delay to be treated as a single line ending). Move those tests to `sequential`. PR-URL: #14681Fixes: #14674 Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com>

MylesBorins · 2017-09-19T18:07:56Z

Should this be backported to v6.x-staging? If yes please follow the guide and raise a backport PR, if no let me know or add the dont-land-on label.

nodejs-github-bot added the readline Issues and PRs related to the built-in readline module. label Aug 8, 2017

Trott mentioned this pull request Aug 8, 2017
test: investigate flaky - parallel/test-readline-interface #14674
Closed

cjihrig approved these changes Aug 8, 2017
View reviewed changes

refack suggested changes Aug 8, 2017
View reviewed changes

Trott force-pushed the fix-readline branch from 6ccbc25 to 2ab9432Compare August 8, 2017 13:21

Trott force-pushed the fix-readline branch from 2ab9432 to 8b5d816Compare August 8, 2017 13:59

Trott force-pushed the fix-readline branch 3 times, most recently from c4a660e to 3fd215cCompare August 8, 2017 14:26

MylesBorins mentioned this pull request Aug 8, 2017
v8.3.0 proposal #14594
Merged

Trott force-pushed the fix-readline branch from 3fd215c to 8f8c293Compare August 8, 2017 17:58

Trott added 2 commits August 8, 2017 12:58

Trott force-pushed the fix-readline branch from 8f8c293 to 710304cCompare August 8, 2017 19:59

refack approved these changes Aug 9, 2017
View reviewed changes

Trott closed this Aug 10, 2017

addaleax mentioned this pull request Aug 10, 2017
test: add block scoping to test-readline-interface #14615
Closed
2 tasks

addaleax mentioned this pull request Aug 13, 2017
v8.4.0 proposal #14811
Merged

MylesBorins added the backport-requested-v6.x label Sep 19, 2017

Trott added dont-land-on-v4.x and removed backport-requested-v6.x labels Sep 19, 2017

maclover7 mentioned this pull request Feb 4, 2018
readline: use Date.now() and move test to parallel #18563
Closed
3 tasks

Trott deleted the fix-readline branch January 13, 2022 22:46

Uh oh!

Uh oh!

Conversation

Trott commented Aug 8, 2017• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Checklist

Affected core subsystem(s)

Uh oh!

Trott commented Aug 8, 2017

Uh oh!

cjihrig left a comment

Choose a reason for hiding this comment

Uh oh!

Trott commented Aug 8, 2017• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

refack left a comment

Choose a reason for hiding this comment

Uh oh!

refackAug 8, 2017

Choose a reason for hiding this comment

Uh oh!

TrottAug 8, 2017

Choose a reason for hiding this comment

Uh oh!

TrottAug 8, 2017

Choose a reason for hiding this comment

Uh oh!

refackAug 8, 2017

Choose a reason for hiding this comment

Uh oh!

TrottAug 8, 2017

Choose a reason for hiding this comment

Uh oh!

TrottAug 8, 2017

Choose a reason for hiding this comment

Uh oh!

TrottAug 8, 2017

Choose a reason for hiding this comment

Uh oh!

addaleax commented Aug 8, 2017

Uh oh!

bnoordhuis commented Aug 8, 2017

Uh oh!

Trott commented Aug 8, 2017

Uh oh!

Trott commented Aug 8, 2017

Uh oh!

bnoordhuis commented Aug 8, 2017

Uh oh!

Trott commented Aug 8, 2017

Uh oh!

refack commented Aug 8, 2017

Uh oh!

Trott commented Aug 8, 2017• edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Trott commented Aug 10, 2017

Uh oh!

Trott commented Aug 10, 2017

Uh oh!

Trott commented Aug 10, 2017

Uh oh!

MylesBorins commented Sep 19, 2017

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

Trott commented Aug 8, 2017•
edited
Loading

Trott commented Aug 8, 2017•
edited
Loading

Trott commented Aug 8, 2017•
edited
Loading