investigate flaky test-http2-pack-end-stream-flag

[Trott]

• Test: test-http2-pack-end-stream-flag
• Platform: freebsd11-x64
• Console Output:

07:19:22 not ok 1964 parallel/test-http2-pack-end-stream-flag
07:19:22   ---
07:19:22   duration_ms: 120.47
07:19:22   severity: fail
07:19:22   exitcode: -15
07:19:22   stack: |-
07:19:22     timeout
07:19:22   ...

• Build Links: https://ci.nodejs.org/job/node-test-commit-freebsd/38488/nodes=freebsd11-x64/console

[targos]

I've seen it fail on macOS too:
https://ci.nodejs.org/job/node-test-commit-osx/39328/nodes=osx1014/console
https://ci.nodejs.org/job/node-test-commit-osx/39332/nodes=osx1014/console

[Trott]

https://ci.nodejs.org/job/node-test-commit-freebsd/38594/nodes=freebsd11-x64/console

00:18:34 not ok 1635 parallel/test-http2-pack-end-stream-flag
00:18:35   ---
00:18:35   duration_ms: 120.94
00:18:35   severity: fail
00:18:35   exitcode: -15
00:18:35   stack: |-
00:18:35     timeout
00:18:35   ...

[Trott]

https://ci.nodejs.org/job/node-test-commit-osx/39441/nodes=osx1014/console

00:14:03 not ok 2222 parallel/test-http2-pack-end-stream-flag
00:14:03   ---
00:14:03   duration_ms: 120.75
00:14:03   severity: fail
00:14:03   exitcode: -15
00:14:03   stack: |-
00:14:03     timeout
00:14:03   ...

[Trott]

I'm able to replicate the problam on macOS without even running stuff in parallel.

 tools/test.py --repeat=192 test/parallel/test-http2-pack-end-stream-flag.js

[Trott]

Bisecting points to f3eb224 as the change where this issue starts to manifest itself.

[Trott]

Still happening on CI with some frequency:

https://ci.nodejs.org/job/node-test-commit-osx/39504/nodes=osx1014/console

00:16:27 not ok 2194 parallel/test-http2-pack-end-stream-flag
00:16:27   ---
00:16:27   duration_ms: 120.91
00:16:27   severity: fail
00:16:27   exitcode: -15
00:16:27   stack: |-
00:16:27     timeout
00:16:27   ...

[Trott]

After some debugging, seems to me that this is a legitimate failure indicative of an http2 and/or perf_hooks bug whereby, for whatever reason, sometimes (infrequently) the Http2Session entry with detail type client never occurs.

This bug appears to have been introduced in f3eb224.

@jasnell

[jasnell]

I'll take a look a bit later today

[Trott]

I'll take a look a bit later today

If it helps, I debugged by adding console.error() statements (don't judge) along with a setTimeout() to throw an error after 5 seconds. So with the modified code below, tools/test.py --timeout=10 --repeat 1920 test/parallel/test-http2-pack-end-stream-flag.js showed the issue. In CI, it happens on macOS and FreeBSD.

'use strict';

console.error('starting');

const common = require('../common');
if (!common.hasCrypto)
  common.skip('missing crypto');
const assert = require('assert');
const http2 = require('http2');

const { PerformanceObserver } = require('perf_hooks');

const server = http2.createServer();

server.on('stream', (stream, headers) => {
  stream.respond({
    'content-type': 'text/html',
    ':status': 200
  });
  switch (headers[':path']) {
    case '/singleEnd':
      stream.end('OK');
      break;
    case '/sequentialEnd':
      stream.write('OK');
      stream.end();
      break;
    case '/delayedEnd':
      stream.write('OK', () => stream.end());
      break;
  }
});

function testRequest(path, targetFrameCount, callback) {
  console.error('test request');
  const obs = new PerformanceObserver(
    common.mustCallAtLeast((list, observer) => {
      console.error('mustcallatleast');
      const entry = list.getEntries()[0];
      console.error(entry.name, entry.detail.type);
      if (entry.name !== 'Http2Session') return;
      if (entry.detail.type !== 'client') return;
      assert.strictEqual(entry.detail.framesReceived, targetFrameCount);
      observer.disconnect();
      callback();
    }));
  obs.observe({ type: 'http2' });
  const client =
    http2.connect(`http://localhost:${server.address().port}`, () => {
      const req = client.request({ ':path': path });
      req.resume();
      req.end();
      req.on('end', () => client.close());
    });
}

// SETTINGS => SETTINGS => HEADERS => DATA
const MIN_FRAME_COUNT = 4;

server.listen(0, () => {
  console.error('listening');
  testRequest('/singleEnd', MIN_FRAME_COUNT, () => {
    console.error('singleend');
    testRequest('/sequentialEnd', MIN_FRAME_COUNT, () => {
      console.error('sequentialend');
      testRequest('/delayedEnd', MIN_FRAME_COUNT + 1, () => {
        console.error('closing');
        server.close();
      });
    });
  });
});

setTimeout(() => { throw new Error('foo'); }, 5000).unref();