Skip to content

Commit 8dae8d1

Browse files
addaleaxtargos
addaleax
authored and
targos
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. PR-URL: nodejs#29122 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>
1 parent fd148d3 commit 8dae8d1

1 file changed

Lines changed: 58 additions & 54 deletions

File tree

‎lib/internal/http2/core.js‎

Lines changed: 58 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -138,6 +138,26 @@ const { StreamPipe } = internalBinding('stream_pipe');
138138
const { _connectionListener: httpConnectionListener } = http;
139139
const debug = require('internal/util/debuglog').debuglog('http2');
140140

141+
// TODO(addaleax): See if this can be made more efficient by figuring out
142+
// whether debugging is enabled before we perform any further steps. Currently,
143+
// this seems pretty fast, though.
144+
function debugStream(id, sessionType, message, ...args) {
145+
debug('Http2Stream %s [Http2Session %s]: ' + message,
146+
id, sessionName(sessionType), ...args);
147+
}
148+
149+
function debugStreamObj(stream, message, ...args) {
150+
debugStream(stream[kID], stream[kSession][kType], ...args);
151+
}
152+
153+
function debugSession(sessionType, message, ...args) {
154+
debug('Http2Session %s: ' + message, sessionName(sessionType), ...args);
155+
}
156+
157+
function debugSessionObj(session, message, ...args) {
158+
debugSession(session[kType], message, ...args);
159+
}
160+
141161
const kMaxFrameSize = (2 ** 24) - 1;
142162
const kMaxInt = (2 ** 32) - 1;
143163
const kMaxStreams = (2 ** 31) - 1;
@@ -256,8 +276,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) {
256276

257277
const type = session[kType];
258278
session[kUpdateTimer]();
259-
debug(`Http2Stream ${id} [Http2Session ` +
260-
`${sessionName(type)}]: headers received`);
279+
debugStream(id, type, 'headers received');
261280
const streams = session[kState].streams;
262281

263282
const endOfStream = !!(flags & NGHTTP2_FLAG_END_STREAM);
@@ -317,8 +336,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) {
317336
const originSet = session[kState].originSet = initOriginSet(session);
318337
originSet.delete(stream[kOrigin]);
319338
}
320-
debug(`Http2Stream ${id} [Http2Session ` +
321-
`${sessionName(type)}]: emitting stream '${event}' event`);
339+
debugStream(id, type, "emitting stream '%s' event", event);
322340
process.nextTick(emit, stream, event, obj, flags, headers);
323341
}
324342
if (endOfStream) {
@@ -359,7 +377,7 @@ function onPing(payload) {
359377
if (session.destroyed)
360378
return;
361379
session[kUpdateTimer]();
362-
debug(`Http2Session ${sessionName(session[kType])}: new ping received`);
380+
debugSessionObj(session, 'new ping received');
363381
session.emit('ping', payload);
364382
}
365383

@@ -374,8 +392,7 @@ function onStreamClose(code) {
374392
if (!stream || stream.destroyed)
375393
return false;
376394

377-
debug(`Http2Stream ${stream[kID]} [Http2Session ` +
378-
`${sessionName(stream[kSession][kType])}]: closed with code ${code}`);
395+
debugStreamObj(stream, 'closed with code %d', code);
379396

380397
if (!stream.closed)
381398
closeStream(stream, code, kNoRstStream);
@@ -412,7 +429,7 @@ function onSettings() {
412429
if (session.destroyed)
413430
return;
414431
session[kUpdateTimer]();
415-
debug(`Http2Session ${sessionName(session[kType])}: new settings received`);
432+
debugSessionObj(session, 'new settings received');
416433
session[kRemoteSettings] = undefined;
417434
session.emit('remoteSettings', session.remoteSettings);
418435
}
@@ -424,9 +441,9 @@ function onPriority(id, parent, weight, exclusive) {
424441
const session = this[kOwner];
425442
if (session.destroyed)
426443
return;
427-
debug(`Http2Stream ${id} [Http2Session ` +
428-
`${sessionName(session[kType])}]: priority [parent: ${parent}, ` +
429-
`weight: ${weight}, exclusive: ${exclusive}]`);
444+
debugStream(id, session[kType],
445+
'priority [parent: %d, weight: %d, exclusive: %s]',
446+
parent, weight, exclusive);
430447
const emitter = session[kState].streams.get(id) || session;
431448
if (!emitter.destroyed) {
432449
emitter[kUpdateTimer]();
@@ -440,8 +457,8 @@ function onFrameError(id, type, code) {
440457
const session = this[kOwner];
441458
if (session.destroyed)
442459
return;
443-
debug(`Http2Session ${sessionName(session[kType])}: error sending frame ` +
444-
`type ${type} on stream ${id}, code: ${code}`);
460+
debugSessionObj(session, 'error sending frame type %d on stream %d, code: %d',
461+
type, id, code);
445462
const emitter = session[kState].streams.get(id) || session;
446463
emitter[kUpdateTimer]();
447464
emitter.emit('frameError', type, code, id);
@@ -451,8 +468,8 @@ function onAltSvc(stream, origin, alt) {
451468
const session = this[kOwner];
452469
if (session.destroyed)
453470
return;
454-
debug(`Http2Session ${sessionName(session[kType])}: altsvc received: ` +
455-
`stream: ${stream}, origin: ${origin}, alt: ${alt}`);
471+
debugSessionObj(session, 'altsvc received: stream: %d, origin: %s, alt: %s',
472+
stream, origin, alt);
456473
session[kUpdateTimer]();
457474
session.emit('altsvc', alt, origin, stream);
458475
}
@@ -479,8 +496,7 @@ function onOrigin(origins) {
479496
const session = this[kOwner];
480497
if (session.destroyed)
481498
return;
482-
debug('Http2Session %s: origin received: %j',
483-
sessionName(session[kType]), origins);
499+
debugSessionObj(session, 'origin received: %j', origins);
484500
session[kUpdateTimer]();
485501
if (!session.encrypted || session.destroyed)
486502
return undefined;
@@ -500,8 +516,8 @@ function onGoawayData(code, lastStreamID, buf) {
500516
const session = this[kOwner];
501517
if (session.destroyed)
502518
return;
503-
debug(`Http2Session ${sessionName(session[kType])}: goaway ${code} ` +
504-
`received [last stream id: ${lastStreamID}]`);
519+
debugSessionObj(session, 'goaway %d received [last stream id: %d]',
520+
code, lastStreamID);
505521

506522
const state = session[kState];
507523
state.goawayCode = code;
@@ -556,8 +572,7 @@ function requestOnConnect(headers, options) {
556572
return;
557573
}
558574

559-
debug(`Http2Session ${sessionName(session[kType])}: connected, ` +
560-
'initializing request');
575+
debugSessionObj(session, 'connected, initializing request');
561576

562577
let streamOptions = 0;
563578
if (options.endStream)
@@ -646,13 +661,13 @@ function settingsCallback(cb, ack, duration) {
646661
this[kState].pendingAck--;
647662
this[kLocalSettings] = undefined;
648663
if (ack) {
649-
debug(`Http2Session ${sessionName(this[kType])}: settings received`);
664+
debugSessionObj(this, 'settings received');
650665
const settings = this.localSettings;
651666
if (typeof cb === 'function')
652667
cb(null, settings, duration);
653668
this.emit('localSettings', settings);
654669
} else {
655-
debug(`Http2Session ${sessionName(this[kType])}: settings canceled`);
670+
debugSessionObj(this, 'settings canceled');
656671
if (typeof cb === 'function')
657672
cb(new ERR_HTTP2_SETTINGS_CANCEL());
658673
}
@@ -662,7 +677,7 @@ function settingsCallback(cb, ack, duration) {
662677
function submitSettings(settings, callback) {
663678
if (this.destroyed)
664679
return;
665-
debug(`Http2Session ${sessionName(this[kType])}: submitting settings`);
680+
debugSessionObj(this, 'submitting settings');
666681
this[kUpdateTimer]();
667682
updateSettingsBuffer(settings);
668683
if (!this[kHandle].settings(settingsCallback.bind(this, callback))) {
@@ -696,7 +711,7 @@ function submitPriority(options) {
696711
function submitGoaway(code, lastStreamID, opaqueData) {
697712
if (this.destroyed)
698713
return;
699-
debug(`Http2Session ${sessionName(this[kType])}: submitting goaway`);
714+
debugSessionObj(this, 'submitting goaway');
700715
this[kUpdateTimer]();
701716
this[kHandle].goaway(code, lastStreamID, opaqueData);
702717
}
@@ -827,7 +842,7 @@ function setupHandle(socket, type, options) {
827842
'Internal HTTP/2 Failure. The socket is not connected. Please ' +
828843
'report this as a bug in Node.js');
829844

830-
debug(`Http2Session ${sessionName(type)}: setting up session handle`);
845+
debugSession(type, 'setting up session handle');
831846
this[kState].flags |= SESSION_FLAGS_READY;
832847

833848
updateOptionsBuffer(options);
@@ -983,7 +998,7 @@ class Http2Session extends EventEmitter {
983998
setupFn();
984999
}
9851000

986-
debug(`Http2Session ${sessionName(type)}: created`);
1001+
debugSession(type, 'created');
9871002
}
9881003

9891004
// Returns undefined if the socket is not yet connected, true if the
@@ -1159,7 +1174,7 @@ class Http2Session extends EventEmitter {
11591174

11601175
if (callback && typeof callback !== 'function')
11611176
throw new ERR_INVALID_CALLBACK(callback);
1162-
debug(`Http2Session ${sessionName(this[kType])}: sending settings`);
1177+
debugSessionObj(this, 'sending settings');
11631178

11641179
this[kState].pendingAck++;
11651180

@@ -1200,7 +1215,7 @@ class Http2Session extends EventEmitter {
12001215
destroy(error = NGHTTP2_NO_ERROR, code) {
12011216
if (this.destroyed)
12021217
return;
1203-
debug(`Http2Session ${sessionName(this[kType])}: destroying`);
1218+
debugSessionObj(this, 'destroying');
12041219

12051220
if (typeof error === 'number') {
12061221
code = error;
@@ -1257,7 +1272,7 @@ class Http2Session extends EventEmitter {
12571272
close(callback) {
12581273
if (this.closed || this.destroyed)
12591274
return;
1260-
debug(`Http2Session ${sessionName(this[kType])}: marking session closed`);
1275+
debugSessionObj(this, 'marking session closed');
12611276
this[kState].flags |= SESSION_FLAGS_CLOSED;
12621277
if (typeof callback === 'function')
12631278
this.once('close', callback);
@@ -1428,7 +1443,7 @@ class ClientHttp2Session extends Http2Session {
14281443
// Submits a new HTTP2 request to the connected peer. Returns the
14291444
// associated Http2Stream instance.
14301445
request(headers, options) {
1431-
debug(`Http2Session ${sessionName(this[kType])}: initiating request`);
1446+
debugSessionObj(this, 'initiating request');
14321447

14331448
if (this.destroyed)
14341449
throw new ERR_HTTP2_INVALID_SESSION();
@@ -1828,8 +1843,7 @@ class Http2Stream extends Duplex {
18281843
if (this.pending) {
18291844
this.once('ready', () => this._final(cb));
18301845
} else if (handle !== undefined) {
1831-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
1832-
`${sessionName(this[kSession][kType])}]: _final shutting down`);
1846+
debugStreamObj(this, '_final shutting down');
18331847
const req = new ShutdownWrap();
18341848
req.oncomplete = afterShutdown;
18351849
req.callback = cb;
@@ -1888,9 +1902,7 @@ class Http2Stream extends Duplex {
18881902
assertIsObject(headers, 'headers');
18891903
headers = Object.assign(Object.create(null), headers);
18901904

1891-
const session = this[kSession];
1892-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
1893-
`${sessionName(session[kType])}]: sending trailers`);
1905+
debugStreamObj(this, 'sending trailers');
18941906

18951907
this[kUpdateTimer]();
18961908

@@ -1943,8 +1955,7 @@ class Http2Stream extends Duplex {
19431955
const handle = this[kHandle];
19441956
const id = this[kID];
19451957

1946-
debug(`Http2Stream ${this[kID] || '<pending>'} [Http2Session ` +
1947-
`${sessionName(session[kType])}]: destroying stream`);
1958+
debugStream(this[kID] || 'pending', session[kType], 'destroying stream');
19481959

19491960
const state = this[kState];
19501961
const sessionCode = session[kState].goawayCode ||
@@ -2270,8 +2281,7 @@ class ServerHttp2Stream extends Http2Stream {
22702281

22712282
const session = this[kSession];
22722283

2273-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2274-
`${sessionName(session[kType])}]: initiating push stream`);
2284+
debugStreamObj(this, 'initiating push stream');
22752285

22762286
this[kUpdateTimer]();
22772287

@@ -2351,9 +2361,7 @@ class ServerHttp2Stream extends Http2Stream {
23512361
assertIsObject(options, 'options');
23522362
options = { ...options };
23532363

2354-
const session = this[kSession];
2355-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2356-
`${sessionName(session[kType])}]: initiating response`);
2364+
debugStreamObj(this, 'initiating response');
23572365
this[kUpdateTimer]();
23582366

23592367
options.endStream = !!options.endStream;
@@ -2426,8 +2434,7 @@ class ServerHttp2Stream extends Http2Stream {
24262434

24272435
validateNumber(fd, 'fd');
24282436

2429-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2430-
`${sessionName(session[kType])}]: initiating response from fd`);
2437+
debugStreamObj(this, 'initiating response from fd');
24312438
this[kUpdateTimer]();
24322439
this.ownsFd = false;
24332440

@@ -2488,8 +2495,7 @@ class ServerHttp2Stream extends Http2Stream {
24882495
}
24892496

24902497
const session = this[kSession];
2491-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2492-
`${sessionName(session[kType])}]: initiating response from file`);
2498+
debugStreamObj(this, 'initiating response from file');
24932499
this[kUpdateTimer]();
24942500
this.ownsFd = true;
24952501

@@ -2523,9 +2529,7 @@ class ServerHttp2Stream extends Http2Stream {
25232529
assertIsObject(headers, 'headers');
25242530
headers = Object.assign(Object.create(null), headers);
25252531

2526-
const session = this[kSession];
2527-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2528-
`${sessionName(session[kType])}]: sending additional headers`);
2532+
debugStreamObj(this, 'sending additional headers');
25292533

25302534
if (headers[HTTP2_HEADER_STATUS] != null) {
25312535
const statusCode = headers[HTTP2_HEADER_STATUS] |= 0;
@@ -2586,8 +2590,7 @@ function socketOnError(error) {
25862590
// we can do and the other side is fully within its rights to do so.
25872591
if (error.code === 'ECONNRESET' && session[kState].goawayCode !== null)
25882592
return session.destroy();
2589-
debug(`Http2Session ${sessionName(session[kType])}: socket error [` +
2590-
`${error.message}]`);
2593+
debugSessionObj(this, 'socket error [%s]', error.message);
25912594
session.destroy(error);
25922595
}
25932596
}
@@ -2632,7 +2635,8 @@ function connectionListener(socket) {
26322635
return httpConnectionListener.call(this, socket);
26332636
}
26342637
// Let event handler deal with the socket
2635-
debug(`Unknown protocol from ${socket.remoteAddress}:${socket.remotePort}`);
2638+
debug('Unknown protocol from %s:%s',
2639+
socket.remoteAddress, socket.remotePort);
26362640
if (!this.emit('unknownProtocol', socket)) {
26372641
// We don't know what to do, so let's just tell the other side what's
26382642
// going on in a format that they *might* understand.
@@ -2757,7 +2761,7 @@ function setupCompat(ev) {
27572761
function socketOnClose() {
27582762
const session = this[kSession];
27592763
if (session !== undefined) {
2760-
debug(`Http2Session ${sessionName(session[kType])}: socket closed`);
2764+
debugSessionObj(session, 'socket closed');
27612765
const err = session.connecting ? new ERR_SOCKET_CLOSED() : null;
27622766
const state = session[kState];
27632767
state.streams.forEach((stream) => stream.close(NGHTTP2_CANCEL));

0 commit comments

Comments
 (0)