Ability to print and log script backtraces

* 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.
reduz · Apr 30, 2024 · bb26553 · bb26553
1 parent 4a01602
commit bb26553
Show file tree

Hide file tree

Showing 25 changed files with 343 additions and 104 deletions.
diff --git a/core/core_bind.cpp b/core/core_bind.cpp
@@ -193,8 +193,55 @@ void ResourceSaver::_bind_methods() {
 	BIND_BITFIELD_FLAG(FLAG_REPLACE_SUBRESOURCE_PATHS);
 }
 
+////// LOGGER ///////
+
+void Logger::_bind_methods() {
+	GDVIRTUAL_BIND(_log_error, "function", "file", "line", "code", "rationale", "editor_notify", "error_type", "script_backtrace");
+	GDVIRTUAL_BIND(_log_message, "message", "error");
+	BIND_ENUM_CONSTANT(ERROR_TYPE_ERROR);
+	BIND_ENUM_CONSTANT(ERROR_TYPE_WARNING);
+	BIND_ENUM_CONSTANT(ERROR_TYPE_SCRIPT);
+	BIND_ENUM_CONSTANT(ERROR_TYPE_SHADER);
+}
+
+void Logger::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, ErrorType p_type, const char *p_script_backtrace) {
+	GDVIRTUAL_CALL(_log_error, p_function, p_file, p_line, p_code, p_rationale, p_editor_notify, p_type, p_script_backtrace);
+}
+
+void Logger::log_message(const String &p_text, bool p_error) {
+	GDVIRTUAL_CALL(_log_message, p_text, p_error);
+}
+
 ////// OS //////
 
+void OS::LoggerBind::logv(const char *p_format, va_list p_list, bool p_err) {
+	if (!should_log(p_err)) {
+		return;
+	}
+
+	const int static_buf_size = 1024;
+	char static_buf[static_buf_size];
+	char *buf = static_buf;
+	va_list list_copy;
+	va_copy(list_copy, p_list);
+	int len = vsnprintf(buf, static_buf_size, p_format, p_list);
+	if (len >= static_buf_size) {
+		buf = (char *)Memory::alloc_static(len + 1);
+		vsnprintf(buf, len + 1, p_format, list_copy);
+	}
+	va_end(list_copy);
+
+	String str;
+	str.parse_utf8(buf, len);
+	for (uint32_t i = 0; i < loggers.size(); i++) {
+		loggers[i]->log_message(str, p_err);
+	}
+
+	if (len >= static_buf_size) {
+		Memory::free_static(buf);
+	}
+}
+
 PackedStringArray OS::get_connected_midi_inputs() {
 	return ::OS::get_singleton()->get_connected_midi_inputs();
 }
@@ -571,6 +618,20 @@ String OS::get_unique_id() const {
 	return ::OS::get_singleton()->get_unique_id();
 }
 
+void OS::add_logger(Ref<Logger> p_logger) {
+	if (!logger_bind) {
+		logger_bind = memnew(LoggerBind);
+		::OS::get_singleton()->add_logger(logger_bind);
+	}
+
+	ERR_FAIL_COND(logger_bind->loggers.find(p_logger) != -1);
+	logger_bind->loggers.push_back(p_logger);
+}
+
+void OS::remove_logger(Ref<Logger> p_logger) {
+	logger_bind->loggers.erase(p_logger);
+}
+
 OS *OS::singleton = nullptr;
 
 void OS::_bind_methods() {
@@ -667,6 +728,9 @@ void OS::_bind_methods() {
 	ClassDB::bind_method(D_METHOD("get_granted_permissions"), &OS::get_granted_permissions);
 	ClassDB::bind_method(D_METHOD("revoke_granted_permissions"), &OS::revoke_granted_permissions);
 
+	ClassDB::bind_method(D_METHOD("add_logger", "logger"), &OS::add_logger);
+	ClassDB::bind_method(D_METHOD("remove_logger", "logger"), &OS::remove_logger);
+
 	ADD_PROPERTY(PropertyInfo(Variant::BOOL, "low_processor_usage_mode"), "set_low_processor_usage_mode", "is_in_low_processor_usage_mode");
 	ADD_PROPERTY(PropertyInfo(Variant::INT, "low_processor_usage_mode_sleep_usec"), "set_low_processor_usage_mode_sleep_usec", "get_low_processor_usage_mode_sleep_usec");
 	ADD_PROPERTY(PropertyInfo(Variant::BOOL, "delta_smoothing"), "set_delta_smoothing", "is_delta_smoothing_enabled");
@@ -690,6 +754,16 @@ void OS::_bind_methods() {
 	BIND_ENUM_CONSTANT(SYSTEM_DIR_RINGTONES);
 }
 
+OS::OS() {
+	singleton = this;
+}
+
+OS::~OS() {
+	if (logger_bind) {
+		logger_bind->clear();
+	}
+}
+
 ////// Geometry2D //////
 
 Geometry2D *Geometry2D::singleton = nullptr;

diff --git a/core/core_bind.h b/core/core_bind.h
@@ -118,11 +118,52 @@ class ResourceSaver : public Object {
 	ResourceSaver() { singleton = this; }
 };
 
+class Logger : public RefCounted {
+	GDCLASS(Logger, RefCounted);
+
+public:
+	enum ErrorType {
+		ERROR_TYPE_ERROR,
+		ERROR_TYPE_WARNING,
+		ERROR_TYPE_SCRIPT,
+		ERROR_TYPE_SHADER
+	};
+
+protected:
+	GDVIRTUAL2(_log_message, String, bool);
+	GDVIRTUAL8(_log_error, String, String, int, String, String, bool, int, String);
+	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);
+	virtual void log_message(const String &p_text, bool p_error);
+};
+
 class OS : public Object {
 	GDCLASS(OS, Object);
 
 	mutable HashMap<String, bool> feature_cache;
 
+	class LoggerBind : public ::Logger {
+	public:
+		LocalVector<Ref<core_bind::Logger>> loggers;
+		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 = ERR_ERROR, const char *p_script_backtrace = nullptr) override {
+			if (!should_log(true)) {
+				return;
+			}
+
+			for (uint32_t i = 0; i < loggers.size(); i++) {
+				loggers[i]->log_error(p_function, p_file, p_line, p_code, p_rationale, p_editor_notify, core_bind::Logger::ErrorType(p_type), p_script_backtrace);
+			}
+		}
+
+		virtual void logv(const char *p_format, va_list p_list, bool p_err) override _PRINTF_FORMAT_ATTRIBUTE_2_0;
+
+		void clear() { loggers.clear(); }
+	};
+
+	LoggerBind *logger_bind = nullptr;
+
 protected:
 	static void _bind_methods();
 	static OS *singleton;
@@ -246,9 +287,13 @@ class OS : public Object {
 	Vector<String> get_granted_permissions() const;
 	void revoke_granted_permissions();
 
+	void add_logger(Ref<Logger> p_logger);
+	void remove_logger(Ref<Logger> p_logger);
+
 	static OS *get_singleton() { return singleton; }
 
-	OS() { singleton = this; }
+	OS();
+	~OS();
 };
 
 class Geometry2D : public Object {
@@ -581,6 +626,7 @@ class EngineDebugger : public Object {
 
 } // namespace core_bind
 
+VARIANT_ENUM_CAST(core_bind::Logger::ErrorType);
 VARIANT_ENUM_CAST(core_bind::ResourceLoader::ThreadLoadStatus);
 VARIANT_ENUM_CAST(core_bind::ResourceLoader::CacheMode);
 

diff --git a/core/error/error_macros.cpp b/core/error/error_macros.cpp
@@ -31,6 +31,7 @@
 #include "error_macros.h"
 
 #include "core/io/logger.h"
+#include "core/object/script_language.h"
 #include "core/os/os.h"
 #include "core/string/ustring.h"
 
@@ -84,7 +85,8 @@ void _err_print_error(const char *p_function, const char *p_file, int p_line, co
 // Main error printing function.
 void _err_print_error(const char *p_function, const char *p_file, int p_line, const char *p_error, const char *p_message, bool p_editor_notify, ErrorHandlerType p_type) {
 	if (OS::get_singleton()) {
-		OS::get_singleton()->print_error(p_function, p_file, p_line, p_error, p_message, p_editor_notify, (Logger::ErrorType)p_type);
+		String script_backtrace = ScriptServer::get_current_script_backtrace();
+		OS::get_singleton()->print_error(p_function, p_file, p_line, p_error, p_message, p_editor_notify, (Logger::ErrorType)p_type, script_backtrace.utf8().get_data());
 	} else {
 		// Fallback if errors happen before OS init or after it's destroyed.
 		const char *err_details = (p_message && *p_message) ? p_message : p_error;

diff --git a/core/io/logger.cpp b/core/io/logger.cpp
@@ -51,7 +51,7 @@ void Logger::set_flush_stdout_on_print(bool value) {
 	_flush_stdout_on_print = value;
 }
 
-void Logger::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, ErrorType p_type) {
+void Logger::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, ErrorType p_type, const char *p_script_backtrace) {
 	if (!should_log(true)) {
 		return;
 	}
@@ -87,7 +87,11 @@ void Logger::log_error(const char *p_function, const char *p_file, int p_line, c
 	} else {
 		logf_error("USER %s: %s\n", err_type, err_details);
 	}
-	logf_error("   at: %s (%s:%i)\n", p_function, p_file, p_line);
+	if (p_script_backtrace && p_script_backtrace[0] != 0) {
+		logf_error("   at: %s (%s:%i)\n%s\n", p_function, p_file, p_line, p_script_backtrace);
+	} else {
+		logf_error("   at: %s (%s:%i)\n", p_function, p_file, p_line);
+	}
 }
 
 void Logger::logf(const char *p_format, ...) {
@@ -247,13 +251,13 @@ void CompositeLogger::logv(const char *p_format, va_list p_list, bool p_err) {
 	}
 }
 
-void CompositeLogger::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, ErrorType p_type) {
+void CompositeLogger::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, ErrorType p_type, const char *p_script_backtrace) {
 	if (!should_log(true)) {
 		return;
 	}
 
 	for (int i = 0; i < loggers.size(); ++i) {
-		loggers[i]->log_error(p_function, p_file, p_line, p_code, p_rationale, p_editor_notify, p_type);
+		loggers[i]->log_error(p_function, p_file, p_line, p_code, p_rationale, p_editor_notify, p_type, p_script_backtrace);
 	}
 }
 

diff --git a/core/io/logger.h b/core/io/logger.h
@@ -54,7 +54,7 @@ class Logger {
 	static void set_flush_stdout_on_print(bool value);
 
 	virtual void logv(const char *p_format, va_list p_list, bool p_err) _PRINTF_FORMAT_ATTRIBUTE_2_0 = 0;
-	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 = ERR_ERROR);
+	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 = ERR_ERROR, const char *p_script_backtrace = nullptr);
 
 	void logf(const char *p_format, ...) _PRINTF_FORMAT_ATTRIBUTE_2_3;
 	void logf_error(const char *p_format, ...) _PRINTF_FORMAT_ATTRIBUTE_2_3;
@@ -99,7 +99,7 @@ class CompositeLogger : public Logger {
 	explicit CompositeLogger(const Vector<Logger *> &p_loggers);
 
 	virtual void logv(const char *p_format, va_list p_list, bool p_err) override _PRINTF_FORMAT_ATTRIBUTE_2_0;
-	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, ErrorType p_type = ERR_ERROR) override;
+	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, ErrorType p_type = ERR_ERROR, const char *p_script_backtrace = nullptr) override;
 
 	void add_logger(Logger *p_logger);
 

diff --git a/core/object/script_language.cpp b/core/object/script_language.cpp
@@ -496,6 +496,21 @@ String ScriptServer::get_global_class_cache_file_path() {
 	return ProjectSettings::get_singleton()->get_global_class_list_path();
 }
 
+String ScriptServer::get_current_script_backtrace() {
+	String trace;
+	for (int i = 0; i < get_language_count(); i++) {
+		ScriptLanguage *sl = get_language(i);
+		Vector<ScriptLanguage::StackInfo> stack = sl->debug_get_current_stack_info();
+		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) + ")";
+			}
+		}
+	}
+	return trace;
+}
+
 ////////////////////
 
 ScriptCodeCompletionCache *ScriptCodeCompletionCache::singleton = nullptr;

diff --git a/core/object/script_language.h b/core/object/script_language.h
@@ -99,6 +99,8 @@ class ScriptServer {
 	static void save_global_classes();
 	static String get_global_class_cache_file_path();
 
+	static String get_current_script_backtrace();
+
 	static void init_languages();
 	static void finish_languages();
 	static bool are_languages_initialized();

diff --git a/core/os/os.cpp b/core/os/os.cpp
@@ -85,13 +85,13 @@ String OS::get_identifier() const {
 	return get_name().to_lower();
 }
 
-void OS::print_error(const char *p_function, const char *p_file, int p_line, const char *p_code, const char *p_rationale, bool p_editor_notify, Logger::ErrorType p_type) {
+void OS::print_error(const char *p_function, const char *p_file, int p_line, const char *p_code, const char *p_rationale, bool p_editor_notify, Logger::ErrorType p_type, const char *p_script_backtrace) {
 	if (!_stderr_enabled) {
 		return;
 	}
 
 	if (_logger) {
-		_logger->log_error(p_function, p_file, p_line, p_code, p_rationale, p_editor_notify, p_type);
+		_logger->log_error(p_function, p_file, p_line, p_code, p_rationale, p_editor_notify, p_type, p_script_backtrace);
 	}
 }
 

diff --git a/core/os/os.h b/core/os/os.h
@@ -105,7 +105,6 @@ class OS {
 	RenderThreadMode _render_thread_mode = RENDER_THREAD_SAFE;
 
 	// Functions used by Main to initialize/deinitialize the OS.
-	void add_logger(Logger *p_logger);
 
 	virtual void initialize() = 0;
 	virtual void initialize_joypads() = 0;
@@ -137,7 +136,7 @@ class OS {
 
 	virtual Vector<String> get_video_adapter_driver_info() const = 0;
 
-	void print_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, Logger::ErrorType p_type = Logger::ERR_ERROR);
+	void print_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, Logger::ErrorType p_type = Logger::ERR_ERROR, const char *p_script_backtrace = nullptr);
 	void print(const char *p_format, ...) _PRINTF_FORMAT_ATTRIBUTE_2_3;
 	void print_rich(const char *p_format, ...) _PRINTF_FORMAT_ATTRIBUTE_2_3;
 	void printerr(const char *p_format, ...) _PRINTF_FORMAT_ATTRIBUTE_2_3;
@@ -324,6 +323,8 @@ class OS {
 
 	virtual Error setup_remote_filesystem(const String &p_server_host, int p_port, const String &p_password, String &r_project_path);
 
+	void add_logger(Logger *p_logger);
+
 	enum PreferredTextureFormat {
 		PREFERRED_TEXTURE_FORMAT_S3TC_BPTC,
 		PREFERRED_TEXTURE_FORMAT_ETC2_ASTC

diff --git a/core/register_core_types.cpp b/core/register_core_types.cpp
@@ -245,6 +245,7 @@ void register_core_types() {
 	GDREGISTER_CLASS(core_bind::Thread);
 	GDREGISTER_CLASS(core_bind::Mutex);
 	GDREGISTER_CLASS(core_bind::Semaphore);
+	GDREGISTER_VIRTUAL_CLASS(core_bind::Logger);
 
 	GDREGISTER_CLASS(XMLParser);
 	GDREGISTER_CLASS(JSON);

diff --git a/core/variant/variant_utility.cpp b/core/variant/variant_utility.cpp
@@ -33,6 +33,7 @@
 #include "core/core_string_names.h"
 #include "core/io/marshalls.h"
 #include "core/object/ref_counted.h"
+#include "core/object/script_language.h"
 #include "core/os/os.h"
 #include "core/templates/oa_hash_map.h"
 #include "core/templates/rid.h"
@@ -1227,6 +1228,10 @@ bool VariantUtilityFunctions::is_same(const Variant &p_a, const Variant &p_b) {
 	return p_a.identity_compare(p_b);
 }
 
+String VariantUtilityFunctions::script_backtrace() {
+	return ScriptServer::get_current_script_backtrace();
+}
+
 #ifdef DEBUG_METHODS_ENABLED
 #define VCALLR *ret = p_func(VariantCasterAndValidate<P>::cast(p_args, Is, r_error)...)
 #define VCALL p_func(VariantCasterAndValidate<P>::cast(p_args, Is, r_error)...)
@@ -1826,6 +1831,8 @@ void Variant::_register_variant_utility_functions() {
 	FUNCBINDR(rid_from_int64, sarray("base"), Variant::UTILITY_FUNC_TYPE_GENERAL);
 
 	FUNCBINDR(is_same, sarray("a", "b"), Variant::UTILITY_FUNC_TYPE_GENERAL);
+
+	FUNCBINDR(script_backtrace, sarray(), Variant::UTILITY_FUNC_TYPE_GENERAL);
 }
 
 void Variant::_unregister_variant_utility_functions() {

diff --git a/core/variant/variant_utility.h b/core/variant/variant_utility.h
@@ -154,6 +154,7 @@ struct VariantUtilityFunctions {
 	static uint64_t rid_allocate_id();
 	static RID rid_from_int64(uint64_t p_base);
 	static bool is_same(const Variant &p_a, const Variant &p_b);
+	static String script_backtrace();
 };
 
 #endif // VARIANT_UTILITY_H
diff --git a/doc/classes/@GlobalScope.xml b/doc/classes/@GlobalScope.xml
@@ -1151,6 +1151,12 @@
 				A type-safe version of [method round], returning an [int].
 			</description>
 		</method>
+		<method name="script_backtrace">
+			<return type="String" />
+			<description>
+				Returns a multiple line text with the current call stack information of running scripts.
+			</description>
+		</method>
 		<method name="seed">
 			<param index="0" name="base" type="int" />
 			<description>