[WIP] Timeout custom JS after 2000ms

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',

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<v8::Object> options, void* cptr, sass_context_wrapper* ctx_w, bool is_file, bool is_sync) {
@@ -120,6 +137,7 @@ int ExtractOptions(v8::Local<v8::Object> options, void* cptr, sass_context_wrapp
     v8::Local<v8::Function> importer = importer_callback.As<v8::Function>();
 
     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<v8::Object> options, void* cptr, sass_context_wrapp
       v8::Local<v8::Function> callback = v8::Local<v8::Function>::Cast(Nan::Get(importers, static_cast<uint32_t>(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<v8::Object> options, void* cptr, sass_context_wrapp
       v8::Local<v8::Function> callback = v8::Local<v8::Function>::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);

src/callback_bridge.h

@@ -6,21 +6,28 @@
 #include <algorithm>
 #include <uv.h>
 
+#include "debug.h"
+
 #define COMMA ,
 
 template <typename T, typename L = void*>
 class CallbackBridge {
   public:
     CallbackBridge(v8::Local<v8::Function>, bool);
+    CallbackBridge(const CallbackBridge<T,L> &);
+    CallbackBridge<T,L>& operator=(const CallbackBridge<T,L> &);
     virtual ~CallbackBridge();
 
     // Executes the callback
     T operator()(std::vector<void*>);
+    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<v8::Function> 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,27 +61,76 @@ template <typename T, typename L>
 Nan::Persistent<v8::Function> CallbackBridge<T, L>::wrapper_constructor;
 
 template <typename T, typename L>
-CallbackBridge<T, L>::CallbackBridge(v8::Local<v8::Function> callback, bool is_sync) : callback(new Nan::Callback(callback)), is_sync(is_sync) {
+CallbackBridge<T, L>::CallbackBridge(v8::Local<v8::Function> 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 <typename T, typename L>
+CallbackBridge<T, L>::CallbackBridge(const CallbackBridge<T,L>& 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 <typename T, typename L>
+CallbackBridge<T, L>&
+CallbackBridge<T, L>::operator= (const CallbackBridge<T,L>& 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 <typename T, typename L>
+void
+CallbackBridge<T, L>::init_uv(void) {
   uv_mutex_init(&this->cv_mutex);
   uv_cond_init(&this->condition_variable);
   if (!is_sync) {
     this->async = new uv_async_t;
     this->async->data = (void*) this;
     uv_async_init(uv_default_loop(), this->async, (uv_async_cb) dispatched_async_uv_callback);
   }
+}
 
+template <typename T, typename L>
+void
+CallbackBridge<T, L>::init_wrapper(void) {
+  Nan::HandleScope scope;
   v8::Local<v8::Function> func = CallbackBridge<T, L>::get_wrapper_constructor().ToLocalChecked();
   wrapper.Reset(Nan::NewInstance(func).ToLocalChecked());
   Nan::SetInternalFieldPointer(Nan::New(wrapper), 0, this);
 }
 
 template <typename T, typename L>
 CallbackBridge<T, L>::~CallbackBridge() {
+  TRACEINST(this) << "Instance shuts down";
   delete this->callback;
   this->wrapper.Reset();
   uv_cond_destroy(&this->condition_variable);
@@ -125,12 +181,12 @@ T CallbackBridge<T, L>::operator()(std::vector<void*> 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<T, L>::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<v8::Local<v8::Value>> 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<v8::Local<v8::Value>> 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<T COMMA L>::ReturnCallback) {
   CallbackBridge<T, L>* bridge = static_cast<CallbackBridge<T, L>*>(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);
+    }
   }
 }
 

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<v8::Value> 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<v8::Local<v8::Value>> CustomFunctionBridge::pre_process_args(std::ve
   std::vector<v8::Local<v8::Value>> argv = std::vector<v8::Local<v8::Value>>();
 
   for (void* value : in) {
+    TRACEINST(&value) << " CustomFunctionBridge: wrapping custom function parameters...";
     argv.push_back(SassTypes::Factory::create(static_cast<Sass_Value*>(value))->get_js_object());
   }
 

src/custom_function_bridge.h

@@ -9,6 +9,7 @@
 class CustomFunctionBridge : public CallbackBridge<Sass_Value*> {
   public:
     CustomFunctionBridge(v8::Local<v8::Function> cb, bool is_sync) : CallbackBridge<Sass_Value*>(cb, is_sync) {}
+    CustomFunctionBridge(const CustomFunctionBridge& other) : CallbackBridge<Sass_Value*>(other) {}
 
   private:
     Sass_Value* post_process_return_value(v8::Local<v8::Value>) const;

src/custom_importer_bridge.h

@@ -11,6 +11,7 @@ typedef Sass_Import_List SassImportList;
 class CustomImporterBridge : public CallbackBridge<SassImportList> {
   public:
     CustomImporterBridge(v8::Local<v8::Function> cb, bool is_sync) : CallbackBridge<SassImportList>(cb, is_sync) {}
+    CustomImporterBridge(const CustomImporterBridge& other) : CallbackBridge<SassImportList>(other) {}
 
   private:
     SassImportList post_process_return_value(v8::Local<v8::Value>) const;

src/debug.cpp

@@ -0,0 +1,29 @@
+#include <stdio.h>
+#include <sstream>
+
+#include <uv.h>
+
+#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);
+}

src/debug.h

@@ -0,0 +1,37 @@
+#ifndef NODE_SASS_DEBUG_H
+#define NODE_SASS_DEBUG_H
+
+#include <sstream>
+
+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