log: support for dumping backtraces in debug builds

Enabled only if the environment has the execinfo.h interface.
By default dumps the backtrace only on log_fatal, use.
TAISEI_LOGLVLS_BACKTRACE to customize that behaviour, e.g.:

    TAISEI_LOGLVLS_BACKTRACE=+w taisei

to also enable it for warnings.

src/CMakeLists.txt

@@ -196,6 +196,13 @@ if(POSIX)
 	add_definitions(-D__POSIX__)
 endif()
 
+if("${CMAKE_BUILD_TYPE}" STREQUAL "Debug")
+	check_symbol_exists(backtrace "execinfo.h" HAVE_BACKTRACE)
+	if(HAVE_BACKTRACE)
+		add_definitions(-DLOG_ENABLE_BACKTRACE)
+	endif()
+endif()
+
 if (CMAKE_GENERATOR STREQUAL "Ninja" AND
     ((CMAKE_C_COMPILER_ID STREQUAL "GNU" AND NOT CMAKE_C_COMPILER_VERSION VERSION_LESS 4.9) OR
      (CMAKE_C_COMPILER_ID STREQUAL "Clang" AND NOT CMAKE_C_COMPILER_VERSION VERSION_LESS 3.5)))

src/log.c

@@ -3,6 +3,10 @@
 #include <SDL_bits.h>
 #include <SDL_mutex.h>
 
+#ifdef LOG_ENABLE_BACKTRACE
+    #include <execinfo.h>
+#endif
+
 #include "log.h"
 #include "util.h"
 #include "list.h"
@@ -22,6 +26,7 @@ typedef struct Logger {
 
 static Logger *loggers = NULL;
 static unsigned int enabled_log_levels;
+static unsigned int backtrace_log_levels;
 static SDL_mutex *log_mutex;
 
 // order must much the LogLevel enum after LOG_NONE
@@ -56,7 +61,7 @@ noreturn static void log_abort(const char *msg) {
     abort();
 }
 
-static void log_internal(LogLevel lvl, const char *funcname, const char *fmt, va_list args) {
+static void log_internal(LogLevel lvl, bool is_backtrace, const char *funcname, const char *fmt, va_list args) {
     assert(fmt[strlen(fmt)-1] != '\n');
 
     char *str = NULL;
@@ -74,30 +79,73 @@ static void log_internal(LogLevel lvl, const char *funcname, const char *fmt, va
                 slen = strlen(str);
             }
 
-            SDL_LockMutex(log_mutex);
-            SDL_RWwrite(l->out, str, 1, slen);
-            SDL_UnlockMutex(log_mutex);
+            // log_backtrace locks the mutex by itself, then recursively calls log_internal
+            if(is_backtrace) {
+                SDL_RWwrite(l->out, str, 1, slen);
+            } else {
+                SDL_LockMutex(log_mutex);
+                SDL_RWwrite(l->out, str, 1, slen);
+                SDL_UnlockMutex(log_mutex);
+            }
         }
     }
 
     free(str);
 
+    if(is_backtrace) {
+        return;
+    }
+
+    if(lvl & backtrace_log_levels) {
+        log_backtrace(lvl);
+    }
+
     if(lvl & LOG_FATAL) {
         log_abort(str);
     }
 }
 
-void _taisei_log(LogLevel lvl, const char *funcname, const char *fmt, ...) {
+static char** get_backtrace(int *num) {
+#ifdef LOG_ENABLE_BACKTRACE
+    void *ptrs[*num];
+    *num = backtrace(ptrs, *num);
+    return backtrace_symbols(ptrs, *num);
+#else
+    char **dummy = malloc(sizeof(char*));
+    *num = 1;
+    *dummy = "[Backtrace support is not available in this build]";
+    return dummy;
+#endif
+}
+
+void log_backtrace(LogLevel lvl) {
+    int num = LOG_BACKTRACE_SIZE;
+    char **symbols = get_backtrace(&num);
+
+    SDL_LockMutex(log_mutex);
+    _taisei_log(lvl, true, __func__, "*** BACKTRACE ***");
+
+    for(int i = 0; i < num; ++i) {
+        _taisei_log(lvl, true, __func__, "> %s", symbols[i]);
+    }
+
+    _taisei_log(lvl, true, __func__, "*** END OF BACKTRACE ***");
+    SDL_UnlockMutex(log_mutex);
+
+    free(symbols);
+}
+
+void _taisei_log(LogLevel lvl, bool is_backtrace, const char *funcname, const char *fmt, ...) {
     va_list args;
     va_start(args, fmt);
-    log_internal(lvl, funcname, fmt, args);
+    log_internal(lvl, is_backtrace, funcname, fmt, args);
     va_end(args);
 }
 
 noreturn void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *fmt, ...) {
     va_list args;
     va_start(args, fmt);
-    log_internal(lvl, funcname, fmt, args);
+    log_internal(lvl, false, funcname, fmt, args);
     va_end(args);
 
     // should usually not get here, log_internal will abort earlier if lvl is LOG_FATAL
@@ -111,8 +159,9 @@ static void delete_logger(void **loggers, void *logger) {
     delete_element(loggers, logger);
 }
 
-void log_init(LogLevel lvls) {
+void log_init(LogLevel lvls, LogLevel backtrace_lvls) {
     enabled_log_levels = lvls;
+    backtrace_log_levels = lvls & backtrace_lvls;
     log_mutex = SDL_CreateMutex();
 }
 
@@ -123,7 +172,11 @@ void log_shutdown(void) {
 }
 
 void log_add_output(LogLevel levels, SDL_RWops *output) {
-    if(!output || !(levels & enabled_log_levels)) {
+    if(!output) {
+        return;
+    }
+
+    if(!(levels & enabled_log_levels)) {
         SDL_RWclose(output);
         return;
     }

src/log.h

@@ -3,6 +3,7 @@
 #define TAISEI_LOG_H
 
 #include <stdnoreturn.h>
+#include <stdbool.h>
 #include <SDL.h>
 
 typedef enum LogLevel {
@@ -42,28 +43,41 @@ typedef enum LogLevel {
     #define LOG_DEFAULT_LEVELS_STDERR LOG_ALERT
 #endif
 
-void log_init(LogLevel lvls);
+#ifndef LOG_DEFAULT_LEVELS_BACKTRACE
+    #ifdef LOG_ENABLE_BACKTRACE
+        #define LOG_DEFAULT_LEVELS_BACKTRACE LOG_FATAL
+    #else
+        #define LOG_DEFAULT_LEVELS_BACKTRACE LOG_NONE
+    #endif
+#endif
+
+#ifndef LOG_BACKTRACE_SIZE
+    #define LOG_BACKTRACE_SIZE 32
+#endif
+
+void log_init(LogLevel lvls, LogLevel backtrace_lvls);
 void log_shutdown(void);
 void log_add_output(LogLevel levels, SDL_RWops *output);
+void log_backtrace(LogLevel lvl);
 LogLevel log_parse_levels(LogLevel lvls, const char *lvlmod);
 
 #ifdef DEBUG
-    #define log_debug(...) _taisei_log(LOG_DEBUG, __func__, __VA_ARGS__)
+    #define log_debug(...) _taisei_log(LOG_DEBUG, false, __func__, __VA_ARGS__)
 #else
     #define log_debug(...)
 #endif
 
-#define log_info(...) _taisei_log(LOG_INFO, __func__, __VA_ARGS__)
-#define log_warn(...) _taisei_log(LOG_WARN, __func__, __VA_ARGS__)
+#define log_info(...) _taisei_log(LOG_INFO, false, __func__, __VA_ARGS__)
+#define log_warn(...) _taisei_log(LOG_WARN, false, __func__, __VA_ARGS__)
 #define log_fatal(...) _taisei_log_fatal(LOG_FATAL, __func__, __VA_ARGS__)
-#define log_custom(lvl, ...) _taisei_log(lvl, __func__, __VA_ARGS__)
+#define log_custom(lvl, ...) _taisei_log(lvl, false, __func__, __VA_ARGS__)
 
 //
 // don't call these directly, use the macros
 //
 
-void _taisei_log(LogLevel lvl, const char *funcname, const char *fmt, ...)
-    __attribute__((format(printf, 3, 4)));
+void _taisei_log(LogLevel lvl, bool is_backtrace, const char *funcname, const char *fmt, ...)
+    __attribute__((format(printf, 4, 5)));
 
 noreturn void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *fmt, ...)
     __attribute__((format(printf, 3, 4)));

src/main.c

@@ -49,8 +49,9 @@ void init_log(void) {
 	LogLevel lvls_stdout = lvls_console & log_parse_levels(LOG_DEFAULT_LEVELS_STDOUT, getenv("TAISEI_LOGLVLS_STDOUT"));
 	LogLevel lvls_stderr = lvls_console & log_parse_levels(LOG_DEFAULT_LEVELS_STDERR, getenv("TAISEI_LOGLVLS_STDERR"));
 	LogLevel lvls_file = log_parse_levels(LOG_DEFAULT_LEVELS_FILE, getenv("TAISEI_LOGLVLS_FILE"));
+	LogLevel lvls_backtrace = log_parse_levels(LOG_DEFAULT_LEVELS_BACKTRACE, getenv("TAISEI_LOGLVLS_BACKTRACE"));
 
-	log_init(LOG_DEFAULT_LEVELS);
+	log_init(LOG_DEFAULT_LEVELS, lvls_backtrace);
 	log_add_output(lvls_stdout, SDL_RWFromFP(stdout, false));
 	log_add_output(lvls_stderr, SDL_RWFromFP(stderr, false));
 	log_add_output(lvls_file, SDL_RWFromFile(logpath, "w"));
@@ -59,9 +60,6 @@ void init_log(void) {
 }
 
 int run_tests(void) {
-	log_init(LOG_DEFAULT_LEVELS);
-	log_add_output(LOG_ALL, SDL_RWFromFP(stdout, false));
-
 	if(tsrand_test()) {
 		return 1;
 	}
@@ -82,7 +80,6 @@ int run_tests(void) {
 		return 1;
 	}
 
-	log_shutdown();
 	return 0;
 }
 
@@ -95,10 +92,6 @@ int run_tests(void) {
 int main(int argc, char **argv) {
 	setlocale(LC_ALL, "C");
 
-	if(run_tests()) {
-		return 0;
-	}
-
 #ifdef DEBUG
 	if(argc >= 2 && argv[1] && !strcmp(argv[1], "dumpstages")) {
 		stage_init_array();
@@ -135,6 +128,10 @@ int main(int argc, char **argv) {
 	init_paths();
 	init_log();
 
+	if(run_tests()) {
+		return 0;
+	}
+
 	log_info("Content path: %s", get_prefix());
 	log_info("Userdata path: %s", get_config_path());