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: #29124
PR-URL: #29122
Reviewed-By: Rich Trott <[email protected]>
Reviewed-By: James M Snell <[email protected]>

Author: addaleax

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] || '<pending>'} [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];