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 00f6846

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: #29124 PR-URL: #29122 Reviewed-By: Rich Trott <rtrott@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>
1 parent 6d42737 commit 00f6846
Copy full SHA for 00f6846

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
@@ -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 (0)
Morty Proxy This is a proxified and sanitized view of the page, visit original site.