Implemented a simple and consistent logging subsystem

The goal of this change is mainly to clean up Taisei's codebase and
improve its console output. I've been frustrated by files littered with
inconsistent printf/fprintf/warnx/errx calls for a long time, and now I
actually did something about it.

All the above functions are now considered deprecated and result in a
compile-time warning when used. Instead, the following macros should be
used:

    log_debug(format, ...)
    log_info(format, ...)
    log_warn(format, ...)
    log_err(format, ...)

As you can see, all of them have the same printf-like interface. But
they have different functionality and purpose:

    log_debug is intended for very verbose and specific information. It
    does nothing in release builds, much like assert(), so don't use
    expressions with side-effects in its arguments.

    log_info is for various status updates that are expected during
    normal operation of the program.

    log_warn is for non-critical failures or other things that may be
    worth investigating, but don't inherently render the program
    non-functional.

    log_err is for when the only choice is to give up. Like errx, it
    also terminates the program. Unlike errx, it actually calls abort(),
    which means the cleanup functions are not ran -- but on the other
    hand, you get a debuggable backtrace. However, if you're trying to
    catch programming errors, consider using assert() instead.

All of them produce output that contains a timestamp, the log level
identifier, the calling function's name, and the formatted message.

The newline at the end of the format string is not required -- no, it is
actually *prohibited*. The logging system will take care of the line
breaks by itself, don't litter the code with that shit.

Internally, the logging system is based on the SDL_RWops abstraction,
and may have multiple, configurable destinations. This makes it easily
extensible. Currently, log_debug and log_info are set to write to
stdout, log_warn and log_err to stderr, and all of them also to the file
log.txt in the Taisei config directory.

Consequently, the nasty freopen hacks we used to make Taisei write to
log files on Windows are no longer needed -- which is a very good thing,
considering they probably would break if the configdir path contains
UTF-8 characters. SDL_RWFromFile does not suffer this limitation.

As an added bonus, it's also thread-safe.

Note about printf and fprintf: in very few cases, the logging system is
not a good substitute for these functions. That is, when you care about
writing exactly to stdout/stderr and about exactly how the output looks.

However, I insist on keeping the deprecation warnings on them to not
tempt anyone to use them for logging/debugging out of habit and/or
laziness.

For this reason, I've added a tsfprintf function to util.c. It is
functionally identical to fprintf, except it returns void. Yes, the name
is deliberately ugly. Avoid using it if possible, but if you must, only
use it to write to stdout or stderr. Do not write to actual files with
it, use SDL_RWops.
This commit is contained in:
Andrei "Akari" Alexeyev 2017-03-13 04:51:58 +02:00
parent 1ac4ff95c4
commit 45da155cb2
37 changed files with 456 additions and 320 deletions

View file

@ -21,6 +21,7 @@ endif()
set(SRCs
main.c
log.c
util.c
taiseigl.c
random.c
@ -110,10 +111,6 @@ else()
)
endif()
if(WIN32)
set(SRCs ${SRCs} taisei_err.c)
endif()
if(DEFINED TAISEI_DEBUG)
if(TAISEI_DEBUG)
set(CMAKE_BUILD_TYPE "Debug")
@ -146,6 +143,10 @@ if(FATALERRS)
add_definitions(-Wfatal-errors)
endif()
if(WIN32 OR APPLE)
add_definitions(-DLOG_ERROR_MSGBOX)
endif()
set(LIBs ${LIBs}
${SDL2_LIBRARIES}
${SDL2_TTF_LIBRARIES}

View file

@ -93,9 +93,9 @@ void stop_bgm(bool force) {
audio_backend_music_pause();
}
printf("BGM stopped.\n");
log_info("BGM stopped");
} else {
printf("stop_bgm(): No BGM was playing.\n");
log_info("No BGM was playing");
}
}
@ -123,7 +123,7 @@ void start_bgm(const char *name) {
stralloc(&current_bgm.name, name);
if((current_bgm.music = get_music(name)) == NULL) {
warnx("start_bgm(): BGM '%s' does not exist", current_bgm.name);
log_warn("BGM '%s' does not exist", current_bgm.name);
stop_bgm(true);
free(current_bgm.name);
current_bgm.name = NULL;
@ -152,7 +152,7 @@ void start_bgm(const char *name) {
current_bgm.started_at = -1;
}
printf("Started %s\n", (current_bgm.title ? current_bgm.title : current_bgm.name));
log_info("Started %s", (current_bgm.title ? current_bgm.title : current_bgm.name));
}
void audio_init(void) {

View file

@ -12,7 +12,6 @@
#include "audio.h"
#include "global.h"
#include "list.h"
#include "taisei_err.h"
#define AUDIO_FREQ 44100
#define AUDIO_FORMAT MIX_DEFAULT_FORMAT
@ -30,7 +29,7 @@ void audio_backend_init(void) {
}
if(SDL_InitSubSystem(SDL_INIT_AUDIO)) {
warnx("audio_backend_init(): SDL_InitSubSystem() failed: %s.\n", SDL_GetError());
log_warn("SDL_InitSubSystem() failed: %s", SDL_GetError());
return;
}
@ -40,21 +39,21 @@ void audio_backend_init(void) {
}
if(Mix_OpenAudio(AUDIO_FREQ, AUDIO_FORMAT, 2, config_get_int(CONFIG_MIXER_CHUNKSIZE)) == -1) {
warnx("audio_backend_init(): Mix_OpenAudio() failed: %s.\n", Mix_GetError());
log_warn("Mix_OpenAudio() failed: %s", Mix_GetError());
Mix_Quit();
return;
}
int channels = Mix_AllocateChannels(AUDIO_CHANNELS);
if(!channels) {
warnx("audio_backend_init(): unable to allocate any channels.\n");
log_warn("Unable to allocate any channels");
Mix_CloseAudio();
Mix_Quit();
return;
}
if(channels < AUDIO_CHANNELS) {
warnx("audio_backend_init(): allocated only %d of %d channels.\n", channels, AUDIO_CHANNELS);
log_warn("Allocated only %d of %d channels", channels, AUDIO_CHANNELS);
}
mixer_loaded = true;
@ -68,13 +67,13 @@ void audio_backend_init(void) {
Mix_QuerySpec(&frequency, &format, &channels);
if(frequency != AUDIO_FREQ || format != AUDIO_FORMAT) {
warnx( "audio_backend_init(): mixer spec doesn't match our request, "
"requested (freq=%i, fmt=%u), got (freq=%i, fmt=%u). "
"Sound may be distorted.",
AUDIO_FREQ, AUDIO_FORMAT, frequency, format);
log_warn( "Mixer spec doesn't match our request, "
"requested (freq=%i, fmt=%u), got (freq=%i, fmt=%u). "
"Sound may be distorted.",
AUDIO_FREQ, AUDIO_FORMAT, frequency, format);
}
printf("audio_backend_init(): audio subsystem initialized (SDL2_Mixer)\n");
log_info("Audio subsystem initialized (SDL2_Mixer)");
}
void audio_backend_shutdown(void) {
@ -83,7 +82,7 @@ void audio_backend_shutdown(void) {
SDL_QuitSubSystem(SDL_INIT_AUDIO);
mixer_loaded = false;
printf("audio_backend_shutdown(): audio subsystem uninitialized (SDL2_Mixer)\n");
log_info("Audio subsystem uninitialized (SDL2_Mixer)");
}
bool audio_backend_initialized(void) {
@ -153,7 +152,7 @@ bool audio_backend_music_play(void *impl) {
bool result = (Mix_PlayMusic((Mix_Music*)impl, -1) != -1);
if(!result) {
warnx("audio_backend_music_play(): Mix_PlayMusic() failed: %s", Mix_GetError());
log_warn("Mix_PlayMusic() failed: %s", Mix_GetError());
}
return result;
@ -166,7 +165,7 @@ bool audio_backend_sound_play(void *impl) {
bool result = (Mix_PlayChannel(-1, (Mix_Chunk*)impl, 0) != -1);
if(!result) {
warnx("audio_backend_sound_play(): Mix_PlayChannel() failed: %s", Mix_GetError());
log_warn("Mix_PlayChannel() failed: %s", Mix_GetError());
}
return result;

View file

@ -173,22 +173,20 @@ void free_attack(Attack *a) {
}
void start_attack(Boss *b, Attack *a) {
#if DEBUG
printf("BOSS start_attack(): %s\n", a->name);
#endif
log_debug("%s", a->name);
if(global.replaymode == REPLAY_RECORD && global.stage->type == STAGE_STORY && !global.plr.continues) {
StageInfo *i = stage_get_by_spellcard(a->info, global.diff);
if(i) {
StageProgress *p = stage_get_progress_from_info(i, global.diff, true);
if(p && !p->unlocked) {
printf("Spellcard unlocked! %s: %s\n", i->title, i->subtitle);
log_info("Spellcard unlocked! %s: %s", i->title, i->subtitle);
p->unlocked = true;
}
}
#if DEBUG
else if(a->type == AT_Spellcard) {
warnx("FIXME: spellcard '%s' is not available in spell practice mode!", a->name);
log_warn("FIXME: spellcard '%s' is not available in spell practice mode!", a->name);
}
#endif
}

View file

@ -12,7 +12,6 @@
#include "config.h"
#include "global.h"
#include "paths/native.h"
#include "taisei_err.h"
static bool config_initialized = false;
@ -182,11 +181,7 @@ static void config_set_val(ConfigIndex idx, ConfigValue v) {
return;
}
#ifdef DEBUG
#define PRINTVAL(t) printf("config_set_val(): %s:" #t " = %" #t "\n", e->name, e->val.t);
#else
#define PRINTVAL(t)
#endif
#define PRINTVAL(t) log_debug("%s:" #t " = %" #t, e->name, e->val.t);
switch(e->type) {
case CONFIG_TYPE_INT:
@ -280,7 +275,7 @@ static SDL_RWops* config_open(const char *filename, const char *mode) {
free(buf);
if(!out) {
warnx("config_open(): SDL_RWFromFile() failed: %s", SDL_GetError());
log_warn("SDL_RWFromFile() failed: %s", SDL_GetError());
}
return out;
@ -323,11 +318,9 @@ void config_save(const char *filename) {
}
SDL_RWclose(out);
printf("Saved config '%s'\n", filename);
log_info("Saved config '%s'", filename);
}
#define SYNTAXERROR { warnx("config_load(): syntax error on line %i, aborted! [%s:%i]\n", line, __FILE__, __LINE__); goto end; }
#define BUFFERERROR { warnx("config_load(): string exceed the limit of %i, aborted! [%s:%i]", CONFIG_LOAD_BUFSIZE, __FILE__, __LINE__); goto end; }
#define INTOF(s) ((int)strtol(s, NULL, 10))
#define FLOATOF(s) ((float)strtod(s, NULL))
@ -335,7 +328,7 @@ static void config_set(const char *key, const char *val, void *data) {
ConfigEntry *e = config_find_entry(key);
if(!e) {
warnx("config_set(): unknown setting '%s'", key);
log_warn("Unknown setting '%s'", key);
config_set_unknown(key, val);
return;
}
@ -349,7 +342,7 @@ static void config_set(const char *key, const char *val, void *data) {
SDL_Scancode scan = SDL_GetScancodeFromName(val);
if(scan == SDL_SCANCODE_UNKNOWN) {
warnx("config_set(): unknown key '%s'", val);
log_warn("Unknown key '%s'", val);
} else {
e->val.i = scan;
}

View file

@ -7,7 +7,6 @@
#include "fbo.h"
#include "global.h"
#include "taisei_err.h"
void init_fbo(FBO *fbo) {
glGenTextures(1, &fbo->tex);

View file

@ -7,7 +7,6 @@
*/
#include "gamepad.h"
#include "taisei_err.h"
#include "config.h"
#include "events.h"
#include "global.h"
@ -28,32 +27,32 @@ void gamepad_init(void) {
return;
if(SDL_InitSubSystem(SDL_INIT_JOYSTICK) < 0) {
warnx("gamepad_init(): couldn't initialize SDL joystick subsystem: %s", SDL_GetError());
log_warn("SDL_InitSubSystem() failed: %s", SDL_GetError());
return;
}
int i, cnt = gamepad_devicecount();
printf("gamepad_init(): found %i devices\n", cnt);
log_info("Found %i devices", cnt);
for(i = 0; i < cnt; ++i)
printf("%i: %s\n", i, SDL_JoystickNameForIndex(i));
log_info("Device #%i: %s", i, SDL_JoystickNameForIndex(i));
int dev = config_get_int(CONFIG_GAMEPAD_DEVICE);
if(dev < 0 || dev >= cnt) {
warnx("gamepad_init(): device %i is not available\n", dev);
log_warn("Device #%i is not available", dev);
gamepad_shutdown();
return;
}
gamepad.device = SDL_JoystickOpen(dev);
if(!gamepad.device) {
warnx("gamepad_init(): failed to open device %i [%s]", dev, gamepad_devicename(dev));
log_warn("Failed to open device %i: %s", dev, SDL_GetError());
gamepad_shutdown();
return;
}
gamepad.axis = malloc(SDL_JoystickNumAxes(gamepad.device));
printf("gamepad_init(): using device #%i: %s\n", dev, gamepad_devicename(dev));
log_info("Using device #%i: %s", dev, gamepad_devicename(dev));
SDL_JoystickEventState(SDL_ENABLE);
gamepad.initialized = 1;
}
@ -63,7 +62,7 @@ void gamepad_shutdown(void) {
return;
if(gamepad.initialized != 2)
printf("gamepad_shutdown(): disabled the gamepad subsystem\n");
log_info("Disabled the gamepad subsystem");
if(gamepad.device)
SDL_JoystickClose(gamepad.device);
@ -282,7 +281,7 @@ void gamepad_init_bare(void) {
return;
if(SDL_InitSubSystem(SDL_INIT_JOYSTICK) < 0) {
warnx("gamepad_init(): couldn't initialize SDL joystick subsystem: %s", SDL_GetError());
log_warn("SDL_InitSubSystem() failed: %s", SDL_GetError());
return;
}

View file

@ -6,14 +6,6 @@
*/
#include "global.h"
#include "video.h"
#include <time.h>
#include <stdio.h>
#include <png.h>
#include "paths/native.h"
#include "resource/resource.h"
#include "taisei_err.h"
#include "replay.h"
Global global;
@ -35,6 +27,6 @@ void init_global(void) {
global.frameskip = INT_MAX;
}
warnx("FPS limiter disabled by environment. Gotta go fast! (frameskip = %i)", global.frameskip);
log_warn("FPS limiter disabled by environment. Gotta go fast! (frameskip = %i)", global.frameskip);
}
}

View file

@ -43,7 +43,6 @@
#include "difficulty.h"
#include "color.h"
#include "audio.h"
#include "taisei_err.h"
#include "rwops/all.h"
#define FILE_PREFIX PREFIX "/share/taisei/"

View file

@ -84,7 +84,7 @@ void delete_all_elements_witharg(void **dest, void (callback)(void **, void *, v
#endif
#ifdef DEBUG_REFS
#define REFLOG(...) fprintf(stderr, __VA_ARGS__);
#define REFLOG(...) log_debug(__VA_ARGS__);
#else
#define REFLOG(...)
#endif
@ -95,7 +95,7 @@ int add_ref(void *ptr) {
for(i = 0; i < global.refs.count; i++) {
if(global.refs.ptrs[i].ptr == ptr) {
global.refs.ptrs[i].refs++;
REFLOG("increased refcount for %p (ref %i): %i\n", ptr, i, global.refs.ptrs[i].refs);
REFLOG("increased refcount for %p (ref %i): %i", ptr, i, global.refs.ptrs[i].refs);
return i;
} else if(firstfree < 0 && global.refs.ptrs[i].ptr == FREEREF) {
firstfree = i;
@ -105,14 +105,14 @@ int add_ref(void *ptr) {
if(firstfree >= 0) {
global.refs.ptrs[firstfree].ptr = ptr;
global.refs.ptrs[firstfree].refs = 1;
REFLOG("found free ref for %p: %i\n", ptr, firstfree);
REFLOG("found free ref for %p: %i", ptr, firstfree);
return firstfree;
}
global.refs.ptrs = realloc(global.refs.ptrs, (++global.refs.count)*sizeof(Reference));
global.refs.ptrs[global.refs.count - 1].ptr = ptr;
global.refs.ptrs[global.refs.count - 1].refs = 1;
REFLOG("new ref for %p: %i\n", ptr, global.refs.count - 1);
REFLOG("new ref for %p: %i", ptr, global.refs.count - 1);
return global.refs.count - 1;
}
@ -130,12 +130,12 @@ void free_ref(int i) {
return;
global.refs.ptrs[i].refs--;
REFLOG("decreased refcount for %p (ref %i): %i\n", global.refs.ptrs[i].ptr, i, global.refs.ptrs[i].refs);
REFLOG("decreased refcount for %p (ref %i): %i", global.refs.ptrs[i].ptr, i, global.refs.ptrs[i].refs);
if(global.refs.ptrs[i].refs <= 0) {
global.refs.ptrs[i].ptr = FREEREF;
global.refs.ptrs[i].refs = 0;
REFLOG("ref %i is now free\n", i);
REFLOG("ref %i is now free", i);
}
}
@ -151,7 +151,7 @@ void free_all_refs(void) {
}
if(inuse) {
warnx("free_all_refs(): %i refs were still in use (%i unique, %i total allocated)", inuse, inuse_unique, global.refs.count);
log_warn("%i refs were still in use (%i unique, %i total allocated)", inuse, inuse_unique, global.refs.count);
}
free(global.refs.ptrs);

140
src/log.c Normal file
View file

@ -0,0 +1,140 @@
#include <assert.h>
#include <SDL_bits.h>
#include <SDL_mutex.h>
#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 {
struct Logger *next;
struct Logger *prev;
SDL_RWops *out;
unsigned int levels;
} Logger;
static Logger *loggers = NULL;
static unsigned int enabled_log_levels;
static SDL_mutex *log_mutex;
static const char* level_prefix(LogLevel lvl) {
static const char *prefmap[] = { "D", "I", "W", "E" };
int idx = SDL_MostSignificantBitIndex32(lvl);
assert(idx >= 0 && idx < sizeof(prefmap));
return prefmap[idx];
}
static void write_timestamp(char buf[11]) {
time_t t = time(0);
struct tm* timeinfo = localtime(&t);
strftime(buf, 9, "%H:%M:%S", timeinfo);
}
static char* format_log_string(LogLevel lvl, const char *funcname, const char *fmt, va_list args) {
const char *pref = level_prefix(lvl);
char *msg = vstrfmt(fmt, args);
char timestamp[11];
write_timestamp(timestamp);
char *final = strjoin(timestamp, " ", pref, ": ", funcname, "(): ", msg, LOG_EOL, NULL);
free(msg);
// TODO: maybe convert all \n in the message to LOG_EOL
return final;
}
noreturn static void log_abort(const char *msg) {
#ifdef LOG_ERROR_MSGBOX
if(msg) {
SDL_ShowSimpleMessageBox(SDL_MESSAGEBOX_ERROR, "Taisei error", msg, NULL);
}
#endif
// abort() doesn't clean up, but it lets us get a backtrace, which is more useful
log_shutdown();
abort();
}
static void log_internal(LogLevel lvl, const char *funcname, const char *fmt, va_list args) {
assert(fmt[strlen(fmt)-1] != '\n');
char *str = NULL;
size_t slen = 0;
lvl &= enabled_log_levels;
if(lvl == LOG_NONE) {
return;
}
for(Logger *l = loggers; l; l = l->next) {
if(l->levels & lvl) {
if(!str) {
str = format_log_string(lvl, funcname, fmt, args);
slen = strlen(str);
}
SDL_LockMutex(log_mutex);
SDL_RWwrite(l->out, str, 1, slen);
SDL_UnlockMutex(log_mutex);
}
}
free(str);
if(lvl & LOG_ERR) {
log_abort(str);
}
}
void _taisei_log(LogLevel lvl, const char *funcname, const char *fmt, ...) {
va_list args;
va_start(args, fmt);
log_internal(lvl, 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);
va_end(args);
// should usually not get here, log_internal will abort earlier if lvl is LOG_ERR
// that is unless LOG_ERR is disabled for some reason
log_abort(NULL);
}
static void delete_logger(void **loggers, void *logger) {
Logger *l = logger;
SDL_RWclose(l->out);
delete_element(loggers, logger);
}
void log_init(LogLevel lvls) {
enabled_log_levels = lvls;
log_mutex = SDL_CreateMutex();
}
void log_shutdown(void) {
delete_all_elements((void**)&loggers, delete_logger);
SDL_DestroyMutex(log_mutex);
log_mutex = NULL;
}
void log_add_output(LogLevel levels, SDL_RWops *output) {
if(!output || !(levels & enabled_log_levels)) {
SDL_RWclose(output);
return;
}
Logger *l = create_element((void**)&loggers, sizeof(Logger));
l->levels = levels;
l->out = output;
}

49
src/log.h Normal file
View file

@ -0,0 +1,49 @@
#ifndef TAISEI_LOG_H
#define TAISEI_LOG_H
#include <stdnoreturn.h>
#include <SDL.h>
typedef enum LogLevel {
LOG_NONE = 0,
LOG_DEBUG = 1,
LOG_INFO = 2,
LOG_WARN = 4,
LOG_ERR = 8,
LOG_SPAM = LOG_DEBUG | LOG_INFO,
LOG_ALERT = LOG_WARN | LOG_ERR,
LOG_ALL = LOG_SPAM | LOG_ALERT,
} LogLevel;
#ifndef LOG_DEFAULT_LEVELS
#define LOG_DEFAULT_LEVELS LOG_ALL
#endif
void log_init(LogLevel lvls);
void log_shutdown(void);
void log_add_output(LogLevel levels, SDL_RWops *output);
#ifdef DEBUG
#define log_debug(...) _taisei_log(LOG_DEBUG, __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_err(...) _taisei_log_fatal(LOG_ERR, __func__, __VA_ARGS__)
#define log_custom(lvl, ...) _taisei_log(lvl, __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)));
noreturn void _taisei_log_fatal(LogLevel lvl, const char *funcname, const char *fmt, ...)
__attribute__((format(printf, 3, 4)));
#endif

View file

@ -8,7 +8,6 @@
#include <sys/stat.h>
#include <errno.h>
#include <locale.h>
#include "taisei_err.h"
#include "global.h"
#include "video.h"
@ -20,11 +19,13 @@
#include "resource/bgm.h"
#include "progress.h"
#include "hashtable.h"
#include "log.h"
void taisei_shutdown(void) {
log_info("Shutting down");
config_save(CONFIG_FILE);
progress_save();
printf("\nshutdown:\n");
free_all_refs();
free_resources(true);
@ -35,25 +36,27 @@ void taisei_shutdown(void) {
config_uninit();
SDL_Quit();
printf("-- Good Bye.\n");
log_info("Good bye");
log_shutdown();
}
void init_log(void) {
#if defined(__WINDOWS__) && !defined(__WINDOWS_CONSOLE__)
const char *pref = get_config_path();
char *s;
char *logpath = strfmt("%s/%s", pref, "log.txt");
s = strfmt("%s/%s", pref, "stdout.txt");
freopen(s, "w", stdout);
free(s);
log_init(LOG_DEFAULT_LEVELS);
log_add_output(LOG_SPAM, SDL_RWFromFP(stdout, false));
log_add_output(LOG_ALERT, SDL_RWFromFP(stderr, false));
log_add_output(LOG_ALL, SDL_RWFromFile(logpath, "w"));
s = strfmt("%s/%s", pref, "stderr.txt");
freopen(s, "w", stderr);
free(s);
#endif
free(logpath);
}
int run_tests(void) {
log_init(LOG_DEFAULT_LEVELS);
log_add_output(LOG_ALL, SDL_RWFromFP(stdout, false));
if(tsrand_test()) {
return 1;
}
@ -74,6 +77,7 @@ int run_tests(void) {
return 1;
}
log_shutdown();
return 0;
}
@ -95,7 +99,7 @@ int main(int argc, char **argv) {
stage_init_array();
for(StageInfo *stg = stages; stg->procs; ++stg) {
printf("%i %s: %s\n", stg->id, stg->title, stg->subtitle);
tsfprintf(stdout, "%i %s: %s\n", stg->id, stg->title, stg->subtitle);
}
return 0;
@ -108,7 +112,7 @@ int main(int argc, char **argv) {
if(argc >= 2 && !strcmp(argv[1], "replay")) {
if(argc < 3) {
fprintf(stderr, "Usage: %s replay /path/to/replay.tsr [stage num]\n", argv[0]);
tsfprintf(stderr, "Usage: %s replay /path/to/replay.tsr [stage num]\n", argv[0]);
return 1;
}
@ -126,40 +130,31 @@ int main(int argc, char **argv) {
init_paths();
init_log();
printf("Content path: %s\n", get_prefix());
printf("Userdata path: %s\n", get_config_path());
log_info("Content path: %s", get_prefix());
log_info("Userdata path: %s", get_config_path());
MKDIR(get_config_path());
MKDIR(get_screenshots_path());
MKDIR(get_replays_path());
if(chdir(get_prefix())) {
errx(-1, "chdir() failed: %s", strerror(errno));
log_err("chdir() failed: %s", strerror(errno));
} else {
char cwd[1024]; // i don't care if this is not enough for you, getcwd is garbage
getcwd(cwd, sizeof(cwd));
printf("Changed working directory to %s\n", cwd);
log_info("Changed working directory to %s", cwd);
}
config_load(CONFIG_FILE);
printf("initialize:\n");
if(SDL_Init(SDL_INIT_VIDEO) < 0)
errx(-1, "Error initializing SDL: %s", SDL_GetError());
printf("-- SDL\n");
log_err("SDL_Init() failed: %s", SDL_GetError());
init_global();
video_init();
printf("-- Video and OpenGL\n");
audio_init();
printf("-- Audio\n");
init_resources();
draw_loading_screen();
load_resources();
gamepad_init();
stage_init_array();
@ -167,7 +162,8 @@ int main(int argc, char **argv) {
set_transition(TransLoader, 0, FADE_TIME*2);
printf("initialization complete.\n");
log_info("Initialization complete");
atexit(taisei_shutdown);
if(replay_path) {
@ -183,28 +179,27 @@ int main(int argc, char **argv) {
return 0;
}
printf("** Compiled with DEBUG flag!\n");
log_warn("Compiled with DEBUG flag!");
if(argc >= 2 && argv[1]) {
printf("** Entering stage skip mode: Stage %d\n", atoi(argv[1]));
log_info("Entering stage skip mode: Stage %d", atoi(argv[1]));
StageInfo* stg = stage_get(atoi(argv[1]));
if(!stg) {
errx(-1, "Invalid stage id");
log_err("Invalid stage id");
}
global.diff = stg->difficulty;
if(!global.diff) {
if(argc == 3 && argv[2]) {
global.diff = atoi(argv[2]);
log_info("Setting difficulty to %s", difficulty_name(global.diff));
} else if(!global.diff) {
global.diff = D_Easy;
}
if(argc == 3 && argv[2]) {
printf("** Setting difficulty to %d.\n", atoi(argv[2]));
global.diff = atoi(argv[2]);
}
printf("** Entering %s.\n", stg->title);
log_info("Entering %s", stg->title);
do {
global.game_over = 0;

View file

@ -13,7 +13,7 @@
void continue_game(MenuData *m, void *arg)
{
printf("The game is being continued...\n");
log_info("The game is being continued...");
if(global.replaymode == REPLAY_RECORD) { // actually... I'd be strange if REPLAY_PLAY ever got there
replay_destroy(&global.replay); // 19:39:29 [@ laochailan] no. no fame for continue users >:D

View file

@ -13,7 +13,6 @@
#include "global.h"
#include "video.h"
#include "paths/native.h"
#include "taisei_err.h"
// --- Menu entry <-> config option binding stuff --- //

View file

@ -266,7 +266,7 @@ int fill_replayview_menu(MenuData *m) {
int rpys = 0;
if(!dir) {
printf("Could't read %s\n", get_replays_path());
log_warn("Could't read %s", get_replays_path());
return -1;
}

View file

@ -9,7 +9,6 @@
#include "progress.h"
#include "paths/native.h"
#include "taisei_err.h"
#include "stage.h"
/*
@ -73,18 +72,18 @@ static void progress_read(SDL_RWops *file) {
int64_t filesize = SDL_RWsize(file);
if(filesize < 0) {
warnx("progress_read(): SDL_RWsize() failed: %s", SDL_GetError());
log_warn("SDL_RWsize() failed: %s", SDL_GetError());
return;
}
if(filesize > PROGRESS_MAXFILESIZE) {
warnx("progress_read(): progress file is huge (%i bytes, %i max)", filesize, PROGRESS_MAXFILESIZE);
log_warn("Progress file is huge (%li bytes, %i max)", (long)filesize, PROGRESS_MAXFILESIZE);
return;
}
for(int i = 0; i < sizeof(progress_magic_bytes); ++i) {
if(SDL_ReadU8(file) != progress_magic_bytes[i]) {
warnx("progress_read(): invalid header");
log_warn("Invalid header");
return;
}
}
@ -101,7 +100,7 @@ static void progress_read(SDL_RWops *file) {
uint8_t *buf = malloc(bufsize);
if(!SDL_RWread(file, buf, bufsize, 1)) {
warnx("progress_read(): SDL_RWread() failed: %s", SDL_GetError());
log_warn("SDL_RWread() failed: %s", SDL_GetError());
free(buf);
return;
}
@ -110,7 +109,7 @@ static void progress_read(SDL_RWops *file) {
uint32_t checksum = progress_checksum(buf, bufsize);
if(checksum != checksum_fromfile) {
warnx("progress_read(): bad checksum: %x != %x", checksum, checksum_fromfile);
log_warn("Bad checksum: %x != %x", checksum, checksum_fromfile);
SDL_RWclose(vfile);
free(buf);
return;
@ -152,7 +151,7 @@ static void progress_read(SDL_RWops *file) {
break;
default:
warnx("progress_read(): unknown command %i, skipping %u bytes", cmd, cmdsize);
log_warn("Unknown command %i, skipping %u bytes", cmd, cmdsize);
while(cur++ < cmdsize)
SDL_ReadU8(vfile);
break;
@ -305,7 +304,7 @@ static void progress_write(SDL_RWops *file) {
if(SDL_RWtell(vfile) != bufsize) {
free(buf);
errx(-1, "progress_write(): buffer is inconsistent\n");
log_err("Buffer is inconsistent");
return;
}
@ -314,7 +313,7 @@ static void progress_write(SDL_RWops *file) {
SDL_RWwrite(file, &cs, 4, 1);
if(!SDL_RWwrite(file, buf, bufsize, 1)) {
warnx("progress_write(): SDL_RWread() failed: %s", SDL_GetError());
log_err("SDL_RWwrite() failed: %s", SDL_GetError());
free(buf);
return;
}
@ -348,7 +347,7 @@ void progress_load(void) {
SDL_RWops *file = SDL_RWFromFile(p, "rb");
if(!file) {
warnx("progress_load(): couldn't open the progress file: %s\n", SDL_GetError());
log_warn("Couldn't open the progress file: %s", SDL_GetError());
free(p);
return;
}
@ -363,7 +362,7 @@ void progress_save(void) {
SDL_RWops *file = SDL_RWFromFile(p, "wb");
if(!file) {
warnx("progress_save(): couldn't open the progress file: %s\n", SDL_GetError());
log_warn("Couldn't open the progress file: %s", SDL_GetError());
free(p);
return;
}

View file

@ -11,7 +11,6 @@
#include <time.h>
#include "global.h"
#include "random.h"
#include "taisei_err.h"
/*
* Multiply-with-carry algorithm
@ -36,7 +35,7 @@ void tsrand_seed_p(RandomState *rnd, uint32_t seed) {
uint32_t tsrand_p(RandomState *rnd) {
if(rnd->locked) {
warnx("Attempted to use a locked RNG state!\n");
log_warn("Attempted to use a locked RNG state");
return 0;
}
@ -105,7 +104,7 @@ static uint32_t tsrand_array[TSRAND_ARRAY_LIMIT];
static int tsrand_array_elems;
static uint64_t tsrand_fillflags = 0;
static void tsrand_error(const char *file, unsigned int line, const char *fmt, ...) {
static void tsrand_error(const char *file, const char *func, unsigned int line, const char *fmt, ...) {
char buf[2048] = { 0 };
va_list args;
@ -113,14 +112,14 @@ static void tsrand_error(const char *file, unsigned int line, const char *fmt, .
vsnprintf(buf, sizeof(buf), fmt, args);
va_end(args);
errx(-1, "tsrand error: %s [%s:%u]", buf, file, line);
log_err("%s(): %s [%s:%u]", func, buf, file, line);
}
#define TSRANDERR(...) tsrand_error(file, line, __VA_ARGS__)
#define TSRANDERR(...) tsrand_error(file, __func__, line, __VA_ARGS__)
void __tsrand_fill_p(RandomState *rnd, int amount, const char *file, unsigned int line) {
if(tsrand_fillflags) {
TSRANDERR("tsrand_fill_p: some indices left unused from the previous call");
TSRANDERR("Some indices left unused from the previous call");
return;
}
@ -138,7 +137,7 @@ void __tsrand_fill(int amount, const char *file, unsigned int line) {
uint32_t __tsrand_a(int idx, const char *file, unsigned int line) {
if(idx >= tsrand_array_elems || idx < 0) {
TSRANDERR("tsrand_a: index out of range (%i / %i)", idx, tsrand_array_elems);
TSRANDERR("Index out of range (%i / %i)", idx, tsrand_array_elems);
return 0;
}
@ -147,7 +146,7 @@ uint32_t __tsrand_a(int idx, const char *file, unsigned int line) {
return tsrand_array[idx];
}
TSRANDERR("tsrand_a: index %i used multiple times", idx);
TSRANDERR("Index %i used multiple times", idx);
return 0;
}

View file

@ -16,14 +16,13 @@
#include "global.h"
#include "paths/native.h"
#include "taisei_err.h"
static uint8_t replay_magic_header[] = REPLAY_MAGIC_HEADER;
void replay_init(Replay *rpy) {
memset(rpy, 0, sizeof(Replay));
stralloc(&rpy->playername, config_get_str(CONFIG_PLAYERNAME));
printf("replay_init(): replay initialized for writting\n");
log_debug("Replay at %p initialized for writing", (void*)rpy);
}
ReplayStage* replay_create_stage(Replay *rpy, StageInfo *stage, uint64_t seed, Difficulty diff, uint32_t points, Player *plr) {
@ -52,7 +51,7 @@ ReplayStage* replay_create_stage(Replay *rpy, StageInfo *stage, uint64_t seed, D
s->plr_power = plr->power;
s->plr_inputflags = plr->inputflags;
printf("replay_init_stage(): created a new stage for writting\n");
log_debug("Created a new stage %p in replay %p", (void*)s, (void*)rpy);
return s;
}
@ -103,7 +102,7 @@ void replay_destroy(Replay *rpy) {
free(rpy->playername);
memset(rpy, 0, sizeof(Replay));
printf("Replay destroyed.\n");
log_debug("Replay at %p destroyed", (void*)rpy);
}
void replay_stage_event(ReplayStage *stg, uint32_t frame, uint8_t type, int16_t value) {
@ -119,14 +118,14 @@ void replay_stage_event(ReplayStage *stg, uint32_t frame, uint8_t type, int16_t
s->numevents++;
if(s->numevents >= s->capacity) {
printf("Replay stage reached its capacity of %d, reallocating\n", s->capacity);
log_debug("Replay stage reached its capacity of %d, reallocating", s->capacity);
s->capacity *= 2;
s->events = (ReplayEvent*)realloc(s->events, sizeof(ReplayEvent) * s->capacity);
printf("The new capacity is %d\n", s->capacity);
log_debug("The new capacity is %d", s->capacity);
}
if(type == EV_OVER) {
printf("The replay is OVER\n");
log_debug("The replay is OVER");
}
}
@ -253,12 +252,12 @@ int replay_write(Replay *rpy, SDL_RWops *file, bool compression) {
}
#ifdef REPLAY_LOAD_GARBAGE_TEST
#define PRINTPROP(prop,fmt) printf("replay_read(): " #prop " = %" # fmt " [%li / %li]\n", prop, (long int)SDL_RWtell(file), (long int)filesize)
#define PRINTPROP(prop,fmt) log_debug(#prop " = %" # fmt " [%li / %li]", prop, (long int)SDL_RWtell(file), (long int)filesize)
#else
#define PRINTPROP(prop,fmt) (void)(prop)
#endif
#define CHECKPROP(prop,fmt) PRINTPROP(prop,fmt); if(filesize > 0 && SDL_RWtell(file) == filesize) { warnx("replay_read(): premature EOF"); return false; }
#define CHECKPROP(prop,fmt) PRINTPROP(prop,fmt); if(filesize > 0 && SDL_RWtell(file) == filesize) { log_warn("Premature EOF"); return false; }
static void replay_read_string(SDL_RWops *file, char **ptr) {
size_t len = SDL_ReadLE16(file);
@ -273,7 +272,7 @@ static int replay_read_header(Replay *rpy, SDL_RWops *file, int64_t filesize, si
for(uint8_t *u8_p = replay_magic_header; *u8_p; ++u8_p) {
++(*ofs);
if(SDL_ReadU8(file) != *u8_p) {
warnx("replay_read(): incorrect header");
log_warn("Incorrect header");
return false;
}
}
@ -282,7 +281,7 @@ static int replay_read_header(Replay *rpy, SDL_RWops *file, int64_t filesize, si
(*ofs) += 2;
if((rpy->version & ~REPLAY_VERSION_COMPRESSION_BIT) != REPLAY_STRUCT_VERSION) {
warnx("replay_read(): incorrect version");
log_warn("Incorrect version");
return false;
}
@ -301,7 +300,7 @@ static int replay_read_meta(Replay *rpy, SDL_RWops *file, int64_t filesize) {
CHECKPROP(rpy->numstages = SDL_ReadLE16(file), u);
if(!rpy->numstages) {
warnx("replay_read(): no stages in replay");
log_warn("No stages in replay");
return false;
}
@ -327,7 +326,7 @@ static int replay_read_meta(Replay *rpy, SDL_RWops *file, int64_t filesize) {
CHECKPROP(stg->numevents = SDL_ReadLE16(file), u);
if(replay_calc_stageinfo_checksum(stg) + SDL_ReadLE32(file)) {
warnx("replay_read(): stageinfo is corrupt");
log_warn("Stageinfo is corrupt");
return false;
}
}
@ -340,7 +339,7 @@ static int replay_read_events(Replay *rpy, SDL_RWops *file, int64_t filesize) {
ReplayStage *stg = rpy->stages + i;
if(!stg->numevents) {
warnx("replay_read(): no events in stage");
log_warn("No events in stage");
return false;
}
@ -366,23 +365,22 @@ int replay_read(Replay *rpy, SDL_RWops *file, ReplayReadMode mode) {
mode &= REPLAY_READ_ALL;
if(!mode) {
errx(-1, "replay_read(): called with invalid read mode");
return false;
log_err("Called with invalid read mode");
}
filesize = SDL_RWsize(file);
if(filesize < 0) {
warnx("replay_read(): SDL_RWsize() failed: %s", SDL_GetError());
log_warn("SDL_RWsize() failed: %s", SDL_GetError());
} else {
printf("replay_read(): %li bytes\n", (long int)filesize);
log_debug("%li bytes", (long int)filesize);
}
if(mode & REPLAY_READ_META) {
memset(rpy, 0, sizeof(Replay));
if(filesize > 0 && filesize <= sizeof(replay_magic_header) + 2) {
warnx("replay_read(): replay file is too short (%i)", filesize);
log_warn("Replay file is too short (%li)", (long int)filesize);
return false;
}
@ -396,7 +394,7 @@ int replay_read(Replay *rpy, SDL_RWops *file, ReplayReadMode mode) {
if(rpy->version & REPLAY_VERSION_COMPRESSION_BIT) {
if(rpy->fileoffset < SDL_RWtell(file)) {
warnx("replay_read(): invalid offset %li", (long int)rpy->fileoffset);
log_warn("Invalid offset %li", (long int)rpy->fileoffset);
return false;
}
@ -425,20 +423,19 @@ int replay_read(Replay *rpy, SDL_RWops *file, ReplayReadMode mode) {
if(mode & REPLAY_READ_EVENTS) {
if(!(mode & REPLAY_READ_META)) {
if(!rpy->fileoffset) {
errx(-1, "replay_read(): tried to read events before reading metadata");
return false;
log_err("Tried to read events before reading metadata");
}
for(int i = 0; i < rpy->numstages; ++i) {
if(rpy->stages[i].events) {
warnx("replay_read(): reading events into a replay that already had events, call replay_destroy_events() if this is intended");
log_warn("Reading events into a replay that already had events, call replay_destroy_events() if this is intended");
replay_destroy_events(rpy);
break;
}
}
if(SDL_RWseek(file, rpy->fileoffset, RW_SEEK_SET) < 0) {
warnx("replay_read(): SDL_RWseek() failed: %s", SDL_GetError());
log_warn("SDL_RWseek() failed: %s", SDL_GetError());
return false;
}
}
@ -488,13 +485,13 @@ char* replay_getpath(const char *name, bool ext) {
int replay_save(Replay *rpy, const char *name) {
char *p = replay_getpath(name, !strendswith(name, REPLAY_EXTENSION));
printf("replay_save(): saving %s\n", p);
log_info("Saving %s", p);
SDL_RWops *file = SDL_RWFromFile(p, "wb");
free(p);
if(!file) {
warnx("replay_save(): SDL_RWFromFile() failed: %s\n", SDL_GetError());
log_warn("SDL_RWFromFile() failed: %s", SDL_GetError());
return false;
}
@ -512,7 +509,7 @@ int replay_load(Replay *rpy, const char *name, ReplayReadMode mode) {
p = replay_getpath(name, !strendswith(name, REPLAY_EXTENSION));
}
printf("replay_load(): loading %s (mode %i)\n", p, mode);
log_info("replay_load(): loading %s (mode %i)", p, mode);
SDL_RWops *file = SDL_RWFromFile(p, "rb");
@ -521,7 +518,7 @@ int replay_load(Replay *rpy, const char *name, ReplayReadMode mode) {
}
if(!file) {
warnx("replay_save(): SDL_RWFromFile() failed: %s\n", SDL_GetError());
log_warn("SDL_RWFromFile() failed: %s", SDL_GetError());
return false;
}
@ -569,14 +566,14 @@ void replay_stage_check_desync(ReplayStage *stg, int time, uint16_t check, Repla
if(mode == REPLAY_PLAY) {
if(stg->desync_check && stg->desync_check != check) {
warnx("replay_check_desync(): Replay desync detected! %u != %u\n", stg->desync_check, check);
log_warn("Replay desync detected! %u != %u\n", stg->desync_check, check);
} else {
printf("replay_check_desync(): %u OK\n", check);
log_debug("%u OK", check);
}
}
#ifdef REPLAY_WRITE_DESYNC_CHECKS
else {
printf("replay_stage_check_desync(): %u\n", check);
log_debug("%u", check);
replay_stage_event(stg, time, EV_CHECK_DESYNC, (int16_t)check);
}
#endif
@ -607,7 +604,7 @@ int replay_test(void) {
SDL_WriteU8(handle, 's');
SDL_WriteU8(handle, 't');
printf("replay_test(): wrote a valid replay header\n");
log_info("Wrote a valid replay header");
RandomState rnd;
tsrand_init(&rnd, time(0));
@ -616,20 +613,20 @@ int replay_test(void) {
SDL_WriteU8(handle, tsrand_p(&rnd) & 0xFF);
}
printf("replay_test(): wrote %i bytes of garbage\n", sz);
log_info("Wrote %i bytes of garbage", sz);
SDL_RWseek(handle, 0, RW_SEEK_SET);
for(int i = 0; i < headsz; ++i) {
printf("%x ", buf[i]);
tsfprintf(stdout, "%x ", buf[i]);
}
printf("\n");
tsfprintf(stdout, "\n");
Replay rpy;
if(replay_read(&rpy, handle, REPLAY_READ_ALL)) {
errx(-1, "Succeeded loading garbage data as a replay... that shouldn't happen");
log_err("Succeeded loading garbage data as a replay... that shouldn't happen");
}