Add user-facing log interception callback

[zorbathut]

Describe the project you are working on

A mod-heavy exploration/building game.

Describe the problem or limitation you are having in your project

Error messages cannot be reported to a central server. Mod developers can't see error messages easily. Testers (both third-party and mod) can't see error messages easily. In addition, it's easy to entirely miss an error message.

Describe the feature / enhancement and how it helps to overcome the problem or limitation

Allow the user to provide a callback which is called on every log message, after which they can do whatever processing they like on it, including "display it in the main game pane".

Importantly, this should buffer messages on the first frame so that the callback can detect super-early load issues.

Describe how your proposal will work, with code, pseudo-code, mock-ups, and/or diagrams

I actually have a working implementation at https://github.com/godotengine/godot/pull/87576 so I'm just going to point over there. But the short answer is "a singleton that lets you attach a callback".

If this enhancement will not be used often, can it be worked around with a few lines of script?

No; there's currently no way to retrieve log messages from in-game without engine modifications.

Is there a reason why this should be core and not an add-on in the asset library?

As far as I know, this is impossible to implement as an add-on. It might be possible in a C++ module as long as you don't care about messages before you apply the hooks, but I do - intrinsically, if you want to record messages before you apply a callback, you need engine support for that.

[Delsin-Yu]

In addition, having an in-game log pad / in-game message capture mechanism allows developers to early-report these errors, without delaying until they actually find some part of the functionality is broken and it is too late to pause for debugging / detail checking.

[Calinou]

Note that a similar proposal was rejected in the past due to performance overhead: https://github.com/godotengine/godot-proposals/issues/536

Does this proposal act upon any stdout/stderr print, or just push_error() and push_warning() (both of which go to stderr)?

[Delsin-Yu]

Note that a similar proposal was rejected in the past due to performance overhead: #536

Does this proposal act upon any stdout/stderr print, or just push_error() and push_warning() (both of which go to stderr)?

As you mentioned in #536, since that proposal needs to be rewritten to handle the creation of custom loggers instead, I believe this is what the PR is achieving.

Performance-wise, the PR creates a new type of logger, UserLogManagerLogger, and adds that into the OS singleton at the initialization level. This means it should react with any form of printing method, and leads to similar performance overheads.

So I think it should be an optional feature (turning on or off in project settings?) for the engine users.

[zorbathut]

A problem with on-or-off-in-project-settings is that I believe those settings are loaded pretty late in the engine startup routine, which means that we can't yet access those by the time we need to decide whether to have this functionality enabled or not.

There's ways to work around this, though, like "default to on, then if it turns out we weren't supposed to, just delete everything and move on as if it never happened". It would slow down engine startup by likely less than a microsecond.

And yes, this doesn't make any attempt to read stdout/stderr, it just hooks into the existing print systems. I'd argue that anything important should be going through those anyway.

[Delsin-Yu]

I'd argue that anything important should be going through those anyway.

Doesn't that mean, that when the user does not intend to have this User-Log on, we end up having this extra instance of user logger in the background and causing performance degradation for every print call? I do see these extra variable constructions in every log method. And if buffering eventually gets implemented, will that grow forever in case no user scripts register and flush it?

[zorbathut]

Actually, thinking over "on-or-off-in-project-settings" a little more, I think this is completely unnecessary.

---

Conceptually, the log manager has three states it can be in: On, Off, and Buffering.

On means it has an attached logger, and obviously this means it needs to do the work of compiling log messages into Dictionaries; no way to avoid that, this is explicitly not an unwanted performance hit.

Off means it has no attached logger and it's past the point in execution where it buffers. The current code actually wastes CPU here - it compiles the Dictionaries, then throws them away - but it wouldn't be hard to change it so it doesn't. In fact, it would probably be possible to have it drop the OS logger callback entirely.

Buffering is the edge case where it's compiling Dictionaries and storing them in the hopes someone wants them later. But this lasts for exactly one frame, and at least on the current engine, this means it gets exactly two messages. Also, I believe both of those messages are sent before it reads the project file.

---

So unless those literal two messages are enough of a perf hit to be a problem, and it's worth coming up with some way to read the project file earlier so it can make a decision earlier, we'd do away with virtually all of the performance hit by just implementing the Off state better, and introducing a switch to the project file would actually be zero savings and a little cost, both of CPU and of code complexity.

[zorbathut]

Whoops, we were typing at the same time :V

Doesn't that mean, that when the user does not intend to have this User-Log on, we end up having this extra instance of user logger in the background

Yeah. I don't think this is a big problem, though, it's a single small object.

and causing performance degradation for every print call?

At the moment, yes, but this is pretty easily fixable - it just needs to detach itself from the OS logger system.

And if buffering eventually gets implemented, will that grow forever in case no user scripts register and flush it?

My implementation gives up buffering after the first frame is rendered; it assumes that if you care, you'd have already registered by then. If you register a handler after that, you'll get only new messages, not a backlog.

(Okay, technically it gives up buffering after the first message arrives after the first frame is rendered.)

[Delsin-Yu]

Yeah.... this on by default and remove it later approach doesn't seem to be preferable, what about creating a launch argument for enabling user logs? Something like enable_user_log=true, or it is an overkill?

[zorbathut]

Yeah.... this on by default and remove it later approach doesn't seem to be preferable, what about creating an extra parameter for enabling user logs? Something like enable_user_log=true, or it is an overkill?

Well, that's where the load-it-early-enough problem comes on; a specific goal of this was to log messages no matter how early they are so you can more easily track startup warnings. But (I believe, someone correct me on this if necessary) the project file is loaded long after the first print messages. So almost by definition, this information can't be contained in the project file - we need to decide whether to buffer these messages before the project file is loaded.

If we make it a command-line parameter then the vast majority of people won't set it, which defeats the point of easy debugging in general.

I think this is one of those cases where the CPU usage is small enough that it's honestly worth being willing to waste it - yes, it is technically a waste, but I was serious when I said "likely less than a microsecond". Just as a comparison, we bind all the Geometry3D methods on startup, even if the user is making a 2d-only game and has no intention of using 3d functionality, which is probably an order of magnitude more expensive than buffering those two messages. Overall, I think being able to provide the entire log file is worth it, just like I think not having to manually bind Geometry3D methods is worth it.

[jinsediaoying]

Yes, I agree. The log system is for debug, the useability is the most important thing. If we must have a toggle for it, then go the project config way. Launch argument is too troublesome to use. And I think a tiny bit (<a microsecond) loss on app launching speed is not important at all.

[fire]

Having a way to intercept the log message is useful for game server telemetry like a sentry APM / crash reporter systems. I'll add my approval.

[nikitalita]

In GDRE Tools, I currently have to do a terrible, terrible hack to add a custom logger so that I can emit per-recovery log files:

Adding something like this would be very useful to me.

[theraot]

• Related: https://github.com/godotengine/godot-proposals/issues/5937