test,http: fix http dump test #19823

mcollina · 2018-04-05T08:18:47Z

Fixes: #19139

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
commit message follows commit guidelines

mcollina · 2018-04-05T08:19:26Z

lib/_http_server.js

@@ -560,7 +560,7 @@ function resOnFinish(req, res, socket, state, server) {
  // if the user never called req.read(), and didn't pipe() or
  // .resume() or .on('data'), then we call req._dump() so that the
  // bytes will be pulled off the wire.
-  if (!req._consuming && !req._readableState.resumeScheduled)
+  if (!req._readableState.resumeScheduled)


this was noted in the original PR. req._consuming is never set.

mcollina · 2018-04-05T08:21:57Z

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

lpinca · 2018-04-05T08:42:57Z

test/parallel/test-http-dump-req-when-res-ends.js

+  req.on('error', function(err) {
+    // ECONNRESET can happen if there is some data still
+    // being sent, as the other side is calling .destroy()
+    if (err.code !== 'ECONNRESET') {


I think on Windows it's ECONNABORTED, and it might also be EPIPE as per #19139 (comment). Should we just ignore the error?

lpinca · 2018-04-05T08:45:52Z

test/parallel/test-http-dump-req-when-res-ends.js

-  req.on('end', common.mustNotCall);
-
-  // this 'data' handler will be removed when dumped
-  req.on('data', common.mustNotCall);


Can we still check that _dump() removes all data listeners?

node/lib/_http_incoming.js

Line 299 in 354849e

this.removeAllListeners('data');

maybe adding an assertion for listenerCount('data') in the 'resume' handler?

mcollina · 2018-04-05T10:14:43Z

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

@lpinca PTAL

lpinca

Added a few more comments. All nits that can be ignored.

lpinca · 2018-04-05T10:19:55Z

test/parallel/test-http-dump-req-when-res-ends.js

  req.on('resume', common.mustCall(function() {
+    // there is no 'data' event handler anymore
+    // it gets automatically removed when dumping the request
+    assert.strictEqual(req.listenerCount('data'), 0);
    console.log('resume called');


Nit: This can be safely removed as the listener is wrapped in mustCall().

lpinca · 2018-04-05T10:20:37Z

test/parallel/test-http-dump-req-when-res-ends.js

 const fs = require('fs');

+let resEnd = null;
+
 const server = http.createServer(function(req, res) {


Nit: I'd wrap the listener with mustCall().

lpinca · 2018-04-05T10:21:26Z

test/parallel/test-http-dump-req-when-res-ends.js

  req.on('resume', common.mustCall(function() {
+    // there is no 'data' event handler anymore
+    // it gets automatically removed when dumping the request
+    assert.strictEqual(req.listenerCount('data'), 0);
    console.log('resume called');

    req.on('data', common.mustCallAtLeast(function(d) {
      console.log('data', d);


Nit: this could also be removed.

BridgeAR · 2018-04-06T10:10:33Z

test/parallel/test-http-dump-req-when-res-ends.js

  // this checks if the request gets dumped
+  // resume will be triggered by res.end()


Nit: would you be so kind and punctuate each sentence and also use a capital letter for the first character of a sentence? :-) That applies to all comments in here. The reason is that it is hard to see the beginning and the end of each sentence right now.

mcollina · 2018-04-06T22:11:21Z

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

Trott · 2018-04-07T03:15:30Z

This fixes the common.mustNotCall problem identified by @lpinca but the test is still sensitive to resource availability so we still need to do #19819 as well. I'll land that now and then resolve any resulting merge conflict that ends up here.

Trott · 2018-04-07T03:21:11Z

(I imagine this also fixes the EPIPE issue that was one of the two ways the test fails in #19139.)

Trott · 2018-04-07T04:08:40Z

CI after rebase: https://ci.nodejs.org/job/node-test-pull-request/14112/

lpinca · 2018-04-07T05:28:32Z

so we still need to do #19819 as well

Do we? I don't think this is still flaky after this rewrite.

mcollina · 2018-04-07T06:11:55Z

I don’t think #19819 was needed.

Fixes: nodejs#19139

mcollina · 2018-04-07T08:04:45Z

Landed as 1f29963

Make sure the dump test actually verify what is happening and it is not flaky. See: #19139 PR-URL: #19823 Reviewed-By: Luigi Pinca <luigipinca@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

Trott · 2018-04-07T15:03:20Z

I don’t think #19819 was needed.

It was needed. I landed this PR on top of master locally on my machine and ran the test under system load and it was still failing.

Trott · 2018-04-07T15:11:59Z

Here's the demo that this alone wasn't enough to fix the test for parallel runs:

$ make -j4
[...SNIP...]
$ git rev-parse HEAD
1f29963eacf587817a6d40da527d05d151668198
$ cp test/sequential/test-http-dump-req-when-res-ends.js test/parallel/test-http-dump-req-when-res-ends.js                                  
$ tools/test.py -j 8 --repeat 192 test/parallel/test-http-dump-req-when-res-ends.js 
=== release test-http-dump-req-when-res-ends ===                    
Path: parallel/test-http-dump-req-when-res-ends
Mismatched <anonymous> function calls. Expected at least 1, actual 0.
    at Object.exports.mustCallAtLeast (/Users/trott/io.js/test/common/index.js:431:10)
    at IncomingMessage.<anonymous> (/Users/trott/io.js/test/parallel/test-http-dump-req-when-res-ends.js:18:27)
    at IncomingMessage.<anonymous> (/Users/trott/io.js/test/common/index.js:467:15)
    at IncomingMessage.emit (events.js:182:13)
    at resume_ (_stream_readable.js:898:10)
    at process._tickCallback (internal/process/next_tick.js:174:19)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-http-dump-req-when-res-ends.js
=== release test-http-dump-req-when-res-ends ===                    
Path: parallel/test-http-dump-req-when-res-ends
Mismatched <anonymous> function calls. Expected at least 1, actual 0.
    at Object.exports.mustCallAtLeast (/Users/trott/io.js/test/common/index.js:431:10)
    at IncomingMessage.<anonymous> (/Users/trott/io.js/test/parallel/test-http-dump-req-when-res-ends.js:18:27)
    at IncomingMessage.<anonymous> (/Users/trott/io.js/test/common/index.js:467:15)
    at IncomingMessage.emit (events.js:182:13)
    at resume_ (_stream_readable.js:898:10)
    at process._tickCallback (internal/process/next_tick.js:174:19)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-http-dump-req-when-res-ends.js
=== release test-http-dump-req-when-res-ends ===                    
Path: parallel/test-http-dump-req-when-res-ends
Mismatched <anonymous> function calls. Expected at least 1, actual 0.
    at Object.exports.mustCallAtLeast (/Users/trott/io.js/test/common/index.js:431:10)
    at IncomingMessage.<anonymous> (/Users/trott/io.js/test/parallel/test-http-dump-req-when-res-ends.js:18:27)
    at IncomingMessage.<anonymous> (/Users/trott/io.js/test/common/index.js:467:15)
    at IncomingMessage.emit (events.js:182:13)
    at resume_ (_stream_readable.js:898:10)
    at process._tickCallback (internal/process/next_tick.js:174:19)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-http-dump-req-when-res-ends.js
[00:11|% 100|+ 189|-   3]: Done 
$

Fix test-http-dump-req-when-res-ends and move it back to test/parallel/ Refs: nodejs#19823

mcollina · 2018-04-09T07:50:49Z

@Trott on my Macbook:

~/Repositories/node (master)
$ git rev-parse HEAD
1f29963eacf587817a6d40da527d05d151668198
~/Repositories/node (master)
$ tools/test.py -j 8 --repeat 192 test/sequential/test-http-dump-req-when-res-ends.js
[00:35|% 100|+ 192|-   0]: Done

So, something weirder was at play here, but I think @lpinca is on to something in #19866.

Trott · 2018-04-09T18:39:56Z

@mcollina Try a bigger -j value. I usually don't trust a test until I can do -j 96 --repeat 192. I showed -j 8 because it was the lowest value I triggered it at. (You probably have a newer/more powerful laptop than I do. In fact, I pretty much guarantee it.)

Fix test-http-dump-req-when-res-ends and move it back to test/parallel/ PR-URL: #19866 Refs: #19823 Reviewed-By: Ruben Bridgewater <ruben@bridgewater.de> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

Make sure the dump test actually verify what is happening and it is not flaky. See: nodejs#19139 PR-URL: nodejs#19823 Reviewed-By: Luigi Pinca <luigipinca@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

mcollina requested review from Trott and lpinca April 5, 2018 08:18

nodejs-github-bot added the http Issues or PRs related to the http subsystem. label Apr 5, 2018

mcollina mentioned this pull request Apr 5, 2018

test: move test-http-dump-req-when-res-end to sequential #19819

Closed

2 tasks

mcollina commented Apr 5, 2018

View reviewed changes

lpinca approved these changes Apr 5, 2018

View reviewed changes

jasnell approved these changes Apr 5, 2018

View reviewed changes

BridgeAR reviewed Apr 6, 2018

View reviewed changes

mcollina force-pushed the fix-http-dump-test branch from c93afee to 010c26c Compare April 6, 2018 22:10

Trott force-pushed the fix-http-dump-test branch from 010c26c to 37ae792 Compare April 7, 2018 04:05

test,http: fix http dump test

8e245ea

Fixes: nodejs#19139

mcollina force-pushed the fix-http-dump-test branch from 37ae792 to 8e245ea Compare April 7, 2018 08:02

mcollina closed this Apr 7, 2018

lpinca mentioned this pull request Apr 7, 2018

test: move back test-http-dump-req-when-res-ends #19866

Closed

3 tasks

lpinca added a commit to lpinca/node that referenced this pull request Apr 8, 2018

test: move back test-http-dump-req-when-res-ends

d6c4cbe

Fix test-http-dump-req-when-res-ends and move it back to test/parallel/ Refs: nodejs#19823

mcollina deleted the fix-http-dump-test branch April 9, 2018 07:49

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test,http: fix http dump test #19823

test,http: fix http dump test #19823

mcollina commented Apr 5, 2018

mcollina Apr 5, 2018

mcollina commented Apr 5, 2018

lpinca Apr 5, 2018

lpinca Apr 5, 2018

mcollina Apr 5, 2018

mcollina commented Apr 5, 2018

lpinca left a comment •

edited

Loading

lpinca Apr 5, 2018

lpinca Apr 5, 2018

lpinca Apr 5, 2018

BridgeAR Apr 6, 2018

mcollina commented Apr 6, 2018

Trott commented Apr 7, 2018

Trott commented Apr 7, 2018

Trott commented Apr 7, 2018

lpinca commented Apr 7, 2018

mcollina commented Apr 7, 2018

mcollina commented Apr 7, 2018

Trott commented Apr 7, 2018

Trott commented Apr 7, 2018 •

edited

Loading

mcollina commented Apr 9, 2018

Trott commented Apr 9, 2018 •

edited

Loading

		// this checks if the request gets dumped
		// resume will be triggered by res.end()

test,http: fix http dump test #19823

test,http: fix http dump test #19823

Conversation

mcollina commented Apr 5, 2018

Checklist

Choose a reason for hiding this comment

mcollina commented Apr 5, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina commented Apr 5, 2018

lpinca left a comment • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina commented Apr 6, 2018

Trott commented Apr 7, 2018

Trott commented Apr 7, 2018

Trott commented Apr 7, 2018

lpinca commented Apr 7, 2018

mcollina commented Apr 7, 2018

mcollina commented Apr 7, 2018

Trott commented Apr 7, 2018

Trott commented Apr 7, 2018 • edited Loading

mcollina commented Apr 9, 2018

Trott commented Apr 9, 2018 • edited Loading

lpinca left a comment •

edited

Loading

Trott commented Apr 7, 2018 •

edited

Loading

Trott commented Apr 9, 2018 •

edited

Loading