Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Investigate flaky test-stream-finished #43623

Closed
F3n67u opened this issue Jun 30, 2022 · 8 comments · Fixed by #43641
Closed

Investigate flaky test-stream-finished #43623

F3n67u opened this issue Jun 30, 2022 · 8 comments · Fixed by #43641
Labels
flaky-test Issues and PRs related to the tests with unstable failures on the CI. stream Issues and PRs related to the stream subsystem.

Comments

@F3n67u
Copy link
Member

F3n67u commented Jun 30, 2022

Test

test-stream-finished

Platform

not specific on a single platform

Console output

node:assert:124
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
+ actual - expected

+ Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
+     at new NodeError (node:internal/errors:387:5)
+     at ServerResponse.onclose (node:internal/streams/end-of-stream:147:30)
+     at ServerResponse.emit (node:events:549:35)
+     at emitCloseNT (node:_http_server:904:10)
+     at Socket.onServerResponseClose (node:_http_server:257:5)
+     at Socket.emit (node:events:549:35)
+     at TCP.<anonymous> (node:net:756:14) {
+   code: 'ERR_STREAM_PREMATURE_CLOSE'
+ }
- undefined
    at ServerResponse.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx11-x64/test/parallel/test-stream-finished.js:656:14)
    at ServerResponse.<anonymous> (/Users/iojs/build/workspace/node-test-commit-osx/nodes/osx11-x64/test/common/index.js:438:15)
    at ServerResponse.<anonymous> (node:internal/util:445:5)
    at ServerResponse.onclose (node:internal/streams/end-of-stream:146:25)
    at ServerResponse.emit (node:events:549:35)
    at emitCloseNT (node:_http_server:904:10)
    at Socket.onServerResponseClose (node:_http_server:257:5)
    at Socket.emit (node:events:549:35)
    at TCP.<anonymous> (node:net:756:14) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
      at new NodeError (node:internal/errors:387:5)
      at ServerResponse.onclose (node:internal/streams/end-of-stream:147:30)
      at ServerResponse.emit (node:events:549:35)
      at emitCloseNT (node:_http_server:904:10)
      at Socket.onServerResponseClose (node:_http_server:257:5)
      at Socket.emit (node:events:549:35)
      at TCP.<anonymous> (node:net:756:14) {
    code: 'ERR_STREAM_PREMATURE_CLOSE'
  },
  expected: undefined,
  operator: 'strictEqual'
}

Node.js v19.0.0-pre

Build links

https://ci.nodejs.org/job/node-test-commit-osx/45891/nodes=osx11-x64/testReport/junit/(root)/test/parallel_test_stream_finished/

https://ci.nodejs.org/job/node-test-commit-linux/46348/nodes=rhel8-x64/testReport/(root)/test/parallel_test_stream_finished/

https://ci.nodejs.org/job/node-test-commit-osx-arm/6307/nodes=osx11/testReport/junit/(root)/test/parallel_test_stream_finished/

Additional information

I can reproduce it on my macOS 12.2.1:

$ repeat 200 ./node test/parallel/test-stream-finished.js
node:assert:124
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
+ actual - expected

+ Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
+     at new NodeError (node:internal/errors:387:5)
+     at ServerResponse.onclose (node:internal/streams/end-of-stream:147:30)
+     at ServerResponse.emit (node:events:549:35)
+     at emitCloseNT (node:_http_server:904:10)
+     at Socket.onServerResponseClose (node:_http_server:257:5)
+     at Socket.emit (node:events:549:35)
+     at TCP.<anonymous> (node:net:756:14) {
+   code: 'ERR_STREAM_PREMATURE_CLOSE'
+ }
- undefined
    at ServerResponse.<anonymous> (/Users/feng/Projects/node/test/parallel/test-stream-finished.js:656:14)
    at ServerResponse.<anonymous> (/Users/feng/Projects/node/test/common/index.js:438:15)
    at ServerResponse.<anonymous> (node:internal/util:445:5)
    at ServerResponse.onclose (node:internal/streams/end-of-stream:146:25)
    at ServerResponse.emit (node:events:549:35)
    at emitCloseNT (node:_http_server:904:10)
    at Socket.onServerResponseClose (node:_http_server:257:5)
    at Socket.emit (node:events:549:35)
    at TCP.<anonymous> (node:net:756:14) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: Error [ERR_STREAM_PREMATURE_CLOSE]: Premature close
      at new NodeError (node:internal/errors:387:5)
      at ServerResponse.onclose (node:internal/streams/end-of-stream:147:30)
      at ServerResponse.emit (node:events:549:35)
      at emitCloseNT (node:_http_server:904:10)
      at Socket.onServerResponseClose (node:_http_server:257:5)
      at Socket.emit (node:events:549:35)
      at TCP.<anonymous> (node:net:756:14) {
    code: 'ERR_STREAM_PREMATURE_CLOSE'
  },
  expected: undefined,
  operator: 'strictEqual'
}

Node.js v19.0.0-pre

Related test:

{
const server = http.createServer(common.mustCall(function(req, res) {
fs.createReadStream(__filename).pipe(res);
finished(res, common.mustCall(function(err) {
assert.strictEqual(err, undefined);
}));
})).listen(0, function() {
http.request(
{ method: 'GET', port: this.address().port },
common.mustCall(function(res) {
res.resume();
server.close();
})
).end();
});
}

It seems like caused by a regression, this sub-test is added at #40941 by @ronag 8 months ago.

@F3n67u F3n67u added flaky-test Issues and PRs related to the tests with unstable failures on the CI. stream Issues and PRs related to the stream subsystem. labels Jun 30, 2022
@MoLow
Copy link
Member

MoLow commented Jun 30, 2022

it seems the flakiness was introduced in this PR
#43522

this.closeIdleConnections();

I have added a delay in the response, converting

fs.createReadStream(__filename).pipe(res);

into

fs.createReadStream(__filename).map(async x => {
      await setTimeout(1);
      return x;
}).pipe(res);

adding such a delay made this reproduce 100% of the time on my mac, and commenting out this line fixed that

this.closeIdleConnections();

I am not very familiar with this code but it like a real bug since the test already recieved a response so why is the socket still open?

CC @ShogunPanda @mcollina

@MoLow
Copy link
Member

MoLow commented Jun 30, 2022

adding res.writeHead(200, { 'Connection': 'close' }); solves that

@tniessen
Copy link
Member

In #43522, four out of five CI runs failed due to test-stream-finished...

@ShogunPanda
Copy link
Contributor

I will send a PR within couple of hours that will fix that test as suggested above.

@F3n67u
Copy link
Member Author

F3n67u commented Jul 1, 2022

I will send a PR within couple of hours that will fix that test as suggested above.

Thanks for help.

@tniessen
Copy link
Member

tniessen commented Jul 1, 2022

Neither #43633 nor #43641 appear to fix this issue, which is causing tons of failures. If #43522 is the culprit, maybe revert (#43636) is the way to go? Looking at its CI history, it probably should not have landed: the test failed a bunch of times there, too.

@panva
Copy link
Member

panva commented Jul 1, 2022

I agree with @tniessen. Revert and re-land once we're confident no more flakiness was introduced.

@ShogunPanda
Copy link
Contributor

#43641 seems to be have fixed the flakyness on those tests now. I think we are good to go there.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
flaky-test Issues and PRs related to the tests with unstable failures on the CI. stream Issues and PRs related to the stream subsystem.
Projects
None yet
5 participants