From e4fdf7149b11645504aa88c5ec43b00da161d533 Mon Sep 17 00:00:00 2001 From: Andrew Naylor Date: Sun, 1 May 2016 23:21:51 +0100 Subject: [PATCH 01/13] Cleanup ended streams to free memory Fixes #64 --- lib/protocol/connection.js | 20 +++++++++++++++++--- 1 file changed, 17 insertions(+), 3 deletions(-) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 2b86b7f1..72a597ed 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -214,6 +214,11 @@ Connection.prototype._insert = function _insert(stream, priority) { }; Connection.prototype._reprioritize = function _reprioritize(stream, priority) { + this._removePrioritisedStream(stream); + this._insert(stream, priority); +}; + +Connection.prototype._removePrioritisedStream = function _removePrioritisedStream(stream) { var bucket = this._streamPriorities[stream._priority]; var index = bucket.indexOf(stream); assert(index !== -1); @@ -221,9 +226,7 @@ Connection.prototype._reprioritize = function _reprioritize(stream, priority) { if (bucket.length === 0) { delete this._streamPriorities[stream._priority]; } - - this._insert(stream, priority); -}; +} // Creating an *inbound* stream with the given ID. It is called when there's an incoming frame to // a previously nonexistent stream. @@ -235,6 +238,8 @@ Connection.prototype._createIncomingStream = function _createIncomingStream(id) this._allocatePriority(stream); this.emit('stream', stream, id); + stream.on('end', this._removeStream.bind(this, stream)); + return stream; }; @@ -246,9 +251,18 @@ Connection.prototype.createStream = function createStream() { var stream = new Stream(this._log, this); this._allocatePriority(stream); + stream.on('end', this._removeStream.bind(this, stream)); + return stream; }; +Connection.prototype._removeStream = function _removeStream(stream) { + this._log.trace('Removing outbound stream.'); + + delete this._streamIds[stream.id]; + this._removePrioritisedStream(stream); +} + // Multiplexing // ------------ From a7f1e30359fb265d5e5b45c10fce4847ff373e64 Mon Sep 17 00:00:00 2001 From: Andrew Naylor Date: Sun, 1 May 2016 23:48:49 +0100 Subject: [PATCH 02/13] Handle server streams correctly --- lib/protocol/connection.js | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 72a597ed..240b00e0 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -238,7 +238,6 @@ Connection.prototype._createIncomingStream = function _createIncomingStream(id) this._allocatePriority(stream); this.emit('stream', stream, id); - stream.on('end', this._removeStream.bind(this, stream)); return stream; }; @@ -304,7 +303,7 @@ priority_loop: // 2. if there's no frame, skip this stream // 3. if forwarding this frame would make `streamCount` greater than `streamLimit`, skip // this stream - // 4. adding stream to the bucket of the next round + // 4. adding stream to the bucket of the next round unless it has ended // 5. assigning an ID to the frame (allocating an ID to the stream if there isn't already) // 6. if forwarding a PUSH_PROMISE, allocate ID to the promised stream // 7. forwarding the frame, changing `streamCount` as appropriate @@ -322,7 +321,11 @@ priority_loop: continue; } - nextBucket.push(stream); + if (!stream._ended) { + nextBucket.push(stream); + } else { + delete this._streamIds[stream.id]; + } if (frame.stream === undefined) { frame.stream = stream.id || this._allocateId(stream); From 9e362361a5d460452c6acc03028258441d686f16 Mon Sep 17 00:00:00 2001 From: Andrew Naylor Date: Sun, 1 May 2016 23:53:21 +0100 Subject: [PATCH 03/13] Fix style issues --- lib/protocol/connection.js | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 240b00e0..8aa313d1 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -226,7 +226,7 @@ Connection.prototype._removePrioritisedStream = function _removePrioritisedStrea if (bucket.length === 0) { delete this._streamPriorities[stream._priority]; } -} +}; // Creating an *inbound* stream with the given ID. It is called when there's an incoming frame to // a previously nonexistent stream. @@ -238,7 +238,6 @@ Connection.prototype._createIncomingStream = function _createIncomingStream(id) this._allocatePriority(stream); this.emit('stream', stream, id); - return stream; }; @@ -260,7 +259,7 @@ Connection.prototype._removeStream = function _removeStream(stream) { delete this._streamIds[stream.id]; this._removePrioritisedStream(stream); -} +}; // Multiplexing // ------------ From 9e81bd5c9b776e77d7b63f2a8369634d202459b5 Mon Sep 17 00:00:00 2001 From: Simon Tretter Date: Thu, 20 Oct 2016 02:09:38 +0200 Subject: [PATCH 04/13] Update connection.js --- lib/protocol/connection.js | 24 ++++++++++++++++++++---- 1 file changed, 20 insertions(+), 4 deletions(-) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 2b86b7f1..8aa313d1 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -214,6 +214,11 @@ Connection.prototype._insert = function _insert(stream, priority) { }; Connection.prototype._reprioritize = function _reprioritize(stream, priority) { + this._removePrioritisedStream(stream); + this._insert(stream, priority); +}; + +Connection.prototype._removePrioritisedStream = function _removePrioritisedStream(stream) { var bucket = this._streamPriorities[stream._priority]; var index = bucket.indexOf(stream); assert(index !== -1); @@ -221,8 +226,6 @@ Connection.prototype._reprioritize = function _reprioritize(stream, priority) { if (bucket.length === 0) { delete this._streamPriorities[stream._priority]; } - - this._insert(stream, priority); }; // Creating an *inbound* stream with the given ID. It is called when there's an incoming frame to @@ -246,9 +249,18 @@ Connection.prototype.createStream = function createStream() { var stream = new Stream(this._log, this); this._allocatePriority(stream); + stream.on('end', this._removeStream.bind(this, stream)); + return stream; }; +Connection.prototype._removeStream = function _removeStream(stream) { + this._log.trace('Removing outbound stream.'); + + delete this._streamIds[stream.id]; + this._removePrioritisedStream(stream); +}; + // Multiplexing // ------------ @@ -290,7 +302,7 @@ priority_loop: // 2. if there's no frame, skip this stream // 3. if forwarding this frame would make `streamCount` greater than `streamLimit`, skip // this stream - // 4. adding stream to the bucket of the next round + // 4. adding stream to the bucket of the next round unless it has ended // 5. assigning an ID to the frame (allocating an ID to the stream if there isn't already) // 6. if forwarding a PUSH_PROMISE, allocate ID to the promised stream // 7. forwarding the frame, changing `streamCount` as appropriate @@ -308,7 +320,11 @@ priority_loop: continue; } - nextBucket.push(stream); + if (!stream._ended) { + nextBucket.push(stream); + } else { + delete this._streamIds[stream.id]; + } if (frame.stream === undefined) { frame.stream = stream.id || this._allocateId(stream); From 542166028c400fef935004e07ffc4924763383b9 Mon Sep 17 00:00:00 2001 From: Simon Tretter Date: Thu, 20 Oct 2016 09:38:51 +0200 Subject: [PATCH 05/13] Update connection.js --- lib/protocol/connection.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 8aa313d1..75012e9d 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -311,6 +311,7 @@ priority_loop: while (bucket.length > 0) { for (var index = 0; index < bucket.length; index++) { var stream = bucket[index]; + if(!stream || !stream.upstream) continue; var frame = stream.upstream.read((this._window > 0) ? this._window : -1); if (!frame) { From 16d37f80ab3ef291b53c00eba8644652a851a272 Mon Sep 17 00:00:00 2001 From: Dana Majid Date: Mon, 13 Feb 2017 21:06:36 -0800 Subject: [PATCH 06/13] Apply @jrabek fix --- lib/protocol/connection.js | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 75012e9d..640de394 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -340,8 +340,12 @@ priority_loop: var moreNeeded = this.push(frame); this._changeStreamCount(frame.count_change); - assert(moreNeeded !== null); // The frame shouldn't be unforwarded - if (moreNeeded === false) { + //assert(moreNeeded !== null); // The frame shouldn't be unforwarded + if (moreNeeded === null) { + this._log.debug('The frame shouldn\'t be unforwarded'); + } + + if (!moreNeeded) { break priority_loop; } } From c1e97722225b843a85cc33409ddf5fc4e63103b4 Mon Sep 17 00:00:00 2001 From: Tom Hughes Date: Fri, 17 Feb 2017 15:34:12 -0800 Subject: [PATCH 07/13] Add logging around FRAME_SIZE_ERROR. --- lib/protocol/framer.js | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/lib/protocol/framer.js b/lib/protocol/framer.js index 244e60ae..a71ec037 100644 --- a/lib/protocol/framer.js +++ b/lib/protocol/framer.js @@ -115,6 +115,7 @@ Deserializer.prototype._transform = function _transform(chunk, encoding, done) { if (payloadSize <= MAX_PAYLOAD_SIZE) { this._next(payloadSize); } else { + this._log.error({ payloadSize: payloadSize, max: MAX_PAYLOAD_SIZE }, 'FRAME_SIZE_ERROR, _transform'); this.emit('error', 'FRAME_SIZE_ERROR'); return; } @@ -236,6 +237,7 @@ Serializer.commonHeader = function writeCommonHeader(frame, buffers) { Deserializer.commonHeader = function readCommonHeader(buffer, frame) { if (buffer.length < 9) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readCommonHeader, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } @@ -303,6 +305,7 @@ Deserializer.DATA = function readData(buffer, frame) { if (frame.flags.PADDED) { if (buffer.length < 1) { // We must have at least one byte for padding control, but we don't. Bad peer! + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readData, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } paddingLength = (buffer.readUInt8(dataOffset) & 0xff); @@ -312,6 +315,7 @@ Deserializer.DATA = function readData(buffer, frame) { if (paddingLength) { if (paddingLength >= (buffer.length - 1)) { // We don't have enough room for the padding advertised - bad peer! + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readData, buffer.length: ' + buffer.length + ' paddingLength: ' + paddingLength); return 'FRAME_SIZE_ERROR'; } frame.data = buffer.slice(dataOffset, -1 * paddingLength); @@ -386,6 +390,8 @@ Deserializer.HEADERS = function readHeadersPriority(buffer, frame) { } if (buffer.length < minFrameLength) { // Peer didn't send enough data - bad peer! + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readHeadersPriority, buffer.length: ' + + buffer.length + ' minFrameLength: ' + minFrameLength); return 'FRAME_SIZE_ERROR'; } @@ -410,6 +416,8 @@ Deserializer.HEADERS = function readHeadersPriority(buffer, frame) { if (paddingLength) { if ((buffer.length - dataOffset) < paddingLength) { // Not enough data left to satisfy the advertised padding - bad peer! + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readHeadersPriority, buffer.length: ' + buffer.length + + ' dataOffset: ' + dataOffset + ' paddingLength: ' + paddingLength); return 'FRAME_SIZE_ERROR'; } frame.data = buffer.slice(dataOffset, -1 * paddingLength); @@ -457,6 +465,7 @@ Serializer.PRIORITY = function writePriority(frame, buffers) { Deserializer.PRIORITY = function readPriority(buffer, frame) { if (buffer.length < 5) { // PRIORITY frames are 5 bytes long. Bad peer! + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPriority, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } var dependencyData = new Buffer(4); @@ -500,6 +509,7 @@ Serializer.RST_STREAM = function writeRstStream(frame, buffers) { Deserializer.RST_STREAM = function readRstStream(buffer, frame) { if (buffer.length < 4) { // RST_STREAM is 4 bytes long. Bad peer! + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readRstStream, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.error = errorCodes[buffer.readUInt32BE(0)]; @@ -571,6 +581,7 @@ Deserializer.SETTINGS = function readSettings(buffer, frame, role) { // field value other than 0 MUST be treated as a connection error // (Section 5.4.1) of type FRAME_SIZE_ERROR. if(frame.flags.ACK && buffer.length != 0) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readSettings, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } @@ -663,12 +674,14 @@ Serializer.PUSH_PROMISE = function writePushPromise(frame, buffers) { Deserializer.PUSH_PROMISE = function readPushPromise(buffer, frame) { if (buffer.length < 4) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } var dataOffset = 0; var paddingLength = 0; if (frame.flags.PADDED) { if (buffer.length < 5) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise PADDED, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } paddingLength = (buffer.readUInt8(dataOffset) & 0xff); @@ -678,6 +691,8 @@ Deserializer.PUSH_PROMISE = function readPushPromise(buffer, frame) { dataOffset += 4; if (paddingLength) { if ((buffer.length - dataOffset) < paddingLength) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise, buffer.length: ' + buffer.length + + ' dataOffset: ' + dataOffset + ' paddingLength: ' + paddingLength); return 'FRAME_SIZE_ERROR'; } frame.data = buffer.slice(dataOffset, -1 * paddingLength); @@ -711,6 +726,7 @@ Serializer.PING = function writePing(frame, buffers) { Deserializer.PING = function readPing(buffer, frame) { if (buffer.length !== 8) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPing, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.data = buffer; @@ -761,6 +777,7 @@ Serializer.GOAWAY = function writeGoaway(frame, buffers) { Deserializer.GOAWAY = function readGoaway(buffer, frame) { if (buffer.length !== 8) { // GOAWAY must have 8 bytes + this._log.error({ frame: frame }, 'FRAME_SIZE_ERROR, readGoAway, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.last_stream = buffer.readUInt32BE(0) & 0x7fffffff; @@ -801,6 +818,7 @@ Serializer.WINDOW_UPDATE = function writeWindowUpdate(frame, buffers) { Deserializer.WINDOW_UPDATE = function readWindowUpdate(buffer, frame) { if (buffer.length !== WINDOW_UPDATE_PAYLOAD_SIZE) { + this._log.error({ frame: frame }, 'FRAME_SIZE_ERROR, readWindowUpdate, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.window_size = buffer.readUInt32BE(0) & 0x7fffffff; @@ -1036,10 +1054,12 @@ function unescape(s) { Deserializer.ALTSVC = function readAltSvc(buffer, frame) { if (buffer.length < 2) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readAltSvc, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } var originLength = buffer.readUInt16BE(0); if ((buffer.length - 2) < originLength) { + this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readAltSvc 2, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.origin = buffer.toString('ascii', 2, 2 + originLength); From 268c239af5a47601ec41523fdaf805e8b32b2f6a Mon Sep 17 00:00:00 2001 From: Tom Hughes Date: Fri, 17 Feb 2017 15:36:12 -0800 Subject: [PATCH 08/13] Add log for case that never seems to be hit --- lib/protocol/stream.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/protocol/stream.js b/lib/protocol/stream.js index 6d520b94..83963541 100644 --- a/lib/protocol/stream.js +++ b/lib/protocol/stream.js @@ -313,6 +313,7 @@ Stream.prototype._write = function _write(buffer, encoding, ready) { // * Call ready when upstream is ready to receive more frames. if (moreNeeded) { + this._log.error('Stream._write moreNeeded'); ready(); } else { this._sendMore = ready; From 638bde8ae7c8ab6dfb38647498b1c782a54eba1d Mon Sep 17 00:00:00 2001 From: Tom Hughes Date: Tue, 21 Feb 2017 09:55:12 -0800 Subject: [PATCH 09/13] Fix FRAME_SIZE_ERROR debug logging. --- lib/protocol/framer.js | 58 +++++++++++++++++++++--------------------- 1 file changed, 29 insertions(+), 29 deletions(-) diff --git a/lib/protocol/framer.js b/lib/protocol/framer.js index a71ec037..d0d46ffc 100644 --- a/lib/protocol/framer.js +++ b/lib/protocol/framer.js @@ -111,7 +111,7 @@ Deserializer.prototype._transform = function _transform(chunk, encoding, done) { // If it's header then the parsed data is stored in a temporary variable and then the // deserializer waits for the specified length payload. if ((this._cursor === this._buffer.length) && this._waitingForHeader) { - var payloadSize = Deserializer.commonHeader(this._buffer, this._frame); + var payloadSize = Deserializer.commonHeader(this._buffer, this._frame, this._log); if (payloadSize <= MAX_PAYLOAD_SIZE) { this._next(payloadSize); } else { @@ -128,7 +128,7 @@ Deserializer.prototype._transform = function _transform(chunk, encoding, done) { // will also run. if ((this._cursor === this._buffer.length) && !this._waitingForHeader) { if (this._frame.type) { - var error = Deserializer[this._frame.type](this._buffer, this._frame, this._role); + var error = Deserializer[this._frame.type](this._buffer, this._frame, this._role, this._log); if (error) { this._log.error('Incoming frame parsing error: ' + error); this.emit('error', error); @@ -235,9 +235,9 @@ Serializer.commonHeader = function writeCommonHeader(frame, buffers) { return size; }; -Deserializer.commonHeader = function readCommonHeader(buffer, frame) { +Deserializer.commonHeader = function readCommonHeader(buffer, frame, logger) { if (buffer.length < 9) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readCommonHeader, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readCommonHeader, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } @@ -299,13 +299,13 @@ Serializer.DATA = function writeData(frame, buffers) { buffers.push(frame.data); }; -Deserializer.DATA = function readData(buffer, frame) { +Deserializer.DATA = function readData(buffer, frame, role, logger) { var dataOffset = 0; var paddingLength = 0; if (frame.flags.PADDED) { if (buffer.length < 1) { // We must have at least one byte for padding control, but we don't. Bad peer! - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readData, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readData, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } paddingLength = (buffer.readUInt8(dataOffset) & 0xff); @@ -315,7 +315,7 @@ Deserializer.DATA = function readData(buffer, frame) { if (paddingLength) { if (paddingLength >= (buffer.length - 1)) { // We don't have enough room for the padding advertised - bad peer! - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readData, buffer.length: ' + buffer.length + ' paddingLength: ' + paddingLength); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readData, buffer.length: ' + buffer.length + ' paddingLength: ' + paddingLength); return 'FRAME_SIZE_ERROR'; } frame.data = buffer.slice(dataOffset, -1 * paddingLength); @@ -380,7 +380,7 @@ Serializer.HEADERS = function writeHeadersPriority(frame, buffers) { buffers.push(frame.data); }; -Deserializer.HEADERS = function readHeadersPriority(buffer, frame) { +Deserializer.HEADERS = function readHeadersPriority(buffer, frame, role, logger) { var minFrameLength = 0; if (frame.flags.PADDED) { minFrameLength += 1; @@ -390,7 +390,7 @@ Deserializer.HEADERS = function readHeadersPriority(buffer, frame) { } if (buffer.length < minFrameLength) { // Peer didn't send enough data - bad peer! - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readHeadersPriority, buffer.length: ' + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readHeadersPriority, buffer.length: ' + buffer.length + ' minFrameLength: ' + minFrameLength); return 'FRAME_SIZE_ERROR'; } @@ -416,7 +416,7 @@ Deserializer.HEADERS = function readHeadersPriority(buffer, frame) { if (paddingLength) { if ((buffer.length - dataOffset) < paddingLength) { // Not enough data left to satisfy the advertised padding - bad peer! - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readHeadersPriority, buffer.length: ' + buffer.length + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readHeadersPriority, buffer.length: ' + buffer.length + ' dataOffset: ' + dataOffset + ' paddingLength: ' + paddingLength); return 'FRAME_SIZE_ERROR'; } @@ -462,10 +462,10 @@ Serializer.PRIORITY = function writePriority(frame, buffers) { buffers.push(buffer); }; -Deserializer.PRIORITY = function readPriority(buffer, frame) { +Deserializer.PRIORITY = function readPriority(buffer, frame, role, logger) { if (buffer.length < 5) { // PRIORITY frames are 5 bytes long. Bad peer! - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPriority, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPriority, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } var dependencyData = new Buffer(4); @@ -506,10 +506,10 @@ Serializer.RST_STREAM = function writeRstStream(frame, buffers) { buffers.push(buffer); }; -Deserializer.RST_STREAM = function readRstStream(buffer, frame) { +Deserializer.RST_STREAM = function readRstStream(buffer, frame, role, logger) { if (buffer.length < 4) { // RST_STREAM is 4 bytes long. Bad peer! - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readRstStream, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readRstStream, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.error = errorCodes[buffer.readUInt32BE(0)]; @@ -574,14 +574,14 @@ Serializer.SETTINGS = function writeSettings(frame, buffers) { buffers.push(buffer); }; -Deserializer.SETTINGS = function readSettings(buffer, frame, role) { +Deserializer.SETTINGS = function readSettings(buffer, frame, role, logger) { frame.settings = {}; // Receipt of a SETTINGS frame with the ACK flag set and a length // field value other than 0 MUST be treated as a connection error // (Section 5.4.1) of type FRAME_SIZE_ERROR. if(frame.flags.ACK && buffer.length != 0) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readSettings, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readSettings, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } @@ -672,16 +672,16 @@ Serializer.PUSH_PROMISE = function writePushPromise(frame, buffers) { buffers.push(frame.data); }; -Deserializer.PUSH_PROMISE = function readPushPromise(buffer, frame) { +Deserializer.PUSH_PROMISE = function readPushPromise(buffer, frame, role, logger) { if (buffer.length < 4) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } var dataOffset = 0; var paddingLength = 0; if (frame.flags.PADDED) { if (buffer.length < 5) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise PADDED, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise PADDED, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } paddingLength = (buffer.readUInt8(dataOffset) & 0xff); @@ -691,7 +691,7 @@ Deserializer.PUSH_PROMISE = function readPushPromise(buffer, frame) { dataOffset += 4; if (paddingLength) { if ((buffer.length - dataOffset) < paddingLength) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise, buffer.length: ' + buffer.length + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPushPromise, buffer.length: ' + buffer.length + ' dataOffset: ' + dataOffset + ' paddingLength: ' + paddingLength); return 'FRAME_SIZE_ERROR'; } @@ -724,9 +724,9 @@ Serializer.PING = function writePing(frame, buffers) { buffers.push(frame.data); }; -Deserializer.PING = function readPing(buffer, frame) { +Deserializer.PING = function readPing(buffer, frame, role, logger) { if (buffer.length !== 8) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPing, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readPing, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.data = buffer; @@ -774,10 +774,10 @@ Serializer.GOAWAY = function writeGoaway(frame, buffers) { buffers.push(buffer); }; -Deserializer.GOAWAY = function readGoaway(buffer, frame) { +Deserializer.GOAWAY = function readGoaway(buffer, frame, role, logger) { if (buffer.length !== 8) { // GOAWAY must have 8 bytes - this._log.error({ frame: frame }, 'FRAME_SIZE_ERROR, readGoAway, buffer.length: ' + buffer.length); + logger.error({ frame: frame }, 'FRAME_SIZE_ERROR, readGoAway, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.last_stream = buffer.readUInt32BE(0) & 0x7fffffff; @@ -816,9 +816,9 @@ Serializer.WINDOW_UPDATE = function writeWindowUpdate(frame, buffers) { buffers.push(buffer); }; -Deserializer.WINDOW_UPDATE = function readWindowUpdate(buffer, frame) { +Deserializer.WINDOW_UPDATE = function readWindowUpdate(buffer, frame, role, logger) { if (buffer.length !== WINDOW_UPDATE_PAYLOAD_SIZE) { - this._log.error({ frame: frame }, 'FRAME_SIZE_ERROR, readWindowUpdate, buffer.length: ' + buffer.length); + logger.error({ frame: frame }, 'FRAME_SIZE_ERROR, readWindowUpdate, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.window_size = buffer.readUInt32BE(0) & 0x7fffffff; @@ -1052,14 +1052,14 @@ function unescape(s) { return t; } -Deserializer.ALTSVC = function readAltSvc(buffer, frame) { +Deserializer.ALTSVC = function readAltSvc(buffer, frame, role, logger) { if (buffer.length < 2) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readAltSvc, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readAltSvc, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } var originLength = buffer.readUInt16BE(0); if ((buffer.length - 2) < originLength) { - this._log.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readAltSvc 2, buffer.length: ' + buffer.length); + logger.error({ buffer: buffer }, 'FRAME_SIZE_ERROR, readAltSvc 2, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } frame.origin = buffer.toString('ascii', 2, 2 + originLength); From 3d901fb45262cc9f7120be5dd52d11fb72dd332b Mon Sep 17 00:00:00 2001 From: Tom Hughes Date: Tue, 21 Feb 2017 15:42:19 -0800 Subject: [PATCH 10/13] GOAWAY frames may have additional debug data They don't need to be exactly 8 bytes; they are allowed to be more. --- lib/protocol/framer.js | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/lib/protocol/framer.js b/lib/protocol/framer.js index d0d46ffc..db8a6fc2 100644 --- a/lib/protocol/framer.js +++ b/lib/protocol/framer.js @@ -752,6 +752,8 @@ typeSpecificAttributes.GOAWAY = ['last_stream', 'error']; // +-+-------------------------------------------------------------+ // | Error Code (32) | // +---------------------------------------------------------------+ +// | Additional Debug Data (*) | +// +---------------------------------------------------------------+ // // The last stream identifier in the GOAWAY frame contains the highest numbered stream identifier // for which the sender of the GOAWAY frame has received frames on and might have taken some action @@ -775,8 +777,8 @@ Serializer.GOAWAY = function writeGoaway(frame, buffers) { }; Deserializer.GOAWAY = function readGoaway(buffer, frame, role, logger) { - if (buffer.length !== 8) { - // GOAWAY must have 8 bytes + if (buffer.length < 8) { + // GOAWAY must have at least 8 bytes logger.error({ frame: frame }, 'FRAME_SIZE_ERROR, readGoAway, buffer.length: ' + buffer.length); return 'FRAME_SIZE_ERROR'; } @@ -786,6 +788,12 @@ Deserializer.GOAWAY = function readGoaway(buffer, frame, role, logger) { // Unknown error types are to be considered equivalent to INTERNAL ERROR frame.error = 'INTERNAL_ERROR'; } + // Read remaining data into "debug_data" + // https://http2.github.io/http2-spec/#GOAWAY + // Endpoints MAY append opaque data to the payload of any GOAWAY frame + if (buffer.length > 8) { + frame.debug_data = buffer.slice(8); + } }; // [WINDOW_UPDATE](https://tools.ietf.org/html/rfc7540#section-6.9) From e0f6b80792818e5ec1dda37f3c14e7312df6d8d1 Mon Sep 17 00:00:00 2001 From: Tom Hughes Date: Wed, 22 Feb 2017 09:56:19 -0800 Subject: [PATCH 11/13] Change log level --- lib/protocol/connection.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 640de394..1007e5b3 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -342,7 +342,7 @@ priority_loop: //assert(moreNeeded !== null); // The frame shouldn't be unforwarded if (moreNeeded === null) { - this._log.debug('The frame shouldn\'t be unforwarded'); + this._log.error('The frame shouldn\'t be unforwarded'); } if (!moreNeeded) { From 02366d8afa4b558569211777f0b512315efd5c5a Mon Sep 17 00:00:00 2001 From: Tom Hughes Date: Wed, 22 Feb 2017 13:58:51 -0800 Subject: [PATCH 12/13] Add log message to see if we hit GOAWAY with debug data --- lib/protocol/framer.js | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/protocol/framer.js b/lib/protocol/framer.js index db8a6fc2..211809fa 100644 --- a/lib/protocol/framer.js +++ b/lib/protocol/framer.js @@ -792,6 +792,7 @@ Deserializer.GOAWAY = function readGoaway(buffer, frame, role, logger) { // https://http2.github.io/http2-spec/#GOAWAY // Endpoints MAY append opaque data to the payload of any GOAWAY frame if (buffer.length > 8) { + logger.error({ frame: frame }, 'readGoAway debug_data, buffer.length: ' + buffer.length); frame.debug_data = buffer.slice(8); } }; From 3cb5cba8cef7ae8dcbeb4a65464792daf10317ff Mon Sep 17 00:00:00 2001 From: Tom Hughes Date: Wed, 22 Feb 2017 14:16:22 -0800 Subject: [PATCH 13/13] Log more info when receiving GOAWAY --- lib/protocol/connection.js | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/protocol/connection.js b/lib/protocol/connection.js index 1007e5b3..d5fb5794 100644 --- a/lib/protocol/connection.js +++ b/lib/protocol/connection.js @@ -598,7 +598,8 @@ Connection.prototype.close = function close(error) { }; Connection.prototype._receiveGoaway = function _receiveGoaway(frame) { - this._log.debug({ error: frame.error }, 'Other end closed the connection'); + // this._log.debug({ error: frame.error }, 'Other end closed the connection'); + this._log.error({ frame: frame }, '_receiveGoaway, Other end closed the connection'); this.push(null); this._closed = true; if (frame.error !== 'NO_ERROR') {