diff --git a/configure b/configure index 17e13a48d47e5a..c4dda999fd23c8 100755 --- a/configure +++ b/configure @@ -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: diff --git a/node.gyp b/node.gyp index f1dc3997b76e47..008e415a0579f0 100644 --- a/node.gyp +++ b/node.gyp @@ -374,6 +374,7 @@ 'src/base_object-inl.h', 'src/connection_wrap.h', 'src/connect_wrap.h', + 'src/debug_utils.h', 'src/env.h', 'src/env-inl.h', 'src/handle_wrap.h', diff --git a/node.gypi b/node.gypi index fd7c70a12b15f4..acd9f83213021d 100644 --- a/node.gypi +++ b/node.gypi @@ -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': [ diff --git a/src/async_wrap.cc b/src/async_wrap.cc index 51db615f703f85..11ce5a387a950c 100644 --- a/src/async_wrap.cc +++ b/src/async_wrap.cc @@ -769,6 +769,11 @@ void EmitAsyncDestroy(Isolate* isolate, async_context asyncContext) { Environment::GetCurrent(isolate), asyncContext.async_id); } +std::string AsyncWrap::diagnostic_name() const { + return std::string(provider_names[provider_type()]) + + " (" + std::to_string(static_cast(async_id_)) + ")"; +} + } // namespace node NODE_BUILTIN_MODULE_CONTEXT_AWARE(async_wrap, node::AsyncWrap::Initialize) diff --git a/src/async_wrap.h b/src/async_wrap.h index 17017ab602c84a..451bcfe12e6717 100644 --- a/src/async_wrap.h +++ b/src/async_wrap.h @@ -167,6 +167,7 @@ class AsyncWrap : public BaseObject { v8::Local* argv); virtual size_t self_size() const = 0; + virtual std::string diagnostic_name() const; static void WeakCallback(const v8::WeakCallbackInfo &info); diff --git a/src/debug_utils.h b/src/debug_utils.h new file mode 100644 index 00000000000000..f10342c79d35be --- /dev/null +++ b/src/debug_utils.h @@ -0,0 +1,92 @@ +#ifndef SRC_DEBUG_UTILS_H_ +#define SRC_DEBUG_UTILS_H_ + +#if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#include "async_wrap.h" +#include "env.h" +#include + +// Use FORCE_INLINE on functions that have a debug-category-enabled check first +// and then ideally only a single function call following it, to maintain +// performance for the common case (no debugging used). +#ifdef __GNUC__ +#define FORCE_INLINE __attribute__((always_inline)) +#define COLD_NOINLINE __attribute__((cold, noinline)) +#else +#define FORCE_INLINE +#define COLD_NOINLINE +#endif + +namespace node { + +template +inline void FORCE_INLINE Debug(Environment* env, + DebugCategory cat, + const char* format, + Args&&... args) { + if (!UNLIKELY(env->debug_enabled(cat))) + return; + fprintf(stderr, format, std::forward(args)...); +} + +inline void FORCE_INLINE Debug(Environment* env, + DebugCategory cat, + const char* message) { + if (!UNLIKELY(env->debug_enabled(cat))) + return; + fprintf(stderr, "%s", message); +} + +template +inline void Debug(Environment* env, + DebugCategory cat, + const std::string& format, + Args&&... args) { + Debug(env, cat, format.c_str(), std::forward(args)...); +} + +// Used internally by the 'real' Debug(AsyncWrap*, ...) functions below, so that +// the FORCE_INLINE flag on them doesn't apply to the contents of this function +// as well. +// We apply COLD_NOINLINE to tell the compiler that it's not worth optimizing +// this function for speed and it should rather focus on keeping it out of +// hot code paths. In particular, we want to keep the string concatenating code +// out of the function containing the original `Debug()` call. +template +void COLD_NOINLINE UnconditionalAsyncWrapDebug(AsyncWrap* async_wrap, + const char* format, + Args&&... args) { + Debug(async_wrap->env(), + static_cast(async_wrap->provider_type()), + async_wrap->diagnostic_name() + " " + format + "\n", + std::forward(args)...); +} + +template +inline void FORCE_INLINE Debug(AsyncWrap* async_wrap, + const char* format, + Args&&... args) { +#ifdef DEBUG + CHECK_NOT_NULL(async_wrap); +#endif + DebugCategory cat = + static_cast(async_wrap->provider_type()); + if (!UNLIKELY(async_wrap->env()->debug_enabled(cat))) + return; + UnconditionalAsyncWrapDebug(async_wrap, format, std::forward(args)...); +} + +template +inline void FORCE_INLINE Debug(AsyncWrap* async_wrap, + const std::string& format, + Args&&... args) { + Debug(async_wrap, format.c_str(), std::forward(args)...); +} + + +} // namespace node + +#endif // defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS + +#endif // SRC_DEBUG_UTILS_H_ diff --git a/src/env-inl.h b/src/env-inl.h index a965bd195ef850..cb8d0c4efe0405 100644 --- a/src/env-inl.h +++ b/src/env-inl.h @@ -519,6 +519,24 @@ inline void Environment::set_http2_state( http2_state_ = std::move(buffer); } +bool Environment::debug_enabled(DebugCategory category) const { +#ifdef DEBUG + CHECK_GE(static_cast(category), 0); + CHECK_LT(static_cast(category), + static_cast(DebugCategory::CATEGORY_COUNT)); +#endif + return debug_enabled_[static_cast(category)]; +} + +void Environment::set_debug_enabled(DebugCategory category, bool enabled) { +#ifdef DEBUG + CHECK_GE(static_cast(category), 0); + CHECK_LT(static_cast(category), + static_cast(DebugCategory::CATEGORY_COUNT)); +#endif + debug_enabled_[static_cast(category)] = enabled; +} + inline AliasedBuffer* Environment::fs_stats_field_array() { return &fs_stats_field_array_; diff --git a/src/env.cc b/src/env.cc index 2fa4432c54d4e9..f6303e6011f54c 100644 --- a/src/env.cc +++ b/src/env.cc @@ -130,6 +130,10 @@ Environment::Environment(IsolateData* isolate_data, // By default, always abort when --abort-on-uncaught-exception was passed. should_abort_on_uncaught_toggle_[0] = 1; + + std::string debug_cats; + SafeGetenv("NODE_DEBUG_NATIVE", &debug_cats); + set_debug_categories(debug_cats, true); } Environment::~Environment() { @@ -496,6 +500,28 @@ Local Environment::GetNow() { } +void Environment::set_debug_categories(const std::string& cats, bool enabled) { + std::string debug_categories = cats; + while (!debug_categories.empty()) { + std::string::size_type comma_pos = debug_categories.find(','); + std::string wanted = ToLower(debug_categories.substr(0, comma_pos)); + +#define V(name) \ + { \ + static const std::string available_category = ToLower(#name); \ + if (available_category.find(wanted) != std::string::npos) \ + set_debug_enabled(DebugCategory::name, enabled); \ + } + + DEBUG_CATEGORY_NAMES(V) + + if (comma_pos == std::string::npos) + break; + // Use everything after the `,` as the list for the next iteration. + debug_categories = debug_categories.substr(comma_pos); + } +} + void CollectExceptionInfo(Environment* env, v8::Local obj, int errorno, diff --git a/src/env.h b/src/env.h index 15d417ba606860..c17cc59b5b5ccd 100644 --- a/src/env.h +++ b/src/env.h @@ -398,6 +398,19 @@ struct ContextInfo { bool is_default = false; }; +// Listing the AsyncWrap provider types first enables us to cast directly +// from a provider type to a debug category. Currently no other debug +// categories are available. +#define DEBUG_CATEGORY_NAMES(V) \ + NODE_ASYNC_PROVIDER_TYPES(V) + +enum class DebugCategory { +#define V(name) name, + DEBUG_CATEGORY_NAMES(V) +#undef V + CATEGORY_COUNT +}; + class Environment { public: class AsyncHooks { @@ -654,6 +667,10 @@ class Environment { inline http2::Http2State* http2_state() const; inline void set_http2_state(std::unique_ptr state); + inline bool debug_enabled(DebugCategory category) const; + inline void set_debug_enabled(DebugCategory category, bool enabled); + void set_debug_categories(const std::string& cats, bool enabled); + inline AliasedBuffer* fs_stats_field_array(); // stat fields contains twice the number of entries because `fs.StatWatcher` @@ -853,6 +870,8 @@ class Environment { bool http_parser_buffer_in_use_ = false; std::unique_ptr http2_state_; + bool debug_enabled_[static_cast(DebugCategory::CATEGORY_COUNT)] = {0}; + AliasedBuffer fs_stats_field_array_; std::vector> diff --git a/src/node.cc b/src/node.cc index 008e7ed599ed70..f927c0d6f01994 100644 --- a/src/node.cc +++ b/src/node.cc @@ -3288,6 +3288,9 @@ static void PrintHelp() { "Environment variables:\n" "NODE_DEBUG ','-separated list of core modules\n" " that should print debug information\n" + "NODE_DEBUG_NATIVE ','-separated list of C++ core debug\n" + " categories that should print debug\n" + " output\n" "NODE_DISABLE_COLORS set to 1 to disable colors in the REPL\n" "NODE_EXTRA_CA_CERTS path to additional CA certificates\n" " file\n" diff --git a/src/node_http2.cc b/src/node_http2.cc index 42d7555fba2c51..0bfdec9a57e380 100644 --- a/src/node_http2.cc +++ b/src/node_http2.cc @@ -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(get_async_id())) + ")"; +} + inline bool HasHttp2Observer(Environment* env) { AliasedBuffer& 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 = 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(maxPayloadLen)); retval = std::max(retval, static_cast(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(bufs[n].base), @@ -751,7 +759,7 @@ int Http2Session::OnBeginHeadersCallback(nghttp2_session* handle, void* user_data) { Http2Session* session = static_cast(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(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(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(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 = 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(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(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 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(ext.payload); - DEBUG_HTTP2SESSION(this, "handling altsvc frame"); + Debug(this, "handling altsvc frame"); Local 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(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 argv[] = { Integer::New(isolate, ret), @@ -1653,7 +1660,7 @@ bool Http2Session::HasWritesOnSocketForStream(Http2Stream* stream) { void Http2Session::Consume(Local external) { StreamBase* stream = static_cast(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(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(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& 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& 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& 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& buffer = env->http2_state()->session_state_buffer; @@ -2204,7 +2216,7 @@ void Http2Session::New(const FunctionCallbackInfo& args) { nghttp2_session_type type = static_cast(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& args) { void Http2Session::Destroy(const FunctionCallbackInfo& 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 = env->context(); @@ -2245,7 +2257,7 @@ void Http2Session::Request(const FunctionCallbackInfo& 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& 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& 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& 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& 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& 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& args) { void Http2Stream::Destroy(const FunctionCallbackInfo& 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& 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& 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& 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& args) { Http2Stream* stream; ASSIGN_OR_RETURN_UNWRAP(&stream, args.Holder()); - DEBUG_HTTP2STREAM(stream, "refreshing state"); + Debug(stream, "refreshing state"); AliasedBuffer& buffer = env->http2_state()->stream_state_buffer; diff --git a/src/node_http2.h b/src/node_http2.h index 043449624fb120..824084d0bafdaf 100644 --- a/src/node_http2.h +++ b/src/node_http2.h @@ -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& 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) { diff --git a/src/util-inl.h b/src/util-inl.h index ff0d47c078815a..90c7447f7e105f 100644 --- a/src/util-inl.h +++ b/src/util-inl.h @@ -293,6 +293,13 @@ char ToLower(char c) { return c >= 'A' && c <= 'Z' ? c + ('a' - 'A') : c; } +std::string ToLower(const std::string& in) { + std::string out(in.size(), 0); + for (size_t i = 0; i < in.size(); ++i) + out[i] = ToLower(in[i]); + return out; +} + bool StringEqualNoCase(const char* a, const char* b) { do { if (*a == '\0') diff --git a/src/util.h b/src/util.h index 069f6d428e7751..e272286d3e4b96 100644 --- a/src/util.h +++ b/src/util.h @@ -34,6 +34,7 @@ #include #include +#include #include // std::function namespace node { @@ -250,6 +251,7 @@ inline void SwapBytes64(char* data, size_t nbytes); // tolower() is locale-sensitive. Use ToLower() instead. inline char ToLower(char c); +inline std::string ToLower(const std::string& in); // strcasecmp() is locale-sensitive. Use StringEqualNoCase() instead. inline bool StringEqualNoCase(const char* a, const char* b); diff --git a/test/parallel/test-http2-debug.js b/test/parallel/test-http2-debug.js new file mode 100644 index 00000000000000..f329a7e57e79dd --- /dev/null +++ b/test/parallel/test-http2-debug.js @@ -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(), ''); diff --git a/vcbuild.bat b/vcbuild.bat index 37df2c2531b2d5..c6921ab1915028 100644 --- a/vcbuild.bat +++ b/vcbuild.bat @@ -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