workerd icon indicating copy to clipboard operation
workerd copied to clipboard

[feature request] console output

Open panva opened this issue 3 years ago • 6 comments

I would like a simple way to have workerd push just the userland script stdout to a file. Currently, using the --verbose flag userland code is a) in stderr, b) wrapped around and escaped beyond repair.

workerd/io/worker.c++:1465: info: console.log(); message() = ["my escaped console log\n"]

The fact that the verbose logs are escaped and wrapped removes the ability to e.g. capture a universal library's test suite TAP output to evaluate.

panva avatar Sep 29 '22 11:09 panva

I'd definitely like this

jasnell avatar Sep 29 '22 22:09 jasnell

Indeed, I think this falls under the "general error logging is awkward" problem mentioned in the readme.

I wonder if console.log() should output to stdout (rather than stderr)?

We should clearly remove the KJ boilerplate, but should we have some other prefix? E.g. <service-name>: ?

What kind of stringification heuristic do we want here, for the values passed to console.log()? Do we toString() everything? Or JSON-encode some things?

kentonv avatar Sep 30 '22 01:09 kentonv

What kind of stringification heuristic do we want here...

I have an idea but I don't think you'll like it. :-) ... We could adopt Node.js' inspect logic to output rich console output. It's rather complicated but proven to be useful, particularly for development/debugging purposes.

I'm not convinced we should have any prefix on the output but as long as it's simple it should be ok?

jasnell avatar Sep 30 '22 12:09 jasnell

If that's easy to do it seems reasonable to me.

kentonv avatar Sep 30 '22 22:09 kentonv

It depends on your definition of easy. Will have to explore it a bit.

jasnell avatar Sep 30 '22 22:09 jasnell

For some context, Node.js' inspect logic is here.. https://github.com/nodejs/node/blob/main/lib/internal/util/inspect.js... there's a lot that we likely don't care about or may not want and it's all a fairly complicated bit of code so "easy" is going to be subjective.

jasnell avatar Oct 03 '22 05:10 jasnell

Thinking about deploying workerd in the wild, I would probably be shipping all logs to somewhere like datadog with different service tags based on the worker script. Right now though there's no way to tell which worker a log originated from.

Another problem is JS errors and stack traces, right now it's printed like:

stack: 1009eae64 1009eba2b 1009eb8e7 1008bca6c 1008bcf6c 1008bdb98 1008be190 1027f5080 1027f7a6

The error is also logged more than once, which isn't ideal.

Also, as mentioned in the readme, I would like some way to separate worker logs from workerd logs. Maybe this is the cause of errors being logged multiple times? This separation is crucial for me to figure out when workers are failing not because of app code, but a bug/error in workerd itself.

And finally, there's no way to collect metrics or other instrumentation - to monitor (on a per worker basis) req/s, memory/cpu usage etc. This also links to being able to attach trace IDs to a group of logs for a single request.

Maybe instrumentation and error stack traces can should be separate issues though, I'm not sure.

tom-sherman avatar Feb 07 '23 15:02 tom-sherman

Also, +1 on mirroring Node's console logging here or at least getting close to it. Seeing "[object Object]" in the log output is no fun.

tom-sherman avatar Feb 07 '23 15:02 tom-sherman

It would be great to see error.stack and error.cause when logging an error. Right now it only shows Error: ${error.message}. It stringifies generic objects, but not errors 😢

frandiox avatar Aug 01 '23 15:08 frandiox