1berry/nodejs
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

http2: improve JS-side debug logging

Browse Source 
DRY up the `debug()` calls, and in particular, avoid building template
strings before we know whether we need to.

PR-URL: https://github.com/nodejs/node/pull/29122
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
This commit is contained in:
Anna Henningsen 2019-08-05 17:22:30 +02:00 committed by Michaël Zasso
parent fd148d38d2
commit 8dae8d12df
No known key found for this signature in database
GPG Key ID: 770F7A9A5AE15600
1 changed files with 58 additions and 54 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

112
lib/internal/http2/core.js
View File

@ -138,6 +138,26 @@ const { StreamPipe } = internalBinding('stream_pipe');
const { _connectionListener: httpConnectionListener } = http;
const debug = require('internal/util/debuglog').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;
@ -256,8 +276,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);
@ -317,8 +336,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) {
@ -359,7 +377,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);
}
@ -374,8 +392,7 @@ function onStreamClose(code) {
if (!stream || stream.destroyed)
return false;
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);
@ -412,7 +429,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);
}
@ -424,9 +441,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]();
@ -440,8 +457,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);
@ -451,8 +468,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);
}
@ -479,8 +496,7 @@ function onOrigin(origins) {
const session = this[kOwner];
if (session.destroyed)
return;
debug('Http2Session %s: origin received: %j',
sessionName(session[kType]), origins);
debugSessionObj(session, 'origin received: %j', origins);
session[kUpdateTimer]();
if (!session.encrypted || session.destroyed)
return undefined;
@ -500,8 +516,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;
@ -556,8 +572,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)
@ -646,13 +661,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 ERR_HTTP2_SETTINGS_CANCEL());
}
@ -662,7 +677,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))) {
@ -696,7 +711,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);
}
@ -827,7 +842,7 @@ function setupHandle(socket, type, options) {
'Internal HTTP/2 Failure. The socket is not connected. Please ' +
'report this as a bug in Node.js');
debug(`Http2Session ${sessionName(type)}: setting up session handle`);
debugSession(type, 'setting up session handle');
this[kState].flags |= SESSION_FLAGS_READY;
updateOptionsBuffer(options);
@ -983,7 +998,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
@ -1159,7 +1174,7 @@ class Http2Session extends EventEmitter {
if (callback && typeof callback !== 'function')
throw new ERR_INVALID_CALLBACK(callback);
debug(`Http2Session ${sessionName(this[kType])}: sending settings`);
debugSessionObj(this, 'sending settings');
this[kState].pendingAck++;
@ -1200,7 +1215,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;
@ -1257,7 +1272,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);
@ -1428,7 +1443,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 ERR_HTTP2_INVALID_SESSION();
@ -1828,8 +1843,7 @@ class Http2Stream extends Duplex {
if (this.pending) {
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;
@ -1888,9 +1902,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]();
@ -1943,8 +1955,7 @@ 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 sessionCode = session[kState].goawayCode ||
@ -2270,8 +2281,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]();
@ -2351,9 +2361,7 @@ class ServerHttp2Stream extends Http2Stream {
assertIsObject(options, 'options');
options = { ...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;
@ -2426,8 +2434,7 @@ class ServerHttp2Stream extends Http2Stream {
validateNumber(fd, 'fd');
debug(`Http2Stream ${this[kID]} [Http2Session ` +
`${sessionName(session[kType])}]: initiating response from fd`);
debugStreamObj(this, 'initiating response from fd');
this[kUpdateTimer]();
this.ownsFd = false;
@ -2488,8 +2495,7 @@ class ServerHttp2Stream extends Http2Stream {
}
const session = this[kSession];
debug(`Http2Stream ${this[kID]} [Http2Session ` +
`${sessionName(session[kType])}]: initiating response from file`);
debugStreamObj(this, 'initiating response from file');
this[kUpdateTimer]();
this.ownsFd = true;
@ -2523,9 +2529,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;
@ -2586,8 +2590,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);
}
}
@ -2632,7 +2635,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.
@ -2757,7 +2761,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 ERR_SOCKET_CLOSED() : null;
const state = session[kState];
state.streams.forEach((stream) => stream.close(NGHTTP2_CANCEL));