Skip to content
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.

Sign up for GitHub

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

Ability to print and log script backtraces #91006

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
+360 −114
Open

Ability to print and log script backtraces #91006

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
76 changes: 76 additions & 0 deletions core/core_bind.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -210,8 +210,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);
Copy link
Contributor

@mihe mihe Apr 30, 2024 •
edited
Loading

Choose a reason for hiding this comment

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

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.

}

if (len >= static_buf_size) {
Memory::free_static(buf);
}
}

PackedByteArray OS::get_entropy(int p_bytes) {
PackedByteArray pba;
pba.resize(p_bytes);
Expand Down Expand Up @@ -628,6 +675,22 @@ String OS::get_unique_id() const {
return ::OS::get_singleton()->get_unique_id();
}

void OS::add_logger(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(logger_bind->loggers.find(p_logger) != -1);
logger_bind->loggers.push_back(p_logger);
}

void OS::remove_logger(Ref<Logger> p_logger) {
ERR_FAIL_COND(p_logger.is_null());
logger_bind->loggers.erase(p_logger);
}

OS *OS::singleton = nullptr;

void OS::_bind_methods() {
Expand Down Expand Up @@ -734,6 +797,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");
Expand Down Expand Up @@ -764,6 +830,16 @@ void OS::_bind_methods() {
BIND_ENUM_CONSTANT(STD_HANDLE_UNKNOWN);
}

OS::OS() {
singleton = this;
}

OS::~OS() {
if (logger_bind) {
logger_bind->clear();
}
}

////// Geometry2D //////

Geometry2D *Geometry2D::singleton = nullptr;
Expand Down
48 changes: 47 additions & 1 deletion core/core_bind.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -120,11 +120,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);
Copy link
Contributor

@mihe mihe Apr 30, 2024 •
edited
Loading

Choose a reason for hiding this comment

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

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?

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;
Expand Down Expand Up @@ -275,9 +316,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 {
Expand Down Expand Up @@ -654,6 +699,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);

Expand Down
4 changes: 3 additions & 1 deletion core/error/error_macros.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"

Expand Down Expand Up @@ -90,7 +91,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;
Expand Down
13 changes: 9 additions & 4 deletions core/io/logger.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 char *p_script_backtrace) {
if (!should_log(true)) {
return;
}
Expand Down Expand Up @@ -87,7 +87,12 @@ 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);

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, ...) {
Expand Down Expand Up @@ -261,13 +266,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);
}
}

Expand Down
4 changes: 2 additions & 2 deletions core/io/logger.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -56,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 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;
Expand Down Expand Up @@ -103,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 char *p_script_backtrace = nullptr) override;

void add_logger(Logger *p_logger);

Expand Down
15 changes: 15 additions & 0 deletions core/object/script_language.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -518,6 +518,21 @@ void ScriptServer::save_global_classes() {
ProjectSettings::get_singleton()->store_global_class_list(gcarr);
}

String ScriptServer::get_current_script_backtrace() {
String trace;
for (int si = 0; si < get_language_count(); si++) {
ScriptLanguage *sl = get_language(si);
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) + ")";
Copy link
Contributor

Choose a reason for hiding this comment

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

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) + ")";

Copy link
Member Author

Choose a reason for hiding this comment

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

makes sense

}
}
}
return trace;
}

////////////////////

ScriptCodeCompletionCache *ScriptCodeCompletionCache::singleton = nullptr;
Expand Down
2 changes: 2 additions & 0 deletions core/object/script_language.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -98,6 +98,8 @@ class ScriptServer {
static void get_inheriters_list(const StringName &p_base_type, List<StringName> *r_classes);
static void save_global_classes();

static String get_current_script_backtrace();

static void init_languages();
static void finish_languages();
static bool are_languages_initialized();
Expand Down
4 changes: 2 additions & 2 deletions core/os/os.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -84,13 +84,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);
}
}

Expand Down
5 changes: 3 additions & 2 deletions core/os/os.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -111,7 +111,6 @@ class OS {
bool _separate_thread_render = false;

// Functions used by Main to initialize/deinitialize the OS.
void add_logger(Logger *p_logger);

virtual void initialize() = 0;
virtual void initialize_joypads() = 0;
Expand Down Expand Up @@ -142,7 +141,7 @@ class OS {
virtual Vector<String> get_video_adapter_driver_info() const = 0;
virtual bool get_user_prefers_integrated_gpu() const { return false; }

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;
Expand Down Expand Up @@ -345,6 +344,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
Expand Down
1 change: 1 addition & 0 deletions core/register_core_types.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -244,6 +244,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);
Expand Down
7 changes: 7 additions & 0 deletions core/variant/variant_utility.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,7 @@

#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"
Expand Down Expand Up @@ -1236,6 +1237,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)...)
Expand Down Expand Up @@ -1855,6 +1860,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() {
Expand Down
1 change: 1 addition & 0 deletions core/variant/variant_utility.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
6 changes: 6 additions & 0 deletions doc/classes/@GlobalScope.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1160,6 +1160,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">
<return type="void" />
<param index="0" name="base" type="int" />
Expand Down
Loading
Loading