diff --git a/CMakeLists.txt b/CMakeLists.txt index 7ac622f..367b784 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -73,6 +73,15 @@ foreach(TARGET ${POUND_PROJECT_TARGETS}) -Wcast-align -Wconversion> ) + + # Set Compile time log level for all targets. + # 1: Trace + # 2: Debug + # 3: Info + # 4: Warning + # 5: Error + # 6: Fatal + target_compile_definitions(${TARGET} PRIVATE COMPILE_TIME_LOG_LEVEL=1) endforeach() diff --git a/src/common/CMakeLists.txt b/src/common/CMakeLists.txt index 963c14f..c5db7b3 100644 --- a/src/common/CMakeLists.txt +++ b/src/common/CMakeLists.txt @@ -6,6 +6,7 @@ target_sources(common PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/PathUtil.cpp ${CMAKE_CURRENT_SOURCE_DIR}/StringUtil.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Thread.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/logging.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Logging/Backend.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Logging/Filter.cpp ${CMAKE_CURRENT_SOURCE_DIR}/Logging/TextFormatter.cpp diff --git a/src/common/logging.cpp b/src/common/logging.cpp new file mode 100644 index 0000000..aae9fa1 --- /dev/null +++ b/src/common/logging.cpp @@ -0,0 +1,166 @@ +#include "logging.h" +#include +#include +#include +#include + +#ifdef _WIN32 +/* + * Stupid shit like this is why I hate Windows. WHY CANT YOU JUST FOLLOW + * THE POSIX STAMDARD GOD DAMN. + */ +#define gmtime_r(src, dest) gmtime_s(dest, src) +#endif // _WIN32 + +/* + * TIMESTMP_BUFFER_LEN - The required buffer size for the timestamp format. + * + * Calculated for "%Y-%m-%dT%H:%M:%SZ": + * YYYY-mm-ddTHH:MM:SSZ + * 4+1+2+1+2+1+2+1+2+1+2+1 = 20 characters + * +1 for the null terminator = 21 bytes. + * + * We define the buffer as 32 bytes to provide a safe margin for future + * format changes, such as adding sub-second precision (e.g., ".123"). + */ +#define TIMESTMP_BUFFER_LEN 32 + +/* + * LOG_LINE_BUFFER_SIZE - A reasonable max size for a single log line. + * + * If it's too long, it will be truncated. + */ +#define LOG_LINE_BUFFER_SIZE 1024 + +/* + * Static strings to use when all else fails. + * Its unique format makes it easy to search for in logs. + */ +static const char* const FAILED_TIMESTAMP = "[TIMESTAMP_UNAVAILABLE]"; +static const char* const FAILED_LOG_LEVEL = "[LOG_LEVEL_UNAVAILABLE]"; + +log_level_t runtime_log_level = LOG_LEVEL_NONE; + +/* + * Pre-allocate a buffer for the timestamp string. + * Make it static so it's not constantly re-allocated on the stack. + */ +static char timestamp_buffer[TIMESTMP_BUFFER_LEN] = {}; + +const char* get_current_timestamp_str(void); + +void log_message(log_level_t level, const char* module_name, const char* file, int line, const char* message, ...) +{ + assert(nullptr != message); + + const char* timestamp_str = get_current_timestamp_str(); + const char* level_str = nullptr; + + if (level < runtime_log_level) + { + return; + } + else if (level <= LOG_LEVEL_NONE) + { + level_str = FAILED_LOG_LEVEL; + } + else + { + switch (level) + { + case LOG_LEVEL_TRACE: + level_str = "TRACE"; + break; + case LOG_LEVEL_DEBUG: + level_str = "DEBUG"; + break; + case LOG_LEVEL_INFO: + level_str = "INFO"; + break; + case LOG_LEVEL_WARNING: + level_str = "WARNING"; + break; + case LOG_LEVEL_ERROR: + level_str = "ERROR"; + break; + case LOG_LEVEL_FATAL: + level_str = "FATAL"; + break; + default: + level_str = FAILED_LOG_LEVEL; + break; + } + } + + char buffer[LOG_LINE_BUFFER_SIZE] = {}; + + /* Keep track of our position in the buffer */ + size_t offset = 0; + offset += (size_t)snprintf(buffer + offset, LOG_LINE_BUFFER_SIZE - offset, "[%s] [%s] [%s] [%s:%d] ", timestamp_str, + level_str, module_name, file, line); + + /* Handle the user's variadic format string. */ + va_list args; + va_start(args, message); + + if (offset < LOG_LINE_BUFFER_SIZE) + { + (void)vsnprintf(buffer + offset, LOG_LINE_BUFFER_SIZE - offset, message, args); + } + va_end(args); + + /* Print the entire, fully-formed buffer to stderr in a SINGLE, ATOMIC call. */ + fprintf(stderr, "%s\n", buffer); + + /* + * TODO(GloriousTaco:common): For guaranteed atomicity across + * threads, this entire function should be protected by a mutex. + * The fprintf call itself is usually thread-safe at the *call* level, but + * our logic requires atomicity at the *message* level. + * + * lock_logging_mutex(); + * fprintf(stderr, "%s\n", buffer); + * unlock_logging_mutex(); + */ +} + +const char* get_current_timestamp_str(void) +{ + time_t now; + + /* time() can fail, though it's rare. */ + if (time(&now) == (time_t)-1) + { + return FAILED_TIMESTAMP; + } + + struct tm time_since_epoch = {}; +#ifdef WIN32 + /* https://learn.microsoft.com/en-us/cpp/c-runtime-library/reference/gmtime-s-gmtime32-s-gmtime64-s?view=msvc-170 */ + (void) gmtime_r(&now, &time_since_epoch); + +#if 0 + TODO(GloriousTacoo:common): Someone fix this error handling. I have little + patience for anything Windows related. + if ((struct tm)-1 == &time_since_epoch) + { + return FAILED_TIMESTAMP; + } +#endif + +#else + if (nullptr == gmtime_r(&now, &time_since_epoch)) + { + return FAILED_TIMESTAMP; + } +#endif // WIN32 + + size_t bytes_written = strftime(timestamp_buffer, TIMESTMP_BUFFER_LEN, "%Y-%m-%dT%H:%M:%SZ", &time_since_epoch); + + if (0 == bytes_written) + { + return FAILED_TIMESTAMP; + } + + return timestamp_buffer; +} diff --git a/src/common/logging.h b/src/common/logging.h new file mode 100644 index 0000000..7c9540a --- /dev/null +++ b/src/common/logging.h @@ -0,0 +1,136 @@ +#ifndef POUND_COMMON_LOGGING_H +#define POUND_COMMON_LOGGING_H + +/* + * API USAGE CONTRACT: + * ------------------- + * + * Any source file (.c) that uses this logging framework MUST define + * the LOG_MODULE macro *before* including this header file. This + * provides a human-readable name for the component that is generating + * the log message. + * + * Example Usage in a .c file: + * + * #define LOG_MODULE "KVM_MMU" + * #include "common/logging.h" + * + * void mmu_translate_address(uint64_t gpa) { + * LOG_DEBUG("Translating GPA: 0x%llx", gpa); + * // ... + * if (error) { + * LOG_ERROR("Page table fault for GPA: 0x%llx", gpa); + * } + * } + */ + +/* + * log_level_t - Defines the severity for log messages. + */ +typedef enum log_level +{ + LOG_LEVEL_NONE = 0, + LOG_LEVEL_TRACE, + LOG_LEVEL_DEBUG, + LOG_LEVEL_INFO, + LOG_LEVEL_WARNING, + LOG_LEVEL_ERROR, + LOG_LEVEL_FATAL, +} log_level_t; + +extern log_level_t runtime_log_level; + +/* + * This function is apart of the initial implementation and should NEVER be + * called directly. Use LOG_DEBUG, etc. macros instead. + */ +void log_message(log_level_t level, const char* module_name, const char* file, int line, const char* message, ...); + +// ------------------------- +// ---- Internal Macros ---- +// ------------------------- + +#define __LOG_MODULE_NOT_DEFINED__ +#ifndef LOG_MODULE +#define LOG_MODULE __LOG_MODULE_NOT_DEFINED__ +#endif + +/* DO NOT USE THESE DIRECTLY. They are internal helpers. */ +#define _STRINGIFY_HELPER(x) #x +#define _STRINGIFY(x) _STRINGIFY_HELPER(x) + +#define CHECK_LOG_MODULE_DEFINED() \ + static_assert(__builtin_strcmp(_STRINGIFY(LOG_MODULE), _STRINGIFY(__LOG_MODULE_NOT_DEFINED__)) != 0, \ + "LOGGING ERROR: LOG_MODULE must be #defined before #including logging.h. Example: #define " \ + "LOG_MODULE \"MY_MODULE\"") + +#if COMPILE_TIME_LOG_LEVEL > LOG_LEVEL_TRACE +#define LOG_TRACE(format, ...) (void)0 +#else +#define LOG_TRACE(format, ...) \ + do \ + { \ + CHECK_LOG_MODULE_DEFINED(); \ + log_message(LOG_LEVEL_TRACE, LOG_MODULE, __FILE__, __LINE__, format, ##__VA_ARGS__); \ + } while (0) +#endif + +// ------------------------------- +// ---- Public Logging Macros ---- +// ------------------------------- + +#if COMPILE_TIME_LOG_LEVEL > LOG_LEVEL_DEBUG +#define LOG_DEBUG(format, ...) (void)0 +#else +#define LOG_DEBUG(format, ...) \ + do \ + { \ + CHECK_LOG_MODULE_DEFINED(); \ + log_message(LOG_LEVEL_DEBUG, LOG_MODULE, __FILE__, __LINE__, format, ##__VA_ARGS__); \ + } while (0) +#endif + +#if COMPILE_TIME_LOG_LEVEL > LOG_LEVEL_INFO +#define LOG_INFO(format, ...) (void)0 +#else +#define LOG_INFO(format, ...) \ + do \ + { \ + CHECK_LOG_MODULE_DEFINED(); \ + log_message(LOG_LEVEL_INFO, LOG_MODULE, __FILE__, __LINE__, format, ##__VA_ARGS__); \ + } while (0) +#endif + +#if COMPILE_TIME_LOG_LEVEL > LOG_LEVEL_WARNING +#define LOG_WARNING(format, ...) (void)0 +#else +#define LOG_WARNING(format, ...) \ + do \ + { \ + CHECK_LOG_MODULE_DEFINED(); \ + log_message(LOG_LEVEL_WARNING, LOG_MODULE, __FILE__, __LINE__, format, ##__VA_ARGS__); \ + } while (0) +#endif + +#if COMPILE_TIME_LOG_LEVEL > LOG_LEVEL_ERROR +#define LOG_ERROR(format, ...) (void)0 +#else +#define LOG_ERROR(format, ...) \ + do \ + { \ + CHECK_LOG_MODULE_DEFINED(); \ + log_message(LOG_LEVEL_ERROR, LOG_MODULE, __FILE__, __LINE__, format, ##__VA_ARGS__); \ + } while (0) +#endif + +#if COMPILE_TIME_LOG_LEVEL > LOG_LEVEL_FATAL +#define LOG_FATAL(format, ...) (void)0 +#else +#define LOG_FATAL(format, ...) \ + do \ + { \ + CHECK_LOG_MODULE_DEFINED(); \ + log_message(LOG_LEVEL_FATAL, LOG_MODULE, __FILE__, __LINE__, format, ##__VA_ARGS__); \ + } while (0) +#endif +#endif // POUND_COMMON_LOGGING_H