Consistent failure of test-http-client-timeout-option-with-agent

[devsnek]

Every time I run the suite I see this failure:

=== release test-http-client-timeout-option-with-agent ===
Path: parallel/test-http-client-timeout-option-with-agent
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: duration 2992ms less than timeout 3000ms
    at ClientRequest.req.on.common.mustCall (node/test/parallel/test-http-client-timeout-option-with-agent.js:46:12)
    at ClientRequest.<anonymous> (node/test/common/index.js:368:15)
    at ClientRequest.emit (events.js:197:13)
    at Socket.emitRequestTimeout (_http_client.js:666:40)
    at Object.onceWrapper (events.js:285:13)
    at Socket.emit (events.js:197:13)
    at Socket._onTimeout (net.js:422:8)
    at listOnTimeout (timers.js:324:15)
    at processTimers (timers.js:268:5)
Command: out/Release/node node/test/parallel/test-http-client-timeout-option-with-agent.js

cc @Trott who messed with the timers in this test last

[Trott]

Do you see the failure when you run tools/test.py test/parallel/test-http-client-timeout-option-with-agent.js or only when you run make test or what exactly?

[Trott]

Seems to me like maybe const start = Date.now(); should be moved immediately before const req = http.request(options); instead of coming immediately after it? If that seems about right to you, does that change fix things for you?

[devsnek]

@Trott it goes from 2993ms to 2998ms, so definitely closer, but still not passing.

[Trott]

What happens with this one (which also switches to process.hrtime.bigint())?:

'use strict';
const common = require('../common');

// Test that when http request uses both timeout and agent,
// timeout will work as expected.

const assert = require('assert');
const http = require('http');

const HTTP_AGENT_TIMEOUT = 1000;
const HTTP_CLIENT_TIMEOUT = 3000;

const agent = new http.Agent({ timeout: HTTP_AGENT_TIMEOUT });
const options = {
  method: 'GET',
  port: undefined,
  host: '127.0.0.1',
  path: '/',
  timeout: HTTP_CLIENT_TIMEOUT,
  agent,
};

const server = http.createServer(() => {
  // Never respond.
});

server.listen(0, options.host, () => {
  doRequest();
});

function doRequest() {
  options.port = server.address().port;
  const start = process.hrtime.bigint();
  const req = http.request(options);
  req.on('error', () => {
    // This space is intentionally left blank.
  });
  req.on('close', common.mustCall(() => server.close()));

  let timeout_events = 0;
  req.on('timeout', common.mustCall(() => {
    timeout_events += 1;
    const duration = process.hrtime.bigint() - start;
    // The timeout event cannot be precisely timed. It will delay
    // some number of milliseconds.
    assert.ok(
      duration >= BigInt(HTTP_CLIENT_TIMEOUT * 1e6),
      `duration ${duration}ms less than timeout ${HTTP_CLIENT_TIMEOUT}ms`
    );
  }));
  req.end();

  setTimeout(() => {
    req.destroy();
    assert.strictEqual(timeout_events, 1);
    // Ensure the `timeout` event fired only once.
  }, common.platformTimeout(HTTP_CLIENT_TIMEOUT * 2));
}

I'll be mildly surprised if that actually fixes it for you, but if so, hey, great.

[Trott]

Another thing to try might be to see if the test passes if you set the agent timeout constant to 3000 instead of 1000. If the test starts passing then, that suggests that this may be a legitimate bug and not a problem with the test.

[devsnek]

@Trott it passes with bigint, but it also passes when i change it to 1000ms

[Trott]

@nodejs/http

[Trott]

@devsnek What OS are you running?

[Trott]

I think switching to process.hrtime.bigint() is probably a good change anyway, so I'd be inclined to do that and call it good. Thoughts? @nodejs/testing

[devsnek]

@Trott macos 10.14.3