From 58d8c9ef4886ff425765eedfc943b3aed240634c 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. PR-URL: https://github.com/nodejs/node/pull/29122 Reviewed-By: Rich Trott Reviewed-By: James M Snell --- lib/internal/http2/core.js | 112 +++++++++++++++++++------------------ 1 file changed, 58 insertions(+), 54 deletions(-) diff --git a/lib/internal/http2/core.js b/lib/internal/http2/core.js index 571ffaa8584007..a5bf0aecd89cee 100644 --- a/lib/internal/http2/core.js +++ b/lib/internal/http2/core.js @@ -139,6 +139,26 @@ const { _connectionListener: httpConnectionListener } = http; const debug = require('internal/util/debuglog').debuglog('http2'); const { getOptionValue } = require('internal/options'); +// 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; @@ -260,8 +280,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); @@ -321,8 +340,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) { @@ -363,7 +381,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); } @@ -378,8 +396,7 @@ function onStreamClose(code) { if (!stream || stream.destroyed) return false; - 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); @@ -416,7 +433,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); } @@ -428,9 +445,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](); @@ -444,8 +461,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); @@ -455,8 +472,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); } @@ -483,8 +500,7 @@ function onOrigin(origins) { const session = this[kOwner]; if (session.destroyed) return; - debug('Http2Session %s: origin received: %j', - sessionName(session[kType]), origins); + debugSessionObj(session, 'origin received: %j', origins); session[kUpdateTimer](); if (!session.encrypted || session.destroyed) return undefined; @@ -504,8 +520,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; @@ -560,8 +576,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) @@ -650,13 +665,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 ERR_HTTP2_SETTINGS_CANCEL()); } @@ -666,7 +681,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))) { @@ -700,7 +715,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); } @@ -831,7 +846,7 @@ function setupHandle(socket, type, options) { 'Internal HTTP/2 Failure. The socket is not connected. Please ' + 'report this as a bug in Node.js'); - debug(`Http2Session ${sessionName(type)}: setting up session handle`); + debugSession(type, 'setting up session handle'); this[kState].flags |= SESSION_FLAGS_READY; updateOptionsBuffer(options); @@ -987,7 +1002,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 @@ -1163,7 +1178,7 @@ class Http2Session extends EventEmitter { if (callback && typeof callback !== 'function') throw new ERR_INVALID_CALLBACK(callback); - debug(`Http2Session ${sessionName(this[kType])}: sending settings`); + debugSessionObj(this, 'sending settings'); this[kState].pendingAck++; @@ -1204,7 +1219,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; @@ -1261,7 +1276,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); @@ -1432,7 +1447,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 ERR_HTTP2_INVALID_SESSION(); @@ -1832,8 +1847,7 @@ class Http2Stream extends Duplex { if (this.pending) { 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; @@ -1892,9 +1906,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](); @@ -1947,8 +1959,7 @@ 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 sessionCode = session[kState].goawayCode || @@ -2274,8 +2285,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](); @@ -2355,9 +2365,7 @@ class ServerHttp2Stream extends Http2Stream { assertIsObject(options, 'options'); options = { ...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; @@ -2430,8 +2438,7 @@ class ServerHttp2Stream extends Http2Stream { validateNumber(fd, 'fd'); - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: initiating response from fd`); + debugStreamObj(this, 'initiating response from fd'); this[kUpdateTimer](); this.ownsFd = false; @@ -2492,8 +2499,7 @@ class ServerHttp2Stream extends Http2Stream { } const session = this[kSession]; - debug(`Http2Stream ${this[kID]} [Http2Session ` + - `${sessionName(session[kType])}]: initiating response from file`); + debugStreamObj(this, 'initiating response from file'); this[kUpdateTimer](); this.ownsFd = true; @@ -2527,9 +2533,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; @@ -2590,8 +2594,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); } } @@ -2636,7 +2639,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. @@ -2761,7 +2765,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 ERR_SOCKET_CLOSED() : null; const state = session[kState]; state.streams.forEach((stream) => stream.close(NGHTTP2_CANCEL));