Investigate flaky parallel/test-http-set-timeout-server #11768

mscdex · 2017-03-09T13:53:05Z

Version: master
Platform: freebsd,pi1-raspbian-wheezy
Subsystem: http

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

not ok 612 parallel/test-http-set-timeout-server
  ---
  duration_ms: 1.315
  severity: fail
  stack: |-
    # serverTimeout
    # serverRequestTimeout
    # serverResponseTimeout
    # serverRequestNotTimeoutAfterEnd
    # serverResponseTimeoutWithPipeline
    # idleTimeout
    ok
    
    assert.js:81
      throw new assert.AssertionError({
      ^
    AssertionError: '' === '/2'
        at process.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:121:12)
        at emitOne (events.js:101:20)
        at process.emit (events.js:191:7)

The text was updated successfully, but these errors were encountered:

It can happen that the connection and server is closed before the second reponse has been processed by server. In this case, the `res.setTimeout()` callback will never be called causing the test to fail. Fix this by only closing the connection and server when the 2nd has been received. PR-URL: nodejs#11790 Fixes: nodejs#11768 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Gibson Fahnestock <gibfahn@gmail.com>

It can happen that the connection and server is closed before the second reponse has been processed by server. In this case, the `res.setTimeout()` callback will never be called causing the test to fail. Fix this by only closing the connection and server when the 2nd has been received. PR-URL: #11790 Fixes: #11768 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Gibson Fahnestock <gibfahn@gmail.com>

refack · 2017-06-30T23:01:00Z

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

not ok 702 parallel/test-http-set-timeout-server
  ---
  duration_ms: 6.648
  severity: fail
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
        at Object.exports.mustCall (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:486:10)
        at serverTimeout (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:45:43)
        at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:520:15
        at run (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:40:5)
        at _combinedTickCallback (internal/process/next_tick.js:134:7)
        at process._tickCallback (internal/process/next_tick.js:201:9)
        at Function.Module.runMain (module.js:607:11)
        at startup (bootstrap_node.js:158:16)
        at bootstrap_node.js:575:3

refack · 2017-07-04T11:52:06Z

Now on ARM (pi1-raspbian-wheezy):

not ok 99 parallel/test-http-set-timeout-server
  ---
  duration_ms: 8.803
  severity: fail
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
        at Object.exports.mustCall (/home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:484:10)
        at serverTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-http-set-timeout-server.js:45:43)
        at /home/iojs/build/workspace/node-test-binary-arm/test/common/index.js:518:15
        at run (/home/iojs/build/workspace/node-test-binary-arm/test/parallel/test-http-set-timeout-server.js:40:5)
        at _combinedTickCallback (internal/process/next_tick.js:134:7)
        at process._tickCallback (internal/process/next_tick.js:201:9)
        at Function.Module.runMain (module.js:607:11)
        at startup (bootstrap_node.js:158:16)
        at bootstrap_node.js:575:3
  ...

https://ci.nodejs.org/job/node-test-binary-arm/9039/RUN_SUBSET=6,label=pi1-raspbian-wheezy/

refack · 2017-07-04T15:57:28Z

https://ci.nodejs.org/job/node-test-binary-arm/9044/RUN_SUBSET=5,label=pi1-raspbian-wheezy/tapResults/

Trott · 2017-07-14T16:03:00Z

FreeBSD again:

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

not ok 697 parallel/test-http-set-timeout-server
  ---
  duration_ms: 2.804
  severity: fail
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
        at Object.exports.mustCall (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:481:10)
        at idleTimeout (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:155:43)
        at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:513:15
        at run (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:40:5)
        at Server.server.on.common.mustCall (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:138:7)
        at Server.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:513:15)
        at emitOne (events.js:115:13)
        at Server.emit (events.js:210:7)
        at Socket.socketOnTimeout (_http_server.js:392:35)

Trott · 2017-07-19T13:32:21Z

More FreeBSD:

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

not ok 701 parallel/test-http-set-timeout-server
  ---
  duration_ms: 2.836
  severity: fail
  stack: |-
    Mismatched <anonymous> function calls. Expected exactly 1, actual 0.
        at Object.exports.mustCall (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:480:10)
        at idleTimeout (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:155:43)
        at /usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:512:15
        at run (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:40:5)
        at Server.server.on.common.mustCall (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/parallel/test-http-set-timeout-server.js:138:7)
        at Server.<anonymous> (/usr/home/iojs/build/workspace/node-test-commit-freebsd/nodes/freebsd10-64/test/common/index.js:512:15)
        at emitOne (events.js:115:13)
        at Server.emit (events.js:210:7)
        at Socket.socketOnTimeout (_http_server.js:392:35)

It can happen that the connection and server is closed before the second reponse has been processed by server. In this case, the `res.setTimeout()` callback will never be called causing the test to fail. Fix this by only closing the connection and server when the 2nd has been received. PR-URL: nodejs/node#11790 Fixes: nodejs/node#11768 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Gibson Fahnestock <gibfahn@gmail.com>

Trott · 2017-07-20T06:02:03Z

I can replicate this by reducing the timeout on line 160 to 1ms and running the test under load. Confirms what seems little obvious, which is that the test is still race-y.

Trott · 2017-07-20T06:03:19Z

Since being re-opened, the error has always been in line 155 which is not where the problem was before, which suggests that this is either a new problem or a problem only revealed by fixing the previous problem.

Trott · 2017-07-20T06:13:37Z

Fixing coming momentarily...

Trott · 2017-07-20T06:22:08Z

Proposed fix in #14380

The tests include a callback that might not be invoked but is wrapped in common.mustCall(). Remove the common.mustCall() wrapper and add a comment explaining that it should not be added. Add a new test case that sets the timeout to 1ms and waits for both the connection handler and the timeout handler to be invoked. This version keeps the common.mustCall() wrapper intact around the connection handler (although it's mostly semantic and not necessary for the test as the test will certainly fail or time out if that handler isn't invoked). Fixes: nodejs#11768

The tests include a callback that might not be invoked but is wrapped in common.mustCall(). Remove the common.mustCall() wrapper and add a comment explaining that it should not be added. Add a new test case that sets the timeout to 1ms and waits for both the connection handler and the timeout handler to be invoked. This version keeps the common.mustCall() wrapper intact around the connection handler (although it's mostly semantic and not necessary for the test as the test will certainly fail or time out if that handler isn't invoked). PR-URL: #14380 Fixes: #11768 Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

mscdex added freebsd Issues and PRs related to the FreeBSD platform. http Issues or PRs related to the http subsystem. test Issues and PRs related to the tests. labels Mar 9, 2017

santigimeno mentioned this issue Mar 10, 2017

test: fix flaky test-http-set-timeout-server #11790

Merged

2 tasks

santigimeno closed this as completed in #11790 Mar 14, 2017

refack added the flaky-test Issues and PRs related to the tests with unstable failures on the CI. label Jun 30, 2017

refack reopened this Jun 30, 2017

refack changed the title ~~Investigate flaky parallel/test-http-set-timeout-server on freebsd~~ Investigate flaky parallel/test-http-set-timeout-server Jul 4, 2017

refack added the arm Issues and PRs related to the ARM platform. label Jul 4, 2017

refack mentioned this issue Jul 4, 2017

fs,doc,test: open reserved characters under win32 #13875

Closed

3 tasks

refack mentioned this issue Jul 18, 2017

v8.2.0 proposal #13744

Merged

Trott mentioned this issue Jul 20, 2017

test: fix flaky http(s)-set-timeout-server tests #14380

Closed

2 tasks

Trott closed this as completed in c5bed4c Jul 25, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Investigate flaky parallel/test-http-set-timeout-server #11768

Investigate flaky parallel/test-http-set-timeout-server #11768

mscdex commented Mar 9, 2017 •

edited by refack

Loading

refack commented Jun 30, 2017

refack commented Jul 4, 2017

refack commented Jul 4, 2017

Trott commented Jul 14, 2017 •

edited

Loading

Trott commented Jul 19, 2017

Trott commented Jul 20, 2017

Trott commented Jul 20, 2017

Trott commented Jul 20, 2017

Trott commented Jul 20, 2017

Investigate flaky parallel/test-http-set-timeout-server #11768

Investigate flaky parallel/test-http-set-timeout-server #11768

Comments

mscdex commented Mar 9, 2017 • edited by refack Loading

refack commented Jun 30, 2017

refack commented Jul 4, 2017

refack commented Jul 4, 2017

Trott commented Jul 14, 2017 • edited Loading

Trott commented Jul 19, 2017

Trott commented Jul 20, 2017

Trott commented Jul 20, 2017

Trott commented Jul 20, 2017

Trott commented Jul 20, 2017

mscdex commented Mar 9, 2017 •

edited by refack

Loading

Trott commented Jul 14, 2017 •

edited

Loading