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/binding.cpp b/src/binding.cpp index 3785e42f6..a01de41aa 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,7 +17,16 @@ 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); - return bridge(argv); + TRACEINST(&bridge) << "Importer will be executed"; + + 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) @@ -29,7 +39,14 @@ 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)); } - return bridge(argv); + TRACEINST(&bridge) << "Function will be executed"; + 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) { @@ -120,6 +137,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 +153,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 +175,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 cf749c1b8..5125f3897 100644 --- a/src/callback_bridge.h +++ b/src/callback_bridge.h @@ -6,21 +6,28 @@ #include #include +#include "debug.h" + #define COMMA , template class CallbackBridge { public: CallbackBridge(v8::Local, bool); + CallbackBridge(const CallbackBridge &); + CallbackBridge& operator=(const CallbackBridge &); virtual ~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. // 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); @@ -54,12 +61,55 @@ 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. */ - Nan::HandleScope scope; + init_uv(); + init_wrapper(); +} + +template +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. + */ + 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) { + TRACEINST(this) << "Instance will be copied over from " << (void *)&other; + 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; + this->timedout = 0; + 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 +117,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); @@ -75,6 +130,7 @@ CallbackBridge::CallbackBridge(v8::Local callback, bool is_s template CallbackBridge::~CallbackBridge() { + TRACEINST(this) << "Instance shuts down"; delete this->callback; this->wrapper.Reset(); uv_cond_destroy(&this->condition_variable); @@ -125,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; @@ -150,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); + } } } @@ -179,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); + } } } 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/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; diff --git a/src/debug.cpp b/src/debug.cpp new file mode 100644 index 000000000..906870c6a --- /dev/null +++ b/src/debug.cpp @@ -0,0 +1,29 @@ +#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 << ":" << 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() << "] " << filen << ":" << lineno << " "; + func = f; + messageLevel = level; + return os; +} +Log::~Log() +{ + os << " (" << func << ")" << 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..91a2800ad --- /dev/null +++ b/src/debug.h @@ -0,0 +1,37 @@ +#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); +protected: + std::ostringstream os; +private: + Log(const Log&); + Log& operator =(const Log&); + TLogLevel messageLevel; + const char *func; +}; + +// 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 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