Skip to content
Closed
Changes from 1 commit
Commits
Show all changes
19 commits
Select commit Hold shift + click to select a range
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Prev Previous commit
Next Next commit
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.
  • Loading branch information
addaleax committed Aug 14, 2019
commit c625114ec8dbef08b552a9769ce6d8d4bdc3e778
115 changes: 61 additions & 54 deletions lib/internal/http2/core.js
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