Skip to content

Commit

Permalink
Ability to print and log script backtraces
Browse files Browse the repository at this point in the history 
* 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.
  • Loading branch information
@reduz
reduz committed Apr 22, 2024
1 parent 4a01602 commit 967fd0d
Show file tree
Hide file tree
Showing 20 changed files with 150 additions and 93 deletions.
4 changes: 3 additions & 1 deletion core/error/error_macros.cpp
View file
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 @@ -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;
Expand Down
12 changes: 8 additions & 4 deletions core/io/logger.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down Expand Up @@ -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, ...) {
Expand Down Expand Up @@ -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);
}
}

Expand Down
4 changes: 2 additions & 2 deletions core/io/logger.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);

Expand Down
15 changes: 15 additions & 0 deletions core/object/script_language.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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++) {

Check failure on line 506 in core/object/script_language.cpp

View workflow job for this annotation

GitHub Actions / 🐧 Linux / Minimal template (target=template_release, everything disabled) 

declaration of 'i' shadows a previous local [-Werror=shadow]
trace += "\n" + itos(i) + ": " + stack[i].func + " (" + stack[i].file + " : " + itos(stack[i].line) + ")";
}
}
}
return trace;
}

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

ScriptCodeCompletionCache *ScriptCodeCompletionCache::singleton = nullptr;
Expand Down
2 changes: 2 additions & 0 deletions core/object/script_language.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
4 changes: 2 additions & 2 deletions core/os/os.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}

Expand Down
2 changes: 1 addition & 1 deletion core/os/os.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -137,7 +137,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;
Expand Down
7 changes: 7 additions & 0 deletions core/variant/variant_utility.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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)...)
Expand Down Expand Up @@ -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() {
Expand Down
1 change: 1 addition & 0 deletions core/variant/variant_utility.h
View file
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
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down
8 changes: 7 additions & 1 deletion drivers/unix/os_unix.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -958,7 +958,7 @@ String OS_Unix::get_executable_path() const {
#endif
}

void UnixTerminalLogger::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 UnixTerminalLogger::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 All @@ -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" : "";
const char *reset = tty ? "\E[0m" : "";

switch (p_type) {
Expand All @@ -1004,6 +1006,10 @@ void UnixTerminalLogger::log_error(const char *p_function, const char *p_file, i
logf_error("%s at: %s (%s:%i)%s\n", gray, p_function, p_file, p_line, reset);
break;
}

if (p_script_backtrace && p_script_backtrace[0] != 0) {
logf_error("%s%s\n", blue, p_script_backtrace);
}
}

UnixTerminalLogger::~UnixTerminalLogger() {}
Expand Down
2 changes: 1 addition & 1 deletion drivers/unix/os_unix.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -105,7 +105,7 @@ class OS_Unix : public OS {

class UnixTerminalLogger : public StdLogger {
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 = 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 = false, ErrorType p_type = ERR_ERROR, const char *p_script_backtrace = nullptr) override;
virtual ~UnixTerminalLogger();
};

Expand Down
16 changes: 13 additions & 3 deletions modules/gdscript/gdscript.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2180,8 +2180,6 @@ String GDScriptLanguage::get_extension() const {
}

void GDScriptLanguage::finish() {
_call_stack.free();

// Clear the cache before parsing the script_list
GDScriptCache::clear();

Expand Down Expand Up @@ -2761,7 +2759,19 @@ String GDScriptLanguage::get_global_class_name(const String &p_path, String *r_b
return c->identifier != nullptr ? String(c->identifier->name) : String();
}

thread_local GDScriptLanguage::CallStack GDScriptLanguage::_call_stack;
thread_local GDScriptLanguage::CallLevel *GDScriptLanguage::_call_stack = nullptr;
thread_local uint32_t GDScriptLanguage::_call_stack_size = 0;

GDScriptLanguage::CallLevel *GDScriptLanguage::_get_stack_level(uint32_t p_level) {
ERR_FAIL_UNSIGNED_INDEX_V(p_level, _call_stack_size, nullptr);
CallLevel *level = _call_stack; // Start from top
uint32_t level_index = 0;
while (p_level > level_index) {
level_index++;
level = level->prev;
}
return level;
}

GDScriptLanguage::GDScriptLanguage() {
calls = 0;
Expand Down
93 changes: 47 additions & 46 deletions modules/gdscript/gdscript.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -419,29 +419,19 @@ class GDScriptLanguage : public ScriptLanguage {
GDScriptInstance *instance = nullptr;
int *ip = nullptr;
int *line = nullptr;
CallLevel *prev = nullptr; // Reverse linked list (stack).
};

static thread_local int _debug_parse_err_line;
static thread_local String _debug_parse_err_file;
static thread_local String _debug_error;
struct CallStack {
CallLevel *levels = nullptr;
int stack_pos = 0;

void free() {
if (levels) {
memdelete(levels);
levels = nullptr;
}
}
~CallStack() {
free();
}
};

static thread_local CallStack _call_stack;
static thread_local CallLevel *_call_stack;
static thread_local uint32_t _call_stack_size;
int _debug_max_call_stack = 0;

static CallLevel *_get_stack_level(uint32_t p_level);

void _add_global(const StringName &p_name, const Variant &p_value);

friend class GDScriptInstance;
Expand All @@ -466,53 +456,64 @@ class GDScriptLanguage : public ScriptLanguage {
bool debug_break(const String &p_error, bool p_allow_continue = true);
bool debug_break_parse(const String &p_file, int p_line, const String &p_error);

_FORCE_INLINE_ void enter_function(GDScriptInstance *p_instance, GDScriptFunction *p_function, Variant *p_stack, int *p_ip, int *p_line) {
if (unlikely(_call_stack.levels == nullptr)) {
_call_stack.levels = memnew_arr(CallLevel, _debug_max_call_stack + 1);
}

if (EngineDebugger::get_script_debugger()->get_lines_left() > 0 && EngineDebugger::get_script_debugger()->get_depth() >= 0) {
EngineDebugger::get_script_debugger()->set_depth(EngineDebugger::get_script_debugger()->get_depth() + 1);
}

if (_call_stack.stack_pos >= _debug_max_call_stack) {
_FORCE_INLINE_ void enter_function(CallLevel *call_level, GDScriptInstance *p_instance, GDScriptFunction *p_function, Variant *p_stack, int *p_ip, int *p_line) {
if (unlikely(_call_stack_size >= _debug_max_call_stack)) {

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🐧 Linux / Editor w/ Mono (target=editor) 

comparison of integer expressions of different signedness: 'uint32_t' {aka 'unsigned int'} and 'int' [-Werror=sign-compare]

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🐧 Linux / Editor with doubles and GCC sanitizers (target=editor, tests=yes, dev_build=yes, scu_build=yes, precision=double, use_asan=yes, use_ubsan=yes, linker=gold) 

comparison of integer expressions of different signedness: 'uint32_t' {aka 'unsigned int'} and 'int' [-Werror=sign-compare]

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🐧 Linux / Editor with doubles and GCC sanitizers (target=editor, tests=yes, dev_build=yes, scu_build=yes, precision=double, use_asan=yes, use_ubsan=yes, linker=gold) 

comparison of integer expressions of different signedness: 'uint32_t' {aka 'unsigned int'} and 'int' [-Werror=sign-compare]

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🐧 Linux / Editor with clang sanitizers (target=editor, tests=yes, dev_build=yes, use_asan=yes, use_ubsan=yes, use_llvm=yes, linker=lld) 

comparison of integers of different signs: 'uint32_t' (aka 'unsigned int') and 'int' [-Werror,-Wsign-compare]

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🐧 Linux / Editor with ThreadSanitizer (target=editor, tests=yes, dev_build=yes, use_tsan=yes, use_llvm=yes, linker=lld) 

comparison of integers of different signs: 'uint32_t' (aka 'unsigned int') and 'int' [-Werror,-Wsign-compare]

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🐧 Linux / Template w/ Mono (target=template_release) 

comparison of integer expressions of different signedness: 'uint32_t' {aka 'unsigned int'} and 'int' [-Werror=sign-compare]

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🏁 Windows / Editor (target=editor, tests=yes) 

the following warning is treated as an error

Check warning on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🏁 Windows / Editor (target=editor, tests=yes) 

'>=': signed/unsigned mismatch

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🏁 Windows / Editor (target=editor, tests=yes) 

the following warning is treated as an error

Check warning on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🏁 Windows / Editor (target=editor, tests=yes) 

'>=': signed/unsigned mismatch

Check failure on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🏁 Windows / Template (target=template_release) 

the following warning is treated as an error

Check warning on line 460 in modules/gdscript/gdscript.h

View workflow job for this annotation

GitHub Actions / 🏁 Windows / Template (target=template_release) 

'>=': signed/unsigned mismatch
//stack overflow
_debug_error = vformat("Stack overflow (stack size: %s). Check for infinite recursion in your script.", _debug_max_call_stack);
EngineDebugger::get_script_debugger()->debug(this);
if (EngineDebugger::get_script_debugger()) {
EngineDebugger::get_script_debugger()->debug(this);
} else {
CRASH_NOW_MSG(_debug_error);
}
return;
}

_call_stack.levels[_call_stack.stack_pos].stack = p_stack;
_call_stack.levels[_call_stack.stack_pos].instance = p_instance;
_call_stack.levels[_call_stack.stack_pos].function = p_function;
_call_stack.levels[_call_stack.stack_pos].ip = p_ip;
_call_stack.levels[_call_stack.stack_pos].line = p_line;
_call_stack.stack_pos++;
if (EngineDebugger::get_script_debugger() && EngineDebugger::get_script_debugger()->get_lines_left() > 0 && EngineDebugger::get_script_debugger()->get_depth() >= 0) {
EngineDebugger::get_script_debugger()->set_depth(EngineDebugger::get_script_debugger()->get_depth() + 1);
}

call_level->prev = _call_stack;
_call_stack = call_level;
call_level->stack = p_stack;
call_level->instance = p_instance;
call_level->function = p_function;
call_level->ip = p_ip;
call_level->line = p_line;
_call_stack_size++;
}

_FORCE_INLINE_ void exit_function() {
if (EngineDebugger::get_script_debugger()->get_lines_left() > 0 && EngineDebugger::get_script_debugger()->get_depth() >= 0) {
EngineDebugger::get_script_debugger()->set_depth(EngineDebugger::get_script_debugger()->get_depth() - 1);
}

if (_call_stack.stack_pos == 0) {
_debug_error = "Stack Underflow (Engine Bug)";
EngineDebugger::get_script_debugger()->debug(this);
if (unlikely(_call_stack_size == 0)) {
if (EngineDebugger::get_script_debugger()) {
_debug_error = "Stack Underflow (Engine Bug)";
EngineDebugger::get_script_debugger()->debug(this);
} else {
ERR_PRINT("Stack underflow! (Engine Bug)");
}
return;
}

_call_stack.stack_pos--;
_call_stack_size--;
_call_stack = _call_stack->prev;

if (EngineDebugger::get_script_debugger() && EngineDebugger::get_script_debugger()->get_lines_left() > 0 && EngineDebugger::get_script_debugger()->get_depth() >= 0) {
EngineDebugger::get_script_debugger()->set_depth(EngineDebugger::get_script_debugger()->get_depth() - 1);
}
}

virtual Vector<StackInfo> debug_get_current_stack_info() override {
Vector<StackInfo> csi;
csi.resize(_call_stack.stack_pos);
for (int i = 0; i < _call_stack.stack_pos; i++) {
csi.write[_call_stack.stack_pos - i - 1].line = _call_stack.levels[i].line ? *_call_stack.levels[i].line : 0;
if (_call_stack.levels[i].function) {
csi.write[_call_stack.stack_pos - i - 1].func = _call_stack.levels[i].function->get_name();
csi.write[_call_stack.stack_pos - i - 1].file = _call_stack.levels[i].function->get_script()->get_script_path();
csi.resize(_call_stack_size);
CallLevel *cl = _call_stack;
uint32_t idx = 0;
while (cl) {
csi.write[idx].line = *cl->line;
if (cl->function) {
csi.write[idx].func = cl->function->get_name();
csi.write[idx].file = cl->function->get_script()->get_script_path();
}
idx++;
cl = cl->prev;
}
return csi;
}
Expand Down
Loading

0 comments on commit 967fd0d

Please sign in to comment.