test: investigate flaky - parallel/test-readline-interface

[refack]

• Version: master
• Platform: pi1-raspbian-wheezy
• Subsystem: readline

not ok 155 parallel/test-readline-interface
  ---
  duration_ms: 3.59
  severity: fail
  stack: |-
    assert.js:42
      throw new errors.AssertionError({
      ^
    
    AssertionError [ERR_ASSERTION]: 2 === 1
        at Timeout.common.mustCall (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-readline-interface.js:349:14)
        at Timeout._onTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:507:15)
        at ontimeout (timers.js:471:11)
        at tryOnTimeout (timers.js:305:5)
        at Timer.listOnTimeout (timers.js:265:5)
  ...

Refs: #13497
https://ci.nodejs.org/job/node-test-binary-arm/9466/RUN_SUBSET=5,label=pi1-raspbian-wheezy/
/cc @nodejs/platform-arm @addaleax @jasnell @Azard @princejwesley

[addaleax]

If somebody has the time, it might be helpful to insert a couple debug statements to check the order in which events happen and then kick of a stress test until this reproduces. Or maybe just increasing the timeouts/using platformTimeout might work?

[Azard]

I support use platformTimeout , 200ms and 500ms maybe too short for raspbian parallel test.

[Trott]

This is already at the top of my short list of things to deal with. daf5596 was a precursor for making it more modular. Definitely flaky under load when resources are constrained.

[Trott]

It's flaky even if I eliminate all the timers etc. and just have a test that looks like this:

'use strict';
const common = require('../common');
const assert = require('assert');
const readline = require('readline');
const internalReadline = require('internal/readline');
const EventEmitter = require('events').EventEmitter;
const inherits = require('util').inherits;
const { Writable, Readable } = require('stream');

function FakeInput() {
  EventEmitter.call(this);
}
inherits(FakeInput, EventEmitter);
FakeInput.prototype.resume = () => {};
FakeInput.prototype.pause = () => {};
FakeInput.prototype.write = () => {};
FakeInput.prototype.end = () => {};

[false].forEach(function(terminal) {
  {
    const fi = new FakeInput();
    const rli = new readline.Interface(
      { input: fi, output: fi, terminal: terminal }
    );
    const expectedLines = ['foo', 'bar', 'baz', 'bat'];
    let callCount = 0;
    rli.on('line', function(line) {
      assert.strictEqual(line, expectedLines[callCount]);
      callCount++;
    });
    expectedLines.forEach(function(line) {
      fi.emit('data', `${line}\r`);
      fi.emit('data', '\n');
    });
    assert.strictEqual(callCount, expectedLines.length);
    rli.close();
  }
});

Running it with this:

tools/test.py -j 96 --repeat 96 test/parallel/test-readline-interface.js

… still shows failures like this:

AssertionError [ERR_ASSERTION]: '' === 'bar'

This means that line events are being emitted but with the data erroneously set to an empty string.

The question is: Is this a feature (under resource constraints, stuff starts getting dropped) or is it actually a bug in readline because the data should never be dropped?

[Trott]

The question is: Is this a feature (under resource constraints, stuff starts getting dropped) or is it actually a bug in readline because the data should never be dropped?

@nodejs/streams maybe?

[addaleax]

@Trott I don’t think data is getting dropped, it’s that 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()?

[Trott]

@Trott I don’t think data is getting dropped, it’s that the delay between processing \r and \n is so long that readline thinks they are actually separate line endings.

😮 Thank you. That makes way more sense.

[Trott]

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()?

@addaleax Brilliant. That doesn't solve all the test's problems, but it solves most of them (and the primary remaining issue looks like it was solved by @Azard in another PR so we're really close...).

[addaleax]

@Trott Did you try that out? If it works, great 👍 Feel free to do a PR yourself if you have the time :)

[Trott]

@Trott Did you try that out? If it works, great 👍 Feel free to do a PR yourself if you have the time :)

#14681