Merge pull request #91006 from reduz/live-backtrace

Ability to print and log script backtraces

Author: Repiteo

core/core_bind.cpp

@@ -210,8 +210,79 @@ 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_backtraces");
+	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 TypedArray<ScriptBacktrace> &p_script_backtraces) {
+	GDVIRTUAL_CALL(_log_error, String::utf8(p_function), String::utf8(p_file), p_line, String::utf8(p_code), String::utf8(p_rationale), p_editor_notify, p_type, p_script_backtraces);
+}
+
+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) || is_logging) {
+		return;
+	}
+
+	is_logging = true;
+
+	constexpr int static_buf_size = 1024;
+	char static_buf[static_buf_size] = { '\0' };
+	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.append_utf8(buf, len);
+	for (Ref<CoreBind::Logger> &logger : loggers) {
+		logger->log_message(str, p_err);
+	}
+
+	if (len >= static_buf_size) {
+		Memory::free_static(buf);
+	}
+
+	is_logging = false;
+}
+
+void OS::LoggerBind::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 Vector<Ref<ScriptBacktrace>> &p_script_backtraces) {
+	if (!should_log(true) || is_logging) {
+		return;
+	}
+
+	TypedArray<ScriptBacktrace> backtraces;
+	backtraces.resize(p_script_backtraces.size());
+	for (int i = 0; i < p_script_backtraces.size(); i++) {
+		backtraces[i] = p_script_backtraces[i];
+	}
+
+	is_logging = true;
+
+	for (Ref<CoreBind::Logger> &logger : loggers) {
+		logger->log_error(p_function, p_file, p_line, p_code, p_rationale, p_editor_notify, CoreBind::Logger::ErrorType(p_type), backtraces);
+	}
+
+	is_logging = false;
+}
+
 PackedByteArray OS::get_entropy(int p_bytes) {
 	PackedByteArray pba;
 	pba.resize(p_bytes);
@@ -628,6 +699,24 @@ String OS::get_unique_id() const {
 	return ::OS::get_singleton()->get_unique_id();
 }
 
+void OS::add_logger(const Ref<Logger> &p_logger) {
+	ERR_FAIL_COND(p_logger.is_null());
+
+	if (!logger_bind) {
+		logger_bind = memnew(LoggerBind);
+		::OS::get_singleton()->add_logger(logger_bind);
+	}
+
+	ERR_FAIL_COND_MSG(logger_bind->loggers.find(p_logger) != -1, "Could not add logger, as it has already been added.");
+	logger_bind->loggers.push_back(p_logger);
+}
+
+void OS::remove_logger(const Ref<Logger> &p_logger) {
+	ERR_FAIL_COND(p_logger.is_null());
+	ERR_FAIL_COND_MSG(!logger_bind || logger_bind->loggers.find(p_logger) == -1, "Could not remove logger, as it hasn't been added.");
+	logger_bind->loggers.erase(p_logger);
+}
+
 OS *OS::singleton = nullptr;
 
 void OS::_bind_methods() {
@@ -734,6 +823,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");
@@ -764,6 +856,20 @@ void OS::_bind_methods() {
 	BIND_ENUM_CONSTANT(STD_HANDLE_UNKNOWN);
 }
 
+OS::OS() {
+	singleton = this;
+}
+
+OS::~OS() {
+	if (singleton == this) {
+		singleton = nullptr;
+	}
+
+	if (logger_bind) {
+		logger_bind->clear();
+	}
+}
+
 ////// Geometry2D //////
 
 Geometry2D *Geometry2D::singleton = nullptr;
@@ -1898,6 +2004,16 @@ ScriptLanguage *Engine::get_script_language(int p_index) const {
 	return ScriptServer::get_language(p_index);
 }
 
+TypedArray<ScriptBacktrace> Engine::capture_script_backtraces(bool p_include_variables) const {
+	Vector<Ref<ScriptBacktrace>> backtraces = ScriptServer::capture_script_backtraces(p_include_variables);
+	TypedArray<ScriptBacktrace> result;
+	result.resize(backtraces.size());
+	for (int i = 0; i < backtraces.size(); i++) {
+		result[i] = backtraces[i];
+	}
+	return result;
+}
+
 void Engine::set_editor_hint(bool p_enabled) {
 	::Engine::get_singleton()->set_editor_hint(p_enabled);
 }
@@ -1985,6 +2101,7 @@ void Engine::_bind_methods() {
 	ClassDB::bind_method(D_METHOD("unregister_script_language", "language"), &Engine::unregister_script_language);
 	ClassDB::bind_method(D_METHOD("get_script_language_count"), &Engine::get_script_language_count);
 	ClassDB::bind_method(D_METHOD("get_script_language", "index"), &Engine::get_script_language);
+	ClassDB::bind_method(D_METHOD("capture_script_backtraces", "include_variables"), &Engine::capture_script_backtraces, DEFVAL(false));
 
 	ClassDB::bind_method(D_METHOD("is_editor_hint"), &Engine::is_editor_hint);
 	ClassDB::bind_method(D_METHOD("is_embedded_in_editor"), &Engine::is_embedded_in_editor);

core/core_bind.h

@@ -33,13 +33,13 @@
 #include "core/debugger/engine_profiler.h"
 #include "core/io/resource_loader.h"
 #include "core/io/resource_saver.h"
+#include "core/object/script_backtrace.h"
 #include "core/os/semaphore.h"
 #include "core/os/thread.h"
 #include "core/templates/safe_refcount.h"
+#include "core/variant/typed_array.h"
 
 class MainLoop;
-template <typename T>
-class TypedArray;
 
 namespace CoreBind {
 
@@ -119,11 +119,46 @@ 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, TypedArray<ScriptBacktrace>);
+	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 TypedArray<ScriptBacktrace> &p_script_backtraces = {});
+	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 {
+		inline static thread_local bool is_logging = false;
+
+	public:
+		LocalVector<Ref<CoreBind::Logger>> 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 = false, ErrorType p_type = ERR_ERROR, const Vector<Ref<ScriptBacktrace>> &p_script_backtraces = {}) override;
+
+		void clear() { loggers.clear(); }
+	};
+
+	LoggerBind *logger_bind = nullptr;
+
 protected:
 	static void _bind_methods();
 	static OS *singleton;
@@ -274,9 +309,13 @@ class OS : public Object {
 	Vector<String> get_granted_permissions() const;
 	void revoke_granted_permissions();
 
+	void add_logger(const Ref<Logger> &p_logger);
+	void remove_logger(const Ref<Logger> &p_logger);
+
 	static OS *get_singleton() { return singleton; }
 
-	OS() { singleton = this; }
+	OS();
+	~OS();
 };
 
 class Geometry2D : public Object {
@@ -579,6 +618,7 @@ class Engine : public Object {
 	Error unregister_script_language(const ScriptLanguage *p_language);
 	int get_script_language_count();
 	ScriptLanguage *get_script_language(int p_index) const;
+	TypedArray<ScriptBacktrace> capture_script_backtraces(bool p_include_variables = false) const;
 
 	void set_editor_hint(bool p_enabled);
 	bool is_editor_hint() const;
@@ -653,6 +693,7 @@ class EngineDebugger : public Object {
 
 } // namespace CoreBind
 
+VARIANT_ENUM_CAST(CoreBind::Logger::ErrorType);
 VARIANT_ENUM_CAST(CoreBind::ResourceLoader::ThreadLoadStatus);
 VARIANT_ENUM_CAST(CoreBind::ResourceLoader::CacheMode);
 

core/error/error_macros.cpp

@@ -32,6 +32,7 @@
 
 #include "core/io/logger.h"
 #include "core/object/object_id.h"
+#include "core/object/script_language.h"
 #include "core/os/os.h"
 #include "core/string/ustring.h"
 
@@ -91,7 +92,15 @@ 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);
+		Vector<Ref<ScriptBacktrace>> script_backtraces;
+
+		// If script languages aren't initialized, we could be in the process of shutting down, in which case we don't want to allocate any objects, as we could be
+		// logging ObjectDB leaks, where ObjectDB would be locked, thus causing a deadlock.
+		if (ScriptServer::are_languages_initialized()) {
+			script_backtraces = ScriptServer::capture_script_backtraces(false);
+		}
+
+		OS::get_singleton()->print_error(p_function, p_file, p_line, p_error, p_message, p_editor_notify, (Logger::ErrorType)p_type, script_backtraces);
 	} 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;

core/io/logger.cpp

@@ -55,7 +55,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 Vector<Ref<ScriptBacktrace>> &p_script_backtraces) {
 	if (!should_log(true)) {
 		return;
 	}
@@ -88,6 +88,10 @@ void Logger::log_error(const char *p_function, const char *p_file, int p_line, c
 
 	logf_error("%s: %s\n", err_type, err_details);
 	logf_error("   at: %s (%s:%i)\n", p_function, p_file, p_line);
+
+	for (const Ref<ScriptBacktrace> &backtrace : p_script_backtraces) {
+		logf_error("%s\n", backtrace->format(3).utf8().get_data());
+	}
 }
 
 void Logger::logf(const char *p_format, ...) {
@@ -263,13 +267,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 Vector<Ref<ScriptBacktrace>> &p_script_backtraces) {
 	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_backtraces);
 	}
 }
 

core/io/logger.h

@@ -31,6 +31,7 @@
 #pragma once
 
 #include "core/io/file_access.h"
+#include "core/object/script_backtrace.h"
 #include "core/string/ustring.h"
 #include "core/templates/vector.h"
 
@@ -55,7 +56,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 Vector<Ref<ScriptBacktrace>> &p_script_backtraces = {});
 
 	void logf(const char *p_format, ...) _PRINTF_FORMAT_ATTRIBUTE_2_3;
 	void logf_error(const char *p_format, ...) _PRINTF_FORMAT_ATTRIBUTE_2_3;
@@ -102,7 +103,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 Vector<Ref<ScriptBacktrace>> &p_script_backtraces = {}) override;
 
 	void add_logger(Logger *p_logger);