Use stdio log prefixing for process.stdio

src/workerd/api/node/tests/process-stdio-fs-nodejs-test.expected_stderr

@@ -1 +0,0 @@
-Direct writeSync to stderr

src/workerd/api/node/tests/process-stdio-fs-nodejs-test.wd-test

@@ -16,4 +16,8 @@ const unitTests :Workerd.Config = (
       )
     ),
   ],
+  logging = (
+    stdoutPrefix = ">",
+    stderrPrefix = ""
+  )
 );

src/workerd/api/node/tests/process-stdio-nodejs-test.expected_stderr

@@ -1,20 +1,2 @@
-Error Line 1
-Error Line 2
-Error Line 3
-Error First
-
-Error Second with empty line
-Error with trailing newlines
-
-
-Error Start
-Error Mid1
-Error Mid2
-Error End
-Test string write to stderr
-Test buffer write
-Hello
 console.error
 console.error interleaves
-24
-😀

src/workerd/api/node/tests/process-stdio-nodejs-test.wd-test

@@ -14,5 +14,5 @@ const unitTests :Workerd.Config = (
         ],
       )
     ),
-  ],
+  ]
 );

src/workerd/api/node/tests/test_process_stdio.sh

@@ -19,7 +19,7 @@ trap "rm -f $ACTUAL_STDOUT $ACTUAL_STDERR $FILTERED_STDOUT $FILTERED_STDERR" EXI
 "$WORKERD_BINARY" test "$TEST_CONFIG" --experimental >"$ACTUAL_STDOUT" 2>"$ACTUAL_STDERR"
 
 # Remove [ PASS ] [ TEST ] [ FAIL ] lines from stderr
-grep -vE "\[ PASS \]|\[ FAIL \]|\[ TEST \]" "$ACTUAL_STDERR" > "$FILTERED_STDERR"
+grep -vE "\[ PASS \]|\[ FAIL \]|\[ TEST \]" "$ACTUAL_STDERR" > "$FILTERED_STDERR" || true
 
 # Compare with expected output (normalize line endings for cross-platform compatibility)
 echo "Comparing stdout..."

src/workerd/io/worker-fs.c++

@@ -1755,17 +1755,29 @@ class DevRandomFile final: public File, public kj::EnableAddRefToThis<DevRandomF
 void writeStdio(jsg::Lock& js, VirtualFileSystem::Stdio type, kj::ArrayPtr<const kj::byte> bytes) {
   auto chars = bytes.asChars();
   size_t endPos = chars.size();
-  if (chars[endPos - 1] == '\n') endPos--;
+  if (endPos > 0 && chars[endPos - 1] == '\n') endPos--;
 
   KJ_IF_SOME(console, js.global().get(js, "console"_kj).tryCast<jsg::JsObject>()) {
-    auto method = console.get(js, type == VirtualFileSystem::Stdio::OUT ? "log"_kj : "error"_kj);
+    auto method = console.get(js, "log"_kj);
     if (method.isFunction()) {
       v8::Local<v8::Value> methodVal(method);
-      auto methodFunc = methodVal.As<v8::Function>();
-      v8::Local<v8::Value> args[] = {js.str(chars.first(endPos))};
-      jsg::check(methodFunc->Call(js.v8Context(), console, 1, args));
+      auto methodFunc = jsg::JsFunction(methodVal.As<v8::Function>());
+
+      kj::String outputStr;
+      auto isolate = &Worker::Isolate::from(js);
+      auto prefix = type == VirtualFileSystem::Stdio::OUT ? isolate->getStdoutPrefix()
+                                                          : isolate->getStderrPrefix();
+      if (endPos == 0) {
+        methodFunc.call(js, console, js.str(prefix));
+      } else if (prefix.size() > 0) {
+        methodFunc.call(js, console, js.str(kj::str(prefix, " "_kj, chars.first(endPos))));
+      } else {
+        methodFunc.call(js, console, js.str(chars.first(endPos)));
+      }
+      return;
     }
   }
+  KJ_LOG(WARNING, "No console.log implementation available for stdio logging");
 }
 
 // An StdioFile is a special file implementation used to represent stdin,

src/workerd/io/worker.c++

@@ -575,8 +575,7 @@ struct Worker::Isolate::Impl {
           progressCounter(impl.lockSuccessCount),
           oldCurrentApi(currentApi),
           limitEnforcer(isolate.getLimitEnforcer()),
-          consoleMode(isolate.consoleMode),
-          structuredLogging(isolate.structuredLogging),
+          loggingOptions(isolate.loggingOptions),
           lock(isolate.api->lock(stackScope)) {
       WarnAboutIsolateLockScope::maybeWarn();
 
@@ -624,7 +623,7 @@ struct Worker::Isolate::Impl {
         i.get()->contextCreated(
             v8_inspector::V8ContextInfo(context, 1, jsg::toInspectorStringView("Worker")));
       }
-      Worker::setupContext(*lock, context, consoleMode, structuredLogging);
+      Worker::setupContext(*lock, context, loggingOptions);
     }
 
     void disposeContext(jsg::JsContext<api::ServiceWorkerGlobalScope> context) {
@@ -659,11 +658,9 @@ struct Worker::Isolate::Impl {
 
     const IsolateLimitEnforcer& limitEnforcer;  // only so we can call getIsolateStats()
 
-    ConsoleMode consoleMode;
-
     // When structuredLogging is YES AND consoleMode is STDOUT js logs will be emitted to STDOUT
-    // as newline separated json objects.
-    StructuredLogging structuredLogging;
+    // as newline separated json objects
+    LoggingOptions loggingOptions;
 
    public:
     kj::Own<jsg::Lock> lock;
@@ -1019,14 +1016,12 @@ Worker::Isolate::Isolate(kj::Own<Api> apiParam,
     kj::StringPtr id,
     kj::Own<IsolateLimitEnforcer> limitEnforcerParam,
     InspectorPolicy inspectorPolicy,
-    ConsoleMode consoleMode,
-    StructuredLogging structuredLogging)
+    LoggingOptions loggingOptions)
     : metrics(kj::mv(metricsParam)),
       id(kj::str(id)),
       limitEnforcer(kj::mv(limitEnforcerParam)),
       api(kj::mv(apiParam)),
-      consoleMode(consoleMode),
-      structuredLogging(structuredLogging),
+      loggingOptions(loggingOptions),
       featureFlagsForFl(makeCompatJson(decompileCompatibilityFlagsForFl(api->getFeatureFlags()))),
       impl(kj::heap<Impl>(*api, *metrics, *limitEnforcer, inspectorPolicy)),
       weakIsolateRef(WeakIsolateRef::wrap(this)),
@@ -1510,10 +1505,8 @@ void setWebAssemblyModuleHasInstance(jsg::Lock& lock, v8::Local<v8::Context> con
       module->DefineOwnProperty(context, v8::Symbol::GetHasInstance(lock.v8Isolate), function));
 }
 
-void Worker::setupContext(jsg::Lock& lock,
-    v8::Local<v8::Context> context,
-    Worker::ConsoleMode consoleMode,
-    StructuredLogging structuredLogging) {
+void Worker::setupContext(
+    jsg::Lock& lock, v8::Local<v8::Context> context, const LoggingOptions& loggingOptions) {
   // Set WebAssembly.Module @@HasInstance
   setWebAssemblyModuleHasInstance(lock, context);
 
@@ -1529,9 +1522,9 @@ void Worker::setupContext(jsg::Lock& lock,
         lock.v8Isolate, jsg::check(console->Get(context, methodStr)).As<v8::Function>());
 
     auto f = lock.wrapSimpleFunction(context,
-        [consoleMode, level, structuredLogging, original = kj::mv(original)](
+        [loggingOptions, level, original = kj::mv(original)](
             jsg::Lock& js, const v8::FunctionCallbackInfo<v8::Value>& info) {
-      handleLog(js, consoleMode, level, structuredLogging, original, info);
+      handleLog(js, loggingOptions, level, original, info);
     });
     jsg::check(console->Set(context, methodStr, f));
   };
@@ -1846,9 +1839,8 @@ void Worker::processEntrypointClass(jsg::Lock& js,
 }
 
 void Worker::handleLog(jsg::Lock& js,
-    ConsoleMode consoleMode,
+    const LoggingOptions& loggingOptions,
     LogLevel level,
-    StructuredLogging structuredLogging,
     const v8::Global<v8::Function>& original,
     const v8::FunctionCallbackInfo<v8::Value>& info) {
   // Call original V8 implementation so messages sent to connected inspector if any
@@ -1945,7 +1937,7 @@ void Worker::handleLog(jsg::Lock& js,
     }
   }
 
-  if (consoleMode == ConsoleMode::INSPECTOR_ONLY) {
+  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.
@@ -1964,7 +1956,7 @@ void Worker::handleLog(jsg::Lock& js,
 
     // Log warnings and errors to stderr
     // Always log to stdout when structuredLogging is enabled.
-    auto useStderr = level >= LogLevel::WARN && !structuredLogging;
+    auto useStderr = level >= LogLevel::WARN && !loggingOptions.structuredLogging;
     auto fd = useStderr ? stderr : stdout;
     auto tty = useStderr ? STDERR_TTY : STDOUT_TTY;
     auto colors =
@@ -1978,7 +1970,7 @@ void Worker::handleLog(jsg::Lock& js,
 
     auto levelStr = logLevelToString(level);
     args[length] = v8::Boolean::New(js.v8Isolate, colors);
-    args[length + 1] = v8::Boolean::New(js.v8Isolate, bool(structuredLogging));
+    args[length + 1] = v8::Boolean::New(js.v8Isolate, bool(loggingOptions.structuredLogging));
     args[length + 2] = jsg::v8StrIntern(js.v8Isolate, levelStr);
     auto formatted = js.toString(
         jsg::check(formatLog->Call(context, js.v8Undefined(), length + 3, args.data())));
@@ -3252,7 +3244,7 @@ void Worker::Isolate::logWarning(kj::StringPtr description, Lock& lock) {
     });
   }
 
-  if (consoleMode == ConsoleMode::INSPECTOR_ONLY) {
+  if (loggingOptions.consoleMode == Worker::ConsoleMode::INSPECTOR_ONLY) {
     // Run with --verbose to log JS exceptions to stderr. Useful when running tests.
     KJ_LOG(INFO, "console warning", description);
   } else {

src/workerd/io/worker.h

@@ -35,6 +35,7 @@ class Isolate;
 namespace workerd {
 
 WD_STRONG_BOOL(StructuredLogging);
+WD_STRONG_BOOL(ProcessStdioPrefixed);
 
 namespace api {
 class DurableObjectState;
@@ -120,6 +121,36 @@ class Worker: public kj::AtomicRefcounted {
     STDOUT,
   };
 
+  struct LoggingOptions {
+    ConsoleMode consoleMode = Worker::ConsoleMode::INSPECTOR_ONLY;
+    StructuredLogging structuredLogging = StructuredLogging::NO;
+    ProcessStdioPrefixed processStdioPrefixed = ProcessStdioPrefixed::YES;
+    kj::String stdoutPrefix = kj::str("stdout:"_kj);
+    kj::String stderrPrefix = kj::str("stderr:"_kj);
+
+    LoggingOptions() = default;
+    LoggingOptions(LoggingOptions&&) = default;
+    LoggingOptions& operator=(LoggingOptions&&) = default;
+
+    explicit LoggingOptions(ConsoleMode mode): consoleMode(mode) {}
+
+    LoggingOptions(const LoggingOptions& other)
+        : consoleMode(other.consoleMode),
+          structuredLogging(other.structuredLogging),
+          processStdioPrefixed(other.processStdioPrefixed),
+          stdoutPrefix(kj::str(other.stdoutPrefix)),
+          stderrPrefix(kj::str(other.stderrPrefix)) {}
+
+    LoggingOptions& operator=(const LoggingOptions& other) {
+      consoleMode = other.consoleMode;
+      structuredLogging = other.structuredLogging;
+      processStdioPrefixed = other.processStdioPrefixed;
+      stdoutPrefix = kj::str(other.stdoutPrefix);
+      stderrPrefix = kj::str(other.stderrPrefix);
+      return *this;
+    }
+  };
+
   explicit Worker(kj::Own<const Script> script,
       kj::Own<WorkerObserver> metrics,
       kj::FunctionParam<void(jsg::Lock& lock,
@@ -185,10 +216,8 @@ class Worker: public kj::AtomicRefcounted {
   void setConnectOverride(kj::String networkAddress, ConnectFn connectFn);
   kj::Maybe<ConnectFn&> getConnectOverride(kj::StringPtr networkAddress);
 
-  static void setupContext(jsg::Lock& lock,
-      v8::Local<v8::Context> context,
-      Worker::ConsoleMode consoleMode,
-      StructuredLogging structuredLogging);
+  static void setupContext(
+      jsg::Lock& lock, v8::Local<v8::Context> context, const LoggingOptions& loggingOptions);
 
  private:
   kj::Own<const Script> script;
@@ -214,9 +243,8 @@ class Worker: public kj::AtomicRefcounted {
   friend constexpr bool _kj_internal_isPolymorphic(AsyncWaiter*);
 
   static void handleLog(jsg::Lock& js,
-      ConsoleMode mode,
+      const LoggingOptions& loggingOptions,
       LogLevel level,
-      StructuredLogging structuredLogging,
       const v8::Global<v8::Function>& original,
       const v8::FunctionCallbackInfo<v8::Value>& info);
 
@@ -334,8 +362,7 @@ class Worker::Isolate: public kj::AtomicRefcounted {
       kj::StringPtr id,
       kj::Own<IsolateLimitEnforcer> limitEnforcer,
       InspectorPolicy inspectorPolicy,
-      ConsoleMode consoleMode = ConsoleMode::INSPECTOR_ONLY,
-      StructuredLogging structuredLogging = StructuredLogging::NO);
+      LoggingOptions loggingOptions = {});
 
   ~Isolate() noexcept(false);
   KJ_DISALLOW_COPY_AND_MOVE(Isolate);
@@ -451,6 +478,15 @@ class Worker::Isolate: public kj::AtomicRefcounted {
 
   bool isInspectorEnabled() const;
 
+  // Get the process stdio prefixed setting from logging options
+  inline kj::StringPtr getStdoutPrefix() const {
+    return loggingOptions.stdoutPrefix;
+  }
+
+  inline kj::StringPtr getStderrPrefix() const {
+    return loggingOptions.stderrPrefix;
+  }
+
   // 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.
@@ -479,8 +515,7 @@ class Worker::Isolate: public kj::AtomicRefcounted {
   kj::String id;
   kj::Own<IsolateLimitEnforcer> limitEnforcer;
   kj::Own<Api> api;
-  ConsoleMode consoleMode;
-  StructuredLogging structuredLogging;
+  LoggingOptions loggingOptions;
 
   // If non-null, a serialized JSON object with a single "flags" property, which is a list of
   // compatibility enable-flags that are relevant to FL.

src/workerd/server/server-test.c++

@@ -326,7 +326,7 @@ class TestServer final: private kj::Filesystem, private kj::EntropySource, priva
             timer,
             mockNetwork,
             *this,
-            consoleMode,
+            Worker::LoggingOptions(consoleMode),
             [this](kj::String error) {
               if (expectedErrors.startsWith(error) && expectedErrors[error.size()] == '\n') {
                 expectedErrors = expectedErrors.slice(error.size() + 1);
@@ -5162,28 +5162,28 @@ KJ_TEST("Server: structured logging with console methods") {
   // process.stdout should be logs split by newline
   expectLogLine(interceptorPipe.output.get(), [](kj::StringPtr logline) {
     KJ_ASSERT(logline.contains(R"("level":"log")"), logline);
-    KJ_ASSERT(logline.contains(R"("message":"stdoutstdout with")"), logline);
+    KJ_ASSERT(logline.contains(R"("message":"stdout: stdoutstdout with")"), logline);
   });
 
   expectLogLine(interceptorPipe.output.get(), [](kj::StringPtr logline) {
     KJ_ASSERT(logline.contains(R"("level":"log")"), logline);
-    KJ_ASSERT(logline.contains(R"("message":"multiple")"), logline);
+    KJ_ASSERT(logline.contains(R"("message":"stdout: multiple")"), logline);
   });
 
   expectLogLine(interceptorPipe.output.get(), [](kj::StringPtr logline) {
     KJ_ASSERT(logline.contains(R"("level":"log")"), logline);
-    KJ_ASSERT(logline.contains(R"("message":"newlines")"), logline);
+    KJ_ASSERT(logline.contains(R"("message":"stdout: newlines")"), logline);
   });
 
   expectLogLine(interceptorPipe.output.get(), [](kj::StringPtr logline) {
     KJ_ASSERT(logline.contains(R"("level":"log")"), logline);
-    KJ_ASSERT(logline.contains(R"("message":"logged")"), logline);
+    KJ_ASSERT(logline.contains(R"("message":"stdout: logged")"), logline);
   });
 
   // process.stderr should be info
   expectLogLine(interceptorPipe.output.get(), [](kj::StringPtr logline) {
-    KJ_ASSERT(logline.contains(R"("level":"error")"), logline);
-    KJ_ASSERT(logline.contains(R"("message":"stderr")"), logline);
+    KJ_ASSERT(logline.contains(R"("level":"log")"), logline);
+    KJ_ASSERT(logline.contains(R"("message":"stderr: stderr")"), logline);
   });
 
   expectLogLine(interceptorPipe.output.get(), [](kj::StringPtr logline) {
@@ -5195,8 +5195,8 @@ KJ_TEST("Server: structured logging with console methods") {
   });
 
   expectLogLine(interceptorPipe.output.get(), [](kj::StringPtr logline) {
-    KJ_ASSERT(logline.contains(R"("level":"error")"), logline);
-    KJ_ASSERT(logline.contains(R"("message":"after await")"), logline);
+    KJ_ASSERT(logline.contains(R"("level":"log")"), logline);
+    KJ_ASSERT(logline.contains(R"("message":"stderr: after await")"), logline);
   });
 }