Logging: colors, non-fatal error level, alt. format for log file

Also removed traceback support entirely as it never produced useful
output.
This commit is contained in:
Andrei Alexeyev 2019-02-14 23:11:27 +02:00
parent f6f6d56caf
commit b91b85c42a
No known key found for this signature in database
GPG key ID: 363707CD4C7FE8A4
44 changed files with 537 additions and 365 deletions

View file

@ -157,7 +157,7 @@ Video and OpenGL
If ``1``, framerate graphs will be drawn on the HUD.
**TAISEI_OBJPOOL_STATS**
| Default: ``0`` for release builds, ``1`` for debug builds
| Default: ``0``
Displays some statistics about usage of in-game objects.
@ -202,7 +202,7 @@ Timing
Logging
~~~~~~~
Taisei's logging system currently has four basic levels and works by
Taisei's logging system currently has five basic levels and works by
dispatching messages to a few output handlers. Each handler has a level
filter, which is configured by a separate environment variable. All of
those variables work the same way: their value looks like an IRC mode
@ -218,15 +218,18 @@ The levels
- **Info** (*i*) logs some events that are expected to occur during
normal operation, for example when a spell is unlocked or a
screenshot is taken.
- **Warning** (*w*) alerts of non-critical errors, for example a
- **Warning** (*w*) usually complains about misuse of the engine
features, deprecations, unimplemented functionality, other small
anomalies that aren't directly detrimental to functionality.
- **Error** (*e*) alerts of non-critical errors, for example a
missing optional resource, corrupted progress data, or failure to
save a replay due to insufficient storage space or privileges.
- **Fatal Error** (*e*) is an irrecoverable failure condition. Such an
- **Fatal** (*f*) is an irrecoverable failure condition. Such an
event most likely signifies a programming error or a broken
installation. The game will immediately crash after writing a message
with this log level. On some platforms, it will also display a
graphical message box.
- **All** (*a*): this is not a real log level, but a shortcut directive
- **All** (*a*) is not a real log level, but a shortcut directive
representing all possible log levels. See *Examples* for usage.
The variables
@ -239,21 +242,16 @@ The variables
- **TAISEI_LOGLVLS_STDOUT**: controls what goes to standard output.
Defaults to *Debug and Info* (``+di``).
- **TAISEI_LOGLVLS_STDERR**: controls what goes to standard error.
Defaults to *Warning and Fatal Error* (``+we``).
Defaults to *Warning, Error, and Fatal* (``+wef``).
- **TAISEI_LOGLVLS_FILE**: controls what goes into the log file
(``{storage directory}/log.txt``). Defaults to *All* (``+a``).
- **TAISEI_LOGLVLS_BACKTRACE**: affects all outputs and controls which
log levels produce a call stack trace upon printing a message. Only
supported in Debug builds with glibc. Defaults to *Fatal Error*
(``+e``).
Examples
^^^^^^^^
- In release builds: print *Info* messages to stdout, in addition to
*Warning*\ s and *Fatal Error*\ s as per default:
*Warning*\ s, *Error*\ s, and *Fatal*\ s as per default:
.. code:: sh
@ -283,11 +281,11 @@ Examples
TAISEI_LOGLVLS_CONSOLE=-a
- Don't save anything to the log file, except for *Warning*\ s:
- Don't save anything to the log file, except for *Errors*\ s and *Fatal*\ s:
.. code:: sh
TAISEI_LOGLVLS_FILE=-a+w
TAISEI_LOGLVLS_FILE=-a+ef
- Print everything except *Debug* to ``stderr``, nothing to ``stdout``:
@ -295,10 +293,3 @@ Examples
TAISEI_LOGLVLS_STDOUT=-a
TAISEI_LOGLVLS_STDERR=+a-d
- In Debug builds: produce a stack trace for every *Warning* message,
in addition to *Fatal Error*\ s as per default:
.. code:: sh
TAISEI_LOGLVLS_BACKTRACE=+w

View file

@ -145,7 +145,6 @@ config.set('TAISEI_BUILDCONF_USE_ZIP', taisei_deps.contains(dep_zip))
have_posix = cc.has_header_symbol('unistd.h', '_POSIX_VERSION')
have_vla = not cc.has_header_symbol('unistd.h', '__STDC_NO_VLA__')
have_complex = not cc.has_header_symbol('unistd.h', '__STDC_NO_COMPLEX__')
have_backtrace = cc.has_header_symbol('execinfo.h', 'backtrace')
have_timespec = cc.has_header_symbol('time.h', 'timespec_get')
if not (have_vla and have_complex)
@ -155,6 +154,7 @@ endif
config.set('TAISEI_BUILDCONF_HAVE_TIMESPEC', have_timespec)
config.set('TAISEI_BUILDCONF_HAVE_INT128', cc.sizeof('__int128') == 16)
config.set('TAISEI_BUILDCONF_HAVE_LONG_DOUBLE', cc.sizeof('long double') > 8)
config.set('TAISEI_BUILDCONF_HAVE_POSIX', have_posix)
if macos_app_bundle
bundle_dir = 'Taisei.app'
@ -218,8 +218,11 @@ is_debug_build = get_option('buildtype').startswith('debug')
is_developer_build = (get_option('developer') == 'auto' ? is_debug_build : get_option('developer') == 'true')
config.set('TAISEI_BUILDCONF_DEVELOPER', is_developer_build)
config.set('TAISEI_BUILDCONF_LOG_ENABLE_BACKTRACE', is_debug_build and have_backtrace)
config.set('TAISEI_BUILDCONF_LOG_FATAL_MSGBOX', host_machine.system() == 'windows' or host_machine.system() == 'darwin')
config.set('TAISEI_BUILDCONF_LOG_FATAL_MSGBOX', (
host_machine.system() == 'windows' or
host_machine.system() == 'darwin' or
not is_developer_build
))
config.set('TAISEI_BUILDCONF_DEBUG_OPENGL', get_option('debug_opengl'))
if host_machine.system() == 'windows'

View file

@ -37,18 +37,18 @@ void audio_backend_init(void) {
}
if(SDL_InitSubSystem(SDL_INIT_AUDIO)) {
log_warn("SDL_InitSubSystem() failed: %s", SDL_GetError());
log_sdl_error(LOG_ERROR, "SDL_InitSubSystem");
return;
}
if(Mix_OpenAudio(AUDIO_FREQ, AUDIO_FORMAT, 2, config_get_int(CONFIG_MIXER_CHUNKSIZE)) == -1) {
log_warn("Mix_OpenAudio() failed: %s", Mix_GetError());
log_error("Mix_OpenAudio() failed: %s", Mix_GetError());
Mix_Quit();
return;
}
if(!(Mix_Init(MIX_INIT_OGG) & MIX_INIT_OGG)) {
log_warn("Mix_Init() failed: %s", Mix_GetError());
log_error("Mix_Init() failed: %s", Mix_GetError());
Mix_Quit(); // Try to shutdown mixer if it was partly initialized
return;
}
@ -56,7 +56,7 @@ void audio_backend_init(void) {
int channels = Mix_AllocateChannels(AUDIO_CHANNELS);
if(!channels) {
log_warn("Unable to allocate any channels");
log_error("Unable to allocate any channels");
Mix_CloseAudio();
Mix_Quit();
return;
@ -186,7 +186,7 @@ static void mixer_music_finished(void) {
if(next_loop) {
if(Mix_PlayMusic(next_loop, next_loop_point ? 0 : -1) == -1) {
log_warn("Mix_PlayMusic() failed: %s", Mix_GetError());
log_error("Mix_PlayMusic() failed: %s", Mix_GetError());
} else if(next_loop_point >= 0) {
Mix_SetMusicPosition(next_loop_point);
} else {
@ -265,7 +265,7 @@ bool audio_backend_music_play(void *impl) {
bool result = (Mix_PlayMusic(mmus, loops) != -1);
if(!result) {
log_warn("Mix_PlayMusic() failed: %s", Mix_GetError());
log_error("Mix_PlayMusic() failed: %s", Mix_GetError());
}
return result;
@ -281,7 +281,7 @@ bool audio_backend_music_set_position(double pos) {
Mix_RewindMusic();
if(Mix_SetMusicPosition(pos)) {
log_warn("Mix_SetMusicPosition() failed: %s", Mix_GetError());
log_error("Mix_SetMusicPosition() failed: %s", Mix_GetError());
return false;
}
@ -315,7 +315,7 @@ static int audio_backend_sound_play_on_channel(int chan, MixerInternalSound *isn
Mix_UnregisterAllEffects(chan);
if(chan < 0) {
log_warn("Mix_PlayChannel() failed: %s", Mix_GetError());
log_error("Mix_PlayChannel() failed: %s", Mix_GetError());
return false;
}
@ -355,7 +355,7 @@ bool audio_backend_sound_loop(void *impl, AudioBackendSoundGroup group) {
Mix_UnregisterAllEffects(snd->loopchan);
if(snd->loopchan == -1) {
log_warn("Mix_PlayChannel() failed: %s", Mix_GetError());
log_error("Mix_PlayChannel() failed: %s", Mix_GetError());
return false;
}

View file

@ -273,7 +273,7 @@ void config_save(void) {
ConfigEntry *e = configdefs;
if(!out) {
log_warn("VFS error: %s", vfs_get_error());
log_error("VFS error: %s", vfs_get_error());
return;
}
@ -457,9 +457,9 @@ void config_load(void) {
VFSInfo i = vfs_query(CONFIG_FILE);
if(i.error) {
log_warn("VFS error: %s", vfs_get_error());
log_error("VFS error: %s", vfs_get_error());
} else if(i.exists) {
log_warn("Config file %s is not readable", config_path);
log_error("Config file %s is not readable", config_path);
}
}

View file

@ -210,8 +210,6 @@ void events_register_handler(EventHandler *handler) {
handler_alloc->priority,
handler_container_prio_func
);
log_debug("Registered handler: %p %u", *(void**)&handler_alloc->proc, handler_alloc->priority);
}
void events_unregister_handler(EventHandlerProc proc) {
@ -365,9 +363,9 @@ static bool events_handler_keyrepeat_workaround(SDL_Event *event, void *arg) {
if(timenow < keyrepeat_paused_until) {
log_debug(
"Prevented a potentially bogus key repeat (%f remaining). "
"Prevented a potentially bogus key repeat (%"PRIuTIME" remaining). "
"This is an SDL bug. See https://bugzilla.libsdl.org/show_bug.cgi?id=3287",
(double)(keyrepeat_paused_until - timenow)
keyrepeat_paused_until - timenow
);
return true;
}

View file

@ -204,7 +204,7 @@ void gamepad_init(void) {
}
if(SDL_InitSubSystem(SDL_INIT_GAMECONTROLLER) < 0) {
log_warn("SDL_InitSubSystem() failed: %s", SDL_GetError());
log_sdl_error(LOG_ERROR, "SDL_InitSubSystem");
return;
}

393
src/log.c
View file

@ -11,77 +11,83 @@
#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"
#ifdef __WINDOWS__
#define LOG_EOL "\r\n"
#else
#define LOG_EOL "\n"
#endif
typedef struct Logger {
LIST_INTERFACE(struct Logger);
FormatterObj formatter;
SDL_RWops *out;
uint levels;
} Logger;
static Logger *loggers = NULL;
static uint enabled_log_levels;
static uint backtrace_log_levels;
static SDL_mutex *log_mutex;
static struct {
Logger *outputs;
size_t num_outputs;
char *fmt_buf1;
char *fmt_buf2;
size_t fmt_buf_size;
SDL_mutex *mutex;
uint enabled_log_levels;
// order must much the LogLevel enum after LOG_NONE
static const char *level_prefix_map[] = { "D", "I", "W", "E" };
static const char* level_prefix(LogLevel lvl) {
int idx = SDL_MostSignificantBitIndex32(lvl);
assert_nolog(idx >= 0 && idx < sizeof(level_prefix_map) / sizeof(char*));
return level_prefix_map[idx];
}
static char* format_log_string(LogLevel lvl, const char *funcname, const char *fmt, va_list args, bool is_backtrace) {
const char *pref = level_prefix(lvl);
char *msg = vstrfmt(fmt, args);
char *final = strfmt("%-9d %s: %s(): %s%s", SDL_GetTicks(), pref, funcname, msg, LOG_EOL);
free(msg);
// TODO: maybe convert all \n in the message to LOG_EOL
#ifdef DEBUG
if((backtrace_log_levels & lvl) && !is_backtrace) {
DebugInfo *debug_info = get_debug_info();
DebugInfo *debug_meta = get_debug_meta();
msg = final;
final = strfmt(
"%s%s%s"
"Debug info: %s:%i:%s%s"
"Debug info set at: %s:%i:%s%s"
"Note: debug info may not be relevant to this issue%s",
msg, LOG_EOL, LOG_EOL,
debug_info->file, debug_info->line, debug_info->func, LOG_EOL,
debug_meta->file, debug_meta->line, debug_meta->func, LOG_EOL,
LOG_EOL
);
free(msg);
}
#ifdef LOG_FATAL_MSGBOX
char *err_appendix;
#endif
} logging;
return final;
}
#define INIT_BUF_SIZE 0x100
#define MAX_BUF_SIZE 0x10000
static const char *level_prefix_map[] = {
[_LOG_DEBUG_ID] = "D",
[_LOG_INFO_ID] = "I",
[_LOG_WARN_ID] = "W",
[_LOG_ERROR_ID] = "E",
[_LOG_FATAL_ID] = "F",
};
static const char *level_name_map[] = {
[_LOG_DEBUG_ID] = "DEBUG",
[_LOG_INFO_ID] = "INFO",
[_LOG_WARN_ID] = "WARNING",
[_LOG_ERROR_ID] = "ERROR",
[_LOG_FATAL_ID] = "FATAL",
};
attr_unused
static const char *level_ansi_style_map[] = {
[_LOG_DEBUG_ID] = "\x1b[1;35m",
[_LOG_INFO_ID] = "\x1b[1;32m",
[_LOG_WARN_ID] = "\x1b[1;33m",
[_LOG_ERROR_ID] = "\x1b[1;31m",
[_LOG_FATAL_ID] = "\x1b[1;31m",
};
#define INDEX_MAP(map, lvl) \
uint idx = SDL_MostSignificantBitIndex32(lvl); \
assert_nolog(idx < sizeof(map) / sizeof(*map)); \
return map[idx];
static const char* level_prefix(LogLevel lvl) { INDEX_MAP(level_prefix_map, lvl) }
static const char* level_name(LogLevel lvl) { INDEX_MAP(level_name_map, lvl) }
attr_unused static const char* level_ansi_style_code(LogLevel lvl) { INDEX_MAP(level_ansi_style_map, lvl) }
noreturn static void log_abort(const char *msg) {
#ifdef LOG_FATAL_MSGBOX
static const char *const title = "Taisei: fatal error";
if(msg) {
SDL_ShowSimpleMessageBox(SDL_MESSAGEBOX_ERROR, "Taisei error", msg, NULL);
if(logging.err_appendix) {
char *m = strfmt("%s\n\n%s", msg, logging.err_appendix);
SDL_ShowSimpleMessageBox(SDL_MESSAGEBOX_ERROR, title, m, NULL);
free(m);
} else {
SDL_ShowSimpleMessageBox(SDL_MESSAGEBOX_ERROR, title, msg, NULL);
}
} else if(logging.err_appendix) {
SDL_ShowSimpleMessageBox(SDL_MESSAGEBOX_ERROR, title, logging.err_appendix, NULL);
}
#endif
@ -90,92 +96,130 @@ noreturn static void log_abort(const char *msg) {
abort();
}
static void log_internal(LogLevel lvl, bool is_backtrace, const char *funcname, const char *fmt, va_list args) {
void log_set_gui_error_appendix(const char *message) {
#ifdef LOG_FATAL_MSGBOX
stralloc(&logging.err_appendix, message);
#endif
}
static void realloc_buffers(size_t min_size) {
min_size = topow2_u64(min_size);
if(min_size > MAX_BUF_SIZE) {
min_size = MAX_BUF_SIZE;
}
if(logging.fmt_buf_size >= min_size) {
return;
}
logging.fmt_buf1 = realloc(logging.fmt_buf1, min_size);
logging.fmt_buf2 = realloc(logging.fmt_buf2, min_size);
logging.fmt_buf_size = min_size;
}
static void add_debug_info(char **buf) {
IF_DEBUG({
DebugInfo *debug_info = get_debug_info();
DebugInfo *debug_meta = get_debug_meta();
char *dbg = strfmt(
"%s\n\n\n"
"Debug info: %s:%i:%s\n"
"Debug info set at: %s:%i:%s\n"
"Note: debug info may not be relevant to this issue\n",
*buf,
debug_info->file, debug_info->line, debug_info->func,
debug_meta->file, debug_meta->line, debug_meta->func
);
free(*buf);
*buf = dbg;
});
}
static void log_internal(LogLevel lvl, const char *funcname, const char *filename, uint line, const char *fmt, va_list args) {
assert(fmt[strlen(fmt)-1] != '\n');
char *str = NULL;
size_t slen = 0;
lvl &= enabled_log_levels;
lvl &= logging.enabled_log_levels;
if(lvl == LOG_NONE) {
return;
}
for(Logger *l = loggers; l; l = l->next) {
SDL_LockMutex(logging.mutex);
va_list args_copy;
va_copy(args_copy, args);
int slen = vsnprintf(logging.fmt_buf1, logging.fmt_buf_size, fmt, args_copy);
va_end(args_copy);
if(slen >= logging.fmt_buf_size) {
realloc_buffers(slen + 1);
va_copy(args_copy, args);
slen = vsnprintf(logging.fmt_buf1, logging.fmt_buf_size, fmt, args_copy);
va_end(args_copy);
}
assert_nolog(slen >= 0);
if(lvl == LOG_FATAL) {
add_debug_info(&logging.fmt_buf1);
}
LogEntry entry = {
.message = logging.fmt_buf1,
.file = filename,
.func = funcname,
.line = line,
.level = lvl,
.time = SDL_GetTicks(),
};
for(Logger *l = logging.outputs; l; l = l->next) {
if(l->levels & lvl) {
if(!str) {
str = format_log_string(lvl, funcname, fmt, args, is_backtrace);
slen = strlen(str);
slen = l->formatter.format(&l->formatter, logging.fmt_buf2, logging.fmt_buf_size, &entry);
if(slen >= logging.fmt_buf_size) {
char *tmp = strdup(logging.fmt_buf1);
realloc_buffers(slen + 1);
strcpy(logging.fmt_buf1, tmp);
free(tmp);
entry.message = logging.fmt_buf1;
attr_unused int old_slen = slen;
slen = l->formatter.format(&l->formatter, logging.fmt_buf2, logging.fmt_buf_size, &entry);
assert_nolog(old_slen == slen);
}
// 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);
assert_nolog(slen >= 0);
if(logging.fmt_buf_size < slen) {
slen = logging.fmt_buf_size;
}
SDL_RWwrite(l->out, logging.fmt_buf2, 1, slen);
}
}
if(is_backtrace) {
free(str);
return;
}
if(lvl & backtrace_log_levels) {
log_backtrace(lvl);
}
if(lvl & LOG_FATAL) {
log_abort(str);
log_abort(entry.message);
}
free(str);
SDL_UnlockMutex(logging.mutex);
}
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, ...) {
void _taisei_log(LogLevel lvl, const char *funcname, const char *filename, uint line, const char *fmt, ...) {
va_list args;
va_start(args, fmt);
log_internal(lvl, is_backtrace, funcname, fmt, args);
log_internal(lvl, funcname, filename, line, fmt, args);
va_end(args);
}
noreturn void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *fmt, ...) {
void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *filename, uint line, const char *fmt, ...) {
va_list args;
va_start(args, fmt);
log_internal(lvl, false, funcname, fmt, args);
log_internal(lvl, funcname, filename, line, fmt, args);
va_end(args);
// should usually not get here, log_internal will abort earlier if lvl is LOG_FATAL
@ -186,6 +230,10 @@ noreturn void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *
static void* delete_logger(List **loggers, List *logger, void *arg) {
Logger *l = (Logger*)logger;
if(l->formatter.free != NULL) {
l->formatter.free(&l->formatter);
}
#if HAVE_STDIO_H
if(l->out->type == SDL_RWOPS_STDFILE) {
fflush(l->out->hidden.stdio.fp);
@ -198,36 +246,47 @@ static void* delete_logger(List **loggers, List *logger, void *arg) {
return NULL;
}
void log_init(LogLevel lvls, LogLevel backtrace_lvls) {
enabled_log_levels = lvls;
backtrace_log_levels = lvls & backtrace_lvls;
log_mutex = SDL_CreateMutex();
void log_init(LogLevel lvls) {
logging.enabled_log_levels = lvls;
logging.mutex = SDL_CreateMutex();
realloc_buffers(INIT_BUF_SIZE);
}
void log_shutdown(void) {
list_foreach(&loggers, delete_logger, NULL);
SDL_DestroyMutex(log_mutex);
log_mutex = NULL;
list_foreach(&logging.outputs, delete_logger, NULL);
SDL_DestroyMutex(logging.mutex);
free(logging.fmt_buf1);
free(logging.fmt_buf2);
#ifdef LOG_FATAL_MSGBOX
free(logging.err_appendix);
#endif
memset(&logging, 0, sizeof(logging));
}
bool log_initialized(void) {
return log_mutex;
return logging.fmt_buf_size > 0;
}
void log_add_output(LogLevel levels, SDL_RWops *output) {
void log_add_output(LogLevel levels, SDL_RWops *output, Formatter *formatter) {
if(!output) {
return;
}
if(!(levels & enabled_log_levels)) {
if(!(levels & logging.enabled_log_levels)) {
SDL_RWclose(output);
return;
}
Logger *l = malloc(sizeof(Logger));
Logger *l = calloc(1, sizeof(Logger));
l->levels = levels;
l->out = output;
list_append(&loggers, l);
formatter(&l->formatter, l->out);
assert(l->formatter.format != NULL);
list_append(&logging.outputs, l);
}
static LogLevel chr2lvl(char c) {
@ -265,3 +324,87 @@ LogLevel log_parse_levels(LogLevel lvls, const char *lvlmod) {
return lvls;
}
static void ensure_newline(char *buf, size_t buf_size, size_t output_size) {
if(output_size >= buf_size) {
*(strrchr(buf, '\0') - 1) = '\n';
}
}
static int log_fmtconsole_format_ansi(FormatterObj *obj, char *buf, size_t buf_size, LogEntry *entry) {
int r = snprintf(
buf,
buf_size,
"\x1b[1;30m%-9d %s%s\x1b[1;30m: \x1b[1;34m%s\x1b[1;30m: \x1b[0m%s\n",
entry->time,
level_ansi_style_code(entry->level),
level_prefix(entry->level),
entry->func,
entry->message
);
ensure_newline(buf, buf_size, r);
return r;
}
static int log_fmtconsole_format_plain(FormatterObj *obj, char *buf, size_t buf_size, LogEntry *entry) {
int r = snprintf(
buf,
buf_size,
"%-9d %s%s: %s: %s\n",
entry->time,
level_ansi_style_code(entry->level),
level_prefix(entry->level),
entry->func,
entry->message
);
ensure_newline(buf, buf_size, r);
return r;
}
#ifdef TAISEI_BUILDCONF_HAVE_POSIX
static bool output_supports_ansi_sequences(const SDL_RWops *output) {
if(!strcmp(env_get("TERM", "dumb"), "dumb")) {
return false;
}
if(output->type != SDL_RWOPS_STDFILE) {
return false;
}
int isatty(int);
int fileno(FILE*);
return isatty(fileno(output->hidden.stdio.fp));
}
#else
static bool output_supports_ansi_sequences(const SDL_RWops *output) {
// TODO: Handle it for windows. The windows console supports ANSI escapes, but requires special setup.
return false;
}
#endif
void log_formatter_console(FormatterObj *obj, const SDL_RWops *output) {
if(output_supports_ansi_sequences(output)) {
obj->format = log_fmtconsole_format_ansi;
} else {
obj->format = log_fmtconsole_format_plain;
}
}
static int log_fmtfile_format(FormatterObj *obj, char *buf, size_t buf_size, LogEntry *entry) {
int r = snprintf(
buf,
buf_size,
"%d %s %s: %s\n",
entry->time,
level_name(entry->level),
entry->func,
entry->message
);
ensure_newline(buf, buf_size, r);
return r;
}
void log_formatter_file(FormatterObj *obj, const SDL_RWops *output) {
obj->format = log_fmtfile_format;
}

View file

@ -13,15 +13,24 @@
#include <SDL.h>
enum {
_LOG_DEBUG_ID,
_LOG_INFO_ID,
_LOG_WARN_ID,
_LOG_ERROR_ID,
_LOG_FATAL_ID,
};
typedef enum LogLevel {
LOG_NONE = 0,
LOG_DEBUG = 1,
LOG_INFO = 2,
LOG_WARN = 4,
LOG_FATAL = 8,
LOG_NONE = 0,
LOG_DEBUG = (1 << _LOG_DEBUG_ID),
LOG_INFO = (1 << _LOG_INFO_ID),
LOG_WARN = (1 << _LOG_WARN_ID),
LOG_ERROR = (1 << _LOG_ERROR_ID),
LOG_FATAL = (1 << _LOG_FATAL_ID),
LOG_SPAM = LOG_DEBUG | LOG_INFO,
LOG_ALERT = LOG_WARN | LOG_FATAL,
LOG_ALERT = LOG_WARN | LOG_ERROR | LOG_FATAL,
LOG_ALL = LOG_SPAM | LOG_ALERT,
} LogLevel;
@ -50,51 +59,68 @@ typedef enum LogLevel {
#define LOG_DEFAULT_LEVELS_STDERR LOG_ALERT
#endif
#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
typedef struct LogEntry {
const char *message;
const char *file;
const char *func;
uint time;
uint line;
LogLevel level;
} LogEntry;
#ifndef LOG_BACKTRACE_SIZE
#define LOG_BACKTRACE_SIZE 32
#endif
typedef struct FormatterObj FormatterObj;
void log_init(LogLevel lvls, LogLevel backtrace_lvls);
struct FormatterObj {
int (*format)(FormatterObj *self, char *buf, size_t buf_size, LogEntry *entry);
void (*free)(FormatterObj *self);
void *data;
};
// "constructor". initializer, actually.
typedef void Formatter(FormatterObj *obj, const SDL_RWops *output);
extern Formatter log_formatter_file;
extern Formatter log_formatter_console;
void log_init(LogLevel lvls);
void log_shutdown(void);
void log_add_output(LogLevel levels, SDL_RWops *output);
void log_add_output(LogLevel levels, SDL_RWops *output, Formatter *formatter) attr_nonnull(3);
void log_backtrace(LogLevel lvl);
LogLevel log_parse_levels(LogLevel lvls, const char *lvlmod);
bool log_initialized(void);
LogLevel log_parse_levels(LogLevel lvls, const char *lvlmod) attr_nodiscard;
bool log_initialized(void) attr_nodiscard;
void log_set_gui_error_appendix(const char *message);
#ifdef DEBUG
#define log_debug(...) _taisei_log(LOG_DEBUG, false, __func__, __VA_ARGS__)
#define log_debug(...) log_custom(LOG_DEBUG, __VA_ARGS__)
#undef UNREACHABLE
#define UNREACHABLE log_fatal("This code should never be reached")
#else
#define log_debug(...)
#define LOG_NO_FILENAMES
#endif
#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, false, __func__, __VA_ARGS__)
#ifdef LOG_NO_FILENAMES
#define _do_log(func, lvl, ...) (func)(lvl, __func__, "<unknown>", 0, __VA_ARGS__)
#else
#define _do_log(func, lvl, ...) (func)(lvl, __func__, __FILE__, __LINE__, __VA_ARGS__)
#endif
#define log_sdl_error(funcname) log_warn("%s() failed: %s", funcname, SDL_GetError())
#define log_custom(lvl, ...) _do_log(_taisei_log, lvl, __VA_ARGS__)
#define log_info(...) log_custom(LOG_INFO, __VA_ARGS__)
#define log_warn(...) log_custom(LOG_WARN, __VA_ARGS__)
#define log_error(...) log_custom(LOG_ERROR, __VA_ARGS__)
#define log_fatal(...) _do_log(_taisei_log_fatal, LOG_FATAL, __VA_ARGS__)
#define log_sdl_error(lvl, funcname) log_custom(lvl, "%s() failed: %s", funcname, SDL_GetError())
//
// don't call these directly, use the macros
//
void _taisei_log(LogLevel lvl, bool is_backtrace, const char *funcname, const char *fmt, ...)
attr_printf(4, 5);
void _taisei_log(LogLevel lvl, const char *funcname, const char *filename, uint line, const char *fmt, ...)
attr_printf(5, 6);
noreturn void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *fmt, ...)
attr_printf(3, 4);
#ifdef DEBUG
#undef UNREACHABLE
#define UNREACHABLE log_fatal("This code should never be reached")
#endif
noreturn void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *filename, uint line, const char *fmt, ...)
attr_printf(5, 6);
#endif // IGUARD_log_h

View file

@ -60,16 +60,29 @@ static void init_log(void) {
LogLevel lvls_console = log_parse_levels(LOG_DEFAULT_LEVELS_CONSOLE, env_get("TAISEI_LOGLVLS_CONSOLE", NULL));
LogLevel lvls_stdout = lvls_console & log_parse_levels(LOG_DEFAULT_LEVELS_STDOUT, env_get("TAISEI_LOGLVLS_STDOUT", NULL));
LogLevel lvls_stderr = lvls_console & log_parse_levels(LOG_DEFAULT_LEVELS_STDERR, env_get("TAISEI_LOGLVLS_STDERR", NULL));
LogLevel lvls_backtrace = log_parse_levels(LOG_DEFAULT_LEVELS_BACKTRACE, env_get("TAISEI_LOGLVLS_BACKTRACE", NULL));
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_init(LOG_DEFAULT_LEVELS);
log_add_output(lvls_stdout, SDL_RWFromFP(stdout, false), log_formatter_console);
log_add_output(lvls_stderr, SDL_RWFromFP(stderr, false), log_formatter_console);
}
static void init_log_file(void) {
LogLevel lvls_file = log_parse_levels(LOG_DEFAULT_LEVELS_FILE, env_get("TAISEI_LOGLVLS_FILE", NULL));
log_add_output(lvls_file, vfs_open("storage/log.txt", VFS_MODE_WRITE));
log_add_output(lvls_file, vfs_open("storage/log.txt", VFS_MODE_WRITE), log_formatter_file);
char *logpath = vfs_repr("storage/log.txt", true);
if(logpath != NULL) {
char *m = strfmt(
"For more information, see the log file at %s\n\n"
"Please report the problem to the developers at https://taisei-project.org/ if it persists.",
logpath
);
log_set_gui_error_appendix(m);
free(m);
} else {
log_set_gui_error_appendix("Please report the problem to the developers at https://taisei-project.org/ if it persists.");
}
}
/*
@ -178,25 +191,24 @@ int main(int argc, char **argv) {
headless = true;
}
} else if(a.type == CLI_DumpVFSTree) {
vfs_setup(true);
vfs_setup(false);
SDL_RWops *rwops = SDL_RWFromFP(stdout, false);
int status = 0;
if(!rwops) {
log_fatal("SDL_RWFromFP() failed: %s", SDL_GetError());
}
if(!vfs_print_tree(rwops, a.filename)) {
log_warn("VFS error: %s", vfs_get_error());
SDL_RWclose(rwops);
free_cli_action(&a);
return 1;
log_sdl_error(LOG_ERROR, "SDL_RWFromFP");
status = 1;
} else if(!vfs_print_tree(rwops, a.filename)) {
log_error("VFS error: %s", vfs_get_error());
status = 2;
}
SDL_RWclose(rwops);
vfs_shutdown();
free_cli_action(&a);
return 0;
return status;
}
free_cli_action(&a);

View file

@ -98,7 +98,7 @@ static bool progress_read_verify_cmd_size(SDL_RWops *vfile, uint8_t cmd, uint16_
log_warn("Command %x with bad size %u ignored", cmd, cmdsize);
if(SDL_RWseek(vfile, cmdsize, RW_SEEK_CUR) < 0) {
log_warn("SDL_RWseek() failed: %s", SDL_GetError());
log_sdl_error(LOG_WARN, "SDL_RWseek");
}
return false;
@ -108,18 +108,18 @@ static void progress_read(SDL_RWops *file) {
int64_t filesize = SDL_RWsize(file);
if(filesize < 0) {
log_warn("SDL_RWsize() failed: %s", SDL_GetError());
log_sdl_error(LOG_ERROR, "SDL_RWseek");
return;
}
if(filesize > PROGRESS_MAXFILESIZE) {
log_warn("Progress file is huge (%"PRIi64" bytes, %i max)", filesize, PROGRESS_MAXFILESIZE);
log_error("Progress file is huge (%"PRIi64" bytes, %i max)", filesize, PROGRESS_MAXFILESIZE);
return;
}
for(int i = 0; i < sizeof(progress_magic_bytes); ++i) {
if(SDL_ReadU8(file) != progress_magic_bytes[i]) {
log_warn("Invalid header");
log_error("Invalid header");
return;
}
}
@ -136,7 +136,7 @@ static void progress_read(SDL_RWops *file) {
uint8_t *buf = malloc(bufsize);
if(!SDL_RWread(file, buf, bufsize, 1)) {
log_warn("SDL_RWread() failed: %s", SDL_GetError());
log_sdl_error(LOG_ERROR, "SDL_RWread");
free(buf);
return;
}
@ -145,7 +145,7 @@ static void progress_read(SDL_RWops *file) {
uint32_t checksum = progress_checksum(buf, bufsize);
if(checksum != checksum_fromfile) {
log_warn("Bad checksum: %x != %x", checksum, checksum_fromfile);
log_error("Bad checksum: %x != %x", checksum, checksum_fromfile);
SDL_RWclose(vfile);
free(buf);
return;
@ -679,7 +679,14 @@ void progress_load(void) {
SDL_RWops *file = vfs_open(PROGRESS_FILE, VFS_MODE_READ);
if(!file) {
log_warn("Couldn't open the progress file: %s", vfs_get_error());
VFSInfo i = vfs_query(PROGRESS_FILE);
if(i.error) {
log_error("VFS error: %s", vfs_get_error());
} else if(i.exists) {
log_error("Progress file %s is not readable", PROGRESS_FILE);
}
return;
}
@ -691,7 +698,7 @@ void progress_save(void) {
SDL_RWops *file = vfs_open(PROGRESS_FILE, VFS_MODE_WRITE);
if(!file) {
log_warn("Couldn't open the progress file: %s", vfs_get_error());
log_error("Couldn't open the progress file for writing: %s", vfs_get_error());
return;
}

View file

@ -22,10 +22,7 @@ static RandomState *tsrand_current;
// CMWC engine
uint32_t tsrand_p(RandomState *rnd) {
if(rnd->locked) {
log_warn("Attempted to use a locked RNG state");
return 0;
}
assert(!rnd->locked);
uint64_t const a = 18782; // as Marsaglia recommends
uint32_t const m = 0xfffffffe; // as Marsaglia recommends

View file

@ -42,7 +42,7 @@ static uint8_t* shader_cache_construct_entry(const ShaderSource *src, size_t *ou
}
default: {
log_warn("Unhandled shading language id=%u", src->lang.lang);
log_error("Unhandled shading language id=%u", src->lang.lang);
goto fail;
}
}
@ -75,7 +75,7 @@ static bool shader_cache_load_entry(SDL_RWops *stream, ShaderSource *out_src) {
out_src->content = NULL;
if(SDL_ReadU8(s) != CACHE_VERSION) {
log_warn("Version mismatch");
log_error("Version mismatch");
goto fail;
}
@ -97,7 +97,7 @@ static bool shader_cache_load_entry(SDL_RWops *stream, ShaderSource *out_src) {
}
default: {
log_warn("Unhandled shading language id=%u", out_src->lang.lang);
log_error("Unhandled shading language id=%u", out_src->lang.lang);
goto fail;
}
}
@ -106,14 +106,14 @@ static bool shader_cache_load_entry(SDL_RWops *stream, ShaderSource *out_src) {
out_src->content = calloc(1, out_src->content_size);
if(SDL_RWread(s, out_src->content, out_src->content_size, 1) != 1) {
log_warn("Read error");
log_error("Read error");
goto fail;
}
uint32_t file_crc = SDL_ReadLE32(stream);
if(crc != file_crc) {
log_warn("CRC mismatch (%08x != %08x), cache entry is corrupted", crc, file_crc);
log_error("CRC mismatch (%08x != %08x), cache entry is corrupted", crc, file_crc);
goto fail;
}
@ -155,7 +155,7 @@ static bool shader_cache_set_raw(const char *hash, const char *key, uint8_t *ent
SDL_RWops *out = vfs_open(path, VFS_MODE_WRITE);
if(out == NULL) {
log_warn("VFS error: %s", vfs_get_error());
log_error("VFS error: %s", vfs_get_error());
return false;
}

View file

@ -81,7 +81,7 @@ static char* glsl_parse_include_directive(GLSLFileParseState *fstate, char *p) {
skip_space(&p);
if(*p != '"') {
log_warn("%s:%d: malformed %s directive: \" expected.", fstate->path, fstate->lineno, INCLUDE_DIRECTIVE);
log_error("%s:%d: malformed %s directive: \" expected.", fstate->path, fstate->lineno, INCLUDE_DIRECTIVE);
return NULL;
}
@ -96,7 +96,7 @@ static char* glsl_parse_include_directive(GLSLFileParseState *fstate, char *p) {
}
if(*p != '"') {
log_warn("%s:%d: malformed %s directive: second \" expected.", fstate->path, fstate->lineno, INCLUDE_DIRECTIVE);
log_error("%s:%d: malformed %s directive: second \" expected.", fstate->path, fstate->lineno, INCLUDE_DIRECTIVE);
return NULL;
}
@ -109,7 +109,7 @@ static GLSLVersion glsl_parse_version_directive(GLSLFileParseState *fstate, char
p += sizeof(INCLUDE_DIRECTIVE) - 1;
if(glsl_parse_version(p, &version) == p) {
log_warn("%s:%d: malformed %s directive.", fstate->path, fstate->lineno, VERSION_DIRECTIVE);
log_error("%s:%d: malformed %s directive.", fstate->path, fstate->lineno, VERSION_DIRECTIVE);
return (GLSLVersion) { 0, GLSL_PROFILE_NONE };
}
@ -122,7 +122,7 @@ static bool glsl_try_write_header(GLSLFileParseState *fstate) {
}
if(fstate->global->options->version.version == 0) {
log_warn("%s:%d: no %s directive in shader and no default specified.", fstate->path, fstate->lineno, VERSION_DIRECTIVE);
log_error("%s:%d: no %s directive in shader and no default specified.", fstate->path, fstate->lineno, VERSION_DIRECTIVE);
return false;
}
@ -146,7 +146,7 @@ static bool check_directive(char *p, const char *directive) {
static bool glsl_process_file(GLSLFileParseState *fstate) {
if(fstate->include_level > GLSL_INCLUDE_DEPTH) {
log_warn("%s: max include depth reached. Maybe there is an include cycle?", fstate->path);
log_error("%s: max include depth reached. Maybe there is an include cycle?", fstate->path);
return false;
}
@ -154,7 +154,7 @@ static bool glsl_process_file(GLSLFileParseState *fstate) {
SDL_RWops *dest = fstate->global->dest;
if(!stream) {
log_warn("VFS error: %s", vfs_get_error());
log_error("VFS error: %s", vfs_get_error());
return false;
}
@ -203,7 +203,7 @@ static bool glsl_process_file(GLSLFileParseState *fstate) {
fstate->need_lineno_marker = true;
} else if(check_directive(p, VERSION_DIRECTIVE)) {
if(fstate->global->version_defined) {
log_warn("%s:%d: duplicate or misplaced %s directive", fstate->path, fstate->lineno, VERSION_DIRECTIVE);
log_error("%s:%d: duplicate or misplaced %s directive", fstate->path, fstate->lineno, VERSION_DIRECTIVE);
SDL_RWclose(stream);
return false;
}
@ -320,12 +320,12 @@ char* glsl_parse_version(const char *str, GLSLVersion *out_version) {
out_version->profile = GLSL_PROFILE_NONE;
if(p == end) {
log_warn("Malformed version '%s': version number expected.", str);
log_error("Malformed version '%s': version number expected.", str);
return orig;
}
if(out_version->version < 100) {
log_warn("Malformed version '%s': bad version number.", str);
log_error("Malformed version '%s': bad version number.", str);
return orig;
}

View file

@ -67,7 +67,7 @@ void spirv_init_compiler(void) {
if(spirv_compiler == NULL) {
spirv_compiler = shaderc_compiler_initialize();
if(spirv_compiler == NULL) {
log_warn("Failed to initialize the compiler");
log_error("Failed to initialize the compiler");
}
}
}
@ -81,19 +81,19 @@ void spirv_shutdown_compiler(void) {
bool _spirv_compile(const ShaderSource *in, ShaderSource *out, const SPIRVCompileOptions *options) {
if(in->lang.lang != SHLANG_GLSL) {
log_warn("Unsupported source language");
log_error("Unsupported source language");
return false;
}
if(spirv_compiler == NULL) {
log_warn("Compiler is not initialized");
log_error("Compiler is not initialized");
return false;
}
shaderc_compile_options_t opts = shaderc_compile_options_initialize();
if(opts == NULL) {
log_warn("Failed to initialize compiler options");
log_error("Failed to initialize compiler options");
return false;
}
@ -125,7 +125,7 @@ bool _spirv_compile(const ShaderSource *in, ShaderSource *out, const SPIRVCompil
shaderc_compile_options_release(opts);
if(result == NULL) {
log_warn("Failed to allocate compilation result");
log_error("Failed to allocate compilation result");
return false;
}
@ -133,19 +133,19 @@ bool _spirv_compile(const ShaderSource *in, ShaderSource *out, const SPIRVCompil
switch(status) {
case shaderc_compilation_status_compilation_error:
log_warn("Compilation failed: errors in the shader");
log_error("Compilation failed: errors in the shader");
break;
case shaderc_compilation_status_internal_error:
log_warn("Compilation failed: internal compiler error");
log_error("Compilation failed: internal compiler error");
break;
case shaderc_compilation_status_invalid_assembly:
log_warn("Compilation failed: invalid assembly");
log_error("Compilation failed: invalid assembly");
break;
case shaderc_compilation_status_invalid_stage:
log_warn("Compilation failed: invalid shader stage");
log_error("Compilation failed: invalid shader stage");
break;
case shaderc_compilation_status_null_result_object:
@ -155,7 +155,7 @@ bool _spirv_compile(const ShaderSource *in, ShaderSource *out, const SPIRVCompil
break;
default:
log_warn("Compilation failed: unknown error");
log_error("Compilation failed: unknown error");
break;
}
@ -164,7 +164,8 @@ bool _spirv_compile(const ShaderSource *in, ShaderSource *out, const SPIRVCompil
if(err_str != NULL && *err_str) {
size_t num_warnings = shaderc_result_get_num_warnings(result);
size_t num_errors = shaderc_result_get_num_errors(result);
log_warn("%s: %zu warnings, %zu errors:\n\n%s", filename, num_warnings, num_errors, err_str);
LogLevel lvl = status == shaderc_compilation_status_success ? LOG_WARN : LOG_ERROR;
log_custom(lvl, "%s: %zu warnings, %zu errors:\n\n%s", filename, num_warnings, num_errors, err_str);
}
if(status != shaderc_compilation_status_success) {
@ -188,12 +189,12 @@ bool _spirv_compile(const ShaderSource *in, ShaderSource *out, const SPIRVCompil
bool _spirv_decompile(const ShaderSource *in, ShaderSource *out, const SPIRVDecompileOptions *options) {
if(in->lang.lang != SHLANG_SPIRV) {
log_warn("Source is not a SPIR-V binary");
log_error("Source is not a SPIR-V binary");
return false;
}
if(options->lang->lang != SHLANG_GLSL) {
log_warn("Target language is not supported");
log_error("Target language is not supported");
return false;
}
@ -203,7 +204,7 @@ bool _spirv_decompile(const ShaderSource *in, ShaderSource *out, const SPIRVDeco
crossc_compiler *cc = crossc_glsl_create(spirv, spirv_size);
if(cc == NULL) {
log_warn("Failed to initialize crossc");
log_error("Failed to initialize crossc");
return false;
}
@ -234,7 +235,7 @@ bool _spirv_decompile(const ShaderSource *in, ShaderSource *out, const SPIRVDeco
return true;
crossc_error:
log_warn("crossc error: %s", crossc_strerror(cc));
log_error("crossc error: %s", crossc_strerror(cc));
crossc_destroy(cc);
return false;
}

View file

@ -16,11 +16,11 @@ void spirv_init_compiler(void) { }
void spirv_shutdown_compiler(void) { }
bool _spirv_compile(const ShaderSource *in, ShaderSource *out, const SPIRVCompileOptions *options) {
log_warn("Compiled without SPIR-V support");
log_error("Compiled without SPIR-V support");
return false;
}
bool _spirv_decompile(const ShaderSource *in, ShaderSource *out, const SPIRVDecompileOptions *options) {