From 3e27dcb60872844d1d37591924b0fe42fdb73c15 Mon Sep 17 00:00:00 2001 From: Marcin Cieslak Date: Sun, 21 Jun 2015 00:46:53 +0000 Subject: [PATCH 1/6] Trace in/out values for custom functions Introduce one true way to print contents of the SassValue union. --- src/custom_function_bridge.cpp | 3 ++ src/sass_types/sass_value_wrapper.h | 63 ++++++++++++++++++++++++++++- 2 files changed, 65 insertions(+), 1 deletion(-) diff --git a/src/custom_function_bridge.cpp b/src/custom_function_bridge.cpp index f0e49b6c8..8338d6493 100644 --- a/src/custom_function_bridge.cpp +++ b/src/custom_function_bridge.cpp @@ -3,9 +3,11 @@ #include "custom_function_bridge.h" #include "sass_types/factory.h" #include "sass_types/value.h" +#include "debug.h" Sass_Value* CustomFunctionBridge::post_process_return_value(v8::Local val) const { SassTypes::Value *v_; + TRACEINST(&val) << " CustomFunctionBridge: unwrapping custom function return value..."; if ((v_ = SassTypes::Factory::unwrap(val))) { return v_->get_sass_value(); } else { @@ -17,6 +19,7 @@ std::vector> CustomFunctionBridge::pre_process_args(std::ve std::vector> argv = std::vector>(); for (void* value : in) { + TRACEINST(&value) << " CustomFunctionBridge: wrapping custom function parameters..."; argv.push_back(SassTypes::Factory::create(static_cast(value))->get_js_object()); } diff --git a/src/sass_types/sass_value_wrapper.h b/src/sass_types/sass_value_wrapper.h index 54eb16a02..d4d1460f6 100644 --- a/src/sass_types/sass_value_wrapper.h +++ b/src/sass_types/sass_value_wrapper.h @@ -4,6 +4,7 @@ #include #include #include +#include "../debug.h" #include "value.h" #include "factory.h" @@ -27,6 +28,59 @@ namespace SassTypes static NAN_METHOD(New); static Sass_Value *fail(const char *, Sass_Value **); + static void print_value(Sass_Value *v) { + if (v) { + if (sass_value_is_null(v)) { + TRACEINST(v) << "#null"; + } else if (sass_value_is_number(v)) { + TRACEINST(v) << "#number " + << sass_number_get_value(v) + << " unit=<" << sass_number_get_unit(v) << ">"; + } else if (sass_value_is_string(v)) { + TRACEINST(v) << "#string " + << '"' << sass_string_get_value(v) << '"' + << ", quoted=" << (sass_string_is_quoted(v) ? 'Y' : 'N'); + } else if (sass_value_is_boolean(v)) { + TRACEINST(v) << "#boolean " << sass_boolean_get_value(v); + } else if (sass_value_is_color(v)) { + TRACEINST(v) << "#color RGBA: <" + << sass_color_get_r(v) << "," + << sass_color_get_g(v) << "," + << sass_color_get_b(v) << "," + << sass_color_get_a(v) << ">"; + } else if (sass_value_is_list(v)) { + enum Sass_Separator sep = sass_list_get_separator(v); + size_t len = sass_list_get_length(v); + TRACEINST(v) << "#list " + << "separator=<" << (sep == SASS_COMMA ? ',' : ' ') << ">" + << "length=" << len; + for(size_t i = 0; i < len; i ++) { + TRACEINST(v) << "item(" << i << ")"; + print_value(sass_list_get_value(v, i)); + } + TRACEINST(v) << "#list end"; + } else if (sass_value_is_map(v)) { + size_t len = sass_map_get_length(v); + TRACEINST(v) << "#map length=" << len; + for(size_t i = 0; i < len; i ++) { + TRACEINST(v) << "key(" << i << ")"; + print_value(sass_map_get_key(v, i)); + TRACEINST(v) << "value(" << i << ")"; + print_value(sass_map_get_value(v, i)); + } + TRACEINST(v) << "#map end"; + } else if (sass_value_is_error(v)) { + TRACEINST(v) << "#error " << sass_error_get_message(v); + } else if (sass_value_is_warning(v)) { + TRACEINST(v) << "#warn " << sass_warning_get_message(v); + } else { + TRACEINST(v) << "#unknown"; + } + } else { + TRACE() << "(null value)"; + } + } + protected: Sass_Value* value; static T* unwrap(v8::Local); @@ -42,6 +96,9 @@ namespace SassTypes template SassValueWrapper::SassValueWrapper(Sass_Value* v) { this->value = sass_clone_value(v); + TRACEINST(this) << "ctor " << (void *)this->value << " := " << (void *)v; + print_value(v); + TRACEINST(this) << "done"; } template @@ -52,7 +109,11 @@ namespace SassTypes template Sass_Value* SassValueWrapper::get_sass_value() { - return sass_clone_value(this->value); + Sass_Value *nv = sass_clone_value(this->value); + TRACEINST(this) << (void *)nv << " := " << (void *)this->value; + print_value(this->value); + TRACEINST(this) << "done"; + return nv; } template From 3bd1ccc87cf3e7c4c93a264798f53993b9407f6c Mon Sep 17 00:00:00 2001 From: Marcin Cieslak Date: Sat, 20 Jun 2015 23:47:17 +0000 Subject: [PATCH 2/6] Add live tracing facility Set NODESASS_TRACE enviroment variable to any value to get lots of output. --- binding.gyp | 1 + src/debug.cpp | 27 +++++++++++++++++++++++++++ src/debug.h | 38 ++++++++++++++++++++++++++++++++++++++ 3 files changed, 66 insertions(+) create mode 100644 src/debug.cpp create mode 100644 src/debug.h diff --git a/binding.gyp b/binding.gyp index ec57d30e0..d80c82cef 100644 --- a/binding.gyp +++ b/binding.gyp @@ -8,6 +8,7 @@ 'src/create_string.cpp', 'src/custom_function_bridge.cpp', 'src/custom_importer_bridge.cpp', + 'src/debug.cpp', 'src/sass_context_wrapper.cpp', 'src/sass_types/boolean.cpp', 'src/sass_types/color.cpp', diff --git a/src/debug.cpp b/src/debug.cpp new file mode 100644 index 000000000..b4999abec --- /dev/null +++ b/src/debug.cpp @@ -0,0 +1,27 @@ +#include +#include + +#include + +#include "debug.h" + +Log::Log() {} + +std::ostringstream& Log::Get(TLogLevel level, void *p, const char *f, const char *filen, int lineno) +{ + os << "[NODESASS@" << uv_thread_self() << "] " << p << ":" << f << " " << filen << ":" << lineno << " "; + messageLevel = level; + return os; +} +std::ostringstream& Log::Get(TLogLevel level, const char *f, const char *filen, int lineno) +{ + os << "[NODESASS@" << uv_thread_self() << "] " << f << " " << filen << ":" << lineno << " "; + messageLevel = level; + return os; +} +Log::~Log() +{ + os << std::endl; + fprintf(stderr, "%s", os.str().c_str()); + fflush(stderr); +} diff --git a/src/debug.h b/src/debug.h new file mode 100644 index 000000000..1e081ab88 --- /dev/null +++ b/src/debug.h @@ -0,0 +1,38 @@ +#ifndef NODE_SASS_DEBUG_H +#define NODE_SASS_DEBUG_H + +#include + +enum TLogLevel {logINFO, logTRACE}; +static TLogLevel LogReportingLevel = getenv("NODESASS_TRACE") ? logTRACE : logINFO; +class Log +{ +public: + Log(); + virtual ~Log(); + std::ostringstream& Get(TLogLevel level, void *p, const char *f, const char *filen, int lineno); + std::ostringstream& Get(TLogLevel level, const char *f, const char *filen, int lineno); +public: +protected: + std::ostringstream os; +private: + Log(const Log&); + Log& operator =(const Log&); +private: + TLogLevel messageLevel; +}; + +// Visual Studio 2013 does not like __func__ +#if _MSC_VER < 1900 +#define __func__ __FUNCTION__ +#endif + +#define TRACE() \ + if (logTRACE > LogReportingLevel) ; \ + else Log().Get(logTRACE, __func__, __FILE__, __LINE__) + +#define TRACEINST(obj) \ + if (logTRACE > LogReportingLevel) ; \ + else Log().Get(logTRACE, (obj), __func__, __FILE__, __LINE__) + +#endif From dedf7af664be9ce3300ec66fefd542ae54c73d02 Mon Sep 17 00:00:00 2001 From: Marcin Cieslak Date: Sat, 29 Aug 2015 00:08:39 +0000 Subject: [PATCH 3/6] Copy constructor and copy assignement --- src/callback_bridge.h | 52 +++++++++++++++++++++++++++++++++++- src/custom_function_bridge.h | 1 + src/custom_importer_bridge.h | 1 + 3 files changed, 53 insertions(+), 1 deletion(-) diff --git a/src/callback_bridge.h b/src/callback_bridge.h index cf749c1b8..d67d8b5e2 100644 --- a/src/callback_bridge.h +++ b/src/callback_bridge.h @@ -12,6 +12,8 @@ template class CallbackBridge { public: CallbackBridge(v8::Local, bool); + CallbackBridge(const CallbackBridge &); + CallbackBridge& operator=(const CallbackBridge &); virtual ~CallbackBridge(); // Executes the callback @@ -21,6 +23,8 @@ class CallbackBridge { // We will expose a bridge object to the JS callback that wraps this instance so we don't loose context. // This is the V8 constructor for such objects. static Nan::MaybeLocal get_wrapper_constructor(); + void init_uv(void); + void init_wrapper(void); static void async_gone(uv_handle_t *handle); static NAN_METHOD(New); static NAN_METHOD(ReturnCallback); @@ -59,7 +63,48 @@ CallbackBridge::CallbackBridge(v8::Local callback, bool is_s * This is invoked from the main JavaScript thread. * V8 context is available. */ - Nan::HandleScope scope; + init_uv(); + init_wrapper(); +} + +template +CallbackBridge::CallbackBridge(const CallbackBridge& other) : callback(new Nan::Callback(other.callback->GetFunction())), is_sync(other.is_sync) { + /* + * This is invoked from the main JavaScript thread. + * V8 context is available. + */ + init_uv(); + init_wrapper(); +} + +template +CallbackBridge& +CallbackBridge::operator= (const CallbackBridge& other) +{ + /* + * This is invoked from the main JavaScript thread. + * V8 context is available. + */ + if (other != *this) { + delete this->callback; + this->wrapper.Reset(); + uv_cond_destroy(&this->condition_variable); + uv_mutex_destroy(&this->cv_mutex); + if (!is_sync) { + uv_close(this->async, &async_gone); + } + + this->callback = new Nan::Callback(other.callback->GetFunction()); + this->is_sync = other.is_sync; + init_uv(); + init_wrapper(); + } + return *this; +} + +template +void +CallbackBridge::init_uv(void) { uv_mutex_init(&this->cv_mutex); uv_cond_init(&this->condition_variable); if (!is_sync) { @@ -67,7 +112,12 @@ CallbackBridge::CallbackBridge(v8::Local callback, bool is_s this->async->data = (void*) this; uv_async_init(uv_default_loop(), this->async, (uv_async_cb) dispatched_async_uv_callback); } +} +template +void +CallbackBridge::init_wrapper(void) { + Nan::HandleScope scope; v8::Local func = CallbackBridge::get_wrapper_constructor().ToLocalChecked(); wrapper.Reset(Nan::NewInstance(func).ToLocalChecked()); Nan::SetInternalFieldPointer(Nan::New(wrapper), 0, this); diff --git a/src/custom_function_bridge.h b/src/custom_function_bridge.h index 99c83ead3..28fdc380e 100644 --- a/src/custom_function_bridge.h +++ b/src/custom_function_bridge.h @@ -9,6 +9,7 @@ class CustomFunctionBridge : public CallbackBridge { public: CustomFunctionBridge(v8::Local cb, bool is_sync) : CallbackBridge(cb, is_sync) {} + CustomFunctionBridge(const CustomFunctionBridge& other) : CallbackBridge(other) {} private: Sass_Value* post_process_return_value(v8::Local) const; diff --git a/src/custom_importer_bridge.h b/src/custom_importer_bridge.h index 0cbd3e6d8..7822fddce 100644 --- a/src/custom_importer_bridge.h +++ b/src/custom_importer_bridge.h @@ -11,6 +11,7 @@ typedef Sass_Import_List SassImportList; class CustomImporterBridge : public CallbackBridge { public: CustomImporterBridge(v8::Local cb, bool is_sync) : CallbackBridge(cb, is_sync) {} + CustomImporterBridge(const CustomImporterBridge& other) : CallbackBridge(other) {} private: SassImportList post_process_return_value(v8::Local) const; From 809750d93a42b28fe555172f8e271a9a55e62c4f Mon Sep 17 00:00:00 2001 From: Marcin Cieslak Date: Sat, 29 Aug 2015 00:54:21 +0000 Subject: [PATCH 4/6] Instrument callback bridge with TRACEINST() --- src/binding.cpp | 6 ++++++ src/callback_bridge.h | 4 ++++ 2 files changed, 10 insertions(+) diff --git a/src/binding.cpp b/src/binding.cpp index 3785e42f6..aaa1667d3 100644 --- a/src/binding.cpp +++ b/src/binding.cpp @@ -4,6 +4,7 @@ #include "custom_function_bridge.h" #include "create_string.h" #include "sass_types/factory.h" +#include "debug.h" Sass_Import_List sass_importer(const char* cur_path, Sass_Importer_Entry cb, struct Sass_Compiler* comp) { @@ -16,6 +17,7 @@ Sass_Import_List sass_importer(const char* cur_path, Sass_Importer_Entry cb, str argv.push_back((void*)cur_path); argv.push_back((void*)prev_path); + TRACEINST(&bridge) << "Importer will be executed"; return bridge(argv); } @@ -29,6 +31,7 @@ union Sass_Value* sass_custom_function(const union Sass_Value* s_args, Sass_Func argv.push_back((void*)sass_list_get_value(s_args, i)); } + TRACEINST(&bridge) << "Function will be executed"; return bridge(argv); } @@ -120,6 +123,7 @@ int ExtractOptions(v8::Local options, void* cptr, sass_context_wrapp v8::Local importer = importer_callback.As(); CustomImporterBridge *bridge = new CustomImporterBridge(importer, ctx_w->is_sync); + TRACEINST(bridge) << "Importer bridge created"; ctx_w->importer_bridges.push_back(bridge); Sass_Importer_List c_importers = sass_make_importer_list(1); @@ -135,6 +139,7 @@ int ExtractOptions(v8::Local options, void* cptr, sass_context_wrapp v8::Local callback = v8::Local::Cast(Nan::Get(importers, static_cast(i)).ToLocalChecked()); CustomImporterBridge *bridge = new CustomImporterBridge(callback, ctx_w->is_sync); + TRACEINST(bridge) << "Importer bridge created (item #" << i << ")"; ctx_w->importer_bridges.push_back(bridge); c_importers[i] = sass_make_importer(sass_importer, importers->Length() - i - 1, bridge); @@ -156,6 +161,7 @@ int ExtractOptions(v8::Local options, void* cptr, sass_context_wrapp v8::Local callback = v8::Local::Cast(Nan::Get(functions, signature).ToLocalChecked()); CustomFunctionBridge *bridge = new CustomFunctionBridge(callback, ctx_w->is_sync); + TRACEINST(bridge) << "Custom function bridge created (item #" << i << ")"; ctx_w->function_bridges.push_back(bridge); Sass_Function_Entry fn = sass_make_function(create_string(signature), sass_custom_function, bridge); diff --git a/src/callback_bridge.h b/src/callback_bridge.h index d67d8b5e2..d13b7894d 100644 --- a/src/callback_bridge.h +++ b/src/callback_bridge.h @@ -6,6 +6,8 @@ #include #include +#include "debug.h" + #define COMMA , template @@ -86,6 +88,7 @@ CallbackBridge::operator= (const CallbackBridge& other) * V8 context is available. */ if (other != *this) { + TRACEINST(this) << "Instance will be copied over from " << (void *)&other; delete this->callback; this->wrapper.Reset(); uv_cond_destroy(&this->condition_variable); @@ -125,6 +128,7 @@ CallbackBridge::init_wrapper(void) { template CallbackBridge::~CallbackBridge() { + TRACEINST(this) << "Instance shuts down"; delete this->callback; this->wrapper.Reset(); uv_cond_destroy(&this->condition_variable); From 9bf96cf303e91bcf165106dd019f0aca027f8080 Mon Sep 17 00:00:00 2001 From: Marcin Cieslak Date: Sat, 29 Aug 2015 00:54:47 +0000 Subject: [PATCH 5/6] TRACE: Print function name at the end --- src/debug.cpp | 8 +++++--- src/debug.h | 3 +-- 2 files changed, 6 insertions(+), 5 deletions(-) diff --git a/src/debug.cpp b/src/debug.cpp index b4999abec..906870c6a 100644 --- a/src/debug.cpp +++ b/src/debug.cpp @@ -9,19 +9,21 @@ Log::Log() {} std::ostringstream& Log::Get(TLogLevel level, void *p, const char *f, const char *filen, int lineno) { - os << "[NODESASS@" << uv_thread_self() << "] " << p << ":" << f << " " << filen << ":" << lineno << " "; + os << "[NODESASS@" << uv_thread_self() << "] " << p << ":" << filen << ":" << lineno << " "; + func = f; messageLevel = level; return os; } std::ostringstream& Log::Get(TLogLevel level, const char *f, const char *filen, int lineno) { - os << "[NODESASS@" << uv_thread_self() << "] " << f << " " << filen << ":" << lineno << " "; + os << "[NODESASS@" << uv_thread_self() << "] " << filen << ":" << lineno << " "; + func = f; messageLevel = level; return os; } Log::~Log() { - os << std::endl; + os << " (" << func << ")" << std::endl; fprintf(stderr, "%s", os.str().c_str()); fflush(stderr); } diff --git a/src/debug.h b/src/debug.h index 1e081ab88..91a2800ad 100644 --- a/src/debug.h +++ b/src/debug.h @@ -12,14 +12,13 @@ class Log virtual ~Log(); std::ostringstream& Get(TLogLevel level, void *p, const char *f, const char *filen, int lineno); std::ostringstream& Get(TLogLevel level, const char *f, const char *filen, int lineno); -public: protected: std::ostringstream os; private: Log(const Log&); Log& operator =(const Log&); -private: TLogLevel messageLevel; + const char *func; }; // Visual Studio 2013 does not like __func__ From dbedf5f3ddabce558c7c589cc75127a21abeaf85 Mon Sep 17 00:00:00 2001 From: Marcin Cieslak Date: Sat, 29 Aug 2015 02:14:13 +0000 Subject: [PATCH 6/6] Implement timeout for callbacks --- src/binding.cpp | 18 +++++++++++++-- src/callback_bridge.h | 54 ++++++++++++++++++++++++------------------- 2 files changed, 46 insertions(+), 26 deletions(-) diff --git a/src/binding.cpp b/src/binding.cpp index aaa1667d3..a01de41aa 100644 --- a/src/binding.cpp +++ b/src/binding.cpp @@ -18,7 +18,15 @@ Sass_Import_List sass_importer(const char* cur_path, Sass_Importer_Entry cb, str argv.push_back((void*)prev_path); TRACEINST(&bridge) << "Importer will be executed"; - return bridge(argv); + + Sass_Import_List retval = bridge(argv); + if (bridge.timedout) { + TRACEINST(&bridge) << "Importer timeout"; + retval = sass_make_import_list(1); + retval[0] = sass_make_import_entry(0, 0, 0); + sass_import_set_error(retval[0], "Importer timed out or blocked (>2000ms)", -1, -1); + } + return retval; } union Sass_Value* sass_custom_function(const union Sass_Value* s_args, Sass_Function_Entry cb, struct Sass_Options* opts) @@ -32,7 +40,13 @@ union Sass_Value* sass_custom_function(const union Sass_Value* s_args, Sass_Func } TRACEINST(&bridge) << "Function will be executed"; - return bridge(argv); + Sass_Value *retval = bridge(argv); + if (bridge.timedout) { + TRACEINST(&bridge) << "Function timeout"; + return sass_make_error("Function timed out or blocked (>2000ms)"); + } else { + return retval; + } } int ExtractOptions(v8::Local options, void* cptr, sass_context_wrapper* ctx_w, bool is_file, bool is_sync) { diff --git a/src/callback_bridge.h b/src/callback_bridge.h index d13b7894d..5125f3897 100644 --- a/src/callback_bridge.h +++ b/src/callback_bridge.h @@ -20,6 +20,7 @@ class CallbackBridge { // Executes the callback T operator()(std::vector); + int timedout; protected: // We will expose a bridge object to the JS callback that wraps this instance so we don't loose context. @@ -60,7 +61,7 @@ template Nan::Persistent CallbackBridge::wrapper_constructor; template -CallbackBridge::CallbackBridge(v8::Local callback, bool is_sync) : callback(new Nan::Callback(callback)), is_sync(is_sync) { +CallbackBridge::CallbackBridge(v8::Local callback, bool is_sync) : timedout(0), callback(new Nan::Callback(callback)), is_sync(is_sync) { /* * This is invoked from the main JavaScript thread. * V8 context is available. @@ -70,7 +71,7 @@ CallbackBridge::CallbackBridge(v8::Local callback, bool is_s } template -CallbackBridge::CallbackBridge(const CallbackBridge& other) : callback(new Nan::Callback(other.callback->GetFunction())), is_sync(other.is_sync) { +CallbackBridge::CallbackBridge(const CallbackBridge& other) : timedout(0), callback(new Nan::Callback(other.callback->GetFunction())), is_sync(other.is_sync) { /* * This is invoked from the main JavaScript thread. * V8 context is available. @@ -99,6 +100,7 @@ CallbackBridge::operator= (const CallbackBridge& other) this->callback = new Nan::Callback(other.callback->GetFunction()); this->is_sync = other.is_sync; + this->timedout = 0; init_uv(); init_wrapper(); } @@ -179,12 +181,12 @@ T CallbackBridge::operator()(std::vector argv) { * async I/O executed from JavaScript callbacks. */ this->argv = argv; - + this->timedout = 0; uv_mutex_lock(&this->cv_mutex); this->has_returned = false; uv_async_send(this->async); - while (!this->has_returned) { - uv_cond_wait(&this->condition_variable, &this->cv_mutex); + while (!this->has_returned && this->timedout == 0) { + this->timedout = uv_cond_timedwait(&this->condition_variable, &this->cv_mutex, 2 * (uint64_t)1e9); } uv_mutex_unlock(&this->cv_mutex); return this->return_value; @@ -204,19 +206,21 @@ void CallbackBridge::dispatched_async_uv_callback(uv_async_t *req) { * from types invoked by pre_process_args() and * post_process_args(). */ - Nan::HandleScope scope; - Nan::TryCatch try_catch; + if (!bridge->timedout) { + Nan::HandleScope scope; + Nan::TryCatch try_catch; - std::vector> argv_v8 = bridge->pre_process_args(bridge->argv); - if (try_catch.HasCaught()) { - Nan::FatalException(try_catch); - } - argv_v8.push_back(Nan::New(bridge->wrapper)); + std::vector> argv_v8 = bridge->pre_process_args(bridge->argv); + if (try_catch.HasCaught()) { + Nan::FatalException(try_catch); + } + argv_v8.push_back(Nan::New(bridge->wrapper)); - bridge->callback->Call(argv_v8.size(), &argv_v8[0]); + bridge->callback->Call(argv_v8.size(), &argv_v8[0]); - if (try_catch.HasCaught()) { - Nan::FatalException(try_catch); + if (try_catch.HasCaught()) { + Nan::FatalException(try_catch); + } } } @@ -233,18 +237,20 @@ NAN_METHOD(CallbackBridge::ReturnCallback) { CallbackBridge* bridge = static_cast*>(Nan::GetInternalFieldPointer(info.This(), 0)); Nan::TryCatch try_catch; - bridge->return_value = bridge->post_process_return_value(info[0]); + if (!bridge->timedout) { + bridge->return_value = bridge->post_process_return_value(info[0]); - { - uv_mutex_lock(&bridge->cv_mutex); - bridge->has_returned = true; - uv_mutex_unlock(&bridge->cv_mutex); - } + { + uv_mutex_lock(&bridge->cv_mutex); + bridge->has_returned = true; + uv_mutex_unlock(&bridge->cv_mutex); + } - uv_cond_broadcast(&bridge->condition_variable); + uv_cond_broadcast(&bridge->condition_variable); - if (try_catch.HasCaught()) { - Nan::FatalException(try_catch); + if (try_catch.HasCaught()) { + Nan::FatalException(try_catch); + } } }