Skip to content

Commit 00f6846

Browse files
addaleaxBethGriggs
addaleax
authored and
BethGriggs
committed
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 <rtrott@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>
1 parent 6d42737 commit 00f6846

File tree

1 file changed

+61
-54
lines changed

1 file changed

+61
-54
lines changed

‎lib/internal/http2/core.js‎

Lines changed: 61 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -64,6 +64,26 @@ const { createPromise, promiseResolve } = process.binding('util');
6464
const { _connectionListener: httpConnectionListener } = http;
6565
const debug = util.debuglog('http2');
6666

67+
// TODO(addaleax): See if this can be made more efficient by figuring out
68+
// whether debugging is enabled before we perform any further steps. Currently,
69+
// this seems pretty fast, though.
70+
function debugStream(id, sessionType, message, ...args) {
71+
debug('Http2Stream %s [Http2Session %s]: ' + message,
72+
id, sessionName(sessionType), ...args);
73+
}
74+
75+
function debugStreamObj(stream, message, ...args) {
76+
debugStream(stream[kID], stream[kSession][kType], ...args);
77+
}
78+
79+
function debugSession(sessionType, message, ...args) {
80+
debug('Http2Session %s: ' + message, sessionName(sessionType), ...args);
81+
}
82+
83+
function debugSessionObj(session, message, ...args) {
84+
debugSession(session[kType], message, ...args);
85+
}
86+
6787
const kMaxFrameSize = (2 ** 24) - 1;
6888
const kMaxInt = (2 ** 32) - 1;
6989
const kMaxStreams = (2 ** 31) - 1;
@@ -189,8 +209,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) {
189209

190210
const type = session[kType];
191211
session[kUpdateTimer]();
192-
debug(`Http2Stream ${id} [Http2Session ` +
193-
`${sessionName(type)}]: headers received`);
212+
debugStream(id, type, 'headers received');
194213
const streams = session[kState].streams;
195214

196215
const endOfStream = !!(flags & NGHTTP2_FLAG_END_STREAM);
@@ -250,8 +269,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) {
250269
const originSet = session[kState].originSet = initOriginSet(session);
251270
originSet.delete(stream[kOrigin]);
252271
}
253-
debug(`Http2Stream ${id} [Http2Session ` +
254-
`${sessionName(type)}]: emitting stream '${event}' event`);
272+
debugStream(id, type, "emitting stream '%s' event", event);
255273
process.nextTick(emit, stream, event, obj, flags, headers);
256274
}
257275
if (endOfStream) {
@@ -292,7 +310,7 @@ function onPing(payload) {
292310
if (session.destroyed)
293311
return;
294312
session[kUpdateTimer]();
295-
debug(`Http2Session ${sessionName(session[kType])}: new ping received`);
313+
debugSessionObj(session, 'new ping received');
296314
session.emit('ping', payload);
297315
}
298316

@@ -307,8 +325,7 @@ function onStreamClose(code) {
307325
if (stream.destroyed)
308326
return;
309327

310-
debug(`Http2Stream ${stream[kID]} [Http2Session ` +
311-
`${sessionName(stream[kSession][kType])}]: closed with code ${code}`);
328+
debugStreamObj(stream, 'closed with code %d', code);
312329

313330
if (!stream.closed)
314331
closeStream(stream, code, kNoRstStream);
@@ -376,7 +393,7 @@ function onSettings() {
376393
if (session.destroyed)
377394
return;
378395
session[kUpdateTimer]();
379-
debug(`Http2Session ${sessionName(session[kType])}: new settings received`);
396+
debugSessionObj(session, 'new settings received');
380397
session[kRemoteSettings] = undefined;
381398
session.emit('remoteSettings', session.remoteSettings);
382399
}
@@ -388,9 +405,9 @@ function onPriority(id, parent, weight, exclusive) {
388405
const session = this[kOwner];
389406
if (session.destroyed)
390407
return;
391-
debug(`Http2Stream ${id} [Http2Session ` +
392-
`${sessionName(session[kType])}]: priority [parent: ${parent}, ` +
393-
`weight: ${weight}, exclusive: ${exclusive}]`);
408+
debugStream(id, session[kType],
409+
'priority [parent: %d, weight: %d, exclusive: %s]',
410+
parent, weight, exclusive);
394411
const emitter = session[kState].streams.get(id) || session;
395412
if (!emitter.destroyed) {
396413
emitter[kUpdateTimer]();
@@ -404,8 +421,8 @@ function onFrameError(id, type, code) {
404421
const session = this[kOwner];
405422
if (session.destroyed)
406423
return;
407-
debug(`Http2Session ${sessionName(session[kType])}: error sending frame ` +
408-
`type ${type} on stream ${id}, code: ${code}`);
424+
debugSessionObj(session, 'error sending frame type %d on stream %d, code: %d',
425+
type, id, code);
409426
const emitter = session[kState].streams.get(id) || session;
410427
emitter[kUpdateTimer]();
411428
emitter.emit('frameError', type, code, id);
@@ -415,8 +432,8 @@ function onAltSvc(stream, origin, alt) {
415432
const session = this[kOwner];
416433
if (session.destroyed)
417434
return;
418-
debug(`Http2Session ${sessionName(session[kType])}: altsvc received: ` +
419-
`stream: ${stream}, origin: ${origin}, alt: ${alt}`);
435+
debugSessionObj(session, 'altsvc received: stream: %d, origin: %s, alt: %s',
436+
stream, origin, alt);
420437
session[kUpdateTimer]();
421438
session.emit('altsvc', alt, origin, stream);
422439
}
@@ -443,8 +460,7 @@ function onOrigin(origins) {
443460
const session = this[kOwner];
444461
if (session.destroyed)
445462
return;
446-
debug(`Http2Session ${sessionName(session[kType])}: origin received: ` +
447-
`${origins.join(', ')}`);
463+
debugSessionObj(session, 'origin received: %j', origins);
448464
session[kUpdateTimer]();
449465
if (!session.encrypted || session.destroyed)
450466
return undefined;
@@ -464,8 +480,8 @@ function onGoawayData(code, lastStreamID, buf) {
464480
const session = this[kOwner];
465481
if (session.destroyed)
466482
return;
467-
debug(`Http2Session ${sessionName(session[kType])}: goaway ${code} ` +
468-
`received [last stream id: ${lastStreamID}]`);
483+
debugSessionObj(session, 'goaway %d received [last stream id: %d]',
484+
code, lastStreamID);
469485

470486
const state = session[kState];
471487
state.goawayCode = code;
@@ -519,8 +535,7 @@ function requestOnConnect(headers, options) {
519535
return;
520536
}
521537

522-
debug(`Http2Session ${sessionName(session[kType])}: connected, ` +
523-
'initializing request');
538+
debugSessionObj(session, 'connected, initializing request');
524539

525540
let streamOptions = 0;
526541
if (options.endStream)
@@ -623,13 +638,13 @@ function settingsCallback(cb, ack, duration) {
623638
this[kState].pendingAck--;
624639
this[kLocalSettings] = undefined;
625640
if (ack) {
626-
debug(`Http2Session ${sessionName(this[kType])}: settings received`);
641+
debugSessionObj(this, 'settings received');
627642
const settings = this.localSettings;
628643
if (typeof cb === 'function')
629644
cb(null, settings, duration);
630645
this.emit('localSettings', settings);
631646
} else {
632-
debug(`Http2Session ${sessionName(this[kType])}: settings canceled`);
647+
debugSessionObj(this, 'settings canceled');
633648
if (typeof cb === 'function')
634649
cb(new errors.Error('ERR_HTTP2_SETTINGS_CANCEL'));
635650
}
@@ -639,7 +654,7 @@ function settingsCallback(cb, ack, duration) {
639654
function submitSettings(settings, callback) {
640655
if (this.destroyed)
641656
return;
642-
debug(`Http2Session ${sessionName(this[kType])}: submitting settings`);
657+
debugSessionObj(this, 'submitting settings');
643658
this[kUpdateTimer]();
644659
updateSettingsBuffer(settings);
645660
if (!this[kHandle].settings(settingsCallback.bind(this, callback))) {
@@ -673,7 +688,7 @@ function submitPriority(options) {
673688
function submitGoaway(code, lastStreamID, opaqueData) {
674689
if (this.destroyed)
675690
return;
676-
debug(`Http2Session ${sessionName(this[kType])}: submitting goaway`);
691+
debugSessionObj(this, 'submitting goaway');
677692
this[kUpdateTimer]();
678693
this[kHandle].goaway(code, lastStreamID, opaqueData);
679694
}
@@ -803,7 +818,9 @@ function setupHandle(socket, type, options) {
803818
process.nextTick(emit, this, 'connect', this, socket);
804819
return;
805820
}
806-
debug(`Http2Session ${sessionName(type)}: setting up session handle`);
821+
822+
debugSession(type, 'setting up session handle');
823+
807824
this[kState].flags |= SESSION_FLAGS_READY;
808825

809826
updateOptionsBuffer(options);
@@ -964,7 +981,7 @@ class Http2Session extends EventEmitter {
964981
setupFn();
965982
}
966983

967-
debug(`Http2Session ${sessionName(type)}: created`);
984+
debugSession(type, 'created');
968985
}
969986

970987
// Returns undefined if the socket is not yet connected, true if the
@@ -1138,7 +1155,7 @@ class Http2Session extends EventEmitter {
11381155

11391156
if (callback && typeof callback !== 'function')
11401157
throw new errors.TypeError('ERR_INVALID_CALLBACK');
1141-
debug(`Http2Session ${sessionName(this[kType])}: sending settings`);
1158+
debugSessionObj(this, 'sending settings');
11421159

11431160
this[kState].pendingAck++;
11441161

@@ -1184,7 +1201,7 @@ class Http2Session extends EventEmitter {
11841201
destroy(error = NGHTTP2_NO_ERROR, code) {
11851202
if (this.destroyed)
11861203
return;
1187-
debug(`Http2Session ${sessionName(this[kType])}: destroying`);
1204+
debugSessionObj(this, 'destroying');
11881205

11891206
if (typeof error === 'number') {
11901207
code = error;
@@ -1245,7 +1262,7 @@ class Http2Session extends EventEmitter {
12451262
close(callback) {
12461263
if (this.closed || this.destroyed)
12471264
return;
1248-
debug(`Http2Session ${sessionName(this[kType])}: marking session closed`);
1265+
debugSessionObj(this, 'marking session closed');
12491266
this[kState].flags |= SESSION_FLAGS_CLOSED;
12501267
if (typeof callback === 'function')
12511268
this.once('close', callback);
@@ -1415,7 +1432,7 @@ class ClientHttp2Session extends Http2Session {
14151432
// Submits a new HTTP2 request to the connected peer. Returns the
14161433
// associated Http2Stream instance.
14171434
request(headers, options) {
1418-
debug(`Http2Session ${sessionName(this[kType])}: initiating request`);
1435+
debugSessionObj(this, 'initiating request');
14191436

14201437
if (this.destroyed)
14211438
throw new errors.Error('ERR_HTTP2_INVALID_SESSION');
@@ -1843,8 +1860,7 @@ class Http2Stream extends Duplex {
18431860
if (this[kID] === undefined) {
18441861
this.once('ready', () => this._final(cb));
18451862
} else if (handle !== undefined) {
1846-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
1847-
`${sessionName(this[kSession][kType])}]: _final shutting down`);
1863+
debugStreamObj(this, '_final shutting down');
18481864
const req = new ShutdownWrap();
18491865
req.oncomplete = afterShutdown;
18501866
req.callback = cb;
@@ -1901,9 +1917,7 @@ class Http2Stream extends Duplex {
19011917
assertIsObject(headers, 'headers');
19021918
headers = Object.assign(Object.create(null), headers);
19031919

1904-
const session = this[kSession];
1905-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
1906-
`${sessionName(session[kType])}]: sending trailers`);
1920+
debugStreamObj(this, 'sending trailers');
19071921

19081922
this[kUpdateTimer]();
19091923

@@ -1959,8 +1973,8 @@ class Http2Stream extends Duplex {
19591973
const handle = this[kHandle];
19601974
const id = this[kID];
19611975

1962-
debug(`Http2Stream ${this[kID] || '<pending>'} [Http2Session ` +
1963-
`${sessionName(session[kType])}]: destroying stream`);
1976+
debugStream(this[kID] || 'pending', session[kType], 'destroying stream');
1977+
19641978
const state = this[kState];
19651979
const code = err != null ?
19661980
NGHTTP2_INTERNAL_ERROR : (state.rstCode || NGHTTP2_NO_ERROR);
@@ -2232,8 +2246,7 @@ class ServerHttp2Stream extends Http2Stream {
22322246

22332247
const session = this[kSession];
22342248

2235-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2236-
`${sessionName(session[kType])}]: initiating push stream`);
2249+
debugStreamObj(this, 'initiating push stream');
22372250

22382251
this[kUpdateTimer]();
22392252

@@ -2315,9 +2328,7 @@ class ServerHttp2Stream extends Http2Stream {
23152328
assertIsObject(options, 'options');
23162329
options = Object.assign({}, options);
23172330

2318-
const session = this[kSession];
2319-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2320-
`${sessionName(session[kType])}]: initiating response`);
2331+
debugStreamObj(this, 'initiating response');
23212332
this[kUpdateTimer]();
23222333

23232334
options.endStream = !!options.endStream;
@@ -2404,8 +2415,7 @@ class ServerHttp2Stream extends Http2Stream {
24042415
throw new errors.TypeError('ERR_INVALID_ARG_TYPE',
24052416
'fd', 'number');
24062417

2407-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2408-
`${sessionName(session[kType])}]: initiating response`);
2418+
debugStreamObj(this, 'initiating response from fd');
24092419
this[kUpdateTimer]();
24102420

24112421
headers = processHeaders(headers);
@@ -2470,8 +2480,7 @@ class ServerHttp2Stream extends Http2Stream {
24702480
}
24712481

24722482
const session = this[kSession];
2473-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2474-
`${sessionName(session[kType])}]: initiating response`);
2483+
debugStreamObj(this, 'initiating response from file');
24752484
this[kUpdateTimer]();
24762485

24772486

@@ -2504,9 +2513,7 @@ class ServerHttp2Stream extends Http2Stream {
25042513
assertIsObject(headers, 'headers');
25052514
headers = Object.assign(Object.create(null), headers);
25062515

2507-
const session = this[kSession];
2508-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2509-
`${sessionName(session[kType])}]: sending additional headers`);
2516+
debugStreamObj(this, 'sending additional headers');
25102517

25112518
if (headers[HTTP2_HEADER_STATUS] != null) {
25122519
const statusCode = headers[HTTP2_HEADER_STATUS] |= 0;
@@ -2595,8 +2602,7 @@ function socketOnError(error) {
25952602
// we can do and the other side is fully within its rights to do so.
25962603
if (error.code === 'ECONNRESET' && session[kState].goawayCode !== null)
25972604
return session.destroy();
2598-
debug(`Http2Session ${sessionName(session[kType])}: socket error [` +
2599-
`${error.message}]`);
2605+
debugSessionObj(this, 'socket error [%s]', error.message);
26002606
session.destroy(error);
26012607
}
26022608
}
@@ -2641,7 +2647,8 @@ function connectionListener(socket) {
26412647
return httpConnectionListener.call(this, socket);
26422648
}
26432649
// Let event handler deal with the socket
2644-
debug(`Unknown protocol from ${socket.remoteAddress}:${socket.remotePort}`);
2650+
debug('Unknown protocol from %s:%s',
2651+
socket.remoteAddress, socket.remotePort);
26452652
if (!this.emit('unknownProtocol', socket)) {
26462653
// We don't know what to do, so let's just tell the other side what's
26472654
// going on in a format that they *might* understand.
@@ -2766,7 +2773,7 @@ function setupCompat(ev) {
27662773
function socketOnClose() {
27672774
const session = this[kSession];
27682775
if (session !== undefined) {
2769-
debug(`Http2Session ${sessionName(session[kType])}: socket closed`);
2776+
debugSessionObj(session, 'socket closed');
27702777
const err = session.connecting ?
27712778
new errors.Error('ERR_SOCKET_CLOSED') : null;
27722779
const state = session[kState];

0 commit comments

Comments
 (0)