From c1f571ecce3c245e80af66cbe74292a16f432b04 Mon Sep 17 00:00:00 2001 From: wargio Date: Thu, 18 Apr 2024 21:33:06 +0800 Subject: [PATCH] Remove globals and refactor to complete implementation of logging. --- librz/bin/dwarf/unit.c | 4 +- librz/core/cconfig.c | 43 ++++---- librz/include/rz_util/rz_log.h | 28 ++--- librz/util/log.c | 184 +++++++++++++++++++++++---------- 4 files changed, 166 insertions(+), 93 deletions(-) diff --git a/librz/bin/dwarf/unit.c b/librz/bin/dwarf/unit.c index ae43b227352..42de760ab3c 100644 --- a/librz/bin/dwarf/unit.c +++ b/librz/bin/dwarf/unit.c @@ -83,7 +83,7 @@ static bool CU_attrs_parse( RzBinDwarfCompUnit *cu, RzBinDwarfAbbrevDecl *abbrev_decl) { - RZ_LOG_SILLY("0x%" PFMT64x ":\t%s%s [%" PFMT64d "] %s\n", + RZ_LOG_DEBUG("0x%" PFMT64x ":\t%s%s [%" PFMT64d "] %s\n", die->offset, rz_str_indent(die->depth), rz_bin_dwarf_tag(die->tag), die->abbrev_code, rz_bin_dwarf_children(die->has_children)); RzBinDwarfAttrSpec *spec = NULL; @@ -195,7 +195,7 @@ static bool CU_dies_parse( }; // there can be "null" entries that have abbr_code == 0 if (!abbrev_code) { - RZ_LOG_SILLY("0x%" PFMT64x ":\t%sNULL\n", offset, rz_str_indent(die.depth)); + RZ_LOG_DEBUG("0x%" PFMT64x ":\t%sNULL\n", offset, rz_str_indent(die.depth)); rz_vector_push(&unit->dies, &die); depth--; if (depth <= 0) { diff --git a/librz/core/cconfig.c b/librz/core/cconfig.c index 4653e248c07..15c10bd965e 100644 --- a/librz/core/cconfig.c +++ b/librz/core/cconfig.c @@ -2880,21 +2880,18 @@ static bool cb_log_config_traplevel(void *coreptr, void *nodeptr) { static bool cb_log_config_file(void *coreptr, void *nodeptr) { RzConfigNode *node = (RzConfigNode *)nodeptr; - const char *value = node->value; - rz_log_set_file(value); - return true; + return rz_log_set_file(node->value); } -static bool cb_log_config_srcinfo(void *coreptr, void *nodeptr) { +static bool cb_log_config_show_sources(void *coreptr, void *nodeptr) { RzConfigNode *node = (RzConfigNode *)nodeptr; const char *value = node->value; - switch (value[0]) { - case 't': - case 'T': - rz_log_set_srcinfo(true); - break; - default: - rz_log_set_srcinfo(false); + if (rz_str_is_true(value)) { + rz_log_set_show_sources(true); + } else if (rz_str_is_false(value)) { + rz_log_set_show_sources(false); + } else { + return false; } return true; } @@ -2902,13 +2899,12 @@ static bool cb_log_config_srcinfo(void *coreptr, void *nodeptr) { static bool cb_log_config_colors(void *coreptr, void *nodeptr) { RzConfigNode *node = (RzConfigNode *)nodeptr; const char *value = node->value; - switch (value[0]) { - case 't': - case 'T': + if (rz_str_is_true(value)) { rz_log_set_colors(true); - break; - default: + } else if (rz_str_is_false(value)) { rz_log_set_colors(false); + } else { + return false; } return true; } @@ -3338,21 +3334,24 @@ RZ_API int rz_core_config_init(RzCore *core) { // RZ_LOGLEVEL / log.level p = rz_sys_getenv("RZ_LOGLEVEL"); SETICB("log.level", p ? atoi(p) : RZ_DEFAULT_LOGLVL, cb_log_config_level, "Target log level/severity" - " (0:SILLY, 1:DEBUG, 2:VERBOSE, 3:INFO, 4:WARN, 5:ERROR, 6:FATAL)"); + " (0:DEBUG, 1:VERBOSE, 2:INFO, 3:WARN, 4:ERROR, 5:FATAL)"); free(p); // RZ_LOGTRAP_LEVEL / log.traplevel p = rz_sys_getenv("RZ_LOGTRAPLEVEL"); - SETICB("log.traplevel", p ? atoi(p) : RZ_LOGLVL_FATAL, cb_log_config_traplevel, "Log level for trapping rizin when hit" - " (0:SILLY, 1:VERBOSE, 2:DEBUG, 3:INFO, 4:WARN, 5:ERROR, 6:FATAL)"); + SETICB("log.traplevel", p ? atoi(p) : RZ_DEFAULT_LOGLVL_TRAP, cb_log_config_traplevel, "Log level for trapping rizin when hit" + " (0:VERBOSE, 1:DEBUG, 2:INFO, 3:WARN, 4:ERROR, 5:FATAL)"); free(p); + // RZ_LOGFILE / log.file p = rz_sys_getenv("RZ_LOGFILE"); SETCB("log.file", p ? p : "", cb_log_config_file, "Logging output filename / path"); free(p); - // RZ_LOGSRCINFO / log.srcinfo - p = rz_sys_getenv("RZ_LOGSRCINFO"); - SETCB("log.srcinfo", p ? p : "false", cb_log_config_srcinfo, "Should the log output contain src info (filename:lineno)"); + + // RZ_LOGSHOWSOURCES / log.show.sources + p = rz_sys_getenv("RZ_LOGSHOWSOURCES"); + SETCB("log.show.sources", p ? p : "false", cb_log_config_show_sources, "Should the log output contain src info (filename:lineno)"); free(p); + // RZ_LOGCOLORS / log.colors p = rz_sys_getenv("RZ_LOGCOLORS"); SETCB("log.colors", p ? p : "false", cb_log_config_colors, "Should the log output use colors (TODO)"); diff --git a/librz/include/rz_util/rz_log.h b/librz/include/rz_util/rz_log.h index b3264c07a0e..3e8cca32fae 100644 --- a/librz/include/rz_util/rz_log.h +++ b/librz/include/rz_util/rz_log.h @@ -14,13 +14,14 @@ #endif typedef enum rz_log_level { - RZ_LOGLVL_SILLY = 0, - RZ_LOGLVL_DEBUG = 1, - RZ_LOGLVL_VERBOSE = 2, - RZ_LOGLVL_INFO = 3, - RZ_LOGLVL_WARN = 4, - RZ_LOGLVL_ERROR = 5, - RZ_LOGLVL_FATAL = 6, // This will call rz_sys_breakpoint() and trap the process for debugging! + RZ_LOGLVL_DEBUG = 0, + RZ_LOGLVL_VERBOSE, + RZ_LOGLVL_INFO, + RZ_LOGLVL_WARN, + RZ_LOGLVL_ERROR, + RZ_LOGLVL_FATAL, ///< This will call rz_sys_breakpoint() and trap the process for debugging! + /* other flags */ + RZ_LOGLVL_SIZE, RZ_LOGLVL_NONE = 0xFF } RzLogLevel; @@ -30,6 +31,8 @@ typedef enum rz_log_level { #define RZ_DEFAULT_LOGLVL RZ_LOGLVL_ERROR #endif +#define RZ_DEFAULT_LOGLVL_TRAP RZ_LOGLVL_FATAL + typedef void (*RzLogCallback)(const char *output, const char *funcname, const char *filename, ut32 lineno, RzLogLevel level, const char *tag, const char *fmtstr, ...) RZ_PRINTF_CHECK(7, 8); @@ -40,12 +43,9 @@ typedef void (*RzLogCallback)(const char *output, const char *funcname, const ch __LINE__, lvl, tag, fmtstr, ##__VA_ARGS__); #if RZ_BUILD_DEBUG -#define RZ_LOG_SILLY(fmtstr, ...) rz_log(MACRO_LOG_FUNC, __FILE__, \ - __LINE__, RZ_LOGLVL_SILLY, NULL, fmtstr, ##__VA_ARGS__); #define RZ_LOG_DEBUG(fmtstr, ...) rz_log(MACRO_LOG_FUNC, __FILE__, \ __LINE__, RZ_LOGLVL_DEBUG, NULL, fmtstr, ##__VA_ARGS__); #else -#define RZ_LOG_SILLY(fmtstr, ...) #define RZ_LOG_DEBUG(fmtstr, ...) #endif @@ -66,14 +66,14 @@ extern "C" { // Called by rz_core to set the configuration variables RZ_API void rz_log_set_level(RzLogLevel level); -RZ_API void rz_log_set_file(const char *filename); -RZ_API void rz_log_set_srcinfo(bool show_info); +RZ_API bool rz_log_set_file(RZ_NULLABLE const char *filename); +RZ_API void rz_log_set_show_sources(bool show_sources); RZ_API void rz_log_set_colors(bool show_colors); RZ_API void rz_log_set_traplevel(RzLogLevel level); // Functions for adding log callbacks -RZ_API void rz_log_add_callback(RzLogCallback cbfunc); -RZ_API void rz_log_del_callback(RzLogCallback cbfunc); +RZ_API void rz_log_add_callback(RZ_NULLABLE RzLogCallback cbfunc); +RZ_API void rz_log_del_callback(RZ_NULLABLE RzLogCallback cbfunc); // TODO: rz_log_get_callbacks() /* Define rz_log as weak so it can be 'overwritten' externally diff --git a/librz/util/log.c b/librz/util/log.c index 2b2209acaa4..e69d95fa502 100644 --- a/librz/util/log.c +++ b/librz/util/log.c @@ -5,133 +5,207 @@ #define LOG_CONFIGSTR_SIZE 512 #define LOG_OUTPUTBUF_SIZE 512 -#include +#include +#include +#include #include -// TODO: Use thread-local storage to make these variables thread-safe -static RzList *log_cbs = NULL; // Functions to call when outputting log string -static int cfg_loglvl = RZ_LOGLVL_WARN; // Log level output -static int cfg_logtraplvl = RZ_LOGLVL_FATAL; // Log trap level -static bool cfg_logsrcinfo = false; // Print out debug source info with the output -static bool cfg_logcolors = false; // Output colored log text based on level -static char cfg_logfile[LOG_CONFIGSTR_SIZE] = ""; // Output text to filename -static const char *level_tags[] = { // Log level to tag string lookup array - [RZ_LOGLVL_SILLY] = "SILLY", +typedef struct log_config_s { + RzList *callbacks; + RzLogLevel level; + RzLogLevel trap_level; + bool show_sources; + FILE *file; + const char **tags; + RzThreadLock *lock; +} log_config_t; + +///< Log level to tag string lookup array +static const char *level_tags_no_colors[] = { [RZ_LOGLVL_VERBOSE] = "VERBOSE", [RZ_LOGLVL_DEBUG] = "DEBUG", [RZ_LOGLVL_INFO] = "INFO", [RZ_LOGLVL_WARN] = "WARNING", [RZ_LOGLVL_ERROR] = "ERROR", - [RZ_LOGLVL_FATAL] = "FATAL" + [RZ_LOGLVL_FATAL] = "FATAL", }; +static const char *level_tags_colors[] = { + [RZ_LOGLVL_VERBOSE] = Color_GREEN "VERBOSE" Color_RESET, + [RZ_LOGLVL_DEBUG] = Color_BLUE "DEBUG" Color_RESET, + [RZ_LOGLVL_INFO] = Color_CYAN "INFO" Color_RESET, + [RZ_LOGLVL_WARN] = Color_YELLOW "WARNING" Color_RESET, + [RZ_LOGLVL_ERROR] = Color_RED "ERROR" Color_RESET, + [RZ_LOGLVL_FATAL] = Color_MAGENTA "FATAL" Color_RESET, +}; + +static log_config_t logcfg = { 0 }; + +static void log_init() { + if (logcfg.lock) { + return; + } + logcfg.callbacks = NULL; + logcfg.level = RZ_DEFAULT_LOGLVL; + logcfg.trap_level = RZ_DEFAULT_LOGLVL_TRAP; + logcfg.show_sources = false; + logcfg.file = NULL; + logcfg.tags = level_tags_no_colors; + logcfg.lock = rz_th_lock_new(false); +} + // cconfig.c configuration callback functions below RZ_API void rz_log_set_level(RzLogLevel level) { - cfg_loglvl = level; + log_init(); + rz_th_lock_enter(logcfg.lock); + logcfg.level = level; + rz_th_lock_leave(logcfg.lock); } RZ_API void rz_log_set_traplevel(RzLogLevel level) { - cfg_logtraplvl = level; + log_init(); + rz_th_lock_enter(logcfg.lock); + logcfg.trap_level = level; + rz_th_lock_leave(logcfg.lock); } -RZ_API void rz_log_set_file(const char *filename) { - int value_len = rz_str_nlen(filename, LOG_CONFIGSTR_SIZE) + 1; - strncpy(cfg_logfile, filename, value_len); +RZ_API bool rz_log_set_file(RZ_NULLABLE const char *filename) { + log_init(); + rz_th_lock_enter(logcfg.lock); + bool ret = true; + if (logcfg.file) { + // if already open, then close the file handler. + fclose(logcfg.file); + logcfg.file = NULL; + } + + if (RZ_STR_ISEMPTY(filename)) { + // allow to have no filename + goto end; + } + + FILE *file = rz_sys_fopen(filename, "a+"); + if (!file) { + file = rz_sys_fopen(filename, "w+"); + } + if (!file) { + // failed to open the file. + ret = false; + goto end; + } + logcfg.file = file; + ret = true; + +end: + rz_th_lock_leave(logcfg.lock); + return ret; } -RZ_API void rz_log_set_srcinfo(bool show_info) { - cfg_logsrcinfo = show_info; +RZ_API void rz_log_set_show_sources(bool show_sources) { + log_init(); + rz_th_lock_enter(logcfg.lock); + logcfg.show_sources = show_sources; + rz_th_lock_leave(logcfg.lock); } -RZ_API void rz_log_set_colors(bool show_info) { - cfg_logcolors = show_info; +RZ_API void rz_log_set_colors(bool show_colors) { + log_init(); + rz_th_lock_enter(logcfg.lock); + logcfg.tags = show_colors ? level_tags_colors : level_tags_no_colors; + rz_th_lock_leave(logcfg.lock); } /** * \brief Add a logging callback * \param cbfunc RzLogCallback style function to be called */ -RZ_API void rz_log_add_callback(RzLogCallback cbfunc) { - if (!log_cbs) { - log_cbs = rz_list_new(); +RZ_API void rz_log_add_callback(RZ_NULLABLE RzLogCallback cbfunc) { + if (!cbfunc) { + return; + } + log_init(); + rz_th_lock_enter(logcfg.lock); + if (!logcfg.callbacks) { + logcfg.callbacks = rz_list_new(); } - if (!rz_list_contains(log_cbs, cbfunc)) { - rz_list_append(log_cbs, cbfunc); + if (!rz_list_contains(logcfg.callbacks, cbfunc)) { + rz_list_append(logcfg.callbacks, cbfunc); } + rz_th_lock_leave(logcfg.lock); } /** * \brief Remove a logging callback * \param cbfunc RzLogCallback style function to be called */ -RZ_API void rz_log_del_callback(RzLogCallback cbfunc) { - if (log_cbs) { - rz_list_delete_data(log_cbs, cbfunc); +RZ_API void rz_log_del_callback(RZ_NULLABLE RzLogCallback cbfunc) { + if (!cbfunc || !logcfg.callbacks) { + return; } + log_init(); + rz_th_lock_enter(logcfg.lock); + rz_list_delete_data(logcfg.callbacks, cbfunc); + rz_th_lock_leave(logcfg.lock); } RZ_API void rz_vlog(const char *funcname, const char *filename, ut32 lineno, RzLogLevel level, const char *tag, const char *fmtstr, va_list args) { - va_list args_copy; - va_copy(args_copy, args); + log_init(); - if (level < cfg_loglvl && level < cfg_logtraplvl) { + if (level < logcfg.level && level < logcfg.trap_level) { // Don't print if output level is lower than current level // Don't ignore fatal/trap errors - va_end(args_copy); return; } - // TODO: Colors + // copy args only if we print the log + va_list args_copy; + va_copy(args_copy, args); // Build output string with src info, and formatted output RzStrBuf sb; rz_strbuf_init(&sb); if (!tag) { - tag = RZ_BETWEEN(0, level, RZ_ARRAY_SIZE(level_tags) - 1) ? level_tags[level] : ""; + tag = RZ_BETWEEN(0, level, (RZ_LOGLVL_SIZE - 1)) ? logcfg.tags[level] : ""; } rz_strbuf_append(&sb, tag); rz_strbuf_append(&sb, ": "); - if (cfg_logsrcinfo) { + if (logcfg.show_sources) { rz_strbuf_appendf(&sb, "%s in %s:%i: ", funcname, filename, lineno); } rz_strbuf_vappendf(&sb, fmtstr, args); - // Actually print out the string with our callbacks char *output_buf = rz_strbuf_drain_nofree(&sb); - if (log_cbs && rz_list_length(log_cbs) > 0) { + + // critical section + rz_th_lock_enter(logcfg.lock); + if (rz_list_length(logcfg.callbacks) > 0) { + // Print the log using the callbacks RzListIter *it; RzLogCallback cb; - - rz_list_foreach (log_cbs, it, cb) { + rz_list_foreach (logcfg.callbacks, it, cb) { cb(output_buf, funcname, filename, lineno, level, NULL, fmtstr, args_copy); } } else { - fprintf(stderr, "%s", output_buf); + // Print the log using stderr + fputs(output_buf, stderr); } va_end(args_copy); // Log to file if enabled - if (cfg_logfile[0] != 0x00) { - FILE *file = rz_sys_fopen(cfg_logfile, "a+"); // TODO: Optimize (static? Needs to remake on cfg change though) - if (!file) { - file = rz_sys_fopen(cfg_logfile, "w+"); - } - if (file) { - fprintf(file, "%s", output_buf); - fclose(file); - } else { - eprintf("%s failed to write to file: %s\n", MACRO_LOG_FUNC, cfg_logfile); - } + if (logcfg.file) { + fputs(output_buf, logcfg.file); + fflush(logcfg.file); } - if (level >= cfg_logtraplvl && level != RZ_LOGLVL_NONE) { - fflush(stdout); // We're about to exit HARD, flush buffers before dying + if (level >= logcfg.trap_level && level != RZ_LOGLVL_NONE) { + // rz_sys_breakpoint is going to be called so we must flush buffers. + fflush(stdout); fflush(stderr); - // TODO: call rz_cons_flush if librz_cons is being used - rz_sys_breakpoint(); // *oof* + rz_sys_breakpoint(); } + rz_th_lock_leave(logcfg.lock); free(output_buf); }