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

http2: switch to new runtime-controlled debugging system

Browse Source 
Remove `--debug-http2` as a compile-time feature and
make all debug statements available using `NODE_DEBUG_NATIVE=http2`
at runtime.

This probably makes the debugging-enabled case a bit slower due to
additional string concatenations, but switching to a runtime-checking
system makes debugging more flexible and can be applied more easily
to other parts of the source code as well.

PR-URL: https://github.com/nodejs/node/pull/20987
Reviewed-By: Daniel Bevenius <daniel.bevenius@gmail.com>
Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>
Reviewed-By: Minwoo Jung <minwoo@nodesource.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
This commit is contained in:
Anna Henningsen 2018-05-27 16:41:35 +02:00
parent bd85844c4e
commit 15c7a49bfc
No known key found for this signature in database
GPG Key ID: 9C63F3A6CD2AD8F9
6 changed files with 115 additions and 154 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
configure vendored
View File

@ -443,11 +443,6 @@ parser.add_option('--debug-lib',
dest='node_debug_lib',
help='build lib with DCHECK macros')
http2_optgroup.add_option('--debug-http2',
action='store_true',
dest='debug_http2',
help='build with http2 debug statements on (default is false)')
http2_optgroup.add_option('--debug-nghttp2',
action='store_true',
dest='debug_nghttp2',
@ -970,11 +965,6 @@ def configure_node(o):
o['variables']['node_debug_lib'] = b(options.node_debug_lib)
if options.debug_http2:
o['variables']['debug_http2'] = 1
else:
o['variables']['debug_http2'] = 'false'
if options.debug_nghttp2:
o['variables']['debug_nghttp2'] = 1
else:

4
node.gypi
View File

@ -90,10 +90,6 @@
'NODE_RELEASE_URLBASE="<(node_release_urlbase)"',
]
}],
[
'debug_http2==1', {
'defines': [ 'NODE_DEBUG_HTTP2=1' ]
}],
[ 'v8_enable_i18n_support==1', {
'defines': [ 'NODE_HAVE_I18N_SUPPORT=1' ],
'dependencies': [

176
src/node_http2.cc
View File

@ -1,4 +1,5 @@
#include "aliased_buffer.h"
#include "debug_utils.h"
#include "node.h"
#include "node_buffer.h"
#include "node_http2.h"
@ -200,7 +201,8 @@ void Http2Session::Http2Settings::Init() {
#define GRABSETTING(N, trace) \
if (flags & (1 << IDX_SETTINGS_##N)) { \
uint32_t val = buffer[IDX_SETTINGS_##N]; \
DEBUG_HTTP2SESSION2(session_, "setting " trace ": %d\n", val); \
if (session_ != nullptr) \
Debug(session_, "setting " trace ": %d\n", val); \
entries_[n++] = \
nghttp2_settings_entry {NGHTTP2_SETTINGS_##N, val}; \
}
@ -334,13 +336,14 @@ Http2Priority::Http2Priority(Environment* env,
int32_t parent_ = parent->Int32Value(context).ToChecked();
int32_t weight_ = weight->Int32Value(context).ToChecked();
bool exclusive_ = exclusive->BooleanValue(context).ToChecked();
DEBUG_HTTP2("Http2Priority: parent: %d, weight: %d, exclusive: %d\n",
parent_, weight_, exclusive_);
Debug(env, DebugCategory::HTTP2STREAM,
"Http2Priority: parent: %d, weight: %d, exclusive: %d\n",
parent_, weight_, exclusive_);
nghttp2_priority_spec_init(&spec, parent_, weight_, exclusive_ ? 1 : 0);
}
inline const char* Http2Session::TypeName() {
const char* Http2Session::TypeName() const {
switch (session_type_) {
case NGHTTP2_SESSION_SERVER: return "server";
case NGHTTP2_SESSION_CLIENT: return "client";
@ -495,10 +498,15 @@ Http2Session::Http2Session(Environment* env,
Http2Session::~Http2Session() {
CHECK_EQ(flags_ & SESSION_STATE_HAS_SCOPE, 0);
DEBUG_HTTP2SESSION(this, "freeing nghttp2 session");
Debug(this, "freeing nghttp2 session");
nghttp2_session_del(session_);
}
std::string Http2Session::diagnostic_name() const {
return std::string("Http2Session ") + TypeName() + " (" +
std::to_string(static_cast<int64_t>(get_async_id())) + ")";
}
inline bool HasHttp2Observer(Environment* env) {
AliasedBuffer<uint32_t, Uint32Array>& observers =
env->performance_state()->observers;
@ -575,7 +583,7 @@ void Http2Session::EmitStatistics() {
// Closes the session and frees the associated resources
void Http2Session::Close(uint32_t code, bool socket_closed) {
DEBUG_HTTP2SESSION(this, "closing session");
Debug(this, "closing session");
if (flags_ & SESSION_STATE_CLOSING)
return;
@ -590,7 +598,7 @@ void Http2Session::Close(uint32_t code, bool socket_closed) {
// the peer but the HTTP/2 spec recommends sending it anyway. We'll
// make a best effort.
if (!socket_closed) {
DEBUG_HTTP2SESSION2(this, "terminating session with code %d", code);
Debug(this, "terminating session with code %d", code);
CHECK_EQ(nghttp2_session_terminate_session(session_, code), 0);
SendPendingData();
} else if (stream_ != nullptr) {
@ -662,7 +670,7 @@ ssize_t Http2Session::OnDWordAlignedPadding(size_t frameLen,
// use the max instead, even tho this means the frame will not be
// aligned.
pad = std::min(maxPayloadLen, pad);
DEBUG_HTTP2SESSION2(this, "using frame size padding: %d", pad);
Debug(this, "using frame size padding: %d", pad);
return pad;
}
@ -670,7 +678,7 @@ ssize_t Http2Session::OnDWordAlignedPadding(size_t frameLen,
// of padding allowed for the current frame.
ssize_t Http2Session::OnMaxFrameSizePadding(size_t frameLen,
size_t maxPayloadLen) {
DEBUG_HTTP2SESSION2(this, "using max frame size padding: %d", maxPayloadLen);
Debug(this, "using max frame size padding: %d", maxPayloadLen);
return maxPayloadLen;
}
@ -681,7 +689,7 @@ ssize_t Http2Session::OnMaxFrameSizePadding(size_t frameLen,
ssize_t Http2Session::OnCallbackPadding(size_t frameLen,
size_t maxPayloadLen) {
if (frameLen == 0) return 0;
DEBUG_HTTP2SESSION(this, "using callback to determine padding");
Debug(this, "using callback to determine padding");
Isolate* isolate = env()->isolate();
HandleScope handle_scope(isolate);
Local<Context> context = env()->context();
@ -696,7 +704,7 @@ ssize_t Http2Session::OnCallbackPadding(size_t frameLen,
uint32_t retval = buffer[PADDING_BUF_RETURN_VALUE];
retval = std::min(retval, static_cast<uint32_t>(maxPayloadLen));
retval = std::max(retval, static_cast<uint32_t>(frameLen));
DEBUG_HTTP2SESSION2(this, "using padding size %d", retval);
Debug(this, "using padding size %d", retval);
return retval;
}
@ -712,9 +720,9 @@ ssize_t Http2Session::Write(const uv_buf_t* bufs, size_t nbufs) {
// will trigger a number of other callbacks. Those will, in turn have
// multiple side effects.
for (size_t n = 0; n < nbufs; n++) {
DEBUG_HTTP2SESSION2(this, "receiving %d bytes [wants data? %d]",
bufs[n].len,
nghttp2_session_want_read(session_));
Debug(this, "receiving %d bytes [wants data? %d]",
bufs[n].len,
nghttp2_session_want_read(session_));
ssize_t ret =
nghttp2_session_mem_recv(session_,
reinterpret_cast<uint8_t*>(bufs[n].base),
@ -751,7 +759,7 @@ int Http2Session::OnBeginHeadersCallback(nghttp2_session* handle,
void* user_data) {
Http2Session* session = static_cast<Http2Session*>(user_data);
int32_t id = GetFrameID(frame);
DEBUG_HTTP2SESSION2(session, "beginning headers for stream %d", id);
Debug(session, "beginning headers for stream %d", id);
Http2Stream* stream = session->FindStream(id);
if (stream == nullptr) {
@ -799,8 +807,8 @@ int Http2Session::OnFrameReceive(nghttp2_session* handle,
void* user_data) {
Http2Session* session = static_cast<Http2Session*>(user_data);
session->statistics_.frame_count++;
DEBUG_HTTP2SESSION2(session, "complete frame received: type: %d",
frame->hd.type);
Debug(session, "complete frame received: type: %d",
frame->hd.type);
switch (frame->hd.type) {
case NGHTTP2_DATA:
session->HandleDataFrame(frame);
@ -837,8 +845,7 @@ int Http2Session::OnInvalidFrame(nghttp2_session* handle,
void* user_data) {
Http2Session* session = static_cast<Http2Session*>(user_data);
DEBUG_HTTP2SESSION2(session, "invalid frame received, code: %d",
lib_error_code);
Debug(session, "invalid frame received, code: %d", lib_error_code);
// If the error is fatal or if error code is ERR_STREAM_CLOSED... emit error
if (nghttp2_is_fatal(lib_error_code) ||
@ -866,8 +873,8 @@ int Http2Session::OnFrameNotSent(nghttp2_session* handle,
void* user_data) {
Http2Session* session = static_cast<Http2Session*>(user_data);
Environment* env = session->env();
DEBUG_HTTP2SESSION2(session, "frame type %d was not sent, code: %d",
frame->hd.type, error_code);
Debug(session, "frame type %d was not sent, code: %d",
frame->hd.type, error_code);
// Do not report if the frame was not sent due to the session closing
if (error_code != NGHTTP2_ERR_SESSION_CLOSING &&
error_code != NGHTTP2_ERR_STREAM_CLOSED &&
@ -906,7 +913,7 @@ int Http2Session::OnStreamClose(nghttp2_session* handle,
HandleScope scope(isolate);
Local<Context> context = env->context();
Context::Scope context_scope(context);
DEBUG_HTTP2SESSION2(session, "stream %d closed with code: %d", id, code);
Debug(session, "stream %d closed with code: %d", id, code);
Http2Stream* stream = session->FindStream(id);
// Intentionally ignore the callback if the stream does not exist or has
// already been destroyed
@ -957,8 +964,8 @@ int Http2Session::OnDataChunkReceived(nghttp2_session* handle,
size_t len,
void* user_data) {
Http2Session* session = static_cast<Http2Session*>(user_data);
DEBUG_HTTP2SESSION2(session, "buffering data chunk for stream %d, size: "
"%d, flags: %d", id, len, flags);
Debug(session, "buffering data chunk for stream %d, size: "
"%d, flags: %d", id, len, flags);
Environment* env = session->env();
HandleScope scope(env->isolate());
// We should never actually get a 0-length chunk so this check is
@ -1050,7 +1057,7 @@ int Http2Session::OnNghttpError(nghttp2_session* handle,
// Unfortunately, this is currently the only way for us to know if
// the session errored because the peer is not an http2 peer.
Http2Session* session = static_cast<Http2Session*>(user_data);
DEBUG_HTTP2SESSION2(session, "Error '%.*s'", len, message);
Debug(session, "Error '%.*s'", len, message);
if (strncmp(message, BAD_PEER_MESSAGE, len) == 0) {
Environment* env = session->env();
Isolate* isolate = env->isolate();
@ -1109,7 +1116,7 @@ void Http2Session::HandleHeadersFrame(const nghttp2_frame* frame) {
Context::Scope context_scope(context);
int32_t id = GetFrameID(frame);
DEBUG_HTTP2SESSION2(this, "handle headers frame for stream %d", id);
Debug(this, "handle headers frame for stream %d", id);
Http2Stream* stream = FindStream(id);
// If the stream has already been destroyed, ignore.
@ -1179,7 +1186,7 @@ void Http2Session::HandlePriorityFrame(const nghttp2_frame* frame) {
nghttp2_priority priority_frame = frame->priority;
int32_t id = GetFrameID(frame);
DEBUG_HTTP2SESSION2(this, "handle priority frame for stream %d", id);
Debug(this, "handle priority frame for stream %d", id);
// Priority frame stream ID should never be <= 0. nghttp2 handles this for us
nghttp2_priority_spec spec = priority_frame.pri_spec;
@ -1198,7 +1205,7 @@ void Http2Session::HandlePriorityFrame(const nghttp2_frame* frame) {
// is set), then we'll terminate the readable side of the StreamBase.
void Http2Session::HandleDataFrame(const nghttp2_frame* frame) {
int32_t id = GetFrameID(frame);
DEBUG_HTTP2SESSION2(this, "handling data frame for stream %d", id);
Debug(this, "handling data frame for stream %d", id);
Http2Stream* stream = FindStream(id);
if (!stream->IsDestroyed() && frame->hd.flags & NGHTTP2_FLAG_END_STREAM)
@ -1214,7 +1221,7 @@ void Http2Session::HandleGoawayFrame(const nghttp2_frame* frame) {
Context::Scope context_scope(context);
nghttp2_goaway goaway_frame = frame->goaway;
DEBUG_HTTP2SESSION(this, "handling goaway frame");
Debug(this, "handling goaway frame");
Local<Value> argv[3] = {
Integer::NewFromUnsigned(isolate, goaway_frame.error_code),
@ -1243,7 +1250,7 @@ void Http2Session::HandleAltSvcFrame(const nghttp2_frame* frame) {
nghttp2_extension ext = frame->ext;
nghttp2_ext_altsvc* altsvc = static_cast<nghttp2_ext_altsvc*>(ext.payload);
DEBUG_HTTP2SESSION(this, "handling altsvc frame");
Debug(this, "handling altsvc frame");
Local<Value> argv[3] = {
Integer::New(isolate, id),
@ -1317,7 +1324,7 @@ void Http2Session::HandleSettingsFrame(const nghttp2_frame* frame) {
// Callback used when data has been written to the stream.
void Http2Session::OnStreamAfterWrite(WriteWrap* w, int status) {
DEBUG_HTTP2SESSION2(this, "write finished with status %d", status);
Debug(this, "write finished with status %d", status);
// Inform all pending writes about their completion.
ClearOutgoing(status);
@ -1336,7 +1343,7 @@ void Http2Session::MaybeScheduleWrite() {
CHECK_EQ(flags_ & SESSION_STATE_WRITE_SCHEDULED, 0);
if (session_ != nullptr && nghttp2_session_want_write(session_)) {
HandleScope handle_scope(env()->isolate());
DEBUG_HTTP2SESSION(this, "scheduling write");
Debug(this, "scheduling write");
flags_ |= SESSION_STATE_WRITE_SCHEDULED;
env()->SetImmediate([](Environment* env, void* data) {
Http2Session* session = static_cast<Http2Session*>(data);
@ -1359,7 +1366,7 @@ void Http2Session::MaybeScheduleWrite() {
void Http2Session::MaybeStopReading() {
int want_read = nghttp2_session_want_read(session_);
DEBUG_HTTP2SESSION2(this, "wants read? %d", want_read);
Debug(this, "wants read? %d", want_read);
if (want_read == 0)
stream_->ReadStop();
}
@ -1422,7 +1429,7 @@ void Http2Session::CopyDataIntoOutgoing(const uint8_t* src, size_t src_length) {
// This is a potential performance optimization target later.
// Returns non-zero value if a write is already in progress.
uint8_t Http2Session::SendPendingData() {
DEBUG_HTTP2SESSION(this, "sending pending data");
Debug(this, "sending pending data");
// Do not attempt to send data on the socket if the destroying flag has
// been set. That means everything is shutting down and the socket
// will not be usable.
@ -1445,7 +1452,7 @@ uint8_t Http2Session::SendPendingData() {
// Part One: Gather data from nghttp2
while ((src_length = nghttp2_session_mem_send(session_, &src)) > 0) {
DEBUG_HTTP2SESSION2(this, "nghttp2 has %d bytes to send", src_length);
Debug(this, "nghttp2 has %d bytes to send", src_length);
CopyDataIntoOutgoing(src, src_length);
}
@ -1521,7 +1528,7 @@ int Http2Session::OnSendData(
session->CopyDataIntoOutgoing(&padding_byte, 1);
}
DEBUG_HTTP2SESSION2(session, "nghttp2 has %d bytes to send directly", length);
Debug(session, "nghttp2 has %d bytes to send directly", length);
while (length > 0) {
// nghttp2 thinks that there is data available (length > 0), which means
// we told it so, which means that we *should* have data available.
@ -1562,7 +1569,7 @@ Http2Stream* Http2Session::SubmitRequest(
size_t len,
int32_t* ret,
int options) {
DEBUG_HTTP2SESSION(this, "submitting request");
Debug(this, "submitting request");
Http2Scope h2scope(this);
Http2Stream* stream = nullptr;
Http2Stream::Provider::Stream prov(options);
@ -1579,7 +1586,7 @@ void Http2Session::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
Context::Scope context_scope(env()->context());
Http2Scope h2scope(this);
CHECK_NOT_NULL(stream_);
DEBUG_HTTP2SESSION2(this, "receiving %d bytes", nread);
Debug(this, "receiving %d bytes", nread);
IncrementCurrentSessionMemory(buf.len);
CHECK(stream_buf_ab_.IsEmpty());
@ -1619,7 +1626,7 @@ void Http2Session::OnStreamRead(ssize_t nread, const uv_buf_t& buf) {
ssize_t ret = Write(&stream_buf_, 1);
if (ret < 0) {
DEBUG_HTTP2SESSION2(this, "fatal error receiving data: %d", ret);
Debug(this, "fatal error receiving data: %d", ret);
Local<Value> argv[] = {
Integer::New(isolate, ret),
@ -1653,7 +1660,7 @@ bool Http2Session::HasWritesOnSocketForStream(Http2Stream* stream) {
void Http2Session::Consume(Local<External> external) {
StreamBase* stream = static_cast<StreamBase*>(external->Value());
stream->PushStreamListener(this);
DEBUG_HTTP2SESSION(this, "i/o stream consumed");
Debug(this, "i/o stream consumed");
}
@ -1699,16 +1706,22 @@ Http2Stream::Http2Stream(
Http2Stream::~Http2Stream() {
DEBUG_HTTP2STREAM(this, "tearing down stream");
Debug(this, "tearing down stream");
if (session_ != nullptr) {
session_->RemoveStream(this);
session_ = nullptr;
}
}
std::string Http2Stream::diagnostic_name() const {
return "HttpStream " + std::to_string(id()) + " (" +
std::to_string(static_cast<int64_t>(get_async_id())) + ") [" +
session()->diagnostic_name() + "]";
}
// Notify the Http2Stream that a new block of HEADERS is being processed.
void Http2Stream::StartHeaders(nghttp2_headers_category category) {
DEBUG_HTTP2STREAM2(this, "starting headers, category: %d", id_, category);
Debug(this, "starting headers, category: %d", id_, category);
CHECK(!this->IsDestroyed());
current_headers_length_ = 0;
current_headers_.clear();
@ -1724,7 +1737,7 @@ void Http2Stream::Close(int32_t code) {
CHECK(!this->IsDestroyed());
flags_ |= NGHTTP2_STREAM_FLAG_CLOSED;
code_ = code;
DEBUG_HTTP2STREAM2(this, "closed with code %d", code);
Debug(this, "closed with code %d", code);
}
int Http2Stream::DoShutdown(ShutdownWrap* req_wrap) {
@ -1736,7 +1749,7 @@ int Http2Stream::DoShutdown(ShutdownWrap* req_wrap) {
flags_ |= NGHTTP2_STREAM_FLAG_SHUT;
CHECK_NE(nghttp2_session_resume_data(**session_, id_),
NGHTTP2_ERR_NOMEM);
DEBUG_HTTP2STREAM(this, "writable side shutdown");
Debug(this, "writable side shutdown");
}
req_wrap->Done(0);
return 0;
@ -1751,7 +1764,7 @@ void Http2Stream::Destroy() {
return;
flags_ |= NGHTTP2_STREAM_FLAG_DESTROYED;
DEBUG_HTTP2STREAM(this, "destroying stream");
Debug(this, "destroying stream");
// Wait until the start of the next loop to delete because there
// may still be some pending operations queued for this stream.
@ -1787,7 +1800,7 @@ void Http2Stream::Destroy() {
int Http2Stream::SubmitResponse(nghttp2_nv* nva, size_t len, int options) {
CHECK(!this->IsDestroyed());
Http2Scope h2scope(this);
DEBUG_HTTP2STREAM(this, "submitting response");
Debug(this, "submitting response");
if (options & STREAM_OPTION_GET_TRAILERS)
flags_ |= NGHTTP2_STREAM_FLAG_TRAILERS;
@ -1805,7 +1818,7 @@ int Http2Stream::SubmitResponse(nghttp2_nv* nva, size_t len, int options) {
int Http2Stream::SubmitInfo(nghttp2_nv* nva, size_t len) {
CHECK(!this->IsDestroyed());
Http2Scope h2scope(this);
DEBUG_HTTP2STREAM2(this, "sending %d informational headers", len);
Debug(this, "sending %d informational headers", len);
int ret = nghttp2_submit_headers(**session_,
NGHTTP2_FLAG_NONE,
id_, nullptr,
@ -1815,7 +1828,7 @@ int Http2Stream::SubmitInfo(nghttp2_nv* nva, size_t len) {
}
void Http2Stream::OnTrailers() {
DEBUG_HTTP2STREAM(this, "let javascript know we are ready for trailers");
Debug(this, "let javascript know we are ready for trailers");
CHECK(!this->IsDestroyed());
Isolate* isolate = env()->isolate();
HandleScope scope(isolate);
@ -1829,7 +1842,7 @@ void Http2Stream::OnTrailers() {
int Http2Stream::SubmitTrailers(nghttp2_nv* nva, size_t len) {
CHECK(!this->IsDestroyed());
Http2Scope h2scope(this);
DEBUG_HTTP2STREAM2(this, "sending %d trailers", len);
Debug(this, "sending %d trailers", len);
int ret;
// Sending an empty trailers frame poses problems in Safari, Edge & IE.
// Instead we can just send an empty data frame with NGHTTP2_FLAG_END_STREAM
@ -1849,7 +1862,7 @@ int Http2Stream::SubmitPriority(nghttp2_priority_spec* prispec,
bool silent) {
CHECK(!this->IsDestroyed());
Http2Scope h2scope(this);
DEBUG_HTTP2STREAM(this, "sending priority spec");
Debug(this, "sending priority spec");
int ret = silent ?
nghttp2_session_change_stream_priority(**session_,
id_, prispec) :
@ -1893,7 +1906,7 @@ Http2Stream* Http2Stream::SubmitPushPromise(nghttp2_nv* nva,
int options) {
CHECK(!this->IsDestroyed());
Http2Scope h2scope(this);
DEBUG_HTTP2STREAM(this, "sending push promise");
Debug(this, "sending push promise");
*ret = nghttp2_submit_push_promise(**session_, NGHTTP2_FLAG_NONE,
id_, nva, len, nullptr);
CHECK_NE(*ret, NGHTTP2_ERR_NOMEM);
@ -1912,7 +1925,7 @@ int Http2Stream::ReadStart() {
flags_ |= NGHTTP2_STREAM_FLAG_READ_START;
flags_ &= ~NGHTTP2_STREAM_FLAG_READ_PAUSED;
DEBUG_HTTP2STREAM(this, "reading starting");
Debug(this, "reading starting");
// Tell nghttp2 about our consumption of the data that was handed
// off to JS land.
@ -1930,7 +1943,7 @@ int Http2Stream::ReadStop() {
if (!IsReading())
return 0;
flags_ |= NGHTTP2_STREAM_FLAG_READ_PAUSED;
DEBUG_HTTP2STREAM(this, "reading stopped");
Debug(this, "reading stopped");
return 0;
}
@ -1955,7 +1968,7 @@ int Http2Stream::DoWrite(WriteWrap* req_wrap,
req_wrap->Done(UV_EOF);
return 0;
}
DEBUG_HTTP2STREAM2(this, "queuing %d buffers to send", id_, nbufs);
Debug(this, "queuing %d buffers to send", id_, nbufs);
for (size_t i = 0; i < nbufs; ++i) {
// Store the req_wrap on the last write info in the queue, so that it is
// only marked as finished once all buffers associated with it are finished.
@ -2036,7 +2049,7 @@ ssize_t Http2Stream::Provider::Stream::OnRead(nghttp2_session* handle,
nghttp2_data_source* source,
void* user_data) {
Http2Session* session = static_cast<Http2Session*>(user_data);
DEBUG_HTTP2SESSION2(session, "reading outbound data for stream %d", id);
Debug(session, "reading outbound data for stream %d", id);
Http2Stream* stream = GetStream(session, id, source);
if (stream->statistics_.first_byte_sent == 0)
stream->statistics_.first_byte_sent = uv_hrtime();
@ -2056,10 +2069,9 @@ ssize_t Http2Stream::Provider::Stream::OnRead(nghttp2_session* handle,
}
if (!stream->queue_.empty()) {
DEBUG_HTTP2SESSION2(session, "stream %d has pending outbound data", id);
Debug(session, "stream %d has pending outbound data", id);
amount = std::min(stream->available_outbound_length_, length);
DEBUG_HTTP2SESSION2(session, "sending %d bytes for data frame on stream %d",
amount, id);
Debug(session, "sending %d bytes for data frame on stream %d", amount, id);
if (amount > 0) {
// Just return the length, let Http2Session::OnSendData take care of
// actually taking the buffers out of the queue.
@ -2070,7 +2082,7 @@ ssize_t Http2Stream::Provider::Stream::OnRead(nghttp2_session* handle,
if (amount == 0 && stream->IsWritable()) {
CHECK(stream->queue_.empty());
DEBUG_HTTP2SESSION2(session, "deferring stream %d", id);
Debug(session, "deferring stream %d", id);
stream->EmitWantsWrite(length);
if (stream->available_outbound_length_ > 0 || !stream->IsWritable()) {
// EmitWantsWrite() did something interesting synchronously, restart:
@ -2080,7 +2092,7 @@ ssize_t Http2Stream::Provider::Stream::OnRead(nghttp2_session* handle,
}
if (stream->queue_.empty() && !stream->IsWritable()) {
DEBUG_HTTP2SESSION2(session, "no more data for stream %d", id);
Debug(session, "no more data for stream %d", id);
*flags |= NGHTTP2_DATA_FLAG_EOF;
if (stream->HasTrailers()) {
*flags |= NGHTTP2_DATA_FLAG_NO_END_STREAM;
@ -2142,11 +2154,11 @@ void Http2Session::SetNextStreamID(const FunctionCallbackInfo<Value>& args) {
ASSIGN_OR_RETURN_UNWRAP(&session, args.Holder());
int32_t id = args[0]->Int32Value(env->context()).ToChecked();
if (nghttp2_session_set_next_stream_id(**session, id) < 0) {
DEBUG_HTTP2SESSION2(session, "failed to set next stream id to %d", id);
Debug(session, "failed to set next stream id to %d", id);
return args.GetReturnValue().Set(false);
}
args.GetReturnValue().Set(true);
DEBUG_HTTP2SESSION2(session, "set next stream id to %d", id);
Debug(session, "set next stream id to %d", id);
}
// A TypedArray instance is shared between C++ and JS land to contain the
@ -2158,7 +2170,7 @@ void Http2Session::RefreshSettings(const FunctionCallbackInfo<Value>& args) {
Http2Session* session;
ASSIGN_OR_RETURN_UNWRAP(&session, args.Holder());
Http2Settings::Update(env, session, fn);
DEBUG_HTTP2SESSION(session, "settings refreshed for session");
Debug(session, "settings refreshed for session");
}
// A TypedArray instance is shared between C++ and JS land to contain state
@ -2168,7 +2180,7 @@ void Http2Session::RefreshState(const FunctionCallbackInfo<Value>& args) {
Environment* env = Environment::GetCurrent(args);
Http2Session* session;
ASSIGN_OR_RETURN_UNWRAP(&session, args.Holder());
DEBUG_HTTP2SESSION(session, "refreshing state");
Debug(session, "refreshing state");
AliasedBuffer<double, Float64Array>& buffer =
env->http2_state()->session_state_buffer;
@ -2204,7 +2216,7 @@ void Http2Session::New(const FunctionCallbackInfo<Value>& args) {
nghttp2_session_type type = static_cast<nghttp2_session_type>(val);
Http2Session* session = new Http2Session(env, args.This(), type);
session->get_async_id(); // avoid compiler warning
DEBUG_HTTP2SESSION(session, "session created");
Debug(session, "session created");
}
@ -2220,7 +2232,7 @@ void Http2Session::Consume(const FunctionCallbackInfo<Value>& args) {
void Http2Session::Destroy(const FunctionCallbackInfo<Value>& args) {
Http2Session* session;
ASSIGN_OR_RETURN_UNWRAP(&session, args.Holder());
DEBUG_HTTP2SESSION(session, "destroying session");
Debug(session, "destroying session");
Environment* env = Environment::GetCurrent(args);
Local<Context> context = env->context();
@ -2245,7 +2257,7 @@ void Http2Session::Request(const FunctionCallbackInfo<Value>& args) {
Headers list(isolate, context, headers);
DEBUG_HTTP2SESSION(session, "request submitted");
Debug(session, "request submitted");
int32_t ret = 0;
Http2Stream* stream =
@ -2253,13 +2265,11 @@ void Http2Session::Request(const FunctionCallbackInfo<Value>& args) {
&ret, options);
if (ret <= 0) {
DEBUG_HTTP2SESSION2(session, "could not submit request: %s",
nghttp2_strerror(ret));
Debug(session, "could not submit request: %s", nghttp2_strerror(ret));
return args.GetReturnValue().Set(ret);
}
DEBUG_HTTP2SESSION2(session, "request submitted, new stream id %d",
stream->id());
Debug(session, "request submitted, new stream id %d", stream->id());
args.GetReturnValue().Set(stream->object());
}
@ -2277,7 +2287,7 @@ void Http2Session::Goaway(uint32_t code,
// the last proc stream id is the most recently created Http2Stream.
if (lastStreamID <= 0)
lastStreamID = nghttp2_session_get_last_proc_stream_id(session_);
DEBUG_HTTP2SESSION(this, "submitting goaway");
Debug(this, "submitting goaway");
nghttp2_submit_goaway(session_, NGHTTP2_FLAG_NONE,
lastStreamID, code, data, len);
}
@ -2332,7 +2342,7 @@ void Http2Stream::RstStream(const FunctionCallbackInfo<Value>& args) {
Http2Stream* stream;
ASSIGN_OR_RETURN_UNWRAP(&stream, args.Holder());
uint32_t code = args[0]->Uint32Value(context).ToChecked();
DEBUG_HTTP2STREAM2(stream, "sending rst_stream with code %d", code);
Debug(stream, "sending rst_stream with code %d", code);
stream->SubmitRstStream(code);
}
@ -2352,7 +2362,7 @@ void Http2Stream::Respond(const FunctionCallbackInfo<Value>& args) {
args.GetReturnValue().Set(
stream->SubmitResponse(*list, list.length(), options));
DEBUG_HTTP2STREAM(stream, "response submitted");
Debug(stream, "response submitted");
}
@ -2368,7 +2378,7 @@ void Http2Stream::Info(const FunctionCallbackInfo<Value>& args) {
Headers list(isolate, context, headers);
args.GetReturnValue().Set(stream->SubmitInfo(*list, list.length()));
DEBUG_HTTP2STREAM2(stream, "%d informational headers sent", list.length());
Debug(stream, "%d informational headers sent", list.length());
}
// Submits trailing headers on the Http2Stream
@ -2383,7 +2393,7 @@ void Http2Stream::Trailers(const FunctionCallbackInfo<Value>& args) {
Headers list(isolate, context, headers);
args.GetReturnValue().Set(stream->SubmitTrailers(*list, list.length()));
DEBUG_HTTP2STREAM2(stream, "%d trailing headers sent", list.length());
Debug(stream, "%d trailing headers sent", list.length());
}
// Grab the numeric id of the Http2Stream
@ -2397,7 +2407,7 @@ void Http2Stream::GetID(const FunctionCallbackInfo<Value>& args) {
void Http2Stream::Destroy(const FunctionCallbackInfo<Value>& args) {
Http2Stream* stream;
ASSIGN_OR_RETURN_UNWRAP(&stream, args.Holder());
DEBUG_HTTP2STREAM(stream, "destroying stream");
Debug(stream, "destroying stream");
stream->Destroy();
}
@ -2406,7 +2416,7 @@ void Http2Stream::FlushData(const FunctionCallbackInfo<Value>& args) {
Http2Stream* stream;
ASSIGN_OR_RETURN_UNWRAP(&stream, args.Holder());
stream->ReadStart();
DEBUG_HTTP2STREAM(stream, "data flushed to js");
Debug(stream, "data flushed to js");
}
// Initiate a Push Promise and create the associated Http2Stream
@ -2422,16 +2432,16 @@ void Http2Stream::PushPromise(const FunctionCallbackInfo<Value>& args) {
Headers list(isolate, context, headers);
DEBUG_HTTP2STREAM(parent, "creating push promise");
Debug(parent, "creating push promise");
int32_t ret = 0;
Http2Stream* stream = parent->SubmitPushPromise(*list, list.length(),
&ret, options);
if (ret <= 0) {
DEBUG_HTTP2STREAM2(parent, "failed to create push stream: %d", ret);
Debug(parent, "failed to create push stream: %d", ret);
return args.GetReturnValue().Set(ret);
}
DEBUG_HTTP2STREAM2(parent, "push stream %d created", stream->id());
Debug(parent, "push stream %d created", stream->id());
args.GetReturnValue().Set(stream->object());
}
@ -2446,7 +2456,7 @@ void Http2Stream::Priority(const FunctionCallbackInfo<Value>& args) {
bool silent = args[3]->BooleanValue(context).ToChecked();
CHECK_EQ(stream->SubmitPriority(*priority, silent), 0);
DEBUG_HTTP2STREAM(stream, "priority submitted");
Debug(stream, "priority submitted");
}
// A TypedArray shared by C++ and JS land is used to communicate state
@ -2457,7 +2467,7 @@ void Http2Stream::RefreshState(const FunctionCallbackInfo<Value>& args) {
Http2Stream* stream;
ASSIGN_OR_RETURN_UNWRAP(&stream, args.Holder());
DEBUG_HTTP2STREAM(stream, "refreshing state");
Debug(stream, "refreshing state");
AliasedBuffer<double, Float64Array>& buffer =
env->http2_state()->stream_state_buffer;

60
src/node_http2.h
View File

@ -21,61 +21,6 @@ using v8::MaybeLocal;
using performance::PerformanceEntry;
#ifdef NODE_DEBUG_HTTP2
// Adapted from nghttp2 own debug printer
static inline void _debug_vfprintf(const char* fmt, va_list args) {
vfprintf(stderr, fmt, args);
}
void inline debug_vfprintf(const char* format, ...) {
va_list args;
va_start(args, format);
_debug_vfprintf(format, args);
va_end(args);
}
#define DEBUG_HTTP2(...) debug_vfprintf(__VA_ARGS__);
#define DEBUG_HTTP2SESSION(session, message) \
do { \
if (session != nullptr) { \
DEBUG_HTTP2("Http2Session %s (%.0lf) " message "\n", \
session->TypeName(), \
session->get_async_id()); \
} \
} while (0)
#define DEBUG_HTTP2SESSION2(session, message, ...) \
do { \
if (session != nullptr) { \
DEBUG_HTTP2("Http2Session %s (%.0lf) " message "\n", \
session->TypeName(), \
session->get_async_id(), \
__VA_ARGS__); \
} \
} while (0)
#define DEBUG_HTTP2STREAM(stream, message) \
do { \
DEBUG_HTTP2("Http2Stream %d (%.0lf) [Http2Session %s (%.0lf)] " message \
"\n", stream->id(), stream->get_async_id(), \
stream->session()->TypeName(), \
stream->session()->get_async_id()); \
} while (0)
#define DEBUG_HTTP2STREAM2(stream, message, ...) \
do { \
DEBUG_HTTP2("Http2Stream %d (%.0lf) [Http2Session %s (%.0lf)] " message \
"\n", stream->id(), stream->get_async_id(), \
stream->session()->TypeName(), \
stream->session()->get_async_id(), \
__VA_ARGS__); \
} while (0)
#else
#define DEBUG_HTTP2(...) do {} while (0)
#define DEBUG_HTTP2SESSION(...) do {} while (0)
#define DEBUG_HTTP2SESSION2(...) do {} while (0)
#define DEBUG_HTTP2STREAM(...) do {} while (0)
#define DEBUG_HTTP2STREAM2(...) do {} while (0)
#endif
// We strictly limit the number of outstanding unacknowledged PINGS a user
// may send in order to prevent abuse. The current default cap is 10. The
// user may set a different limit using a per Http2Session configuration
@ -557,6 +502,7 @@ class Http2Stream : public AsyncWrap,
nghttp2_stream* operator*();
Http2Session* session() { return session_; }
const Http2Session* session() const { return session_; }
void EmitStatistics();
@ -675,6 +621,7 @@ class Http2Stream : public AsyncWrap,
uv_stream_t* send_handle) override;
size_t self_size() const override { return sizeof(*this); }
std::string diagnostic_name() const override;
// JavaScript API
static void GetID(const FunctionCallbackInfo<Value>& args);
@ -819,7 +766,7 @@ class Http2Session : public AsyncWrap, public StreamListener {
inline uint32_t GetMaxHeaderPairs() const { return max_header_pairs_; }
inline const char* TypeName();
inline const char* TypeName() const;
inline bool IsDestroyed() {
return (flags_ & SESSION_STATE_CLOSED) || session_ == nullptr;
@ -849,6 +796,7 @@ class Http2Session : public AsyncWrap, public StreamListener {
ssize_t Write(const uv_buf_t* bufs, size_t nbufs);
size_t self_size() const override { return sizeof(*this); }
std::string diagnostic_name() const override;
// Schedule an RstStream for after the current write finishes.
inline void AddPendingRstStream(int32_t stream_id) {

18
test/parallel/test-http2-debug.js Normal file
View File

@ -0,0 +1,18 @@
'use strict';
require('../common');
const assert = require('assert');
const child_process = require('child_process');
const path = require('path');
process.env.NODE_DEBUG_NATIVE = 'http2';
const { stdout, stderr } = child_process.spawnSync(process.execPath, [
path.resolve(__dirname, 'test-http2-ping.js')
], { encoding: 'utf8' });
assert(stderr.match(/Http2Session client \(\d+\) handling data frame for stream \d+/),
stderr);
assert(stderr.match(/HttpStream \d+ \(\d+\) \[Http2Session client \(\d+\)\] reading starting/),
stderr);
assert(stderr.match(/HttpStream \d+ \(\d+\) \[Http2Session server \(\d+\)\] tearing down stream/),
stderr);
assert.strictEqual(stdout.trim(), '');

1
vcbuild.bat
View File

@ -114,7 +114,6 @@ if /i "%1"=="enable-vtune" set enable_vtune_arg=1&goto arg-ok
if /i "%1"=="dll" set dll=1&goto arg-ok
if /i "%1"=="static" set enable_static=1&goto arg-ok
if /i "%1"=="no-NODE-OPTIONS" set no_NODE_OPTIONS=1&goto arg-ok
if /i "%1"=="debug-http2" set debug_http2=1&goto arg-ok
if /i "%1"=="debug-nghttp2" set debug_nghttp2=1&goto arg-ok
if /i "%1"=="link-module" set "link_module= --link-module=%2%link_module%"&goto arg-ok-2
if /i "%1"=="no-cctest" set no_cctest=1&goto arg-ok