portugalfuturista/rizin
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Refactor logging. (#4446)

Browse source 
* Remove globals and refactor to complete implementation of logging.
* Renamed log.traplevel to log.abortlevel and hide it on release builds.
This commit is contained in:
Giovanni 2024-04-19 13:02:58 +08:00 committed by GitHub
parent fffc34296a
commit 3033f62865
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
12 changed files with 250 additions and 128 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

4
librz/bin/dwarf/unit.c
View file

@ -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) {

56
librz/core/cconfig.c
View file

@ -2872,29 +2872,28 @@ static bool cb_log_config_level(void *coreptr, void *nodeptr) {
return true;
}
static bool cb_log_config_traplevel(void *coreptr, void *nodeptr) {
#if RZ_BUILD_DEBUG
static bool cb_log_config_abortlevel(void *coreptr, void *nodeptr) {
RzConfigNode *node = (RzConfigNode *)nodeptr;
rz_log_set_traplevel(node->i_value);
rz_log_set_abortlevel(node->i_value);
return true;
}
#endif /* RZ_BUILD_DEBUG */
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 +2901,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 +3336,27 @@ 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)");
#if RZ_BUILD_DEBUG
// RZ_ABORTLEVEL / log.abortlevel
p = rz_sys_getenv("RZ_ABORTLEVEL");
SETICB("log.abortlevel", p ? atoi(p) : RZ_DEFAULT_LOGLVL_ABORT, cb_log_config_abortlevel, "Target log level/severity when to abort."
" (0:DEBUG, 1:VERBOSE, 2:INFO, 3:WARN, 4:ERROR, 5:FATAL)");
free(p);
#endif /* RZ_BUILD_DEBUG */
// 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)");

29
librz/include/rz_util/rz_log.h
View file

@ -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;
@ -40,12 +41,10 @@ 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_DEFAULT_LOGLVL_ABORT RZ_LOGLVL_FATAL
#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 +65,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 void rz_log_set_abortlevel(RzLogLevel level);
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

265
librz/util/log.c
View file

@ -1,137 +1,256 @@
// SPDX-FileCopyrightText: 2024 RizinOrg <info@rizin.re>
// SPDX-FileCopyrightText: 2007-2018 pancake <pancake@nopcode.org>
// SPDX-FileCopyrightText: 2007-2018 ret2libc <sirmy15@gmail.com>
// SPDX-License-Identifier: LGPL-3.0-only
#define LOG_CONFIGSTR_SIZE 512
#define LOG_OUTPUTBUF_SIZE 512
#include <rz_core.h>
#include <rz_cons.h>
#include <rz_util.h>
#include <rz_th.h>
#include <stdarg.h>
// 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 /*<RzLogCallback *>*/ *callbacks;
RzLogLevel level;
#if RZ_BUILD_DEBUG
RzLogLevel abortlevel;
#endif
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",
};
// cconfig.c configuration callback functions below
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;
#if RZ_BUILD_DEBUG
logcfg.abortlevel = RZ_DEFAULT_LOGLVL_ABORT;
#endif
logcfg.show_sources = false;
logcfg.file = NULL;
logcfg.tags = level_tags_no_colors;
logcfg.lock = rz_th_lock_new(false);
}
/**
* \brief Sets the log level
*
* \param[in] level The log level to set.
*/
RZ_API void rz_log_set_level(RzLogLevel level) {
cfg_loglvl = level;
}
RZ_API void rz_log_set_traplevel(RzLogLevel level) {
cfg_logtraplvl = level;
}
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 void rz_log_set_srcinfo(bool show_info) {
cfg_logsrcinfo = show_info;
}
RZ_API void rz_log_set_colors(bool show_info) {
cfg_logcolors = show_info;
log_init();
rz_th_lock_enter(logcfg.lock);
logcfg.level = level;
rz_th_lock_leave(logcfg.lock);
}
/**
* \brief Add a logging callback
* \param cbfunc RzLogCallback style function to be called
* \brief Sets the log level when to abort execution
*
* \param[in] level The abort log level to set.
*/
RZ_API void rz_log_add_callback(RzLogCallback cbfunc) {
if (!log_cbs) {
log_cbs = rz_list_new();
}
if (!rz_list_contains(log_cbs, cbfunc)) {
rz_list_append(log_cbs, cbfunc);
}
RZ_API void rz_log_set_abortlevel(RzLogLevel level) {
log_init();
#if RZ_BUILD_DEBUG
rz_th_lock_enter(logcfg.lock);
logcfg.abortlevel = level;
rz_th_lock_leave(logcfg.lock);
#else
(void)level;
#endif
}
/**
* \brief Remove a logging callback
* \brief When not empty, enable logging to a file.
* This method allows to enable or disable logging to a file.
* To enable logging, just pass a filename to write to and to
* disable the logging is enough to pass an empty or NULL filename.
*
* \param[in] filename The file name to log to.
*/
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) {
logcfg.file = file;
} else {
// failed to open the file.
ret = false;
}
end:
rz_th_lock_leave(logcfg.lock);
return ret;
}
/**
* \brief When true, shows the function name and the source lines in the logs.
*
* \param[in] show_sources The boolean value to set show_sources to.
*/
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);
}
/**
* \brief Enables colored logs.
*
* \param[in] show_colors Sets the pointer to colored or not colored tags.
*/
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 Adds a logging callback.
*
* \param[in] show_colors RzLogCallback style function to be called.
*/
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(logcfg.callbacks, cbfunc)) {
rz_list_append(logcfg.callbacks, cbfunc);
}
rz_th_lock_leave(logcfg.lock);
}
/**
* \brief Removes 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) {
return;
}
log_init();
rz_th_lock_enter(logcfg.lock);
if (logcfg.callbacks) {
rz_list_delete_data(logcfg.callbacks, cbfunc);
}
rz_th_lock_leave(logcfg.lock);
}
#if RZ_BUILD_DEBUG
#define is_log_quiet(x) ((x) < logcfg.level && (x) < logcfg.abortlevel)
#else
#define is_log_quiet(x) ((x) < logcfg.level)
#endif /* RZ_BUILD_DEBUG */
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 (is_log_quiet(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 RZ_BUILD_DEBUG
if (level >= logcfg.abortlevel && level != RZ_LOGLVL_NONE) {
// this will abort the execution
// 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();
}
#endif
rz_th_lock_leave(logcfg.lock);
free(output_buf);
}

4
test/db/archos/linux-x64/dbg_oo
View file

@ -94,7 +94,7 @@ RUN
NAME=dm flags after ood
FILE=bins/elf/analysis/x86-helloworld-gcc
ARGS=-e log.level=5
ARGS=-e log.level=4
CMDS=<<EOF
ood
fl@F:maps~?
@ -108,7 +108,7 @@ RUN
NAME=ood check for ptrace errors
FILE=bins/elf/analysis/x86-helloworld-gcc
ARGS=-e log.level=4
ARGS=-e log.level=3
CMDS=<<EOF
ood
EOF

2
test/db/cmd/cmd_basefind
View file

@ -5,7 +5,7 @@ CMDS=<<EOF
e basefind.max.threads=1
e basefind.search.start=0x06000000
e basefind.search.end=0x10000000
e log.level=3
e log.level=2
Bj
Bq
B

4
test/db/cmd/cmd_flags
View file

@ -304,7 +304,7 @@ RUN
NAME=f.lj
FILE=bins/elf/analysis/main
ARGS=-e log.level=4
ARGS=-e log.level=3
CMDS=<<EOF
af
f. patata
@ -331,7 +331,7 @@ RUN
NAME=f.-
FILE=bins/elf/analysis/main
ARGS=-e log.level=4
ARGS=-e log.level=3
CMDS=<<EOF
af
f. patata

2
test/db/formats/elf/main
View file

@ -1,7 +1,7 @@
NAME=ELF: endbr-main-mov
FILE=bins/elf/endbr-main
CMDS=%v main
ARGS=-e log.level=4
ARGS=-e log.level=3
EXPECT=<<EOF
0x401126
EOF

6
test/db/formats/elf/sections
View file

@ -100,7 +100,7 @@ RUN
NAME=disable sections load
FILE=bins/elf/analysis/hello-linux-x86_64
ARGS=-e log.level=4 -e elf.load.sections=false
ARGS=-e log.level=3 -e elf.load.sections=false
CMDS=iS
EXPECT=<<EOF
paddr size vaddr vsize align perm name type flags
@ -113,7 +113,7 @@ RUN
NAME=disable sections checks
FILE=bins/elf/libmemalloc-dump-mem
ARGS=-e log.level=4 -e elf.checks.sections=false
ARGS=-e log.level=3 -e elf.checks.sections=false
CMDS=iS
EXPECT=<<EOF
paddr size vaddr vsize align perm name type flags
@ -150,7 +150,7 @@ RUN
NAME=disable segments checks
FILE=bins/elf/analysis/tiny.elf
ARGS=-e log.level=4 -e elf.checks.segments=false
ARGS=-e log.level=3 -e elf.checks.segments=false
CMDS=iS
EXPECT=<<EOF
paddr size vaddr vsize align perm name type flags

2
test/db/formats/pdb
View file

@ -526,7 +526,7 @@ NAME=Extract pdb via idbx
FILE==
CMDS=<<EOF
idpi bins/pdb/basic32.pd_
e log.level=3
e log.level=2
mkdir .tmp
idpx bins/pdb/basic32.pd_ .tmp
!rz-hash -a md5 .tmp/basic32.pdb

2
test/db/tools/rz_bin
View file

@ -52,7 +52,7 @@ RUN
NAME=rz-bin -k file
FILE=bins/elf/analysis/hello-linux-x86_64
CMDS=!rz-bin -k ${RZ_FILE}
ARGS=-e log.level=4
ARGS=-e log.level=3
EXPECT=<<EOF
EOF
EXPECT_ERR=<<EOF

2
test/db/tools/rz_test
View file

@ -36,7 +36,7 @@ RUN
NAME=bin with space in filename
FILE=bins/elf/_Exit (42)
CMDS=i~^file
ARGS=-e log.level=4
ARGS=-e log.level=3
EXPECT=<<EOF
file bins/elf/_Exit (42)
EOF