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