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

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

Closed
DamianEdwards opened this issue Oct 12, 2015 · 24 comments
Closed

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

DamianEdwards opened this issue Oct 12, 2015 · 24 comments
Labels
confirmed-bug Issues with confirmed bugs. http Issues or PRs related to the http subsystem.

Comments

@DamianEdwards
Copy link

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
Copy link
Contributor

rmg commented Oct 12, 2015

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

@DamianEdwards
Copy link
Author

I reproduced on both 4.1.2 and 4.2.0

@mscdex mscdex added the http Issues or PRs related to the http subsystem. label Oct 13, 2015
@brendanashworth
Copy link
Contributor

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

@DamianEdwards
Copy link
Author

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

@Fishrock123
Copy link
Contributor

cc @indutny

@indutny
Copy link
Member

indutny commented Oct 13, 2015

Actually, latter one should be enough to verify it.

@DamianEdwards
Copy link
Author

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

@indutny
Copy link
Member

indutny commented Oct 13, 2015

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

@DamianEdwards
Copy link
Author

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

@indutny
Copy link
Member

indutny commented Oct 13, 2015

Yep.

@indutny
Copy link
Member

indutny commented Oct 13, 2015

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
Copy link
Member

indutny commented Oct 13, 2015

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

@indutny
Copy link
Member

indutny commented Oct 13, 2015

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
Copy link
Member

indutny commented Oct 13, 2015

Full fix with test is here: #3342

@indutny indutny added the confirmed-bug Issues with confirmed bugs. label Oct 13, 2015
jasnell added a commit that referenced this issue Oct 13, 2015
* 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
jasnell added a commit that referenced this issue Oct 13, 2015
* 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
jasnell added a commit that referenced this issue Oct 13, 2015
* 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
Copy link
Author

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.

indutny added a commit to indutny/io.js that referenced this issue Oct 14, 2015
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
Copy link

NawarA commented Oct 22, 2015

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
Copy link
Member

jasnell commented Oct 22, 2015

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

@NawarA
Copy link

NawarA commented Oct 22, 2015

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

@jasnell
Copy link
Member

jasnell commented Oct 22, 2015

@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
Copy link

NawarA commented Oct 22, 2015

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
Copy link
Member

indutny commented Oct 22, 2015

@NawarA this does not look related to this issue

@NawarA
Copy link

NawarA commented Oct 22, 2015

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
Copy link
Member

indutny commented Oct 22, 2015

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).

indutny added a commit that referenced this issue Oct 26, 2015
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>
rvagg added a commit to rvagg/io.js that referenced this issue Oct 28, 2015
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>
indutny added a commit that referenced this issue Oct 29, 2015
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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
confirmed-bug Issues with confirmed bugs. http Issues or PRs related to the http subsystem.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

8 participants