Ability to print and log script backtraces #91006

reduz · 2024-04-22T10:39:01Z

Changes how stack information is stored in GDScript to a reverse linked list.
This makes it fast enough to leave it enabled all time time on debug.
Added a new script function script_backtrace() to get a string with the current script backtrace.
Added the script backtrace to the logger. Errors now include the full currently running script backtraces.
Added script backtrace printing to console logs (Windows, MacOS, Linux) using blue color.
Additionally, added a custom Logger class to allow users intercept the internal messages/warnings/error (supersedes Add user-facing log interception callback. #87576).

How it looks:

using script_backtrace()

Results in the following output:

Logger

Backtraces are now added to the loggers. Here is how it looks for ANSI/Windows console loggers:

realcoloride · 2024-04-22T10:51:01Z

Extremely wanted feature that could make it way easier to debug. Love this

mihe · 2024-04-22T11:10:12Z

core/object/script_language.cpp

+		if (stack.size()) {
+			trace += "stack_language: " + sl->get_name();
+			for (int i = 0; i < stack.size(); i++) {
+				trace += "\n" + itos(i) + ": " + stack[i].func + " (" + stack[i].file + " : " + itos(stack[i].line) + ")";


Seeing as how the existing error/warning printing formats file-with-line as %s:%i (as seen in your own screenshot), rather than %s : %i, the spaces in " : " should probably be removed.

Suggested change

trace += "\n" + itos(i) + ": " + stack[i].func + " (" + stack[i].file + " : " + itos(stack[i].line) + ")";

trace += "\n" + itos(i) + ": " + stack[i].func + " (" + stack[i].file + ":" + itos(stack[i].line) + ")";

makes sense

bruvzg · 2024-04-22T13:16:05Z

Not sure how reliable it will be, but it might be worth calling it from the crash handler as well (tested on macOS only and seems to be working):

diff --git a/platform/macos/crash_handler_macos.mm b/platform/macos/crash_handler_macos.mm
index c370422bfa..91f76dc3b5 100644
--- a/platform/macos/crash_handler_macos.mm
+++ b/platform/macos/crash_handler_macos.mm
@@ -31,6 +31,7 @@
 #include "crash_handler_macos.h"
 
 #include "core/config/project_settings.h"
+#include "core/object/script_language.h"
 #include "core/os/os.h"
 #include "core/string/print_string.h"
 #include "core/version.h"
@@ -171,6 +172,9 @@ static void handle_crash(int sig) {
 	}
 	print_error("-- END OF BACKTRACE --");
 	print_error("================================================================");
+	print_error(ScriptServer::get_current_script_backtrace());
+	print_error("-- END OF SCRIPT BACKTRACE --");
+	print_error("================================================================");
 
 	// Abort to pass the error to the OS
 	abort();

RedMser · 2024-04-22T15:31:33Z

How does the new function relate to the existing @GDScript.get_stack() and print_stack()? I assume there are technical differences, but these are not really made clear enough to the average user (when should I use this new function vs the existing ones?).

farfalk · 2024-04-22T16:39:14Z

In addition to what RedMser asked, how does this relate to #87576 ?

Calinou · 2024-04-22T18:20:27Z

drivers/unix/os_unix.cpp

@@ -983,6 +983,8 @@ void UnixTerminalLogger::log_error(const char *p_function, const char *p_file, i
 	const char *magenta_bold = tty ? "\E[1;35m" : "";
 	const char *cyan = tty ? "\E[0;96m" : "";
 	const char *cyan_bold = tty ? "\E[1;36m" : "";
+	const char *blue = tty ? "\E[0;94m" : "";
+	//const char *blue_bold = tty ? "\E[1;34m" : "";


This can probably be removed, it's trivial to readd later if we need it:

Suggested change

//const char *blue_bold = tty ? "\E[1;34m" : "";

reduz · 2024-04-22T21:01:46Z

@RedMser

This new one works always, even if not running the debugger and it also is generic for all languages. print_stack() was created mostly for testing and should be deprecated and removed since its pretty useless.

@farfalk

Both PRs should work great together

permelin · 2024-04-23T16:05:46Z

Did a quick test script with a function that is recursively called 500 times inside a for loop. To my surprise, this branch is 5% faster than master.

(Pushing the call stack beyond a depth of 506 or 507 will SIGSEGV, but that happens in master too.)

dalexeev · 2024-04-30T06:29:55Z

Can script_backtrace() return data in a structured form (Array[Dictionary]), like get_stack()? It also looks like this PR will resolve godotengine/godot-proposals#105.

reduz · 2024-04-30T10:27:25Z

@dalexeev I honestly don't see a lot of use for this, since the main use case is to print it, but I think adding another function script_stack() may be good for this, that could also include more stack information if you want.

mihe · 2024-04-30T13:41:07Z

core/core_bind.h

+	static void _bind_methods();
+
+public:
+	virtual void log_error(const char *p_function, const char *p_file, int p_line, const char *p_code, const char *p_rationale, bool p_editor_notify = false, ErrorType p_type = ERROR_TYPE_ERROR, const char *p_script_backtrace = nullptr);


Not sure how big of a deal this is, but if someone uses auto-complete (or just copies the signature verbatim) to implement this virtual method in GDScript, they will trigger the "Shadowed Global Identifier" warning due to the script_backtrace parameter shadowing the global function by the same name.

Maybe renaming the script_backtrace function to get_script_backtrace is the better option?

mihe · 2024-04-30T14:04:20Z

core/core_bind.cpp

+	String str;
+	str.parse_utf8(buf, len);
+	for (uint32_t i = 0; i < loggers.size(); i++) {
+		loggers[i]->log_message(str, p_err);


Seeing as how _log_message will end up getting called on every print, you can fairly easily get yourself into a stack overflow by trying to print anything from _log_message.

Might be good to mention in the documentation at least.

EDIT: I would assume the same applies when trying to push_error from _log_error.

* Changes how stack information is stored in GDScript to a reverse linked list. * This makes it fast enough to leave it enabled all time time on debug. * Added a new script function script_backtrace() to get a string with the current script backtrace. * Added the script backtrace to the logger. * Added script backtrace to console logs (Windows, MacOS, Linux) using blue color. * Added a custom Logger class to help log errors from script.

mihe · 2024-05-06T18:44:23Z

modules/gdscript/gdscript_vm.cpp

+	GDScriptLanguage::CallLevel call_level;
+	GDScriptLanguage::get_singleton()->enter_function(&call_level, p_instance, this, stack, &ip, &line);


This whole thing with keeping a pointer to this call_level here seems to cause some trouble with coroutines (functions that await), as they're allowed to exit this method without calling GDScriptLanguage::exit_function first (causing this pointer to go stale) since that gets called as part of GDScriptFunctionState::resume instead.

Calinou

Tested locally, it works as expected.

extends Node2D

var iteration := 0

func _ready() -> void:
	recurse()


func recurse() -> void:
	iteration += 1
	if iteration < 5:
		recurse()
	else:
		print(script_backtrace())
		for i in 20:
			# Needed so the print shows up reliably in the Output panel.
			await get_tree().process_frame
		get_tree().quit()

Results in:

stack_language: GDScript
0: recurse (res://node_2d.gd : 14)
1: recurse (res://node_2d.gd : 12)
2: recurse (res://node_2d.gd : 12)
3: recurse (res://node_2d.gd : 12)
4: recurse (res://node_2d.gd : 12)
5: _ready (res://node_2d.gd : 6)

Some remarks:

Should the method be renamed to get_script_backtrace(), since it's a getter and has no side effects in itself?
Printed stack traces seem to go to stdout, but I'd generally expect them to go to stderr like in most other languages.
The stacktrace could have a note of the form Traceback (most recent call last) on the first line, like in Python.
- To avoid making the stack trace longer, we can format the first line as follows:
- GDScript traceback (most recent call last):
Colored printing in errors seems to be missing a reset color code at the end. Here, I use push_error() then manually print some text afterwards (which shouldn't appear colored as a result):

In error traces, I'd indent each line with 4 spaces so the entire error message is indented (except its first line).

reduz requested review from a team as code owners April 22, 2024 10:39

AThousandShips added enhancement feature proposal topic:core labels Apr 22, 2024

AThousandShips added this to the 4.x milestone Apr 22, 2024

reduz force-pushed the live-backtrace branch from 967fd0d to e21f4e7 Compare April 22, 2024 10:47

mihe reviewed Apr 22, 2024

View reviewed changes

Calinou reviewed Apr 22, 2024

View reviewed changes

This was referenced Apr 26, 2024

Node / Resource duplication usability improvements godotengine/godot-proposals#9603

Open

Add a Reference Cycle Breaker #90576

Open

dalexeev mentioned this pull request Apr 30, 2024

Make get_stack() available in release/debug export templates as well as in the editor godotengine/godot-proposals#105

Open

reduz force-pushed the live-backtrace branch from e21f4e7 to aa0ebd8 Compare April 30, 2024 10:25

reduz force-pushed the live-backtrace branch 4 times, most recently from bb26553 to bcfa1bd Compare April 30, 2024 12:23

reduz requested a review from a team as a code owner April 30, 2024 12:23

mihe reviewed Apr 30, 2024

View reviewed changes

reduz force-pushed the live-backtrace branch from bcfa1bd to 9c8fcc3 Compare April 30, 2024 15:44

mihe reviewed May 6, 2024

View reviewed changes

Calinou reviewed May 6, 2024

View reviewed changes

CedNaru mentioned this pull request May 15, 2024

[Proposal] Print JVM stack trace when the error is being thrown inside a cpp file. utopia-rise/godot-kotlin-jvm#186

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Ability to print and log script backtraces #91006

Ability to print and log script backtraces #91006

reduz commented Apr 22, 2024 •

edited

realcoloride commented Apr 22, 2024

mihe Apr 22, 2024

reduz Apr 22, 2024

bruvzg commented Apr 22, 2024

RedMser commented Apr 22, 2024

farfalk commented Apr 22, 2024 •

edited

Calinou Apr 22, 2024

reduz commented Apr 22, 2024 •

edited

permelin commented Apr 23, 2024

dalexeev commented Apr 30, 2024

reduz commented Apr 30, 2024

mihe Apr 30, 2024 •

edited

mihe Apr 30, 2024 •

edited

mihe May 6, 2024 •

edited

Calinou left a comment •

edited

	trace += "\n" + itos(i) + ": " + stack[i].func + " (" + stack[i].file + " : " + itos(stack[i].line) + ")";
	trace += "\n" + itos(i) + ": " + stack[i].func + " (" + stack[i].file + ":" + itos(stack[i].line) + ")";

		GDScriptLanguage::CallLevel call_level;
		GDScriptLanguage::get_singleton()->enter_function(&call_level, p_instance, this, stack, &ip, &line);

Ability to print and log script backtraces #91006

Are you sure you want to change the base?

Ability to print and log script backtraces #91006

Conversation

reduz commented Apr 22, 2024 • edited

How it looks:

using script_backtrace()

Logger

realcoloride commented Apr 22, 2024

mihe Apr 22, 2024

Choose a reason for hiding this comment

reduz Apr 22, 2024

Choose a reason for hiding this comment

bruvzg commented Apr 22, 2024

RedMser commented Apr 22, 2024

farfalk commented Apr 22, 2024 • edited

Calinou Apr 22, 2024

Choose a reason for hiding this comment

reduz commented Apr 22, 2024 • edited

permelin commented Apr 23, 2024

dalexeev commented Apr 30, 2024

reduz commented Apr 30, 2024

mihe Apr 30, 2024 • edited

Choose a reason for hiding this comment

mihe Apr 30, 2024 • edited

Choose a reason for hiding this comment

mihe May 6, 2024 • edited

Choose a reason for hiding this comment

Calinou left a comment • edited

Choose a reason for hiding this comment

reduz commented Apr 22, 2024 •

edited

farfalk commented Apr 22, 2024 •

edited

reduz commented Apr 22, 2024 •

edited

mihe Apr 30, 2024 •

edited

mihe Apr 30, 2024 •

edited

mihe May 6, 2024 •

edited

Calinou left a comment •

edited