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.

Backport-PR-URL: #29123
PR-URL: #29122
Reviewed-By: Rich Trott <rtrott@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
  • Loading branch information
@addaleax @BethGriggs
addaleax authored and BethGriggs committed Aug 15, 2019
1 parent 74507fa commit 76a7ada
Showing 1 changed file with 61 additions and 54 deletions.
115 changes: 61 additions & 54 deletions lib/internal/http2/core.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -127,6 +127,26 @@ const { StreamPipe } = internalBinding('stream_pipe');
const { _connectionListener: httpConnectionListener } = http;
const debug = util.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;
Expand Down Expand Up @@ -248,8 +268,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 @@ -309,8 +328,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 @@ -351,7 +369,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 @@ -366,8 +384,7 @@ function onStreamClose(code) {
if (stream.destroyed)
return;

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 @@ -403,7 +420,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 @@ -415,9 +432,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 @@ -431,8 +448,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 @@ -442,8 +459,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 @@ -470,8 +487,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 @@ -491,8 +507,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 @@ -545,8 +561,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 @@ -641,13 +656,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 @@ -657,7 +672,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 @@ -691,7 +706,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 @@ -821,7 +836,9 @@ function setupHandle(socket, type, options) {
process.nextTick(emit, this, 'connect', this, socket);
return;
}
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 @@ -983,7 +1000,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 @@ -1156,7 +1173,7 @@ class Http2Session extends EventEmitter {

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

this[kState].pendingAck++;

Expand Down Expand Up @@ -1197,7 +1214,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 @@ -1258,7 +1275,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 @@ -1430,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 @@ -1827,8 +1844,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 @@ -1887,9 +1903,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 @@ -1944,8 +1958,8 @@ 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 code = err != null ?
NGHTTP2_INTERNAL_ERROR : (state.rstCode || NGHTTP2_NO_ERROR);
Expand Down Expand Up @@ -2256,8 +2270,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 @@ -2339,9 +2352,7 @@ class ServerHttp2Stream extends Http2Stream {
assertIsObject(options, 'options');
options = Object.assign({}, 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 @@ -2420,8 +2431,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 @@ -2481,8 +2491,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 @@ -2515,9 +2524,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 @@ -2608,8 +2615,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 @@ -2654,7 +2660,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 @@ -2779,7 +2786,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 76a7ada

Please sign in to comment.