Skip to content

Commit

Permalink
http2: improve JS-side debug logging
Browse files Browse the repository at this point in the history 
DRY up the `debug()` calls, and in particular, avoid building template
strings before we know whether we need to.

PR-URL: #29122
Reviewed-By: Rich Trott <[email protected]>
Reviewed-By: James M Snell <[email protected]>
  • Loading branch information
@addaleax @targos
addaleax authored and targos committed Aug 15, 2019
1 parent bfeb5fc commit 58d8c9e
Showing 1 changed file with 58 additions and 54 deletions.
112 changes: 58 additions & 54 deletions lib/internal/http2/core.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -139,6 +139,26 @@ const { _connectionListener: httpConnectionListener } = http;
const debug = require('internal/util/debuglog').debuglog('http2');
const { getOptionValue } = require('internal/options');

// 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;
Expand Down Expand Up @@ -260,8 +280,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);
Expand Down Expand Up @@ -321,8 +340,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) {
Expand Down Expand Up @@ -363,7 +381,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);
}

Expand All @@ -378,8 +396,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);
Expand Down Expand Up @@ -416,7 +433,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);
}
Expand All @@ -428,9 +445,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]();
Expand All @@ -444,8 +461,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);
Expand All @@ -455,8 +472,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);
}
Expand All @@ -483,8 +500,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;
Expand All @@ -504,8 +520,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;
Expand Down Expand Up @@ -560,8 +576,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)
Expand Down Expand Up @@ -650,13 +665,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());
}
Expand All @@ -666,7 +681,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))) {
Expand Down Expand Up @@ -700,7 +715,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);
}
Expand Down Expand Up @@ -831,7 +846,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);
Expand Down Expand Up @@ -987,7 +1002,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
Expand Down Expand Up @@ -1163,7 +1178,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++;

Expand Down Expand Up @@ -1204,7 +1219,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;
Expand Down Expand Up @@ -1261,7 +1276,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);
Expand Down Expand Up @@ -1432,7 +1447,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();
Expand Down Expand Up @@ -1832,8 +1847,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;
Expand Down Expand Up @@ -1892,9 +1906,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]();

Expand Down Expand Up @@ -1947,8 +1959,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 ||
Expand Down Expand Up @@ -2274,8 +2285,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]();

Expand Down Expand Up @@ -2355,9 +2365,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;
Expand Down Expand Up @@ -2430,8 +2438,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;

Expand Down Expand Up @@ -2492,8 +2499,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;

Expand Down Expand Up @@ -2527,9 +2533,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;
Expand Down Expand Up @@ -2590,8 +2594,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);
}
}
Expand Down Expand Up @@ -2636,7 +2639,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.
Expand Down Expand Up @@ -2761,7 +2765,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));
Expand Down

0 comments on commit 58d8c9e

Please sign in to comment.