From 00f6846b7329954c7f8b5d5fc992e40d5743c82a Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Mon, 5 Aug 2019 17:22:30 +0200 Subject: [PATCH] http2: improve JS-side debug logging DRY up the `debug()` calls, and in particular, avoid building template strings before we know whether we need to. Backport-PR-URL: https://github.com/nodejs/node/pull/29124 PR-URL: https://github.com/nodejs/node/pull/29122 Reviewed-By: Rich Trott Reviewed-By: James M Snell --- lib/internal/http2/core.js | 115 ++++++++++++++++++++----------------- 1 file changed, 61 insertions(+), 54 deletions(-) diff --git a/lib/internal/http2/core.js b/lib/internal/http2/core.js index 055009d07c815b..85625f9ef30d5a 100644 --- a/lib/internal/http2/core.js +++ b/lib/internal/http2/core.js @@ -64,6 +64,26 @@ const { createPromise, promiseResolve } = process.binding('util'); const { _connectionListener: httpConnectionListener } = http; const debug = util.debuglog('http2'); +// TODO(addaleax): See if this can be made more efficient by figuring out +// whether debugging is enabled before we perform any further steps. Currently, +// this seems pretty fast, though. +function debugStream(id, sessionType, message, ...args) { + debug('Http2Stream %s [Http2Session %s]: ' + message, + id, sessionName(sessionType), ...args); +} + +function debugStreamObj(stream, message, ...args) { + debugStream(stream[kID], stream[kSession][kType], ...args); +} + +function debugSession(sessionType, message, ...args) { + debug('Http2Session %s: ' + message, sessionName(sessionType), ...args); +} + +function debugSessionObj(session, message, ...args) { + debugSession(session[kType], message, ...args); +} + const kMaxFrameSize = (2 ** 24) - 1; const kMaxInt = (2 ** 32) - 1; const kMaxStreams = (2 ** 31) - 1; @@ -189,8 +209,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) { const type = session[kType]; session[kUpdateTimer](); - debug(`Http2Stream ${id} [Http2Session ` + - `${sessionName(type)}]: headers received`); + debugStream(id, type, 'headers received'); const streams = session[kState].streams; const endOfStream = !!(flags & NGHTTP2_FLAG_END_STREAM); @@ -250,8 +269,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) { const originSet = session[kState].originSet = initOriginSet(session); originSet.delete(stream[kOrigin]); } - debug(`Http2Stream ${id} [Http2Session ` + - `${sessionName(type)}]: emitting stream '${event}' event`); + debugStream(id, type, "emitting stream '%s' event", event); process.nextTick(emit, stream, event, obj, flags, headers); } if (endOfStream) { @@ -292,7 +310,7 @@ function onPing(payload) { if (session.destroyed) return; session[kUpdateTimer](); - debug(`Http2Session ${sessionName(session[kType])}: new ping received`); + debugSessionObj(session, 'new ping received'); session.emit('ping', payload); } @@ -307,8 +325,7 @@ function onStreamClose(code) { if (stream.destroyed) return; - debug(`Http2Stream ${stream[kID]} [Http2Session ` + - `${sessionName(stream[kSession][kType])}]: closed with code ${code}`); + debugStreamObj(stream, 'closed with code %d', code); if (!stream.closed) closeStream(stream, code, kNoRstStream); @@ -376,7 +393,7 @@ function onSettings() { if (session.destroyed) return; session[kUpdateTimer](); - debug(`Http2Session ${sessionName(session[kType])}: new settings received`); + debugSessionObj(session, 'new settings received'); session[kRemoteSettings] = undefined; session.emit('remoteSettings', session.remoteSettings); } @@ -388,9 +405,9 @@ function onPriority(id, parent, weight, exclusive) { const session = this[kOwner]; if (session.destroyed) return; - debug(`Http2Stream ${id} [Http2Session ` + - `${sessionName(session[kType])}]: priority [parent: ${parent}, ` + - `weight: ${weight}, exclusive: ${exclusive}]`); + debugStream(id, session[kType], + 'priority [parent: %d, weight: %d, exclusive: %s]', + parent, weight, exclusive); const emitter = session[kState].streams.get(id) || session; if (!emitter.destroyed) { emitter[kUpdateTimer](); @@ -404,8 +421,8 @@ function onFrameError(id, type, code) { const session = this[kOwner]; if (session.destroyed) return; - debug(`Http2Session ${sessionName(session[kType])}: error sending frame ` + - `type ${type} on stream ${id}, code: ${code}`); + debugSessionObj(session, 'error sending frame type %d on stream %d, code: %d', + type, id, code); const emitter = session[kState].streams.get(id) || session; emitter[kUpdateTimer](); emitter.emit('frameError', type, code, id); @@ -415,8 +432,8 @@ function onAltSvc(stream, origin, alt) { const session = this[kOwner]; if (session.destroyed) return; - debug(`Http2Session ${sessionName(session[kType])}: altsvc received: ` + - `stream: ${stream}, origin: ${origin}, alt: ${alt}`); + debugSessionObj(session, 'altsvc received: stream: %d, origin: %s, alt: %s', + stream, origin, alt); session[kUpdateTimer](); session.emit('altsvc', alt, origin, stream); } @@ -443,8 +460,7 @@ function onOrigin(origins) { const session = this[kOwner]; if (session.destroyed) return; - debug(`Http2Session ${sessionName(session[kType])}: origin received: ` + - `${origins.join(', ')}`); + debugSessionObj(session, 'origin received: %j', origins); session[kUpdateTimer](); if (!session.encrypted || session.destroyed) return undefined; @@ -464,8 +480,8 @@ function onGoawayData(code, lastStreamID, buf) { const session = this[kOwner]; if (session.destroyed) return; - debug(`Http2Session ${sessionName(session[kType])}: goaway ${code} ` + - `received [last stream id: ${lastStreamID}]`); + debugSessionObj(session, 'goaway %d received [last stream id: %d]', + code, lastStreamID); const state = session[kState]; state.goawayCode = code; @@ -519,8 +535,7 @@ function requestOnConnect(headers, options) { return; } - debug(`Http2Session ${sessionName(session[kType])}: connected, ` + - 'initializing request'); + debugSessionObj(session, 'connected, initializing request'); let streamOptions = 0; if (options.endStream) @@ -623,13 +638,13 @@ function settingsCallback(cb, ack, duration) { this[kState].pendingAck--; this[kLocalSettings] = undefined; if (ack) { - debug(`Http2Session ${sessionName(this[kType])}: settings received`); + debugSessionObj(this, 'settings received'); const settings = this.localSettings; if (typeof cb === 'function') cb(null, settings, duration); this.emit('localSettings', settings); } else { - debug(`Http2Session ${sessionName(this[kType])}: settings canceled`); + debugSessionObj(this, 'settings canceled'); if (typeof cb === 'function') cb(new errors.Error('ERR_HTTP2_SETTINGS_CANCEL')); } @@ -639,7 +654,7 @@ function settingsCallback(cb, ack, duration) { function submitSettings(settings, callback) { if (this.destroyed) return; - debug(`Http2Session ${sessionName(this[kType])}: submitting settings`); + debugSessionObj(this, 'submitting settings'); this[kUpdateTimer](); updateSettingsBuffer(settings); if (!this[kHandle].settings(settingsCallback.bind(this, callback))) { @@ -673,7 +688,7 @@ function submitPriority(options) { function submitGoaway(code, lastStreamID, opaqueData) { if (this.destroyed) return; - debug(`Http2Session ${sessionName(this[kType])}: submitting goaway`); + debugSessionObj(this, 'submitting goaway'); this[kUpdateTimer](); this[kHandle].goaway(code, lastStreamID, opaqueData); } @@ -803,7 +818,9 @@ function setupHandle(socket, type, options) { process.nextTick(emit, this, 'connect', this, socket); return; } - debug(`Http2Session ${sessionName(type)}: setting up session handle`); + + debugSession(type, 'setting up session handle'); + this[kState].flags |= SESSION_FLAGS_READY; updateOptionsBuffer(options); @@ -964,7 +981,7 @@ class Http2Session extends EventEmitter { setupFn(); } - debug(`Http2Session ${sessionName(type)}: created`); + debugSession(type, 'created'); } // Returns undefined if the socket is not yet connected, true if the @@ -1138,7 +1155,7 @@ class Http2Session extends EventEmitter { if (callback && typeof callback !== 'function') throw new errors.TypeError('ERR_INVALID_CALLBACK'); - debug(`Http2Session ${sessionName(this[kType])}: sending settings`); + debugSessionObj(this, 'sending settings'); this[kState].pendingAck++; @@ -1184,7 +1201,7 @@ class Http2Session extends EventEmitter { destroy(error = NGHTTP2_NO_ERROR, code) { if (this.destroyed) return; - debug(`Http2Session ${sessionName(this[kType])}: destroying`); + debugSessionObj(this, 'destroying'); if (typeof error === 'number') { code = error; @@ -1245,7 +1262,7 @@ class Http2Session extends EventEmitter { close(callback) { if (this.closed || this.destroyed) return; - debug(`Http2Session ${sessionName(this[kType])}: marking session closed`); + debugSessionObj(this, 'marking session closed'); this[kState].flags |= SESSION_FLAGS_CLOSED; if (typeof callback === 'function') this.once('close', callback); @@ -1415,7 +1432,7 @@ class ClientHttp2Session extends Http2Session { // Submits a new HTTP2 request to the connected peer. Returns the // associated Http2Stream instance. request(headers, options) { - debug(`Http2Session ${sessionName(this[kType])}: initiating request`); + debugSessionObj(this, 'initiating request'); if (this.destroyed) throw new errors.Error('ERR_HTTP2_INVALID_SESSION'); @@ -1843,8 +1860,7 @@ class Http2Stream extends Duplex { if (this[kID] === undefined) { this.once('ready', () => this._final(cb)); } else if (handle !== undefined) { - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(this[kSession][kType])}]: _final shutting down`); + debugStreamObj(this, '_final shutting down'); const req = new ShutdownWrap(); req.oncomplete = afterShutdown; req.callback = cb; @@ -1901,9 +1917,7 @@ class Http2Stream extends Duplex { assertIsObject(headers, 'headers'); headers = Object.assign(Object.create(null), headers); - const session = this[kSession]; - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: sending trailers`); + debugStreamObj(this, 'sending trailers'); this[kUpdateTimer](); @@ -1959,8 +1973,8 @@ class Http2Stream extends Duplex { const handle = this[kHandle]; const id = this[kID]; - debug(`Http2Stream ${this[kID] || ''} [Http2Session ` + - `${sessionName(session[kType])}]: destroying stream`); + debugStream(this[kID] || 'pending', session[kType], 'destroying stream'); + const state = this[kState]; const code = err != null ? NGHTTP2_INTERNAL_ERROR : (state.rstCode || NGHTTP2_NO_ERROR); @@ -2232,8 +2246,7 @@ class ServerHttp2Stream extends Http2Stream { const session = this[kSession]; - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: initiating push stream`); + debugStreamObj(this, 'initiating push stream'); this[kUpdateTimer](); @@ -2315,9 +2328,7 @@ class ServerHttp2Stream extends Http2Stream { assertIsObject(options, 'options'); options = Object.assign({}, options); - const session = this[kSession]; - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: initiating response`); + debugStreamObj(this, 'initiating response'); this[kUpdateTimer](); options.endStream = !!options.endStream; @@ -2404,8 +2415,7 @@ class ServerHttp2Stream extends Http2Stream { throw new errors.TypeError('ERR_INVALID_ARG_TYPE', 'fd', 'number'); - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: initiating response`); + debugStreamObj(this, 'initiating response from fd'); this[kUpdateTimer](); headers = processHeaders(headers); @@ -2470,8 +2480,7 @@ class ServerHttp2Stream extends Http2Stream { } const session = this[kSession]; - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: initiating response`); + debugStreamObj(this, 'initiating response from file'); this[kUpdateTimer](); @@ -2504,9 +2513,7 @@ class ServerHttp2Stream extends Http2Stream { assertIsObject(headers, 'headers'); headers = Object.assign(Object.create(null), headers); - const session = this[kSession]; - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: sending additional headers`); + debugStreamObj(this, 'sending additional headers'); if (headers[HTTP2_HEADER_STATUS] != null) { const statusCode = headers[HTTP2_HEADER_STATUS] |= 0; @@ -2595,8 +2602,7 @@ function socketOnError(error) { // we can do and the other side is fully within its rights to do so. if (error.code === 'ECONNRESET' && session[kState].goawayCode !== null) return session.destroy(); - debug(`Http2Session ${sessionName(session[kType])}: socket error [` + - `${error.message}]`); + debugSessionObj(this, 'socket error [%s]', error.message); session.destroy(error); } } @@ -2641,7 +2647,8 @@ function connectionListener(socket) { return httpConnectionListener.call(this, socket); } // Let event handler deal with the socket - debug(`Unknown protocol from ${socket.remoteAddress}:${socket.remotePort}`); + debug('Unknown protocol from %s:%s', + socket.remoteAddress, socket.remotePort); if (!this.emit('unknownProtocol', socket)) { // We don't know what to do, so let's just tell the other side what's // going on in a format that they *might* understand. @@ -2766,7 +2773,7 @@ function setupCompat(ev) { function socketOnClose() { const session = this[kSession]; if (session !== undefined) { - debug(`Http2Session ${sessionName(session[kType])}: socket closed`); + debugSessionObj(session, 'socket closed'); const err = session.connecting ? new errors.Error('ERR_SOCKET_CLOSED') : null; const state = session[kState];