[Miniflare 3] Problems with the new logs

[frandiox]

Hi 👋

Thanks a lot for the effort on improving console logging in workerd/Miniflare. Here's some feedback on that feature.

I'm making a CLI for Shopify/Hydrogen apps and, before this feature was released, we relied on inspector connections to get the console logs -- very similar to what Wrangler does but without ink/React, adding sourcemaps, and logging Error objects with cause. Also, we currently overwrite console.error and other methods in the CLI process to enhance well-known errors and warnings. For example, we show a link to a local GraphiQL if the error has certain information in its cause property:

The new console logging is now enabled by default so I could try disabling the custom implementation based on inspector protocol. However, here are some issues I've found:

Each string line is logged in its own console.log call.

For example, calling console.log('first\nsecond') in-app will turn into 2 separate calls to console.log in Miniflare, one per line. This is because Miniflare uses the readline module to pipe logs.

This makes it impossible for us to detect and replace known warnings and errors at the CLI level because they are now split in different console calls.

On top of that, console.warn and console.error come with red color. I think it would be better if Miniflare didn't have any opinion on how these things are printed:

-  const stdout = rl.createInterface(runtime.stdout);
-  const stderr = rl.createInterface(runtime.stderr);
-  stdout.on("line", (data) => console.log(data));
-  stderr.on("line", (data) => console.error(red(data)));
+  runtime.stdout.on("data", (data) => console.log(data.toString()));
+  runtime.stderr.on("data", (data) => console.error(data.toString()));

But I'm not sure if that would break anything in Wrangler. It should still work with Ink since it's turned into console.log calls -- and I think this is a good thing, it's more similar to the in-app code that also calls console.log.

Otherwise, maybe pipeOutput could be an optional parameter in Miniflare?

Logged errors and objects are stringified

This is likely something that Miniflare shouldn't care but still mentioning it here just in case. Since everything comes stringified from workerd and is passed as a string to console, we are not able to detect Error objects anymore and read properties such as Error.cause or Error.stack.

In our current implementation using the inspector, we reconstruct the Error object before calling console.error in the CLI process. We could always change our CLI to use regexps and find the stringified { [cause]: ... }, of course, so it's not the end of the world.

Logged errors don't use sourcemaps

Probably similar to cloudflare/miniflare#729 but unsure if that one was for Miniflare 3 or 2.
As mentioned, logged errors with console.error seem to be stringified in workerd and then streamed to the Miniflare process. Since workerd doesn't implement sourcemaps (afaik), we don't get nice stack traces. This could probably be implemented again around the pipeOutput function since Miniflare is actually aware of sourcemaps.

In our current implementation using the inspector, we are able to add sourcemaps directly there before calling console.error.

Can't disable the new console logging feature

While some of the previous issues are fixable, I think it would be nice to provide an option to simply disable console logging from the app so that we can keep relying on the inspector protocol until everything works well.

For now, we'll probably keep using an older version of Miniflare that doesn't have the console logging feature 👍

[mrbbot]

Hey! 👋 Thank you very much for the detailed feedback! 😃

As you point out, Each string line is logged in its own `console.log` call. and Can't disable the new console logging feature could be addressed by adding something like a pipeOutput option. This would allow us to directly pipe to stdout/stderr by default, and do the console.log()ing in Wrangler where it's required because of Ink. Passing a no-op function would disable logging (and admittedly silence all workerd logs, but this is probably ok if an inspector is connected). This would also allows users to do things like prefix workerd logs, so definitely in favour of adding this option.

For Logged errors and objects are stringified, I'm not sure there's much we can do here. Do you have a single place where you log uncaught exceptions that you want to reconstruct in this way? Could you log some recognisable tag and JSON-serialised error there? If not, you could consider monkeypatching console methods in your worker, but definitely not an ideal solution.

Logged errors don't use sourcemaps is something we're planning to fix. See cloudflare/miniflare#729 (comment).

[frandiox]

Thanks for the quick response!

(and admittedly silence all workerd logs, but this is probably ok if an inspector is connected)

I'd consider this a feature since right now we are manually muting certain workerd logs that are not actionable -- e.g. Network connection lost error when a prefetch is canceled.

so definitely in favour of adding this option

Yay. Not sure the best way to contribute right now since PRs are frozen here cloudflare/miniflare#728 . Or maybe you want to implement this yourself since you have more context on Wrangler/etc to ensure the feature is flexible enough.

Perhaps something to keep in mind: if sourcemap support ends up implemented in the default pipeOutput, it would be nice to still be able to use sourcemaps optionally even if we overwrite the default behavior somehow.

For Logged errors and objects are stringified, I'm not sure there's much we can do here. Do you have a single place where you log uncaught exceptions that you want to reconstruct in this way?

Yeah, as mentioned, it's probably not Miniflare's business. We do include prefixes for well-known errors and warnings so we can just detect that with regexps (as long as they are logged within the same console call 😆 ).

[mrbbot]

Hey! 👋 I'm going to transfer this to workers-sdk as that's the new home for Miniflare 3, and that will make it easier for us to track this. 👍

[Cherry]

I hit this today with console.warn('test warn log') throwing back a:

✘ [ERROR] test warn log