From 50c0bc1faeb23ab9487930bc476bd3f822b067e4 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Mon, 16 Oct 2017 20:08:57 -0700 Subject: [PATCH 1/3] inspector: track async stacks when necessary With this change, we do async stack tracking only when explicitly requested by the inspector client. This avoids unnecessary overhead for clients that might not be interested in async stack traces. Fixes: https://github.com/nodejs/node/issues/16180 --- lib/internal/inspector_async_hook.js | 6 - src/env.h | 4 + src/inspector_agent.cc | 160 +++++++++++++++--- src/inspector_agent.h | 6 + test/inspector/test-async-hook-inspector.js | 55 ++++++ .../test-async-hook-teardown-at-debug-end.js | 33 ---- 6 files changed, 198 insertions(+), 66 deletions(-) create mode 100644 test/inspector/test-async-hook-inspector.js delete mode 100644 test/inspector/test-async-hook-teardown-at-debug-end.js diff --git a/lib/internal/inspector_async_hook.js b/lib/internal/inspector_async_hook.js index e32a026cd69155..4ccf862697756d 100644 --- a/lib/internal/inspector_async_hook.js +++ b/lib/internal/inspector_async_hook.js @@ -55,10 +55,4 @@ function disable() { exports.setup = function() { inspector.registerAsyncHook(enable, disable); - - if (inspector.isEnabled()) { - // If the inspector was already enabled via --inspect or --inspect-brk, - // the we need to enable the async hook immediately at startup. - enable(); - } }; diff --git a/src/env.h b/src/env.h index 6e5e639744b118..427a1e01072774 100644 --- a/src/env.h +++ b/src/env.h @@ -101,6 +101,7 @@ class ModuleWrap; V(address_string, "address") \ V(args_string, "args") \ V(async, "async") \ + V(async_stack_depth_string, "Debugger.setAsyncCallStackDepth") \ V(buffer_string, "buffer") \ V(bytes_string, "bytes") \ V(bytes_parsed_string, "bytesParsed") \ @@ -185,7 +186,9 @@ class ModuleWrap; V(length_string, "length") \ V(mac_string, "mac") \ V(max_buffer_string, "maxBuffer") \ + V(max_depth_string, "maxDepth") \ V(message_string, "message") \ + V(method_string, "method") \ V(minttl_string, "minttl") \ V(model_string, "model") \ V(modulus_string, "modulus") \ @@ -228,6 +231,7 @@ class ModuleWrap; V(output_string, "output") \ V(order_string, "order") \ V(owner_string, "owner") \ + V(params_string, "params") \ V(parse_error_string, "Parse Error") \ V(path_string, "path") \ V(pbkdf2_error_string, "PBKDF2 Error") \ diff --git a/src/inspector_agent.cc b/src/inspector_agent.cc index 4828fa3071cc5b..e8fcf2bdd56d29 100644 --- a/src/inspector_agent.cc +++ b/src/inspector_agent.cc @@ -29,7 +29,10 @@ using v8::Function; using v8::HandleScope; using v8::Isolate; using v8::Local; +using v8::Maybe; +using v8::MaybeLocal; using v8::Object; +using v8::String; using v8::Value; using v8_inspector::StringBuffer; @@ -449,7 +452,9 @@ Agent::Agent(Environment* env) : parent_env_(env), client_(nullptr), platform_(nullptr), enabled_(false), - next_context_number_(1) {} + next_context_number_(1), + pending_enable_async_hook_(false), + pending_disable_async_hook_(false) {} // Destructor needs to be defined here in implementation file as the header // does not have full definition of some classes. @@ -497,18 +502,6 @@ bool Agent::StartIoThread(bool wait_for_connect) { v8::Isolate* isolate = parent_env_->isolate(); HandleScope handle_scope(isolate); - // Enable tracking of async stack traces - if (!enable_async_hook_function_.IsEmpty()) { - Local enable_fn = enable_async_hook_function_.Get(isolate); - auto context = parent_env_->context(); - auto result = enable_fn->Call(context, Undefined(isolate), 0, nullptr); - if (result.IsEmpty()) { - FatalError( - "node::InspectorAgent::StartIoThread", - "Cannot enable Inspector's AsyncHook, please report this."); - } - } - // Send message to enable debug in workers Local process_object = parent_env_->process_object(); Local emit_fn = @@ -554,20 +547,6 @@ void Agent::Stop() { } void Agent::Connect(InspectorSessionDelegate* delegate) { - if (!enabled_) { - // Enable tracking of async stack traces - v8::Isolate* isolate = parent_env_->isolate(); - HandleScope handle_scope(isolate); - auto context = parent_env_->context(); - Local enable_fn = enable_async_hook_function_.Get(isolate); - auto result = enable_fn->Call(context, Undefined(isolate), 0, nullptr); - if (result.IsEmpty()) { - FatalError( - "node::InspectorAgent::Connect", - "Cannot enable Inspector's AsyncHook, please report this."); - } - } - enabled_ = true; client_->connectFrontend(delegate); } @@ -593,6 +572,7 @@ void Agent::FatalException(Local error, Local message) { void Agent::Dispatch(const StringView& message) { CHECK_NE(client_, nullptr); + InterceptAsyncStackDepthMessage(message); client_->dispatchMessageFromFrontend(message); } @@ -625,6 +605,37 @@ void Agent::RegisterAsyncHook(Isolate* isolate, v8::Local disable_function) { enable_async_hook_function_.Reset(isolate, enable_function); disable_async_hook_function_.Reset(isolate, disable_function); + if (pending_enable_async_hook_) { + pending_enable_async_hook_ = false; + EnableAsyncHook(isolate); + } else if (pending_disable_async_hook_) { + pending_disable_async_hook_ = false; + DisableAsyncHook(isolate); + } +} + +void Agent::EnableAsyncHook(Isolate* isolate) { + CHECK(!enable_async_hook_function_.IsEmpty()); + Local enable_fn = enable_async_hook_function_.Get(isolate); + auto context = parent_env_->context(); + auto result = enable_fn->Call(context, Undefined(isolate), 0, nullptr); + if (result.IsEmpty()) { + FatalError( + "node::inspector::Agent::EnableAsyncHook", + "Cannot enable Inspector's AsyncHook, please report this."); + } +} + +void Agent::DisableAsyncHook(Isolate* isolate) { + CHECK(!disable_async_hook_function_.IsEmpty()); + Local disable_fn = disable_async_hook_function_.Get(isolate); + auto context = parent_env_->context(); + auto result = disable_fn->Call(context, Undefined(isolate), 0, nullptr); + if (result.IsEmpty()) { + FatalError( + "node::inspector::Agent::DisableAsyncHook", + "Cannot disable Inspector's AsyncHook, please report this."); + } } void Agent::AsyncTaskScheduled(const StringView& task_name, void* task, @@ -648,6 +659,101 @@ void Agent::AllAsyncTasksCanceled() { client_->AllAsyncTasksCanceled(); } +void Agent::InterceptAsyncStackDepthMessage(const StringView& message) { + // This logic would be better implemented in JavaScript, but when using + // --inspect-brk, the debugger must necessarily attach before much JavaScript + // can execute. The Debugger.setAsyncCallStackDepth message arrives too early + // and we must intercept this in C++. + + v8::Isolate* isolate = parent_env_->isolate(); + Local context = parent_env_->context(); + + MaybeLocal string = + String::NewFromTwoByte(isolate, message.characters16(), + v8::NewStringType::kNormal, message.length()); + if (string.IsEmpty()) { + return; + } + + // Basically, the logic we want to implement is: + // let parsed; try { + // parsed = JSON.parse(string); + // } catch (e) { return; } + // if (parsed && parsed.method && parsed.method === 'Debugger.setAsync..' && + // parsed.params && parsed.params.maxDepth && + // typeof parsed.params.maxDepth === 'number') { + // // Enable or Disable, depending on maxDepth. + // } + // + // We ignore (return early) on malformed messages and let v8-inspector deal + // with them. + + MaybeLocal maybe_parsed = + v8::JSON::Parse(context, string.ToLocalChecked()); + if (maybe_parsed.IsEmpty()) { + return; + } + + Local parsed = maybe_parsed.ToLocalChecked(); + if (!parsed->IsObject()) { + return; + } + + Local object = parsed.As(); + + Local method; + if (!object->Get(context, parent_env_->method_string()).ToLocal(&method) || + !method->IsString() || + !method->StrictEquals(parent_env_->async_stack_depth_string())) { + return; + } + + Local params; + if (!object->Get(context, parent_env_->params_string()).ToLocal(¶ms) || + !params->IsObject()) { + return; + } + + Local depth_value; + if (!params.As()->Get(context, parent_env_->max_depth_string()) + .ToLocal(&depth_value) || + !depth_value->IsNumber()) { + return; + } + + Maybe maybe_depth = depth_value->NumberValue(context); + if (maybe_depth.IsNothing()) { + return; + } + + double depth = maybe_depth.FromJust(); + if (depth == 0) { + // Disable. + if (!disable_async_hook_function_.IsEmpty()) { + DisableAsyncHook(isolate); + } else { + if (pending_enable_async_hook_) { + CHECK(!pending_disable_async_hook_); + pending_enable_async_hook_ = false; + } else { + pending_disable_async_hook_ = true; + } + } + } else { + // Enable. + if (!enable_async_hook_function_.IsEmpty()) { + EnableAsyncHook(isolate); + } else { + if (pending_disable_async_hook_) { + CHECK(!pending_enable_async_hook_); + pending_disable_async_hook_ = false; + } else { + pending_enable_async_hook_ = true; + } + } + } +} + void Agent::RequestIoThreadStart() { // We need to attempt to interrupt V8 flow (in case Node is running // continuous JS code) and to wake up libuv thread (in case Node is waiting diff --git a/src/inspector_agent.h b/src/inspector_agent.h index 9119e7263b2799..d14c6650360173 100644 --- a/src/inspector_agent.h +++ b/src/inspector_agent.h @@ -62,6 +62,7 @@ class Agent { void AsyncTaskStarted(void* task); void AsyncTaskFinished(void* task); void AllAsyncTasksCanceled(); + void InterceptAsyncStackDepthMessage(const v8_inspector::StringView& message); void RegisterAsyncHook(v8::Isolate* isolate, v8::Local enable_function, @@ -93,6 +94,9 @@ class Agent { void ContextCreated(v8::Local context); private: + void EnableAsyncHook(v8::Isolate* isolate); + void DisableAsyncHook(v8::Isolate* isolate); + node::Environment* parent_env_; std::unique_ptr client_; std::unique_ptr io_; @@ -102,6 +106,8 @@ class Agent { DebugOptions debug_options_; int next_context_number_; + bool pending_enable_async_hook_; + bool pending_disable_async_hook_; v8::Persistent enable_async_hook_function_; v8::Persistent disable_async_hook_function_; }; diff --git a/test/inspector/test-async-hook-inspector.js b/test/inspector/test-async-hook-inspector.js new file mode 100644 index 00000000000000..e8d46c785c3ab4 --- /dev/null +++ b/test/inspector/test-async-hook-inspector.js @@ -0,0 +1,55 @@ +'use strict'; +const common = require('../common'); +common.skipIfInspectorDisabled(); +common.skipIf32Bits(); + +const assert = require('assert'); +const async_hooks = require('async_hooks'); +const inspector = require('inspector'); + +// Verify that inspector-async-hook is not registered, +// thus emitInit() ignores invalid arguments +// See test/async-hooks/test-emit-init.js +function verifyAsyncHookDisabled(message) { + assert.doesNotThrow(() => async_hooks.emitInit(), message); +} + +// Verify that inspector-async-hook is registered +// by checking that emitInit with invalid arguments +// throw an error. +// See test/async-hooks/test-emit-init.js +function verifyAsyncHookEnabled(message) { + assert.throws(() => async_hooks.emitInit(), message); +} + +// By default inspector async hooks should not have been installed. +verifyAsyncHookDisabled('inspector async hook should be disabled at startup'); + +const session = new inspector.Session(); +verifyAsyncHookDisabled('creating a session should not enable async hooks'); + +session.connect(); +verifyAsyncHookDisabled('creating a session should not enable async hooks'); + +session.post('Debugger.setAsyncCallStackDepth', { invalid: 'message' }, () => { + verifyAsyncHookDisabled('invalid message should not enable async hooks'); + + session.post('Debugger.setAsyncCallStackDepth', { maxDepth: 'five' }, () => { + verifyAsyncHookDisabled('invalid maxDepth (sting) should not enable async' + + ' hooks'); + + session.post('Debugger.setAsyncCallStackDepth', { maxDepth: NaN }, () => { + verifyAsyncHookDisabled('invalid maxDepth (NaN) should not enable async' + + ' hooks'); + + session.post('Debugger.setAsyncCallStackDepth', { maxDepth: 10 }, () => { + verifyAsyncHookEnabled('valid message should enable async hook'); + + session.post('Debugger.setAsyncCallStackDepth', { maxDepth: 0 }, () => { + verifyAsyncHookDisabled('Setting maxDepth to 0 should disable ' + + 'async hooks'); + }); + }); + }); + }); +}); diff --git a/test/inspector/test-async-hook-teardown-at-debug-end.js b/test/inspector/test-async-hook-teardown-at-debug-end.js deleted file mode 100644 index 9084efdd412bcf..00000000000000 --- a/test/inspector/test-async-hook-teardown-at-debug-end.js +++ /dev/null @@ -1,33 +0,0 @@ -'use strict'; -const common = require('../common'); -common.skipIfInspectorDisabled(); -common.skipIf32Bits(); - -const spawn = require('child_process').spawn; - -const script = ` -const assert = require('assert'); - -// Verify that inspector-async-hook is registered -// by checking that emitInit with invalid arguments -// throw an error. -// See test/async-hooks/test-emit-init.js -assert.throws( - () => async_hooks.emitInit(), - 'inspector async hook should have been enabled initially'); - -process._debugEnd(); - -// Verify that inspector-async-hook is no longer registered, -// thus emitInit() ignores invalid arguments -// See test/async-hooks/test-emit-init.js -assert.doesNotThrow( - () => async_hooks.emitInit(), - 'inspector async hook should have beend disabled by _debugEnd()'); -`; - -const args = ['--inspect', '-e', script]; -const child = spawn(process.execPath, args, { stdio: 'inherit' }); -child.on('exit', (code, signal) => { - process.exit(code || signal); -}); From df628ce5b9234e250c8bb9eab3278d2384922697 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Wed, 18 Oct 2017 09:22:18 -0700 Subject: [PATCH 2/3] [SQUASH] address comments --- src/inspector_agent.cc | 95 +++++++++++++++--------------------------- src/inspector_agent.h | 3 +- 2 files changed, 34 insertions(+), 64 deletions(-) diff --git a/src/inspector_agent.cc b/src/inspector_agent.cc index e8fcf2bdd56d29..649f485533b541 100644 --- a/src/inspector_agent.cc +++ b/src/inspector_agent.cc @@ -535,14 +535,7 @@ void Agent::Stop() { // Disable tracking of async stack traces if (!disable_async_hook_function_.IsEmpty()) { - Local disable_fn = disable_async_hook_function_.Get(isolate); - auto result = disable_fn->Call(parent_env_->context(), - Undefined(parent_env_->isolate()), 0, nullptr); - if (result.IsEmpty()) { - FatalError( - "node::InspectorAgent::Stop", - "Cannot disable Inspector's AsyncHook, please report this."); - } + ToggleAsyncHook(isolate, disable_async_hook_function_.Get(isolate)); } } @@ -607,34 +600,21 @@ void Agent::RegisterAsyncHook(Isolate* isolate, disable_async_hook_function_.Reset(isolate, disable_function); if (pending_enable_async_hook_) { pending_enable_async_hook_ = false; - EnableAsyncHook(isolate); + ToggleAsyncHook(isolate, enable_async_hook_function_.Get(isolate)); } else if (pending_disable_async_hook_) { pending_disable_async_hook_ = false; - DisableAsyncHook(isolate); + ToggleAsyncHook(isolate, disable_async_hook_function_.Get(isolate)); } } -void Agent::EnableAsyncHook(Isolate* isolate) { - CHECK(!enable_async_hook_function_.IsEmpty()); - Local enable_fn = enable_async_hook_function_.Get(isolate); - auto context = parent_env_->context(); - auto result = enable_fn->Call(context, Undefined(isolate), 0, nullptr); - if (result.IsEmpty()) { - FatalError( - "node::inspector::Agent::EnableAsyncHook", - "Cannot enable Inspector's AsyncHook, please report this."); - } -} - -void Agent::DisableAsyncHook(Isolate* isolate) { - CHECK(!disable_async_hook_function_.IsEmpty()); - Local disable_fn = disable_async_hook_function_.Get(isolate); +void Agent::ToggleAsyncHook(Isolate* isolate, Local fn) { + HandleScope handle_scope(isolate); auto context = parent_env_->context(); - auto result = disable_fn->Call(context, Undefined(isolate), 0, nullptr); + auto result = fn->Call(context, Undefined(isolate), 0, nullptr); if (result.IsEmpty()) { FatalError( - "node::inspector::Agent::DisableAsyncHook", - "Cannot disable Inspector's AsyncHook, please report this."); + "node::inspector::Agent::ToggleAsyncHook", + "Cannot toggle Inspector's AsyncHook, please report this."); } } @@ -664,10 +644,15 @@ void Agent::InterceptAsyncStackDepthMessage(const StringView& message) { // --inspect-brk, the debugger must necessarily attach before much JavaScript // can execute. The Debugger.setAsyncCallStackDepth message arrives too early // and we must intercept this in C++. + // + // TODO: for performance reasons, it would be good to pre-scan the string for + // 'Debugger.setAsyncCallStackDepth' and return early if not found. v8::Isolate* isolate = parent_env_->isolate(); + HandleScope handle_scope(isolate); Local context = parent_env_->context(); + v8::TryCatch try_catch(isolate); // catch and ignore exceptions. MaybeLocal string = String::NewFromTwoByte(isolate, message.characters16(), v8::NewStringType::kNormal, message.length()); @@ -688,28 +673,23 @@ void Agent::InterceptAsyncStackDepthMessage(const StringView& message) { // We ignore (return early) on malformed messages and let v8-inspector deal // with them. - MaybeLocal maybe_parsed = - v8::JSON::Parse(context, string.ToLocalChecked()); - if (maybe_parsed.IsEmpty()) { - return; - } - - Local parsed = maybe_parsed.ToLocalChecked(); - if (!parsed->IsObject()) { + Local scratch; + Local parsed; + if (!v8::JSON::Parse(context, string.ToLocalChecked()).ToLocal(&scratch) || + !scratch->IsObject() || + !scratch->ToObject(context).ToLocal(&parsed)) { return; } - Local object = parsed.As(); - Local method; - if (!object->Get(context, parent_env_->method_string()).ToLocal(&method) || + if (!parsed->Get(context, parent_env_->method_string()).ToLocal(&method) || !method->IsString() || !method->StrictEquals(parent_env_->async_stack_depth_string())) { return; } Local params; - if (!object->Get(context, parent_env_->params_string()).ToLocal(¶ms) || + if (!parsed->Get(context, parent_env_->params_string()).ToLocal(¶ms) || !params->IsObject()) { return; } @@ -721,35 +701,26 @@ void Agent::InterceptAsyncStackDepthMessage(const StringView& message) { return; } - Maybe maybe_depth = depth_value->NumberValue(context); - if (maybe_depth.IsNothing()) { - return; - } - - double depth = maybe_depth.FromJust(); + double depth = depth_value->NumberValue(context).FromJust(); if (depth == 0) { // Disable. - if (!disable_async_hook_function_.IsEmpty()) { - DisableAsyncHook(isolate); + if (pending_enable_async_hook_) { + CHECK(!pending_disable_async_hook_); + pending_enable_async_hook_ = false; + } else if (!disable_async_hook_function_.IsEmpty()) { + ToggleAsyncHook(isolate, disable_async_hook_function_.Get(isolate)); } else { - if (pending_enable_async_hook_) { - CHECK(!pending_disable_async_hook_); - pending_enable_async_hook_ = false; - } else { - pending_disable_async_hook_ = true; - } + pending_disable_async_hook_ = true; } } else { // Enable. - if (!enable_async_hook_function_.IsEmpty()) { - EnableAsyncHook(isolate); + if (pending_disable_async_hook_) { + CHECK(!pending_enable_async_hook_); + pending_disable_async_hook_ = false; + } else if (!enable_async_hook_function_.IsEmpty()) { + ToggleAsyncHook(isolate, enable_async_hook_function_.Get(isolate)); } else { - if (pending_disable_async_hook_) { - CHECK(!pending_enable_async_hook_); - pending_disable_async_hook_ = false; - } else { - pending_enable_async_hook_ = true; - } + pending_enable_async_hook_ = true; } } } diff --git a/src/inspector_agent.h b/src/inspector_agent.h index d14c6650360173..6c205c6407cd6a 100644 --- a/src/inspector_agent.h +++ b/src/inspector_agent.h @@ -94,8 +94,7 @@ class Agent { void ContextCreated(v8::Local context); private: - void EnableAsyncHook(v8::Isolate* isolate); - void DisableAsyncHook(v8::Isolate* isolate); + void ToggleAsyncHook(v8::Isolate* isolate, v8::Local fn); node::Environment* parent_env_; std::unique_ptr client_; From 0a48cf73d84d78ed2b77a7c94183ec6e740cd097 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Wed, 18 Oct 2017 11:53:00 -0700 Subject: [PATCH 3/3] [SQUASH] fix typos in test --- test/inspector/test-async-hook-inspector.js | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/inspector/test-async-hook-inspector.js b/test/inspector/test-async-hook-inspector.js index e8d46c785c3ab4..aa7a367e1b5869 100644 --- a/test/inspector/test-async-hook-inspector.js +++ b/test/inspector/test-async-hook-inspector.js @@ -29,14 +29,14 @@ const session = new inspector.Session(); verifyAsyncHookDisabled('creating a session should not enable async hooks'); session.connect(); -verifyAsyncHookDisabled('creating a session should not enable async hooks'); +verifyAsyncHookDisabled('connecting a session should not enable async hooks'); session.post('Debugger.setAsyncCallStackDepth', { invalid: 'message' }, () => { verifyAsyncHookDisabled('invalid message should not enable async hooks'); session.post('Debugger.setAsyncCallStackDepth', { maxDepth: 'five' }, () => { - verifyAsyncHookDisabled('invalid maxDepth (sting) should not enable async' + - ' hooks'); + verifyAsyncHookDisabled('invalid maxDepth (string) should not enable ' + + 'async hooks'); session.post('Debugger.setAsyncCallStackDepth', { maxDepth: NaN }, () => { verifyAsyncHookDisabled('invalid maxDepth (NaN) should not enable async' +