From e33db211db5817bf7ea9a431e7c44cc67a988048 Mon Sep 17 00:00:00 2001 From: Dmitry Bezhetskov Date: Wed, 3 Jun 2026 12:13:27 +0200 Subject: [PATCH] Refactor console method decoration for snapshotting The current console decoration scheme breaks V8 snapshot creation in two ways: 1) The C++ lambdas used as decorators hold v8::Global handles to the original console methods, but V8 does not support serializing Global handles. 2) The decorator for each console method is created through wrapSimpleFunction, which allocates an opaque JS wrapper using the Wrappable path and binds that wrapper to the resulting V8 function via V8::Function::New. The JS wrapper, which holds the C++ lambda, belongs to the context. However, V8 snapshot forbids pointers from isolate-level snapshot objects to context-level data. In this case, the function/template machinery belongs to the isolate-level snapshot, while the wrapper belongs to the context-level snapshot. This patch addresses both issues: - We preserve the original methods in a private, context-level embedder-data slots instead of holding them in v8::Global handles. This establishes edges from the context to those JS objects, so they remain reachable and are automatically captured in the snapshot as part of the context graph. - We no longer use the Wrappable path for decoration. Instead, we create the V8 functions directly with V8::Function::New and use a plain C++ functor that retrieves the required state from the context-level embedder-data slot. This avoids creating JS wrappers that hold references to C++ state. --- src/workerd/io/worker.c++ | 374 +++++++++++++++++++++--------------- src/workerd/io/worker.h | 17 +- src/workerd/jsg/wrappable.h | 25 +++ 3 files changed, 248 insertions(+), 168 deletions(-) diff --git a/src/workerd/io/worker.c++ b/src/workerd/io/worker.c++ index f2729d34c12..fe86aebb1b5 100644 --- a/src/workerd/io/worker.c++ +++ b/src/workerd/io/worker.c++ @@ -661,7 +661,7 @@ struct Worker::Isolate::Impl { i.get()->contextCreated(v8_inspector::V8ContextInfo( context, 1, jsg::toInspectorStringView("Worker").stringView)); } - Worker::setupContext(*lock, context, loggingOptions); + Worker::setupContext(*lock, context); } void disposeContext(jsg::JsContext context) { @@ -1769,32 +1769,226 @@ void shimWebAssemblyInstantiate(jsg::Lock& lock, v8::Local context) shimFn.call(lock, lock.global(), jsg::JsFunction(registerFn)); } -void Worker::setupContext( - jsg::Lock& lock, v8::Local context, const LoggingOptions& loggingOptions) { +namespace { + +// The console methods wrapped by setupContext (debug, error, info, log, warn). Each entry has the +// method name with its log level and the native decorator callback. +struct ConsoleMethod { + const char* name; + LogLevel level; + v8::FunctionCallback callback; +}; + +// The C++ decorator template for console.* methods. +template +void consoleDecorator(const v8::FunctionCallbackInfo& info); + +constexpr ConsoleMethod kConsoleMethods[] = { + {"debug", LogLevel::DEBUG_, &consoleDecorator<0>}, + {"error", LogLevel::ERROR, &consoleDecorator<1>}, + {"info", LogLevel::INFO, &consoleDecorator<2>}, + {"log", LogLevel::LOG, &consoleDecorator<3>}, + {"warn", LogLevel::WARN, &consoleDecorator<4>}, +}; + +constexpr size_t kConsoleMethodsCount = kj::size(kConsoleMethods); + +// Each decorator reads its method's saved original from a context embedder-data slot at +// CONSOLE_ORIGINAL_DEBUG + methodIndex, so the table must hold exactly one entry per +// CONSOLE_ORIGINAL_* slot, in the same order. +static_assert(static_cast(jsg::ContextDataSlot::CONSOLE_ORIGINAL_WARN) - + static_cast(jsg::ContextDataSlot::CONSOLE_ORIGINAL_DEBUG) + 1 == + static_cast(kConsoleMethodsCount), + "kConsoleMethods must have one entry per CONSOLE_ORIGINAL_* embedder-data slot, in slot order"); + +void handleLog(jsg::Lock& js, + const Worker::LoggingOptions& loggingOptions, + LogLevel level, + v8::Local original, + const v8::FunctionCallbackInfo& info) { + // Call original V8 implementation so messages sent to connected inspector if any + auto context = js.v8Context(); + int length = info.Length(); + // to pass additional arguments from this function to js' `formatLog` we add arguments to the end + // of the arguments vector, then in formatLog we `pop` these from the vector. + // 3 is just the number of args we currently pass. + v8::LocalVector args(js.v8Isolate, length + 3); + for (auto i: kj::zeroTo(length)) args[i] = info[i]; + jsg::check(original->Call(context, info.This(), length, args.data())); + + // The TryCatch is initialized here to catch cases where the v8 isolate's execution is + // terminating, usually as a result of an infinite loop. We need to perform the initialization + // here because `message` is called multiple times. + v8::TryCatch tryCatch(js.v8Isolate); + auto message = [&]() { + int length = info.Length(); + kj::Vector stringified(length); + for (auto i: kj::zeroTo(length)) { + auto arg = info[i]; + // serializeJson and v8::Value::ToString can throw JS exceptions + // (e.g. for recursive objects) so we eat them here, to ensure logging and non-logging code + // have the same exception behavior. + if (!tryCatch.CanContinue()) { + stringified.add(kj::str("{}")); + break; + } + // The following code checks the `arg` to see if it should be serialised to JSON. + // + // We use the following criteria: if arg is null, a number, a boolean, an array, a string, an + // object or it defines a `toJSON` property that is a function, then the arg gets serialised + // to JSON. + // + // Otherwise we stringify the argument. + js.withinHandleScope([&] { + auto context = js.v8Context(); + bool shouldSerialiseToJson = false; + if (arg->IsNull() || arg->IsNumber() || arg->IsArray() || arg->IsBoolean() || + arg->IsString() || + arg->IsUndefined()) { // This is special cased for backwards compatibility. + shouldSerialiseToJson = true; + } + if (arg->IsObject()) { + v8::Local obj = arg.As(); + v8::Local freshObj = v8::Object::New(js.v8Isolate); + + // Determine whether `obj` is constructed using `{}` or `new Object()`. This ensures + // we don't serialise values like Promises to JSON. + if (obj->GetPrototype()->SameValue(freshObj->GetPrototype()) || + obj->GetPrototype()->IsNull()) { + shouldSerialiseToJson = true; + } + + // Check if arg has a `toJSON` property which is a function. + auto toJSONStr = jsg::v8StrIntern(js.v8Isolate, "toJSON"_kj); + v8::MaybeLocal toJSON = obj->GetRealNamedProperty(context, toJSONStr); + if (!toJSON.IsEmpty()) { + if (jsg::check(toJSON)->IsFunction()) { + shouldSerialiseToJson = true; + } + } + } + + if (kj::runCatchingExceptions([&]() { + // On the off chance the the arg is the request.cf object, let's make + // sure we do not log proxied fields here. + if (shouldSerialiseToJson) { + auto s = js.serializeJson(arg); + // serializeJson returns the string "undefined" for some values (undefined, + // Symbols, functions). We remap these values to null to ensure valid JSON output. + if (s == "undefined"_kj) { + stringified.add(kj::str("null")); + } else { + stringified.add(kj::mv(s)); + } + } else { + stringified.add(js.serializeJson(jsg::check(arg->ToString(context)))); + } + }) != kj::none) { + stringified.add(kj::str("{}")); + }; + }); + } + return kj::str("[", kj::delimited(stringified, ", "_kj), "]"); + }; + + // Only check tracing if console.log() was not invoked at the top level. + KJ_IF_SOME(ioContext, IoContext::tryCurrent()) { + KJ_IF_SOME(tracer, ioContext.getWorkerTracer()) { + auto timestamp = ioContext.now(); + tracer.addLog(ioContext.getInvocationSpanContext(), timestamp, level, message()); + } + } + + if (loggingOptions.consoleMode == Worker::ConsoleMode::INSPECTOR_ONLY) { + // Lets us dump console.log()s to stdout when running test-runner with --verbose flag, to make + // it easier to debug tests. Note that when --verbose is not passed, KJ_LOG(INFO, ...) will + // not even evaluate its arguments, so `message()` will not be called at all. + KJ_LOG(INFO, "console.log()", message()); + } else { + // Write to stdio if allowed by console mode. This is making use of our internal + // built-in implementation of the node:util inspect API. + static const ColorMode COLOR_MODE = permitsColor(); +#if _WIN32 + static bool STDOUT_TTY = _isatty(_fileno(stdout)); + static bool STDERR_TTY = _isatty(_fileno(stderr)); +#else + static bool STDOUT_TTY = isatty(STDOUT_FILENO); + static bool STDERR_TTY = isatty(STDERR_FILENO); +#endif + + // Log warnings and errors to stderr + // Always log to stdout when structuredLogging is enabled. + auto useStderr = level >= LogLevel::WARN && !loggingOptions.structuredLogging; + auto fd = useStderr ? stderr : stdout; + auto tty = useStderr ? STDERR_TTY : STDOUT_TTY; + auto colors = + COLOR_MODE == ColorMode::ENABLED || (COLOR_MODE == ColorMode::ENABLED_IF_TTY && tty); + + constexpr auto kSpecifier = "node-internal:internal_inspect"_kj; + auto inspectModule = KJ_ASSERT_NONNULL(js.resolveInternalModule(kSpecifier)); + v8::Local formatLogVal = inspectModule.get(js, "formatLog"_kj); + KJ_ASSERT(formatLogVal->IsFunction()); + auto formatLog = formatLogVal.As(); + + auto levelStr = logLevelToString(level); + args[length] = js.boolean(colors); + args[length + 1] = js.boolean(loggingOptions.structuredLogging.toBool()); + args[length + 2] = js.strIntern(levelStr); + auto formatted = js.toString( + jsg::check(formatLog->Call(context, js.v8Undefined(), length + 3, args.data()))); + fprintf(fd, "%s\n", formatted.cStr()); + fflush(fd); + } +} + +template +void consoleDecorator(const v8::FunctionCallbackInfo& info) { + auto& js = jsg::Lock::from(info.GetIsolate()); + js.withinHandleScope([&] { + auto original_slot_index = static_cast( + static_cast(jsg::ContextDataSlot::CONSOLE_ORIGINAL_DEBUG) + + static_cast(methodIndex)); + auto original_method_value = + jsg::getContextDataSlot(js.v8Context(), original_slot_index).As(); + KJ_ASSERT(!original_method_value.IsEmpty() && original_method_value->IsFunction(), + "console original method slot was not initialized"); + auto original_function = original_method_value.As(); + auto& isolate = Worker::Isolate::from(js); + handleLog(js, isolate.getLoggingOptions(), kConsoleMethods[methodIndex].level, + original_function, info); + }); +} + +} // namespace + +void Worker::setupContext(jsg::Lock& lock, v8::Local context) { // We replace the default V8 console.log(), etc. methods, to give the worker access to // logged content, and log formatted values to stdout/stderr locally. auto global = context->Global(); auto consoleStr = jsg::v8StrIntern(lock.v8Isolate, "console"); auto console = jsg::check(global->Get(context, consoleStr)).As(); - auto setHandler = [&](const char* method, LogLevel level) { - auto methodStr = jsg::v8StrIntern(lock.v8Isolate, method); - v8::Global original( - lock.v8Isolate, jsg::check(console->Get(context, methodStr)).As()); - - auto f = lock.wrapSimpleFunction(context, - [loggingOptions, level, original = kj::mv(original)]( - jsg::Lock& js, const v8::FunctionCallbackInfo& info) { - handleLog(js, loggingOptions, level, original, info); - }); - jsg::check(console->Set(context, methodStr, f)); - }; + // Skip decorating and saving the originals if they have already been saved. + auto debugSlotIndex = static_cast(jsg::ContextDataSlot::CONSOLE_ORIGINAL_DEBUG); + if (context->GetNumberOfEmbedderDataFields() > debugSlotIndex) { + auto savedDebug = jsg::getContextDataSlot(context, jsg::ContextDataSlot::CONSOLE_ORIGINAL_DEBUG) + .As(); + if (!savedDebug.IsEmpty() && savedDebug->IsFunction()) { + return; + } + } - setHandler("debug", LogLevel::DEBUG_); - setHandler("error", LogLevel::ERROR); - setHandler("info", LogLevel::INFO); - setHandler("log", LogLevel::LOG); - setHandler("warn", LogLevel::WARN); + // Save original methods into context so that GC can track them (so they are captured in a + // snapshot) and we can find them at a known location from the decorator. + for (size_t i = 0; i < kConsoleMethodsCount; ++i) { + auto methodStr = jsg::v8StrIntern(lock.v8Isolate, kConsoleMethods[i].name); + auto original = jsg::check(console->Get(context, methodStr)).As(); + auto slot = static_cast( + static_cast(jsg::ContextDataSlot::CONSOLE_ORIGINAL_DEBUG) + static_cast(i)); + jsg::setContextDataSlot(context, slot, original); + auto decorator = jsg::check(v8::Function::New(context, kConsoleMethods[i].callback)); + jsg::check(console->Set(context, methodStr, decorator)); + } } void Worker::setupContextInternalScripts(jsg::Lock& lock, v8::Local context) { @@ -2162,146 +2356,6 @@ void Worker::processEntrypointClass(jsg::Lock& js, }); } -void Worker::handleLog(jsg::Lock& js, - const LoggingOptions& loggingOptions, - LogLevel level, - const v8::Global& original, - const v8::FunctionCallbackInfo& info) { - // Call original V8 implementation so messages sent to connected inspector if any - auto context = js.v8Context(); - int length = info.Length(); - // to pass additional arguments from this function to js' `formatLog` we add arguments to the end - // of the arguments vector, then in formatLog we `pop` these from the vector. - // 3 is just the number of args we currently pass. - v8::LocalVector args(js.v8Isolate, length + 3); - for (auto i: kj::zeroTo(length)) args[i] = info[i]; - jsg::check(original.Get(js.v8Isolate)->Call(context, info.This(), length, args.data())); - - // The TryCatch is initialized here to catch cases where the v8 isolate's execution is - // terminating, usually as a result of an infinite loop. We need to perform the initialization - // here because `message` is called multiple times. - v8::TryCatch tryCatch(js.v8Isolate); - auto message = [&]() { - int length = info.Length(); - kj::Vector stringified(length); - for (auto i: kj::zeroTo(length)) { - auto arg = info[i]; - // serializeJson and v8::Value::ToString can throw JS exceptions - // (e.g. for recursive objects) so we eat them here, to ensure logging and non-logging code - // have the same exception behavior. - if (!tryCatch.CanContinue()) { - stringified.add(kj::str("{}")); - break; - } - // The following code checks the `arg` to see if it should be serialised to JSON. - // - // We use the following criteria: if arg is null, a number, a boolean, an array, a string, an - // object or it defines a `toJSON` property that is a function, then the arg gets serialised - // to JSON. - // - // Otherwise we stringify the argument. - js.withinHandleScope([&] { - auto context = js.v8Context(); - bool shouldSerialiseToJson = false; - if (arg->IsNull() || arg->IsNumber() || arg->IsArray() || arg->IsBoolean() || - arg->IsString() || - arg->IsUndefined()) { // This is special cased for backwards compatibility. - shouldSerialiseToJson = true; - } - if (arg->IsObject()) { - v8::Local obj = arg.As(); - v8::Local freshObj = v8::Object::New(js.v8Isolate); - - // Determine whether `obj` is constructed using `{}` or `new Object()`. This ensures - // we don't serialise values like Promises to JSON. - if (obj->GetPrototype()->SameValue(freshObj->GetPrototype()) || - obj->GetPrototype()->IsNull()) { - shouldSerialiseToJson = true; - } - - // Check if arg has a `toJSON` property which is a function. - auto toJSONStr = jsg::v8StrIntern(js.v8Isolate, "toJSON"_kj); - v8::MaybeLocal toJSON = obj->GetRealNamedProperty(context, toJSONStr); - if (!toJSON.IsEmpty()) { - if (jsg::check(toJSON)->IsFunction()) { - shouldSerialiseToJson = true; - } - } - } - - if (kj::runCatchingExceptions([&]() { - // On the off chance the the arg is the request.cf object, let's make - // sure we do not log proxied fields here. - if (shouldSerialiseToJson) { - auto s = js.serializeJson(arg); - // serializeJson returns the string "undefined" for some values (undefined, - // Symbols, functions). We remap these values to null to ensure valid JSON output. - if (s == "undefined"_kj) { - stringified.add(kj::str("null")); - } else { - stringified.add(kj::mv(s)); - } - } else { - stringified.add(js.serializeJson(jsg::check(arg->ToString(context)))); - } - }) != kj::none) { - stringified.add(kj::str("{}")); - }; - }); - } - return kj::str("[", kj::delimited(stringified, ", "_kj), "]"); - }; - - // Only check tracing if console.log() was not invoked at the top level. - KJ_IF_SOME(ioContext, IoContext::tryCurrent()) { - KJ_IF_SOME(tracer, ioContext.getWorkerTracer()) { - auto timestamp = ioContext.now(); - tracer.addLog(ioContext.getInvocationSpanContext(), timestamp, level, message()); - } - } - - if (loggingOptions.consoleMode == Worker::ConsoleMode::INSPECTOR_ONLY) { - // Lets us dump console.log()s to stdout when running test-runner with --verbose flag, to make - // it easier to debug tests. Note that when --verbose is not passed, KJ_LOG(INFO, ...) will - // not even evaluate its arguments, so `message()` will not be called at all. - KJ_LOG(INFO, "console.log()", message()); - } else { - // Write to stdio if allowed by console mode. This is making use of our internal - // built-in implementation of the node:util inspect API. - static const ColorMode COLOR_MODE = permitsColor(); -#if _WIN32 - static bool STDOUT_TTY = _isatty(_fileno(stdout)); - static bool STDERR_TTY = _isatty(_fileno(stderr)); -#else - static bool STDOUT_TTY = isatty(STDOUT_FILENO); - static bool STDERR_TTY = isatty(STDERR_FILENO); -#endif - - // Log warnings and errors to stderr - // Always log to stdout when structuredLogging is enabled. - auto useStderr = level >= LogLevel::WARN && !loggingOptions.structuredLogging; - auto fd = useStderr ? stderr : stdout; - auto tty = useStderr ? STDERR_TTY : STDOUT_TTY; - auto colors = - COLOR_MODE == ColorMode::ENABLED || (COLOR_MODE == ColorMode::ENABLED_IF_TTY && tty); - - constexpr auto kSpecifier = "node-internal:internal_inspect"_kj; - auto inspectModule = KJ_ASSERT_NONNULL(js.resolveInternalModule(kSpecifier)); - v8::Local formatLogVal = inspectModule.get(js, "formatLog"_kj); - KJ_ASSERT(formatLogVal->IsFunction()); - auto formatLog = formatLogVal.As(); - - auto levelStr = logLevelToString(level); - args[length] = js.boolean(colors); - args[length + 1] = js.boolean(loggingOptions.structuredLogging.toBool()); - args[length + 2] = js.strIntern(levelStr); - auto formatted = js.toString( - jsg::check(formatLog->Call(context, js.v8Undefined(), length + 3, args.data()))); - fprintf(fd, "%s\n", formatted.cStr()); - fflush(fd); - } -} - Worker::Lock::TakeSynchronously::TakeSynchronously(kj::Maybe requestParam) { KJ_IF_SOME(r, requestParam) { request = &r; diff --git a/src/workerd/io/worker.h b/src/workerd/io/worker.h index 3a4b12c806f..4bc8488d840 100644 --- a/src/workerd/io/worker.h +++ b/src/workerd/io/worker.h @@ -217,8 +217,7 @@ class Worker: public kj::AtomicRefcounted { kj::Promise takeAsyncLockWhenActorCacheReady( kj::Date now, Actor& actor, RequestObserver& request) const; - static void setupContext( - jsg::Lock& lock, v8::Local context, const LoggingOptions& loggingOptions); + static void setupContext(jsg::Lock& lock, v8::Local context); static void setupContextInternalScripts(jsg::Lock& lock, v8::Local context); @@ -243,12 +242,6 @@ class Worker: public kj::AtomicRefcounted { class AsyncWaiter; friend constexpr bool _kj_internal_isPolymorphic(AsyncWaiter*); - static void handleLog(jsg::Lock& js, - const LoggingOptions& loggingOptions, - LogLevel level, - const v8::Global& original, - const v8::FunctionCallbackInfo& info); - void processEntrypointClass(jsg::Lock& js, EntrypointClass cls, EntrypointClasses entrypointClasses, @@ -518,6 +511,14 @@ class Worker::Isolate: public kj::AtomicRefcounted { return loggingOptions.stderrPrefix; } + // Used by the console decorators (see Worker::setupContext) to read the logging options on + // every console.* call, rather than capturing them at context-setup time. + // The decorator is a plain static callback with no captured state so it can be embedded in a V8 + // snapshot, so it has to recover the options from the isolate at call time. + inline const LoggingOptions& getLoggingOptions() const { + return loggingOptions; + } + // Represents a weak reference back to the isolate that code within the isolate can use as an // indirect pointer when they want to be able to race destruction safely. A caller wishing to // use a weak reference to the isolate should acquire a strong reference to weakIsolateRef. diff --git a/src/workerd/jsg/wrappable.h b/src/workerd/jsg/wrappable.h index 849f596b554..0f34132d214 100644 --- a/src/workerd/jsg/wrappable.h +++ b/src/workerd/jsg/wrappable.h @@ -60,6 +60,31 @@ enum class ContextPointerSlot : int { MAX_POINTER_SLOT = BOOTSTRAP_STATE, }; +// V2 (Local) embedder data slots. Read/written via +// SetEmbedderDataV2/GetEmbedderDataV2 — distinct API from the aligned-pointer +// slots above. Indices start past MAX_POINTER_SLOT so the two slot kinds never +// collide in the underlying embedder-data array. +enum class ContextDataSlot : int { + // One slot per decorated console method, holding that method's original v8 function directly. + // MUST stay consecutive and ordered to match the kConsoleMethods table in worker.c++ + // (slot = CONSOLE_ORIGINAL_DEBUG + index). + CONSOLE_ORIGINAL_DEBUG = static_cast(ContextPointerSlot::MAX_POINTER_SLOT) + 1, + CONSOLE_ORIGINAL_ERROR, + CONSOLE_ORIGINAL_INFO, + CONSOLE_ORIGINAL_LOG, + CONSOLE_ORIGINAL_WARN, +}; + +inline void setContextDataSlot( + v8::Local context, ContextDataSlot slot, v8::Local value) { + context->SetEmbedderDataV2(static_cast(slot), value); +} + +inline v8::Local getContextDataSlot( + v8::Local context, ContextDataSlot slot) { + return context->GetEmbedderDataV2(static_cast(slot)); +} + inline void setAlignedPointerInEmbedderData( v8::Local context, ContextPointerSlot slot, void* ptr) { // The type tag is a small integer that should be different for every pointer