Issue with Node 4.x when receiving pipelined reqeusts #3332

DamianEdwards · 2015-10-12T23:46:41Z

After updating to Node 4.x from 0.12.x, benchmarking by sending pipelining requests results in an initial spike of requests followed by no requests being processed on those connections, and those connections remaining open even after the load generator client finishes (connection leak). The same behavior does not occur when not pipelining requests, and it doesn't occur on 0.10.x or 0.12.x at all. The issue reproduces on both Linux and Windows.

I'm generating load using "wrk" (from a remote Linux machine) and the app is the benchmark app from the TechEmpower benchmarks.

rmg · 2015-10-12T23:55:10Z

@DamianEdwards which specific version? v4.2.0? v4.1.2?

DamianEdwards · 2015-10-13T00:08:53Z

I reproduced on both 4.1.2 and 4.2.0

brendanashworth · 2015-10-13T03:17:58Z

Does it occur on 4.1.1? There were a few changes in 4.1.2 (0504066, b3d9678) that might be causing this.

DamianEdwards · 2015-10-13T03:22:15Z

I'll drop back to 4.1.1 tomorrow and try it out.

Fishrock123 · 2015-10-13T04:52:24Z

cc @indutny

indutny · 2015-10-13T05:13:08Z

@DamianEdwards does removing those lines help?

indutny · 2015-10-13T05:13:41Z

Actually, latter one should be enough to verify it.

DamianEdwards · 2015-10-13T05:41:01Z

@indutny I'm assuming I have to build from source to try out removing that line?

indutny · 2015-10-13T05:41:53Z

@DamianEdwards yeah. Sorry, I forgot to mention it.

DamianEdwards · 2015-10-13T05:44:50Z

@indutny 😄
I'll see what I can do. That change was added in 4.1.2?

indutny · 2015-10-13T05:46:20Z

Yep.

indutny · 2015-10-13T05:57:35Z

Found one bug, already:

diff --git a/lib/_http_outgoing.js b/lib/_http_outgoing.js
index 6650c06..366c516 100644
--- a/lib/_http_outgoing.js
+++ b/lib/_http_outgoing.js
@@ -663,6 +663,9 @@ OutgoingMessage.prototype._flush = function() {
       this.output = [];
       this.outputEncodings = [];
       this.outputCallbacks = [];
+      if (this._onPendingData !== null)
+        this._onPendingData(-this.outputSize);
+      this.outputSize = 0;
     }

     if (this.finished) {

Looking for more.

indutny · 2015-10-13T06:06:14Z

Second part of issue is handling of paused parser in consumed socket. Working on fix.

indutny · 2015-10-13T06:13:05Z

Full fix:

diff --git a/lib/_http_outgoing.js b/lib/_http_outgoing.js
index 6650c06..366c516 100644
--- a/lib/_http_outgoing.js
+++ b/lib/_http_outgoing.js
@@ -663,6 +663,9 @@ OutgoingMessage.prototype._flush = function() {
       this.output = [];
       this.outputEncodings = [];
       this.outputCallbacks = [];
+      if (this._onPendingData !== null)
+        this._onPendingData(-this.outputSize);
+      this.outputSize = 0;
     }

     if (this.finished) {
diff --git a/lib/_http_server.js b/lib/_http_server.js
index c11d369..ffaa0b8 100644
--- a/lib/_http_server.js
+++ b/lib/_http_server.js
@@ -270,6 +270,7 @@ function connectionListener(socket) {
     // need to pause TCP socket/HTTP parser, and wait until the data will be
     // sent to the client.
     outgoingData += delta;
+    console.log(outgoingData);
     if (socket._paused && outgoingData < socket._writableState.highWaterMark)
       return socketOnDrain();
   }
@@ -405,6 +406,7 @@ function connectionListener(socket) {
     if (socket._paused) {
       // onIncoming paused the socket, we should pause the parser as well
       debug('pause parser');
+      parser.unconsume(socket._handle._externalStream);
       socket.parser.pause();
     }
   }

@DamianEdwards may I ask you to give it a try?

indutny · 2015-10-13T06:20:10Z

Full fix with test is here: #3342

* Includes fixes for two regressions - Assertion error in WeakCallback - see [#3329](#3329) - Undefined timeout regression - see [#3331](#3331) * Document an additional known issue with pipelined requests - See: #3332 and #3342

DamianEdwards · 2015-10-13T18:45:25Z

I just confirmed the issue is not present in 4.1.1

I'll try building from source to test out the fix on our rig here.

This is a two-part fix: - Fix pending data notification in `OutgoingMessage` to notify server about flushed data too - Fix pause/resume behavior for the consumed socket. `resume` event is emitted on a next tick, and `socket._paused` can already be `true` at this time. Pause the socket again to avoid PAUSED error on parser. Fix: nodejs#3332

NawarA · 2015-10-22T19:10:38Z

Hey guys, I believe we're seeing this issue in production for 4.2.1. I can share the error if that'd be helpful.

I believe @indutny fixed this, right? If so, why isn't this released? This should be considered a hotfix and get released as a 4.2.2 release ASAP

Just curious on whats going on with this given what we're seeing, given its fixed, and given the fix is unreleased

jasnell · 2015-10-22T19:18:06Z

@NawarA ... I'm likely going to be taking a look at spinning out a 4.2.2 early next week.

NawarA · 2015-10-22T19:20:10Z

@jasnell thanks. I had to roll back to iojs to keep production stable. Let me know if I can help with the release

jasnell · 2015-10-22T19:21:59Z

@NawarA ... smoke testing the v4.x branch would be helpful. If you pull the branch, do a fresh build, does it resolve the issue or are there specific commits we still need to land to address the issue?

NawarA · 2015-10-22T20:00:42Z

Will do. To confirm the error and ensure its related to this issue, here's what I'm seeing:

_stream_readable.js:480
  dest.on('unpipe', onunpipe);
       ^
TypeError: dest.on is not a function
    at Gzip.Readable.pipe (_stream_readable.js:480:8)
    at ChildProcess.onMessage (/home/admin_augur_io/Augur/LearningServer/routes/recon-master.js:60:10)
    at emitTwo (events.js:87:13)
    at ChildProcess.emit (events.js:172:7)
    at handleMessage (internal/child_process.js:686:10)
    at Pipe.channel.onread (internal/child_process.js:440:11)

I'll pull the latest master branch, and see if it resolves the issue.

indutny · 2015-10-22T20:08:07Z

@NawarA this does not look related to this issue

NawarA · 2015-10-22T21:40:26Z

Good to know. I thought because it was as stream where piping was failing, and due to me seeing this issue after upgrading, that the issue was related. Thanks for sharing @indutny

indutny · 2015-10-22T22:01:54Z

Pipelining, not piping ;)

On Thursday, October 22, 2015, Nawar Alsafar notifications@github.com
wrote:

Good to know. I thought because it was as stream where piping was failing,
and due to me seeing this issue after upgrading, that the issue was
related. Thanks for sharing @indutny https://github.com/indutny

—
Reply to this email directly or view it on GitHub
#3332 (comment).

This is a two-part fix: - Fix pending data notification in `OutgoingMessage` to notify server about flushed data too - Fix pause/resume behavior for the consumed socket. `resume` event is emitted on a next tick, and `socket._paused` can already be `true` at this time. Pause the socket again to avoid PAUSED error on parser. Fix: #3332 PR-URL: #3342 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

Original commit ab03635: This is a two-part fix: - Fix pending data notification in `OutgoingMessage` to notify server about flushed data too - Fix pause/resume behavior for the consumed socket. `resume` event is emitted on a next tick, and `socket._paused` can already be `true` at this time. Pause the socket again to avoid PAUSED error on parser. Fix: nodejs#3332 PR-URL: nodejs#3342 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

This is a two-part fix: - Fix pending data notification in `OutgoingMessage` to notify server about flushed data too - Fix pause/resume behavior for the consumed socket. `resume` event is emitted on a next tick, and `socket._paused` can already be `true` at this time. Pause the socket again to avoid PAUSED error on parser. Fix: #3332 PR-URL: #3342 Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

mscdex added the http Issues or PRs related to the http subsystem. label Oct 13, 2015

indutny mentioned this issue Oct 13, 2015

http: fix stalled pipeline bug #3342

Closed

indutny added the confirmed-bug Issues with confirmed bugs. label Oct 13, 2015

indutny closed this as completed in ab03635 Oct 14, 2015

snyk-bot mentioned this issue Apr 24, 2023

[Snyk] Security upgrade lerna from 3.22.1 to 5.5.2 aliscco/alisco-node#102

Open

This was referenced May 13, 2024

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 leonardoadame/node#821

Open

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 leonardoadame/node#851

Open

This was referenced May 14, 2024

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 aliscco/alisco-node#1462

Open

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 aliscco/alisco-node#1472

Open

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 aliscco/alisco-node#1482

Open

leonardoadame mentioned this issue May 14, 2024

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 leonardoadame/node#892

Open

This was referenced May 14, 2024

[Snyk] Fix for 2 vulnerabilities aliscco/alisco-node#1491

Open

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 aliscco/alisco-node#1548

Open

[Snyk] Security upgrade karma from 3.1.4 to 4.2.0 aliscco/alisco-node#1549

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Issue with Node 4.x when receiving pipelined reqeusts #3332

Issue with Node 4.x when receiving pipelined reqeusts #3332

DamianEdwards commented Oct 12, 2015

rmg commented Oct 12, 2015

DamianEdwards commented Oct 13, 2015

brendanashworth commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

Fishrock123 commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

indutny commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

NawarA commented Oct 22, 2015

jasnell commented Oct 22, 2015

NawarA commented Oct 22, 2015

jasnell commented Oct 22, 2015

NawarA commented Oct 22, 2015

indutny commented Oct 22, 2015

NawarA commented Oct 22, 2015

indutny commented Oct 22, 2015

Issue with Node 4.x when receiving pipelined reqeusts #3332

Issue with Node 4.x when receiving pipelined reqeusts #3332

Comments

DamianEdwards commented Oct 12, 2015

rmg commented Oct 12, 2015

DamianEdwards commented Oct 13, 2015

brendanashworth commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

Fishrock123 commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

indutny commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

indutny commented Oct 13, 2015

DamianEdwards commented Oct 13, 2015

NawarA commented Oct 22, 2015

jasnell commented Oct 22, 2015

NawarA commented Oct 22, 2015

jasnell commented Oct 22, 2015

NawarA commented Oct 22, 2015

indutny commented Oct 22, 2015

NawarA commented Oct 22, 2015

indutny commented Oct 22, 2015