Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly
Appearance settings

Commit 76a7ada

Browse filesBrowse 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: #29123 PR-URL: #29122 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>
1 parent 74507fa commit 76a7ada
Copy full SHA for 76a7ada

File tree

Expand file treeCollapse file tree

1 file changed

+61
-54
lines changed
Open diff view settings
Filter options
Expand file treeCollapse file tree

1 file changed

+61
-54
lines changed
Open diff view settings
Collapse file

‎lib/internal/http2/core.js‎

Copy file name to clipboardExpand all lines: lib/internal/http2/core.js
+61-54Lines changed: 61 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -127,6 +127,26 @@ const { StreamPipe } = internalBinding('stream_pipe');
127127
const { _connectionListener: httpConnectionListener } = http;
128128
const debug = util.debuglog('http2');
129129

130+
// TODO(addaleax): See if this can be made more efficient by figuring out
131+
// whether debugging is enabled before we perform any further steps. Currently,
132+
// this seems pretty fast, though.
133+
function debugStream(id, sessionType, message, ...args) {
134+
debug('Http2Stream %s [Http2Session %s]: ' + message,
135+
id, sessionName(sessionType), ...args);
136+
}
137+
138+
function debugStreamObj(stream, message, ...args) {
139+
debugStream(stream[kID], stream[kSession][kType], ...args);
140+
}
141+
142+
function debugSession(sessionType, message, ...args) {
143+
debug('Http2Session %s: ' + message, sessionName(sessionType), ...args);
144+
}
145+
146+
function debugSessionObj(session, message, ...args) {
147+
debugSession(session[kType], message, ...args);
148+
}
149+
130150
const kMaxFrameSize = (2 ** 24) - 1;
131151
const kMaxInt = (2 ** 32) - 1;
132152
const kMaxStreams = (2 ** 31) - 1;
@@ -248,8 +268,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) {
248268

249269
const type = session[kType];
250270
session[kUpdateTimer]();
251-
debug(`Http2Stream ${id} [Http2Session ` +
252-
`${sessionName(type)}]: headers received`);
271+
debugStream(id, type, 'headers received');
253272
const streams = session[kState].streams;
254273

255274
const endOfStream = !!(flags & NGHTTP2_FLAG_END_STREAM);
@@ -309,8 +328,7 @@ function onSessionHeaders(handle, id, cat, flags, headers) {
309328
const originSet = session[kState].originSet = initOriginSet(session);
310329
originSet.delete(stream[kOrigin]);
311330
}
312-
debug(`Http2Stream ${id} [Http2Session ` +
313-
`${sessionName(type)}]: emitting stream '${event}' event`);
331+
debugStream(id, type, "emitting stream '%s' event", event);
314332
process.nextTick(emit, stream, event, obj, flags, headers);
315333
}
316334
if (endOfStream) {
@@ -351,7 +369,7 @@ function onPing(payload) {
351369
if (session.destroyed)
352370
return;
353371
session[kUpdateTimer]();
354-
debug(`Http2Session ${sessionName(session[kType])}: new ping received`);
372+
debugSessionObj(session, 'new ping received');
355373
session.emit('ping', payload);
356374
}
357375

@@ -366,8 +384,7 @@ function onStreamClose(code) {
366384
if (stream.destroyed)
367385
return;
368386

369-
debug(`Http2Stream ${stream[kID]} [Http2Session ` +
370-
`${sessionName(stream[kSession][kType])}]: closed with code ${code}`);
387+
debugStreamObj(stream, 'closed with code %d', code);
371388

372389
if (!stream.closed)
373390
closeStream(stream, code, kNoRstStream);
@@ -403,7 +420,7 @@ function onSettings() {
403420
if (session.destroyed)
404421
return;
405422
session[kUpdateTimer]();
406-
debug(`Http2Session ${sessionName(session[kType])}: new settings received`);
423+
debugSessionObj(session, 'new settings received');
407424
session[kRemoteSettings] = undefined;
408425
session.emit('remoteSettings', session.remoteSettings);
409426
}
@@ -415,9 +432,9 @@ function onPriority(id, parent, weight, exclusive) {
415432
const session = this[kOwner];
416433
if (session.destroyed)
417434
return;
418-
debug(`Http2Stream ${id} [Http2Session ` +
419-
`${sessionName(session[kType])}]: priority [parent: ${parent}, ` +
420-
`weight: ${weight}, exclusive: ${exclusive}]`);
435+
debugStream(id, session[kType],
436+
'priority [parent: %d, weight: %d, exclusive: %s]',
437+
parent, weight, exclusive);
421438
const emitter = session[kState].streams.get(id) || session;
422439
if (!emitter.destroyed) {
423440
emitter[kUpdateTimer]();
@@ -431,8 +448,8 @@ function onFrameError(id, type, code) {
431448
const session = this[kOwner];
432449
if (session.destroyed)
433450
return;
434-
debug(`Http2Session ${sessionName(session[kType])}: error sending frame ` +
435-
`type ${type} on stream ${id}, code: ${code}`);
451+
debugSessionObj(session, 'error sending frame type %d on stream %d, code: %d',
452+
type, id, code);
436453
const emitter = session[kState].streams.get(id) || session;
437454
emitter[kUpdateTimer]();
438455
emitter.emit('frameError', type, code, id);
@@ -442,8 +459,8 @@ function onAltSvc(stream, origin, alt) {
442459
const session = this[kOwner];
443460
if (session.destroyed)
444461
return;
445-
debug(`Http2Session ${sessionName(session[kType])}: altsvc received: ` +
446-
`stream: ${stream}, origin: ${origin}, alt: ${alt}`);
462+
debugSessionObj(session, 'altsvc received: stream: %d, origin: %s, alt: %s',
463+
stream, origin, alt);
447464
session[kUpdateTimer]();
448465
session.emit('altsvc', alt, origin, stream);
449466
}
@@ -470,8 +487,7 @@ function onOrigin(origins) {
470487
const session = this[kOwner];
471488
if (session.destroyed)
472489
return;
473-
debug('Http2Session %s: origin received: %j',
474-
sessionName(session[kType]), origins);
490+
debugSessionObj(session, 'origin received: %j', origins);
475491
session[kUpdateTimer]();
476492
if (!session.encrypted || session.destroyed)
477493
return undefined;
@@ -491,8 +507,8 @@ function onGoawayData(code, lastStreamID, buf) {
491507
const session = this[kOwner];
492508
if (session.destroyed)
493509
return;
494-
debug(`Http2Session ${sessionName(session[kType])}: goaway ${code} ` +
495-
`received [last stream id: ${lastStreamID}]`);
510+
debugSessionObj(session, 'goaway %d received [last stream id: %d]',
511+
code, lastStreamID);
496512

497513
const state = session[kState];
498514
state.goawayCode = code;
@@ -545,8 +561,7 @@ function requestOnConnect(headers, options) {
545561
return;
546562
}
547563

548-
debug(`Http2Session ${sessionName(session[kType])}: connected, ` +
549-
'initializing request');
564+
debugSessionObj(session, 'connected, initializing request');
550565

551566
let streamOptions = 0;
552567
if (options.endStream)
@@ -641,13 +656,13 @@ function settingsCallback(cb, ack, duration) {
641656
this[kState].pendingAck--;
642657
this[kLocalSettings] = undefined;
643658
if (ack) {
644-
debug(`Http2Session ${sessionName(this[kType])}: settings received`);
659+
debugSessionObj(this, 'settings received');
645660
const settings = this.localSettings;
646661
if (typeof cb === 'function')
647662
cb(null, settings, duration);
648663
this.emit('localSettings', settings);
649664
} else {
650-
debug(`Http2Session ${sessionName(this[kType])}: settings canceled`);
665+
debugSessionObj(this, 'settings canceled');
651666
if (typeof cb === 'function')
652667
cb(new ERR_HTTP2_SETTINGS_CANCEL());
653668
}
@@ -657,7 +672,7 @@ function settingsCallback(cb, ack, duration) {
657672
function submitSettings(settings, callback) {
658673
if (this.destroyed)
659674
return;
660-
debug(`Http2Session ${sessionName(this[kType])}: submitting settings`);
675+
debugSessionObj(this, 'submitting settings');
661676
this[kUpdateTimer]();
662677
updateSettingsBuffer(settings);
663678
if (!this[kHandle].settings(settingsCallback.bind(this, callback))) {
@@ -691,7 +706,7 @@ function submitPriority(options) {
691706
function submitGoaway(code, lastStreamID, opaqueData) {
692707
if (this.destroyed)
693708
return;
694-
debug(`Http2Session ${sessionName(this[kType])}: submitting goaway`);
709+
debugSessionObj(this, 'submitting goaway');
695710
this[kUpdateTimer]();
696711
this[kHandle].goaway(code, lastStreamID, opaqueData);
697712
}
@@ -821,7 +836,9 @@ function setupHandle(socket, type, options) {
821836
process.nextTick(emit, this, 'connect', this, socket);
822837
return;
823838
}
824-
debug(`Http2Session ${sessionName(type)}: setting up session handle`);
839+
840+
debugSession(type, 'setting up session handle');
841+
825842
this[kState].flags |= SESSION_FLAGS_READY;
826843

827844
updateOptionsBuffer(options);
@@ -983,7 +1000,7 @@ class Http2Session extends EventEmitter {
9831000
setupFn();
9841001
}
9851002

986-
debug(`Http2Session ${sessionName(type)}: created`);
1003+
debugSession(type, 'created');
9871004
}
9881005

9891006
// Returns undefined if the socket is not yet connected, true if the
@@ -1156,7 +1173,7 @@ class Http2Session extends EventEmitter {
11561173

11571174
if (callback && typeof callback !== 'function')
11581175
throw new ERR_INVALID_CALLBACK();
1159-
debug(`Http2Session ${sessionName(this[kType])}: sending settings`);
1176+
debugSessionObj(this, 'sending settings');
11601177

11611178
this[kState].pendingAck++;
11621179

@@ -1197,7 +1214,7 @@ class Http2Session extends EventEmitter {
11971214
destroy(error = NGHTTP2_NO_ERROR, code) {
11981215
if (this.destroyed)
11991216
return;
1200-
debug(`Http2Session ${sessionName(this[kType])}: destroying`);
1217+
debugSessionObj(this, 'destroying');
12011218

12021219
if (typeof error === 'number') {
12031220
code = error;
@@ -1258,7 +1275,7 @@ class Http2Session extends EventEmitter {
12581275
close(callback) {
12591276
if (this.closed || this.destroyed)
12601277
return;
1261-
debug(`Http2Session ${sessionName(this[kType])}: marking session closed`);
1278+
debugSessionObj(this, 'marking session closed');
12621279
this[kState].flags |= SESSION_FLAGS_CLOSED;
12631280
if (typeof callback === 'function')
12641281
this.once('close', callback);
@@ -1430,7 +1447,7 @@ class ClientHttp2Session extends Http2Session {
14301447
// Submits a new HTTP2 request to the connected peer. Returns the
14311448
// associated Http2Stream instance.
14321449
request(headers, options) {
1433-
debug(`Http2Session ${sessionName(this[kType])}: initiating request`);
1450+
debugSessionObj(this, 'initiating request');
14341451

14351452
if (this.destroyed)
14361453
throw new ERR_HTTP2_INVALID_SESSION();
@@ -1827,8 +1844,7 @@ class Http2Stream extends Duplex {
18271844
if (this.pending) {
18281845
this.once('ready', () => this._final(cb));
18291846
} else if (handle !== undefined) {
1830-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
1831-
`${sessionName(this[kSession][kType])}]: _final shutting down`);
1847+
debugStreamObj(this, '_final shutting down');
18321848
const req = new ShutdownWrap();
18331849
req.oncomplete = afterShutdown;
18341850
req.callback = cb;
@@ -1887,9 +1903,7 @@ class Http2Stream extends Duplex {
18871903
assertIsObject(headers, 'headers');
18881904
headers = Object.assign(Object.create(null), headers);
18891905

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

18941908
this[kUpdateTimer]();
18951909

@@ -1944,8 +1958,8 @@ class Http2Stream extends Duplex {
19441958
const handle = this[kHandle];
19451959
const id = this[kID];
19461960

1947-
debug(`Http2Stream ${this[kID] || '<pending>'} [Http2Session ` +
1948-
`${sessionName(session[kType])}]: destroying stream`);
1961+
debugStream(this[kID] || 'pending', session[kType], 'destroying stream');
1962+
19491963
const state = this[kState];
19501964
const code = err != null ?
19511965
NGHTTP2_INTERNAL_ERROR : (state.rstCode || NGHTTP2_NO_ERROR);
@@ -2256,8 +2270,7 @@ class ServerHttp2Stream extends Http2Stream {
22562270

22572271
const session = this[kSession];
22582272

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

22622275
this[kUpdateTimer]();
22632276

@@ -2339,9 +2352,7 @@ class ServerHttp2Stream extends Http2Stream {
23392352
assertIsObject(options, 'options');
23402353
options = Object.assign({}, options);
23412354

2342-
const session = this[kSession];
2343-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2344-
`${sessionName(session[kType])}]: initiating response`);
2355+
debugStreamObj(this, 'initiating response');
23452356
this[kUpdateTimer]();
23462357

23472358
options.endStream = !!options.endStream;
@@ -2420,8 +2431,7 @@ class ServerHttp2Stream extends Http2Stream {
24202431

24212432
validateNumber(fd, 'fd');
24222433

2423-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2424-
`${sessionName(session[kType])}]: initiating response from fd`);
2434+
debugStreamObj(this, 'initiating response from fd');
24252435
this[kUpdateTimer]();
24262436
this.ownsFd = false;
24272437

@@ -2481,8 +2491,7 @@ class ServerHttp2Stream extends Http2Stream {
24812491
}
24822492

24832493
const session = this[kSession];
2484-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2485-
`${sessionName(session[kType])}]: initiating response from file`);
2494+
debugStreamObj(this, 'initiating response from file');
24862495
this[kUpdateTimer]();
24872496
this.ownsFd = true;
24882497

@@ -2515,9 +2524,7 @@ class ServerHttp2Stream extends Http2Stream {
25152524
assertIsObject(headers, 'headers');
25162525
headers = Object.assign(Object.create(null), headers);
25172526

2518-
const session = this[kSession];
2519-
debug(`Http2Stream ${this[kID]} [Http2Session ` +
2520-
`${sessionName(session[kType])}]: sending additional headers`);
2527+
debugStreamObj(this, 'sending additional headers');
25212528

25222529
if (headers[HTTP2_HEADER_STATUS] != null) {
25232530
const statusCode = headers[HTTP2_HEADER_STATUS] |= 0;
@@ -2608,8 +2615,7 @@ function socketOnError(error) {
26082615
// we can do and the other side is fully within its rights to do so.
26092616
if (error.code === 'ECONNRESET' && session[kState].goawayCode !== null)
26102617
return session.destroy();
2611-
debug(`Http2Session ${sessionName(session[kType])}: socket error [` +
2612-
`${error.message}]`);
2618+
debugSessionObj(this, 'socket error [%s]', error.message);
26132619
session.destroy(error);
26142620
}
26152621
}
@@ -2654,7 +2660,8 @@ function connectionListener(socket) {
26542660
return httpConnectionListener.call(this, socket);
26552661
}
26562662
// Let event handler deal with the socket
2657-
debug(`Unknown protocol from ${socket.remoteAddress}:${socket.remotePort}`);
2663+
debug('Unknown protocol from %s:%s',
2664+
socket.remoteAddress, socket.remotePort);
26582665
if (!this.emit('unknownProtocol', socket)) {
26592666
// We don't know what to do, so let's just tell the other side what's
26602667
// going on in a format that they *might* understand.
@@ -2779,7 +2786,7 @@ function setupCompat(ev) {
27792786
function socketOnClose() {
27802787
const session = this[kSession];
27812788
if (session !== undefined) {
2782-
debug(`Http2Session ${sessionName(session[kType])}: socket closed`);
2789+
debugSessionObj(session, 'socket closed');
27832790
const err = session.connecting ? new ERR_SOCKET_CLOSED() : null;
27842791
const state = session[kState];
27852792
state.streams.forEach((stream) => stream.close(NGHTTP2_CANCEL));

0 commit comments

Comments
0 (0)
Morty Proxy This is a proxified and sanitized view of the page, visit original site.