Skip to content

Conversation

guybedford
Copy link
Contributor

@guybedford guybedford commented Sep 3, 2025

Another process follow-on that we determined could be made as an incremental improvement post-unflagging.

Instead of treating process.stderr as a console.error instead treating process.stderr as a console.debug call.

In addition, this updates the STDOUT ConsoleMode to use stderr when outputting LogLevel::DEBUG_ in workerd server.

This seems to more closely align with the semantic meaning of stderr but we would need to verify the DX here.

@guybedford guybedford requested review from a team as code owners September 3, 2025 20:05
@guybedford
Copy link
Contributor Author

This is causing a Miniflare failure here:


  index › Miniflare: logs are treated as standard stdout/stderr chunks be default

  test/index.spec.ts:3422

   3421:                                                            
   3422:   t.is(collected.stdout, "__LOG__\n__INFO__\n__DEBUG__\n");
   3423:   t.is(collected.stderr, "__WARN__\n__ERROR__\n");         

  Difference (- actual, + expected):

    `__LOG__␊
    __INFO__␊
  + __DEBUG__␊
    `

  › <anonymous> (test/index.spec.ts:3422:4)

  ─

  1 test failed

so the question is whether this needs a compat flag / or can be done as a non-breaking change - if we want to go in this direction.

@jasnell
Copy link
Collaborator

jasnell commented Sep 4, 2025

@cloudflare/wrangler team.. if you can help with the above error

Copy link
Collaborator

@jasnell jasnell left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM once the workers-sdk test failure is worked out

@guybedford
Copy link
Contributor Author

Note that one competing concern with this approach is that having console.debug output to stderr instead of stdout would be contrary to what all other server runtimes do when working with console logging in the terminal. So the question is is that difference worth making to try to align with the supposed better convention here.

@guybedford
Copy link
Contributor Author

Posted cloudflare/workers-sdk#10560 on Miniflare. I think this is the right way to go, just important to be explicit about tradeoffs.

@vicb
Copy link
Contributor

vicb commented Sep 8, 2025

@guybedford I must admit that I don't not fully understand the changes and their implications in this PR. Could you please answer a few questions to help me understand (I think it's worth adding the answers/info in the PR description).

IIUC the main change in this PR is that process.stderr will use console.debug vs console.error, is that right?

Maybe you can add a code snippet with the behavior before and after this PR to better explain how users will be affected.

You say:

This seems to more closely align with the semantic meaning of stderr but we would need to verify the DX here.

What do other runtimes do today (Node, Bun, Deno) do today?
What does unenv does today - i.e. wrangler dev with the nodejs_compat flag?

Note that one competing concern with this approach is that having console.debug output to stderr instead of stdout would be contrary to what all other server runtimes do when working with console logging in the terminal. So the question is is that difference worth making to try to align with the supposed better convention here.

This seems to indicate that other runtimes are doing differently.
I think it would help if you can explain in more details why you think it's worth using a different behavior for workerd.

@guybedford
Copy link
Contributor Author

guybedford commented Sep 8, 2025

Could you please answer a few questions to help me understand (I think it's worth adding the answers/info in the PR description).

Absolutely.

IIUC the main change in this PR is that process.stderr will use console.debug vs console.error, is that right?

Yes, exactly.

What do other runtimes do today (Node, Bun, Deno) do today?
What does unenv does today - i.e. wrangler dev with the nodejs_compat flag?

All JS runtimes print console.debug to stdout not to stderr. But we are not a terminal-based JS runtime operating on terminal stdio like them. Our stdio is a logging side effect of the server, not a developer output, and our debugging target is the inspector and granular log entries, not stdio streams.

I think it would help if you can explain in more details why you think it's worth using a different behavior for workerd.

Since our primary logging output is granular console entries and not raw terminal-style stdio, if we route process.stderr.write('debugging info') into console.error we would be emitting inspector logs with red error boxes and JSON logs like { type: "error", msg: "debugging info" }. The concern here is thus incorrectly triggering error paths in debugging workflows for these log streams when process.stderr is typically very often used for debugs and warnings that aren't critical errors.

The tradeoff is in aligning inspector logging and JSON logging with browser-style logging, where we effectively prioritise the browser conventions of avoiding noisy console.error being a "big red box", which is in direct opposition to the Node.js conventions of console.debug writing to stdout instead of stderr (which could actually be understood to be a mistake, that everyone followed).

@guybedford
Copy link
Contributor Author

Conversely - if I am over-indexing on the importance of not creating "error" log entries from line-split debugging output, and that this is not a real concern for degbugging workflows, please let me know too. My knowledge of the various consumers of these worker log streams is limited. But I would have assumed that in all of the sinks, there's a filter for "error" logs, and a count, which we likely don't want to be adding to for non-errors (Node.js libs may output process.stderr.write() for simple info messages)?

@vicb
Copy link
Contributor

vicb commented Sep 8, 2025

Thanks for your answer, I'll unpack all of that tomorrow.

I think it would also help to have a clear view about the differences from today, i.e.

What does unenv does today - i.e. wrangler dev with the nodejs_compat flag?

That is what will be different

  • for dev (wrangler dev)
  • for deployed applications (in the dashboard when observability is enabled)

@guybedford
Copy link
Contributor Author

Today, unenv treats process.stdout and process.stderr as otherwise unused streams, so by default I believe they don't get output? It would be worth verifying though, perhaps there is a configuration that sends them somewhere? Would be good to verify as a first step indeed.

@vicb
Copy link
Contributor

vicb commented Sep 8, 2025

Today, unenv treats process.stdout and process.stderr as otherwise unused streams, so by default I believe they don't get output? It would be worth verifying though, perhaps there is a configuration that sends them somewhere? Would be good to verify as a first step indeed.

Should we also check how unenv is handling console.debug(...)?
Can you think of a that that would check the behavior of the current wrangler vs this PR?

@guybedford
Copy link
Contributor Author

Should we also check how unenv is handling console.debug(...)?

I don't believe unenv alters console.debug, or otherwise uses it?

Can you think of a that that would check the behavior of the current wrangler vs this PR?

Consider for example a npm library using https://www.npmjs.com/package/debug. All debug output will be written to process.stderr. With unenv it would all be swallowed and invisible. With the new process implementation each line of debug info will be emitted individually as "error" console log types in the inspector and logs.

Attaching to the worker logs would show a large number of errors in the logs, when these are not errors.

We can either wait for this problem to hit us, or we can resolve the issue now. Up to you.

@vicb
Copy link
Contributor

vicb commented Sep 9, 2025

We can either wait for this problem to hit us, or we can resolve the issue now. Up to you.

I would prefer to handle this now that I have the context into memory.

And again what I am looking for here is to really understand what the impacts will be for end users:

  • are they still going to see all of their logs in the console during development and in the dashboard for deployed app with observability enabled
  • might console.debug be reported as an error for dev or deployed app
  • ...

The fact that tests need to be updated with this PR tells me that the behavior has changed. How will this impact users.

It might be easier to VC to discuss about that - feel free to pick a slot in my calendar when I'm available.

Consider for example a npm library using https://www.npmjs.com/package/debug. All debug output will be written to process.stderr. With unenv it would all be swallowed and invisible. With the new process implementation each line of debug info will be emitted individually as "error" console log types in the inspector and logs.

Using debug works fine today with wrangler/unenv:

[wrangler:info] Ready on http://localhost:8787
2025-09-09T07:52:27.517Z test debug message

(form an earlier message on this thread) Today, unenv treats process.stdout and process.stderr as otherwise unused streams, so by default I believe they don't get output? It would be worth verifying though

unenv actually uses the tty streams which direct the output to console.log

I created a sample test app to verify:

// logs "stdout"
process.stdout.write('stdout');
// logs "stderr"
process.stderr.write('stderr');

@petebacondarwin
Copy link
Contributor

Today, unenv treats process.stdout and process.stderr as otherwise unused streams, so by default I believe they don't get output? It would be worth verifying though, perhaps there is a configuration that sends them somewhere? Would be good to verify as a first step indeed.

So it looks like this is not accurate, given the links to unenv from @vicb above?
In other words, when using unenv, process.stderr.write() and process.stdout.write() both result in calls to console.log()?

https://github.com/unjs/unenv/blob/5677b8881beb69f5a329bb0c624bf9e220d26f95/src/runtime/node/internal/process/process.ts#L64-L70

  get stdout() {
    return (this.#stdout ??= new WriteStream(1) as NodeJS.Process["stdout"]);
  }

  get stderr() {
    return (this.#stderr ??= new WriteStream(2) as NodeJS.Process["stderr"]);
  }

and

https://github.com/unjs/unenv/blob/5677b8881beb69f5a329bb0c624bf9e220d26f95/src/runtime/node/internal/tty/write-stream.ts#L60-L69

  write(str: unknown, encoding?: unknown, cb?: unknown): boolean {
    if (str instanceof Uint8Array) {
      str = new TextDecoder().decode(str);
    }
    try {
      console.log(str);
    } catch {}
    cb && typeof cb === "function" && cb();
    return false;
  }

@petebacondarwin
Copy link
Contributor

I think that with this PR's change (once the unenv polyfill is removed) the process.stderr.write() will result in a call to console.debug()? So if users had their log level set to INFO then they would no longer see these messages?

But equally if the current runtime set up is used (once the unenv polyfill is removed) would we start to see that process.stderr.write() will result in a call to console.error()? Also a breaking change?

Is the least breaking approach to send process.stderr.write() to console.log()?

@petebacondarwin
Copy link
Contributor

petebacondarwin commented Sep 9, 2025

If I understand, though, in Wrangler we now use "structured logging" which I think means that none of this has any effect?
This might be why only Miniflare tests are broken, since Wrangler doesn't rely upon handleRuntimeStdio() in the same way, since everything will come through stdout? Although I think the structure logs from process.stderr.write() would be marked as debug rather than error and Wrangler will then process these accordingly which could be breaking.

Perhaps we need to make sure that these tests still pass with this PR?

https://github.com/cloudflare/workers-sdk/blob/5cb806f41cc95442b2e4f7047459b1d312da9da6/fixtures/worker-logs/tests/index.test.ts

@petebacondarwin
Copy link
Contributor

I note that we are not yet using structuredLogging in the Vite plugin and the Vitest integration:

https://github.com/cloudflare/workers-sdk/blob/443d1f1e625226595d901d91bc930ffb464f100d/packages/vite-plugin-cloudflare/src/miniflare-options.ts#L537-L543

		handleRuntimeStdio(stdout, stderr) {
			const decoder = new TextDecoder();
			stdout.forEach((data) => logger.info(decoder.decode(data)));
			stderr.forEach((error) =>
				logger.logWithLevel(LogLevel.ERROR, decoder.decode(error))
			);
		},

and

https://github.com/cloudflare/workers-sdk/blob/443d1f1e625226595d901d91bc930ffb464f100d/packages/vitest-pool-workers/src/pool/index.ts#L140-L150

function handleRuntimeStdio(stdout: Readable, stderr: Readable): void {
	stdout.on("data", (chunk: Buffer) => {
		process.stdout.write(chunk);
	});
	stderr.on("data", (chunk: Buffer) => {
		const str = trimSymbolizerWarning(chunk.toString());
		if (ignoreMessages.some((message) => str.includes(message))) {
			return;
		}
		process.stderr.write(str);
	});

So I expect that this PR would also be a breaking change for these.

We could/should consider moving these over to use structuredLogging instead but then it would have the same concerns as Wrangler.

@petebacondarwin
Copy link
Contributor

I built workerd from this PR and then ran it locally with the changes in cloudflare/workers-sdk#10577.
I then updated the worker-logs fixture to include:

process.stderr.write("<<<<<this is a stderr message>>>>>\n");
process.stdout.write("<<<<<this is a stdout message>>>>>\n");

and in the basic test (where log level is default) we get:

without this change:

[31mX �[41;31m[�[41;97mERROR�[41;31m]�[0m �[1m<<<<<this is a stderr message>>>>>�[0m
[31mX �[41;31m[�[41;97mERROR�[41;31m]�[0m �[1m<<<<<this is an error>>>>>�[0m
[33m▲ �[43;33m[�[43;30mWARNING�[43;33m]�[0m �[1m<<<<<this is a warning>>>>>�[0m
<<<<<this is a log>>>>>
<<<<<this is a stdout message>>>>>

with this change

[31mX �[41;31m[�[41;97mERROR�[41;31m]�[0m �[1m<<<<<this is an error>>>>>�[0m
[33m▲ �[43;33m[�[43;30mWARNING�[43;33m]�[0m �[1m<<<<<this is a warning>>>>>�[0m
<<<<<this is a log>>>>>
<<<<<this is a stdout message>>>>>

so the stderr message is disappearing, which concurs with our discussions above.

And then with debug logging:

without this change:

�[31mX �[41;31m[�[41;97mERROR�[41;31m]�[0m �[1m<<<<<this is a stderr message>>>>>�[0m
�[31mX �[41;31m[�[41;97mERROR�[41;31m]�[0m �[1m<<<<<this is an error>>>>>�[0m
�[33m▲ �[43;33m[�[43;30mWARNING�[43;33m]�[0m �[1m<<<<<this is a warning>>>>>�[0m
<<<<<this is a debug message>>>>>
<<<<<this is a log>>>>>
<<<<<this is a stdout message>>>>>
<<<<<this is an info message>>>>>

with this change

 [31mX �[41;31m[�[41;97mERROR�[41;31m]�[0m �[1m<<<<<this is an error>>>>>�[0m
 [33m▲ �[43;33m[�[43;30mWARNING�[43;33m]�[0m �[1m<<<<<this is a warning>>>>>�[0m
<<<<<this is a debug message>>>>>
<<<<<this is a log>>>>>
<<<<<this is a stderr message>>>>>
<<<<<this is a stdout message>>>>>
<<<<<this is an info message>>>>>

Note that the stderr message has moved from error level to debug level.

@petebacondarwin
Copy link
Contributor

I guess the questions are:

  1. is this a breaking change (in which case perhaps it needs its own compat flag and date)
  2. do we actually want this behaviour?

My preference is 1. yes, 2. yes. But what do others think?

@petebacondarwin
Copy link
Contributor

Actually since unenv currently pushes stderr.write to console.log then just moving to the current native process implementation from unenv is breaking.

@vicb vicb closed this Sep 9, 2025
@vicb vicb reopened this Sep 9, 2025
@vicb
Copy link
Contributor

vicb commented Sep 9, 2025

The behavior is definitely different.

IMO changes in behavior can be classified as either a breaking change (major version) or a fix (patch version).

What I think we should fo is work on the narrative for users explaining what the behavior is before and after (we will need this whether it's a breaking change or fix). But I hope that having a clear narrative will also help us classify this PR.

@guybedford
Copy link
Contributor Author

I've added an alternative to this with console.log stdio prefixing in #5024. Let's please continue discussion there.

@guybedford
Copy link
Contributor Author

Closing as #5024 has now been landed instead here.

@guybedford guybedford closed this Sep 11, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants