René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"HTTP OutgoingMessage _send in two packets when a Buffer is written","articleBody":"\u003c!--\nThank you for reporting an issue.\nPlease fill in as much of the template below as you're able.\n\nVersion: output of `node -v`\nPlatform: output of `uname -a` (UNIX), or version and 32 or 64-bit (Windows)\nSubsystem: if known, please specify affected core module name\n\nIf possible, please provide code that demonstrates the problem, keeping it as\nsimple and free of external dependencies as you are able.\n--\u003e\n- **Version**: node -v: v6.2.2\n- **Platform**: OS X 10.10.5 and Ubuntu Linux 14.0.4 LTS\n- **Subsystem**: HTTP\n\n\u003c!-- Enter your issue details below this comment. --\u003e\n\nWhen sending an HTTP outgoing message (HTTP.ServerResponse in this case), the behavior of _send, _flushOutput and _writeRaw cause short HTTP messages that should fit in one packet to often be written in two packets.  I believe this is caused by some inefficient cork/uncork.\n\nHere is an example program:\n\n``` javascript\nvar http = require('http');\n\nvar endStr = 'This is the body';\nvar endBuf = new Buffer(endStr);\nvar i = 0;\n\nvar server = http.createServer(function (req, res) {\n  debugger;\n  if (i % 2 === 0) {\n    console.log('Sending the end as a string');\n    res.setHeader('Content-Length', endStr.length);\n    res.write(endStr);\n  } else {\n    console.log('Sending the end as a buffer');\n    res.setHeader('Content-Length', endBuf.length);\n    res.write(endBuf);\n  }\n  res.end();\n  i++;\n}).listen(0, '127.0.0.1', function () {\n  console.log('listening on ', server.address());\n});\n```\n\nI know that I could use res.end(endBuf) / res.end(endStr) in this case but I'm not because this is just an example.  I actually found this in a program that is piping from an HTTP.ClientResponse to an HTTP.ServerResponse, but that is much more complicated to work with.  In this application, we're also forwarding the Content-Length header from the origin server (that's why I set Content-Length, too).  This is the simplest example I could come up with that demonstrates the behavior.\n\nActual results:\n- The first request (write(endStr)) gets the response with the HTTP headers and body in one packet.\n- The second request (write(endBuf)) gets the response with the HTTP headers in one packet and the body in the next.\n\n```\n$ node uncorktest.js \u0026\nlistening on  { address: '127.0.0.1', family: 'IPv4', port: 53440 }\n$ sudo tcpdump -i lo0 -lnX tcp port 53440\n\n\n(another terminal)$ curl http://localhost:53440/\nnode says: Sending the end as a string\n(tcpdump excerpt, note one packet):\n16:04:26.224813 IP 127.0.0.1.53440 \u003e 127.0.0.1.53442: Flags [P.], seq 1:117, ack 80, win 12756, options [nop,nop,TS val 4062\n97891 ecr 406297885], length 116\n        0x0000:  4500 00a8 2b8c 4000 4006 0000 7f00 0001  E...+.@.@.......\n        0x0010:  7f00 0001 d0c0 d0c2 5167 4a6e ab94 4704  ........QgJn..G.\n        0x0020:  8018 31d4 fe9c 0000 0101 080a 1837 9d23  ..1..........7.#\n        0x0030:  1837 9d1d 4854 5450 2f31 2e31 2032 3030  .7..HTTP/1.1.200\n        0x0040:  204f 4b0d 0a43 6f6e 7465 6e74 2d4c 656e  .OK..Content-Len\n        0x0050:  6774 683a 2031 360d 0a44 6174 653a 2054  gth:.16..Date:.T\n        0x0060:  6875 2c20 3238 204a 756c 2032 3031 3620  hu,.28.Jul.2016.\n        0x0070:  3232 3a30 343a 3236 2047 4d54 0d0a 436f  22:04:26.GMT..Co\n        0x0080:  6e6e 6563 7469 6f6e 3a20 6b65 6570 2d61  nnection:.keep-a\n        0x0090:  6c69 7665 0d0a 0d0a 5468 6973 2069 7320  live....This.is.\n        0x00a0:  7468 6520 626f 6479                      the.body\n\n(another terminal)$ curl http://localhost:53440/\nnode says: Sending the end as a buffer\n(tcpdump excerpt, note two packets):\n16:10:09.708172 IP 127.0.0.1.53440 \u003e 127.0.0.1.53498: Flags [P.], seq 1:101, ack 80, win 12756, options [nop,nop,TS val 406639933 ecr 406639932], length 100\n        0x0000:  4500 0098 65d8 4000 4006 0000 7f00 0001  E...e.@.@.......\n        0x0010:  7f00 0001 d0c0 d0fa 0f3e d5c2 0f29 e2ae  .........\u003e...)..\n        0x0020:  8018 31d4 fe8c 0000 0101 080a 183c d53d  ..1..........\u003c.=\n        0x0030:  183c d53c 4854 5450 2f31 2e31 2032 3030  .\u003c.\u003cHTTP/1.1.200\n        0x0040:  204f 4b0d 0a43 6f6e 7465 6e74 2d4c 656e  .OK..Content-Len\n        0x0050:  6774 683a 2031 360d 0a44 6174 653a 2054  gth:.16..Date:.T\n        0x0060:  6875 2c20 3238 204a 756c 2032 3031 3620  hu,.28.Jul.2016.\n        0x0070:  3232 3a31 303a 3039 2047 4d54 0d0a 436f  22:10:09.GMT..Co\n        0x0080:  6e6e 6563 7469 6f6e 3a20 6b65 6570 2d61  nnection:.keep-a\n        0x0090:  6c69 7665 0d0a 0d0a                      live....\n...\n16:10:09.708261 IP 127.0.0.1.53440 \u003e 127.0.0.1.53498: Flags [P.], seq 101:117, ack 80, win 12756, options [nop,nop,TS val 40\n6639933 ecr 406639933], length 16\n        0x0000:  4500 0044 5e99 4000 4006 0000 7f00 0001  E..D^.@.@.......\n        0x0010:  7f00 0001 d0c0 d0fa 0f3e d626 0f29 e2ae  .........\u003e.\u0026.)..\n        0x0020:  8018 31d4 fe38 0000 0101 080a 183c d53d  ..1..8.......\u003c.=\n        0x0030:  183c d53d 5468 6973 2069 7320 7468 6520  .\u003c.=This.is.the.\n        0x0040:  626f 6479                                body\n```\n\nExpected Results:\n- The first request (write(endStr)) gets the response with the HTTP headers and body in one packet. _(This is correct already)_\n- The second request (write(endBuf)) should also get the response with the HTTP headers and body in one packet.  _(This is not what I am observing currently)_\n\nMy analysis:\nI think that the use of cork in _http_outgoing.js is not 100% correct in this case.  It looks like in the buffer path we cork, write the headers, uncork and write the body.\n\nIf OutgoingMessage.prototype._send is called with a string, it will create one data string of the headers + body portion combined, and then call this._writeRaw() with that combined string.  This path works (though pays the price of a) not using node Buffers and b) forcing a string concatenation.\n\n  If instead it is called with a Buffer, it executes the else{} case which cleverly unshifts the serialized headers into the output buffer and and then calls _writeRaw with the body portion.  So far so good.\n\n``` javascript\nOutgoingMessage.prototype._send = function(data, encoding, callback) {\n  // This is a shameful hack to get the headers and first body chunk onto\n  // the same packet. Future versions of Node are going to take care of\n  // this at a lower level and in a more general way.\n  if (!this._headerSent) {\n    if (typeof data === 'string' \u0026\u0026\n        encoding !== 'hex' \u0026\u0026\n        encoding !== 'base64') {\n      data = this._header + data;\n    } else {\n      this.output.unshift(this._header);\n      this.outputEncodings.unshift('latin1');\n      this.outputCallbacks.unshift(null);\n      this.outputSize += this._header.length;\n      if (typeof this._onPendingData === 'function')\n        this._onPendingData(this._header.length);\n    }\n    this._headerSent = true;\n  }\n  return this._writeRaw(data, encoding, callback);\n};\n```\n\nOK, next _writeRaw actually pushes things out in two stages: it calls _flushOutput and then connection.write:\n\n``` javascript\nOutgoingMessage.prototype._writeRaw = function(data, encoding, callback) {\n  if (typeof encoding === 'function') {\n    callback = encoding;\n    encoding = null;\n  }\n\n  var connection = this.connection;\n  if (connection \u0026\u0026\n      connection._httpMessage === this \u0026\u0026\n      connection.writable \u0026\u0026\n      !connection.destroyed) {\n    // There might be pending data in the this.output buffer.\n    var outputLength = this.output.length;\n    if (outputLength \u003e 0) {\n      this._flushOutput(connection);   // \u003c----!!! headers\n    } else if (data.length === 0) {\n      if (typeof callback === 'function')\n        process.nextTick(callback);\n      return true;\n    }\n\n    // Directly write to socket.\n    return connection.write(data, encoding, callback);   // \u003c----!!! body portion\n  } else if (connection \u0026\u0026 connection.destroyed) {\n    // The socket was destroyed.  If we're still trying to write to it,\n    // then we haven't gotten the 'close' event yet.\n    return false;\n  } else {\n    // buffer, as long as we're not destroyed.\n    return this._buffer(data, encoding, callback);\n  }\n};\n```\n\n_flushOutput does wrap its writes in cork()/uncork() but unfortunately it _calls uncork() before the connection.write() of the body hits_.  On my system this usually forces the writes into two packets.\n\n``` javascript\nOutgoingMessage.prototype._flushOutput = function _flushOutput(socket) {\n  //...\n  socket.cork();\n  for (var i = 0; i \u003c outputLength; i++) {\n    ret = socket.write(output[i], outputEncodings[i],\n                       outputCallbacks[i]);\n  }\n  socket.uncork();\n  //...\n}\n```\n\nI hacked this shim into my program which does an extremely hacky and ugly job of calling uncork() only after also writing out the body, and this fixes it for me.  See the \"!!!\" for the changes I made.\n\n``` javascript\nhttp.OutgoingMessage.prototype._writeRaw = function (data, encoding, callback) {\n  if (typeof encoding === 'function') {\n    callback = encoding;\n    encoding = null;\n  }\n\n  var connection = this.connection;\n  if (connection \u0026\u0026\n      connection._httpMessage === this \u0026\u0026\n      connection.writable \u0026\u0026\n      !connection.destroyed) {\n    // There might be pending data in the this.output buffer.\n    var outputLength = this.output.length;\n    if (outputLength \u003e 0) {\n      connection.cork();  //!!! Add a cork before flushOutput\n      this._flushOutput(connection);\n    } else if (data.length === 0) {\n      if (typeof callback === 'function')\n        process.nextTick(callback);\n      return true;\n    }\n\n    // Directly write to socket.\n    var rc = connection.write(data, encoding, callback);\n    connection.uncork();  // Only uncork after writing the body portion\n    return rc;\n  } else if (connection \u0026\u0026 connection.destroyed) {\n    // The socket was destroyed.  If we're still trying to write to it,\n    // then we haven't gotten the 'close' event yet.\n    return false;\n  } else {\n    // buffer, as long as we're not destroyed.\n    return this._buffer(data, encoding, callback);\n  }\n};\n\nhttp.OutgoingMessage.prototype._flushOutput = function _flushOutput(socket) {\n  var ret;\n  var outputLength = this.output.length;\n  if (outputLength \u003c= 0)\n    return ret;\n\n  var output = this.output;\n  var outputEncodings = this.outputEncodings;\n  var outputCallbacks = this.outputCallbacks;\n  //socket.cork();  //!!! Let the parent handle cork/uncork\n  for (var i = 0; i \u003c outputLength; i++) {\n    ret = socket.write(output[i], outputEncodings[i],\n                       outputCallbacks[i]);\n  }\n  //socket.uncork();  //!!! Let the parent handle cork/uncork\n\n  this.output = [];\n  this.outputEncodings = [];\n  this.outputCallbacks = [];\n  if (typeof this._onPendingData === 'function')\n    this._onPendingData(-this.outputSize);\n  this.outputSize = 0;\n\n  return ret;\n};\n```\n","author":{"url":"https://github.com/andrewjjenkins","@type":"Person","name":"andrewjjenkins"},"datePublished":"2016-07-28T22:24:47.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":4},"url":"https://github.com/7914/node/issues/7914"}