Skip to content

Prevent infinite recursion during printing #108860

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Jul 22, 2025

Conversation

mihe
Copy link
Contributor

@mihe mihe commented Jul 22, 2025

Fixes #108838.
Supersedes #108839.

This introduces a reentrancy guard to _err_print_error, and another reentrancy guard to cover __print_line, __print_line_rich and print_error, which is meant to prevent cases where we (deliberately or not) emit an error from within a logger, or print from within a logger, thus causing infinite recursion.

In such cases we would now fall back on using fprintf instead.

I also removed an already existing reentrancy guard in CoreBind::OS::LoggerBind, which I added as part of #91006 to achieve the same effect, albeit more localized.

@mihe mihe added this to the 4.5 milestone Jul 22, 2025
@mihe mihe requested a review from a team as a code owner July 22, 2025 09:46
Copy link
Member

@Ivorforce Ivorforce left a comment

Choose a reason for hiding this comment

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

I didn't test, but this makes a lot of sense to me.

As discussed in the earlier PR, we can expect for infinite recursions to occur again and again, especially during development. We should really have a robust fallback.

thread_local notably incurs some cost, but given that printing is not performance critical (and costly anyway), it should be acceptable.

@mihe mihe force-pushed the printing-infinite-recursion branch from cd7cae5 to 7a45095 Compare July 22, 2025 11:59
@mihe
Copy link
Contributor Author

mihe commented Jul 22, 2025

If anyone wants to try it for themselves, this MRP should (only with this PR) force the recursion to happen and thus show these new fallback messages in the terminal output: logger_recursion_2025-07-22_13-58-04.zip

@Ivorforce
Copy link
Member

Ivorforce commented Jul 22, 2025

I tested with the reproducer. I didn't get an infinite recursion on master (71a9948) (but I did get a single recursion, perhaps this is what you wanted to test?).

Instead, the master implementation printed two errors:

 ❯ bin/godot.macos.editor.arm64.master --path /Users/lukas/Downloads/logger-recursion/
Godot Engine v4.5.beta.custom_build.71a994815 (2025-07-18 16:05:19 UTC) - https://godotengine.org
Metal 3.2 - Forward+ - Using Device #0: Apple - Apple M1 Max (Apple7)

Just printing normally from _enter_tree
Trying to print normally from _log_message
Trying to print rich from _log_message
Just printing rich from _enter_tree
Trying to print normally from _log_message
Trying to print rich from _log_message
ERROR: Printing an error from _enter_tree
   at: push_error (core/variant/variant_utility.cpp:1024)
   GDScript backtrace (most recent call first):
       [0] _enter_tree (res://main.gd:18)
ERROR: Trying to log an error from _log_error
   at: push_error (core/variant/variant_utility.cpp:1024)
   GDScript backtrace (most recent call first):
       [0] _log_error (res://main.gd:12)
       [1] _enter_tree (res://main.gd:18)
2025-07-22 15:23:56.558 godot.macos.editor.arm64.master[35078:41616486] +[IMKClient subclass]: chose IMKClient_Modern
2025-07-22 15:23:56.630 godot.macos.editor.arm64.master[35078:41616486] +[IMKInputSession subclass]: chose IMKInputSession_Modern

The new implementation printed a bunch of fallback errors, and falls back for the second error message:

 ❯ bin/godot.macos.editor.arm64 --path /Users/lukas/Downloads/logger-recursion/
Godot Engine v4.5.beta.custom_build.7a4509556 (2025-07-22 11:58:33 UTC) - https://godotengine.org
Metal 3.2 - Forward+ - Using Device #0: Apple - Apple M1 Max (Apple7)

Just printing normally from _enter_tree
Unable to print the following message, due to printing another message:
Trying to print normally from _log_message
Unable to print the following message, due to printing another message:
Trying to print rich from _log_message
Just printing rich from _enter_tree
Unable to print the following message, due to printing another message:
Trying to print normally from _log_message
Unable to print the following message, due to printing another message:
Trying to print rich from _log_message
ERROR: Printing an error from _enter_tree
   at: push_error (core/variant/variant_utility.cpp:1024)
   GDScript backtrace (most recent call first):
       [0] _enter_tree (res://main.gd:18)
Unable to print the following error, due to printing another error:
ERROR: Trying to log an error from _log_error
   at: push_error (core/variant/variant_utility.cpp:1024)
2025-07-22 15:24:08.465 godot.macos.editor.arm64[35225:41617391] +[IMKClient subclass]: chose IMKClient_Modern
2025-07-22 15:24:08.560 godot.macos.editor.arm64[35225:41617391] +[IMKInputSession subclass]: chose IMKInputSession_Modern

One thing I'm noting is that there is no "following error" in the last example. It's particularly unclear to me which is the "following error" and which is the "another error".

I have a third proposition for the message, what do you think? "While attempting to print an error, another error was printed:"

@mihe mihe force-pushed the printing-infinite-recursion branch from 7a45095 to 836a1a0 Compare July 22, 2025 14:13
@mihe
Copy link
Contributor Author

mihe commented Jul 22, 2025

I didn't get an infinite recursion on master (71a9948)

On master you'd be covered by the reentrancy guard that this PR removes from CoreBind::OS::LoggerBind, which just does an early-out for the script-based loggers, so you won't get any infinite recursion there when dealing with script-based loggers specifically.

The MRP was mostly just an easy way to test these new fallbacks, now that the reentrancy guard in CoreBind::OS::LoggerBind is gone.

One thing I'm noting is that there is no "following error" in the last example. It's particularly unclear to me which is the "following error" and which is the "another error".

Fair enough. That does indeed read a bit weird.

I have a third proposition for the message, what do you think? "While attempting to print an error, another error was printed:"

Done! That does indeed read better.

Copy link
Member

@Ivorforce Ivorforce left a comment

Choose a reason for hiding this comment

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

Re-approving after changes. Should be good to merge now!

Copy link
Member

@Calinou Calinou left a comment

Choose a reason for hiding this comment

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

Tested locally with the MRP from #108860 (comment), it works as expected. Code looks good to me.

Just printing normally from _enter_tree
While attempting to print a message, another message was printed:
Trying to print normally from _log_message
While attempting to print a message, another message was printed:
Trying to print rich from _log_message
Just printing rich from _enter_tree
While attempting to print a message, another message was printed:
Trying to print normally from _log_message
While attempting to print a message, another message was printed:
Trying to print rich from _log_message
ERROR: Printing an error from _enter_tree
   at: push_error (./core/variant/variant_utility.cpp:1024)
   GDScript backtrace (most recent call first):
       [0] _enter_tree (res://main.gd:18)
While attempting to print an error, another error was printed:
ERROR: Trying to log an error from _log_error
   at: push_error (./core/variant/variant_utility.cpp:1024)

Note that the recursion messages are not colored according to their type (i.e. errors appear as plain text, not red). This could probably be added later on unless there's a good reason not to do it.

Recursion messages also won't appear in the editor Output panel, but I don't think anything can be done about that.

@Ivorforce
Copy link
Member

Recursion messages also won't appear in the editor Output panel, but I don't think anything can be done about that.

I think we don't want these messages to appear in the editor. Getting them there risks more recursion, and you really don't want more risks in your fallback.

@Repiteo Repiteo merged commit 77b6aef into godotengine:master Jul 22, 2025
39 of 40 checks passed
@Repiteo
Copy link
Contributor

Repiteo commented Jul 22, 2025

Thanks!

@mihe mihe deleted the printing-infinite-recursion branch July 22, 2025 16:42
@mihe
Copy link
Contributor Author

mihe commented Jul 22, 2025

I don't know if it makes any real difference, but with this being merged we might want to re-evaluate the fprintf that were added in #85397 and #89490 (CC @AThousandShips), since this should presumably be able to cover all of those as well.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

StringName errors can cause stack overflow through infinite recursion
4 participants