Implement Node-like `console.log()`ing #1294

mrbbot · 2023-10-10T14:16:23Z

Hey! 👋 This PR...

Changes console.log() to log directly to stdout/err, regardless of whether the --verbose flag is set
Uses Node's util.inspect() function to stringify values as opposed to JSON.stringify()
Logs to the console even if an inspector is connected
Closes [feature request] console output #52 and 🐛 BUG: Regression with console.log-ing objects workers-sdk#3591

The end result is easier-to-read, detailed, coloured logs when running workerd locally. As an example, with the following script:

export default {
  async fetch(request, env, ctx) {
    console.log({ a: { b: 2 }, c: "x".repeat(50) });
    console.log(request.headers);
    console.log(new Map([["a", 1], ["b", 2], ["c", 3]]));
    console.log(new Set([1, 2, 3]));
    return new Response();
  }
}

Before:

After:

Follow-up tasks:

Adopt util.inspect() from Node.js: the current polyfill has a few limitations. We should be able to implement the required native code to get around these.
Switch to util.formatWithOptions() for formatting: this will add support printf-style % strings, as required for console.log()
Export util.inspect(): if our util.inspect() function matches Node's, we should be able to export it from the node:util module if nodejs_compat is enabled.
Custom inspects: some built-in classes have internal state that would be good to log. For example, logging request.headers above should probably log something similar to the Map.
Unhandled exception logging: unhandled JavaScript exceptions should probably be logged in a similar way, and should definitely include the stack trace if we've got one.

src/node/internal/inspect_polyfill.d.ts

src/workerd/io/worker.c++

mrbbot · 2023-10-10T14:20:33Z

src/workerd/io/worker.c++

+    // 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());


I was going to remove this line completely, but there are some tests in server-test.c++ that expect logs to be written, and intercepting fprintf didn't seem like a good idea. Maybe it would be better to pass an output stream for writing to, instead of using fprintf directly? This was definitely simpler though... 😃

Yeah, for this I'm not sure. These end up being non-ops in production. @kentonv any thoughts on this one?

src/workerd/jsg/modules.h

mrbbot · 2023-10-10T14:23:27Z

src/workerd/io/worker.h

@@ -78,6 +78,13 @@ class Worker: public kj::AtomicRefcounted {

  class LockType;

+  enum ConsoleMode {
+    // Only send `console.log`s to the inspector
+    INSPECTOR_ONLY,


INSPECTOR_ONLY is the previous behaviour, and the default. STDOUT must be explicitly enabled. The production runtime will continue to have the previous behaviour,

I would add this additional detail into the comment, tbh.

mrbbot · 2023-10-10T15:00:48Z

src/workerd/io/worker.c++

+      auto setHandler = [&](const char* method, LogLevel level) {
+        auto methodStr = jsg::v8StrIntern(lock->v8Isolate, method);
+        v8::Global<v8::Function> original(
+          lock->v8Isolate, jsg::check(console->Get(context, methodStr)).As<v8::Function>());
+
+        auto f = lock->wrapSimpleFunction(context,
+            [mode, level, original = kj::mv(original)](jsg::Lock& js,
+                const v8::FunctionCallbackInfo<v8::Value>& info) {
+          handleLog(js, mode, level, original, info);
+        });
+        jsg::check(console->Set(context, methodStr, f));
+      };
+
+      setHandler("debug", LogLevel::DEBUG_);
+      setHandler("error", LogLevel::ERROR);
+      setHandler("info", LogLevel::INFO);
+      setHandler("log", LogLevel::LOG);
+      setHandler("warn", LogLevel::WARN);


While I was looking into calling the original console methods, I came across https://source.chromium.org/chromium/chromium/src/+/main:v8/src/d8/d8-console.h. Is there a reason we don't use ConsoleDelegate for this custom console stuff? Is it because we wouldn't be able to link up logs with the correct worker or something like that?

Good question. This particular bit predates me so I'm not sure and I haven't looked into it yet. @kentonv might have some insight. It might be that ConsoleDelegate would just work but no one has tried? Really not sure.

irvinebroque · 2023-10-10T17:45:25Z

Amazing. Thank you @mrbbot!

src/node/internal/internal_types.ts

src/workerd/jsg/modules.h

src/workerd/jsg/jsvalue.h

src/workerd/io/worker.c++

jasnell · 2023-10-17T14:51:31Z

Extremely happy to see this! Initial review pass looks very good but I want to take a more detailed dig through a bit later.

jasnell · 2023-10-17T14:52:21Z

One clarifying question: You say, "Logs to the console even if an inspector is connected" ... it still logs to the inspector in that case tho, correct?

mrbbot · 2023-10-17T14:56:56Z

it still logs to the inspector in that case tho, correct?

Yep, it logs to both the inspector and the console. 👍

src/workerd/api/node/node.h

jasnell · 2023-10-17T20:45:52Z

@mrbbot ... I'm marking this "needs-internal-pr" to ensure that we get a good internal CI run with this change before it lands. I just want to verify in CI that the default behavior on internal builds remains unchanged.

Otherwise, other than the few comments I've already left, this LGTM. Once we have the internal CI run and you're done with whatever additional edits you want to make here, I'll approve the PR.

mrbbot · 2023-10-18T17:34:06Z

@jasnell Internal PR #6521 is now passing tests. I've applied your suggestions, so I think this is ready to go. 👍

mrbbot requested a review from jasnell October 10, 2023 14:16

mrbbot commented Oct 10, 2023

View reviewed changes

mrbbot marked this pull request as ready for review October 10, 2023 14:23

mrbbot commented Oct 10, 2023

View reviewed changes

mrbbot commented Oct 17, 2023

View reviewed changes

src/node/internal/internal_types.ts Show resolved Hide resolved

jasnell reviewed Oct 17, 2023

View reviewed changes

src/workerd/jsg/modules.h Show resolved Hide resolved

jasnell reviewed Oct 17, 2023

View reviewed changes

src/workerd/jsg/jsvalue.h Show resolved Hide resolved

jasnell reviewed Oct 17, 2023

View reviewed changes

src/workerd/io/worker.c++ Outdated Show resolved Hide resolved

jasnell reviewed Oct 17, 2023

View reviewed changes

src/workerd/api/node/node.h Outdated Show resolved Hide resolved

jasnell added the needs-internal-pr label Oct 17, 2023

mrbbot force-pushed the bcoll/pretty-console-logging branch from 50bbc20 to 0cc40a7 Compare October 18, 2023 14:26

mrbbot added 8 commits October 18, 2023 15:27

Implement Node-like console.log()ing

2f0a2d2

Adopt Node inspect.js

b176653

Adapt Node inspect.js for workerd and use for logging

9890de0

Use util.inspect() in Node internals

b382322

Implement custom inspector for JSG resource types

64c2d8f

Show Headers immutability when inspecting

6f562c4

Show Readable/WriteableStream state when inspecting

cb6f3d7

Move node-internal:inspect into node-internal:util

4daaf83

mrbbot force-pushed the bcoll/pretty-console-logging branch from 0cc40a7 to 4daaf83 Compare October 18, 2023 14:33

mrbbot requested a review from jasnell October 18, 2023 17:34

mrbbot removed the needs-internal-pr label Oct 18, 2023

jasnell approved these changes Oct 18, 2023

View reviewed changes

jasnell merged commit 713d982 into main Oct 18, 2023
7 of 8 checks passed

jasnell deleted the bcoll/pretty-console-logging branch October 18, 2023 23:23

This was referenced Oct 19, 2023

🐛 BUG: Regression with console.log-ing objects cloudflare/workers-sdk#3591

Closed

Fix Node-like console.log()ing when spawning from Node #1343

Merged

0xakihiko mentioned this pull request Oct 25, 2023

🐛 Bug Report — console.log() behaviour changed, possibly unintentionally? #1344

Closed

frandiox mentioned this pull request Oct 30, 2023

[Miniflare 3] Problems with the new logs cloudflare/workers-sdk#4357

Open

This was referenced Oct 30, 2023

Temporarily disable Node-style logging for service workers #1364

Merged

[wrangler] Log Error#cause and DOMException reasons when running wrangler dev cloudflare/workers-sdk#2851

Closed

mrbbot mentioned this pull request Nov 10, 2023

🐛 BUG: 3.15.0 breaks Remix HMR with "TypeError: error loading dynamically imported module" cloudflare/workers-sdk#4318

Closed

RamIdeas mentioned this pull request Nov 13, 2023

startDevWorker Milestone 1 - Reboot cloudflare/workers-sdk#4413

Merged

6 tasks

mrbbot mentioned this pull request Nov 28, 2023

Log warnings directly to stderr locally #1444

Merged

mrbbot mentioned this pull request Feb 16, 2024

Ignore unimplemented resource type properties in util.inspect() #1679

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Implement Node-like `console.log()`ing #1294

Implement Node-like `console.log()`ing #1294

mrbbot commented Oct 10, 2023 •

edited

Loading

mrbbot Oct 10, 2023

jasnell Oct 17, 2023

mrbbot Oct 10, 2023

jasnell Oct 17, 2023

mrbbot Oct 10, 2023

jasnell Oct 17, 2023

irvinebroque commented Oct 10, 2023

jasnell commented Oct 17, 2023

jasnell commented Oct 17, 2023

mrbbot commented Oct 17, 2023

jasnell commented Oct 17, 2023

mrbbot commented Oct 18, 2023 •

edited

Loading

Implement Node-like console.log()ing #1294

Implement Node-like console.log()ing #1294

Conversation

mrbbot commented Oct 10, 2023 • edited Loading

mrbbot Oct 10, 2023

Choose a reason for hiding this comment

jasnell Oct 17, 2023

Choose a reason for hiding this comment

mrbbot Oct 10, 2023

Choose a reason for hiding this comment

jasnell Oct 17, 2023

Choose a reason for hiding this comment

mrbbot Oct 10, 2023

Choose a reason for hiding this comment

jasnell Oct 17, 2023

Choose a reason for hiding this comment

irvinebroque commented Oct 10, 2023

jasnell commented Oct 17, 2023

jasnell commented Oct 17, 2023

mrbbot commented Oct 17, 2023

jasnell commented Oct 17, 2023

mrbbot commented Oct 18, 2023 • edited Loading

Implement Node-like `console.log()`ing #1294

Implement Node-like `console.log()`ing #1294

mrbbot commented Oct 10, 2023 •

edited

Loading

mrbbot commented Oct 18, 2023 •

edited

Loading