Repository: nodejs/node
Pull request: src: add contextify interceptor debug logs

Add debug logs to help investigate vm interceptor call order issues like
https://github.com/nodejs/node/pull/61898#issuecomment-4142811603

The format of the V8 values are conditional by the presence of
`NODE_DEBUG_NATIVE`. So these values are not always converted to c++
values by utilizing `per_process::Debug` debuglog.

Changed files:
filename: src/debug_utils-inl.h
patch: @@ -62,6 +62,25 @@ struct ToStringHelper {
   static std::string Convert(const std::string& value) { return value; }
   static std::string_view Convert(std::string_view value) { return value; }
   static std::string Convert(bool value) { return value ? "true" : "false"; }
+
+  static std::string Convert(v8::Local<v8::Value> value) {
+    v8::Isolate* isolate = v8::Isolate::GetCurrent();
+    if (value->IsString()) {
+      Utf8Value utf8_value(isolate, value);
+      return SPrintF("\"%s\"", utf8_value.ToString());
+    }
+    v8::MaybeLocal<v8::String> maybe_detail =
+        value->ToDetailString(isolate->GetCurrentContext());
+    v8::Local<v8::String> detail;
+    if (!maybe_detail.ToLocal(&detail)) {
+      // This will only occur when terminating. No exception is expected
+      // with `ToDetailString`.
+      return "<Unable to stringify v8::Value>";
+    }
+    Utf8Value utf8_value(isolate, detail);
+    return utf8_value.ToString();
+  }
+
   template <unsigned BASE_BITS,
             typename T,
             typename = std::enable_if_t<std::is_integral_v<T>>>

filename: src/debug_utils.h
patch: @@ -47,6 +47,7 @@ void NODE_EXTERN_PRIVATE FWrite(FILE* file, const std::string& str);
   V(BOOTSTRAP)                                                                 \
   V(CRYPTO)                                                                    \
   V(COMPILE_CACHE)                                                             \
+  V(CONTEXTIFY)                                                                \
   V(DIAGNOSTICS)                                                               \
   V(HUGEPAGES)                                                                 \
   V(INSPECTOR_SERVER)                                                          \

filename: src/node_contextify.cc
patch: @@ -23,6 +23,7 @@
 
 #include "base_object-inl.h"
 #include "cppgc/allocation.h"
+#include "debug_utils-inl.h"
 #include "memory_tracker-inl.h"
 #include "module_wrap.h"
 #include "node_context_data.h"
@@ -484,6 +485,9 @@ Intercepted ContextifyContext::PropertyQueryCallback(
     return Intercepted::kNo;
   }
 
+  per_process::Debug(
+      DebugCategory::CONTEXTIFY, "PropertyQuery(%s)\n", property);
+
   Local<Context> context = ctx->context();
   Local<Object> sandbox = ctx->sandbox();
 
@@ -530,6 +534,9 @@ Intercepted ContextifyContext::PropertyGetterCallback(
     return Intercepted::kNo;
   }
 
+  per_process::Debug(
+      DebugCategory::CONTEXTIFY, "PropertyGetter(name: %s)\n", property);
+
   Local<Context> context = ctx->context();
   Local<Object> sandbox = ctx->sandbox();
 
@@ -567,6 +574,12 @@ Intercepted ContextifyContext::PropertySetterCallback(
     return Intercepted::kNo;
   }
 
+  per_process::Debug(DebugCategory::CONTEXTIFY,
+                     "PropertySetter(name: %s, value: %s), use-strict(%s)\n",
+                     property,
+                     value,
+                     args.ShouldThrowOnError());
+
   Local<Context> context = ctx->context();
   PropertyAttribute attributes = PropertyAttribute::None;
   bool is_declared_on_global_proxy = ctx->global_proxy()
@@ -644,6 +657,9 @@ Intercepted ContextifyContext::PropertyDescriptorCallback(
     return Intercepted::kNo;
   }
 
+  per_process::Debug(
+      DebugCategory::CONTEXTIFY, "PropertyDescriptor(name: %s)\n", property);
+
   Local<Context> context = ctx->context();
 
   Local<Object> sandbox = ctx->sandbox();
@@ -670,6 +686,9 @@ Intercepted ContextifyContext::PropertyDefinerCallback(
     return Intercepted::kNo;
   }
 
+  per_process::Debug(
+      DebugCategory::CONTEXTIFY, "PropertyDefiner(name: %s)\n", property);
+
   Local<Context> context = ctx->context();
   Isolate* isolate = Isolate::GetCurrent();
 
@@ -740,6 +759,9 @@ Intercepted ContextifyContext::PropertyDeleterCallback(
     return Intercepted::kNo;
   }
 
+  per_process::Debug(
+      DebugCategory::CONTEXTIFY, "PropertyDeleter(name: %s)\n", property);
+
   Maybe<bool> success = ctx->sandbox()->Delete(ctx->context(), property);
 
   if (success.FromMaybe(false)) {
@@ -767,6 +789,8 @@ void ContextifyContext::PropertyEnumeratorCallback(
   // Still initializing
   if (IsStillInitializing(ctx)) return;
 
+  per_process::Debug(DebugCategory::CONTEXTIFY, "PropertyEnumerator()\n");
+
   Local<Array> properties;
   // Only get own named properties, exclude indices.
   if (!ctx->sandbox()
@@ -798,6 +822,9 @@ void ContextifyContext::IndexedPropertyEnumeratorCallback(
   // Still initializing
   if (IsStillInitializing(ctx)) return;
 
+  per_process::Debug(DebugCategory::CONTEXTIFY,
+                     "IndexedPropertyEnumerator()\n");
+
   Local<Array> properties;
 
   // Only get own index properties.