logger v2.0
2026-08-30
Logger v1.0 was good enough for printf debugging but when expanding it’s usage for an actual desktop application, it falls short on many things. v2.0 tries to address those (tho I still have some more ideas to improve it further).
Wrong (or Lack of) information in the log statements
The logger printed out functions and filenames where the log statements occurred, that’s more than enough in some cases, but can get confusing when there are multiple log statements in a function. So, to change the format, I’ve decided to opt for __FILE__:__LINE__ syntax for log location indication. Modern text editors and terminals also understand this format and can easily navigate to the corresponding line with just a click.
So, this
#define mscbl_log_warn(fmt, ...) printf(ANSI_YELLOW "[%s]" ANSI_PINK "[%s] " ANSI_RESET fmt "\n", __func__, __FILE__ + log_build_path_len, __VA_ARGS__)is now more like this
#define mscbl_log_warn(fmt, ...) printf(ANSI_YELLOW "[%s]" ANSI_PINK "[%s] " ANSI_RESET fmt "\n", __func__, __FILE__ + log_build_path_len, __VA_ARGS__)Logs are pretty much useless without a terminal
When the application is packaged and shipped to a user’s computer, the logging system becomes useless because the application will not spawn a debug terminal. We can solve this by writing our logs to a separate file in the user’s computer. This will actually help in taking user feedback and finding bugs.
Implementation
- Make a pair of init/deinit functions that manage the lifetime of the logger and the log file.
- Write a different log macro that can generate log statements that are cleaner, more file-friendly, easier to read and free of ASCII color-codes.
- This is optional, but I don’t like to have my application’s log files flood someone else’s computer with gigabytes of logs, so the log function can auto delete logs older thant specific date.
log.h
#if DBG
#define _color_log(c1, fmt, ...) printf(c1 "[%s:" Stringify(__LINE__) "] " ANSI_RESET fmt "\n", __FILE__ + (sizeof(__FILE__) > log_build_path_len ? log_build_path_len : 0) __VA_OPT__(, ) __VA_ARGS__)
#define mscbl_log_error(fmt, ...) _color_log(ANSI_RED, fmt, __VA_ARGS__)
#define mscbl_log_warn(fmt, ...) _color_log(ANSI_YELLOW, fmt, __VA_ARGS__)
#define mscbl_log_info(fmt, ...) _color_log(ANSI_CYAN, fmt, __VA_ARGS__)
#else
#define mscbl_log_info(fmt, ...) _mscbl_log("INFO", fmt, __VA_ARGS__)
#define mscbl_log_warn(fmt, ...) _mscbl_log("WARN", fmt, __VA_ARGS__)
#define mscbl_log_error(fmt, ...) _mscbl_log("ERROR", fmt, __VA_ARGS__)
#endif
void mscbl_log_init(U64 log_age);
void mscbl_log_deinit();
MSCBL_API void mscbl_log(const char *fmt, ...);
#define _mscbl_log(level, fmt, ...) mscbl_log("[" level "] [%s:" Stringify(__LINE__) "] " fmt "\n", __FILE__ + (sizeof(__FILE__) > log_build_path_len ? log_build_path_len : 0) __VA_OPT__(, ) __VA_ARGS__)log.cpp
void mscbl_log_init(U64 log_age)
{
// Get log path dir
StringBuilder base = string_init(app_arena, root);
Result res = ResultSuccess();
// If logs dir exists, delete logs older than 10 days
if (os_path_exists(StringCast(base), &res))
{
ArenaScoped(app_arena)
{
String pattern_part = sv(LOG_FILE_NAME_PRE "*" LOG_FILE_NAME_EXT);
StringBuilder pattern = string_init(app_arena, root);
path_join(&pattern, append);
path_join(&pattern, pattern_part);
U64 cur_time = os_get_timestamp();
FileMTime *files = os_list_by_pattern(StringCast(pattern), StringCast(base), app_arena);
for (S64 i = 0; i < arr_getsize(files); i++)
{
FileMTime entry = files[i];
U64 seconds_since = cur_time - entry.mtime;
if (log_age * 86400 <= seconds_since)
{
os_file_delete(entry.path, &res);
}
}
}
}
else
{
os_mkdirs(StringCast(base));
}
// Create today's log file
ArenaScoped(app_arena)
{
StringBuilder log_filepath = string_empty(app_arena, KB(4));
string_format(&log_filepath, "%.*s" LOG_FILE_NAME_PRE "%02d-%02d-%04d" LOG_FILE_NAME_EXT,
StringSpr(base), os_info.start_time.date, os_info.start_time.month + 1, os_info.start_time.year);
log_file = os_file_open(StringCast(log_filepath), FileAccess_Append, FileMode_OpenAlways, &res);
}
}
void mscbl_log_deinit()
{
Result res = ResultSuccess();
os_file_close(log_file, &res);
}
void mscbl_log(const char *fmt, ...)
{
char buffer[KB(8)];
Result res = ResultSuccess();
Time time = get_cur_time();
// Format log entry
U64 header_size = snprintf(buffer, 256, "[%02d-%02d-%04d %02d:%02d:%02d.%03d] ", time.date, time.month + 1, time.year, time.hour, time.minute, time.second, time.milsec);
va_list args;
va_start(args, fmt);
U64 size = vsnprintf(buffer + header_size, sizeof(buffer) - header_size, fmt, args) + header_size;
va_end(args);
// Serialize the entry to log file
os_file_write(log_file, size, (U8 *)buffer, &res);
}A way to capture logs from thirdparty libraries
Since now I’m using ONNX Runtime in my application which emits it’s own logs on the terminal as well, I need a way to redirect logs from it to my application’s log files. So, I’ve made this bare log function.
log.h
#if DBG
#define mscbl_log_bare(level, loc, fmt, ...) printf(ANSI_PURPLE "[%s] [%s] " ANSI_RESET fmt "\n", level, loc __VA_OPT__(, ) __VA_ARGS__)
#else
#define mscbl_log_bare(level, loc, fmt, ...) _mscbl_log_bare(level, loc, fmt "\n" __VA_OPT__(, ) __VA_ARGS__)
#endif
MSCBL_API void _mscbl_log_bare(const char *level, const char *location, const char *fmt, ...);log.cpp
void _mscbl_log_bare(const char *level, const char *location, const char *fmt, ...)
{
char buffer[KB(8)];
Result res = ResultSuccess();
Time time = get_cur_time();
U64 header_size = snprintf(buffer, 256, "[%02d-%02d-%04d %02d:%02d:%02d.%03d] ", time.date, time.month + 1, time.year, time.hour, time.minute, time.second, time.milsec);
U64 prefix_size = snprintf(buffer + header_size, 512, "[%s] [%s] ", level, location);
U64 offset = header_size + prefix_size;
va_list args;
va_start(args, fmt);
U64 payload_size = vsnprintf(buffer + offset, sizeof(buffer) - offset, fmt, args);
va_end(args);
U64 total_size = offset + payload_size;
os_file_write(log_file, total_size, (U8 *)buffer, &res);
}(ONNX Runtime specific calling code)
void ORT_API_CALL ort_logger(void *param, OrtLoggingLevel severity, const char *category, const char *logid, const char *code_location, const char *message)
{
const char *level = NULL;
switch (severity)
{
case ORT_LOGGING_LEVEL_VERBOSE:
case ORT_LOGGING_LEVEL_INFO:
level = "INFO";
break;
case ORT_LOGGING_LEVEL_WARNING:
level = "WARN";
break;
case ORT_LOGGING_LEVEL_ERROR:
case ORT_LOGGING_LEVEL_FATAL:
level = "ERROR";
break;
}
// Little hack to avoid having double newline characters in end
String message_str = sv(message);
while (message_str.v[message_str.size - 1] == '\n')
message_str.size--;
mscbl_log_bare(level, code_location, "[%s] %.*s", category, StringSpr(message_str));
}clock_t doesn’t have enough resolution
I often noticed this code always produced timestamps ending with a .0000 so, the resolution was always limited to 1 millisecond. To get around this, I started looking around (asking AI also) for methods to get more precise clock times while also not having to rely on std::chrono.
log.h
#define perf_beg(A) U64 __perf_start_##A = clock()
#define perf_end(A) mscbl_log_info("[perf]: %.4fms", (F64)(clock() - __perf_start_##A) / CLOCKS_PER_SEC * 1000.0f)And turns out, I already had something like that in the OS layer code. QueryPerformanceCounter on Windows and clock_gettime on Linux gives the value of a high resolution time stamp that can be used for time-interval measurements. (Just what we need)
win32_core.cpp (windows example)
U64 os_get_ticks_now()
{
LARGE_INTEGER count;
Assert(QueryPerformanceCounter(&count), "Error Code: (%u)\n", GetLastError());
return (U64)count.QuadPart;
}So, after switching things up a little we get this.
log.h
#define perf_beg(A) U64 __perf_start_##A = os_get_ticks_now()
#define perf_end(A) mscbl_log_info("[PERF:" Stringify(A) "] %.4fms", ((F64)(os_get_ticks_now() - __perf_start_##A) * 1000.0f) / (os_info.ticks_per_sec > 0 ? os_info.ticks_per_sec : 1000))And now we instantly have much more precise timing results.
[src\db/db_helpers.cpp:56] [PERF:query] 18.5148ms
[src\inference/inference.cpp:328] [PERF:text_embedding] 170.6764ms
...Also, a little macro to get timing results as a variable.
#define perf_gap(A) ((F64)(os_get_ticks_now() - __perf_start_##A) * 1000.0) / os_info.ticks_per_sec)