From d27a46a7fd816397c2d1fa03d7c3f98d46772725 Mon Sep 17 00:00:00 2001 From: Alberto Leiva Popper Date: Thu, 20 May 2021 13:26:21 -0500 Subject: [PATCH] Logging: Code review Two bugfixes: 1. (warning) The libcrypto error stack trace was always showing empty. This was because of a bad counter. 2. (critical) Normal stack traces were only being printed in the standard streams, never on syslog. This is probably the reason why we don't have a proper error message on #49. It's probably a segmentation fault. Also a whole bunch of cleanup. The logging module had a bit of a duplicate code problem. --- src/common.c | 14 +- src/config.c | 4 +- src/debug.c | 9 +- src/log.c | 448 +++++++++++---------------------------- src/log.h | 53 +++-- src/object/certificate.c | 5 +- src/object/crl.c | 3 +- src/object/name.c | 3 +- src/object/tal.c | 2 +- src/reqs_errors.c | 4 +- src/rtr/db/vrps.c | 4 +- src/rtr/pdu.c | 3 +- src/rtr/pdu_sender.c | 5 +- src/rtr/rtr.c | 2 +- 14 files changed, 200 insertions(+), 359 deletions(-) diff --git a/src/common.c b/src/common.c index 925ad357..de96f8e0 100644 --- a/src/common.c +++ b/src/common.c @@ -187,7 +187,7 @@ process_file_or_dir(char const *location, char const *file_ext, bool empty_err, bool valid_file_or_dir(char const *location, bool check_file, bool check_dir, - int (*cb) (int error, const char *format, ...)) + int (*error_fn)(int error, const char *format, ...)) { FILE *file; struct stat attr; @@ -200,15 +200,15 @@ valid_file_or_dir(char const *location, bool check_file, bool check_dir, result = false; file = fopen(location, "rb"); if (file == NULL) { - if (cb != NULL) - cb(errno, "Could not open location '%s'", + if (error_fn != NULL) + error_fn(errno, "Could not open location '%s'", location); return false; } if (fstat(fileno(file), &attr) == -1) { - if (cb != NULL) - cb(errno, "fstat(%s) failed", location); + if (error_fn != NULL) + error_fn(errno, "fstat(%s) failed", location); goto end; } @@ -223,8 +223,8 @@ valid_file_or_dir(char const *location, bool check_file, bool check_dir, end: if (fclose(file) == -1) - if (cb != NULL) - cb(errno, "fclose() failed"); + if (error_fn != NULL) + error_fn(errno, "fclose() failed"); return result; } diff --git a/src/config.c b/src/config.c index a1bcf6b4..2d4c4668 100644 --- a/src/config.c +++ b/src/config.c @@ -1117,7 +1117,7 @@ validate_config(void) /* A file location at --tal isn't valid when --init-tals is set */ if (!valid_file_or_dir(rpki_config.tal, !rpki_config.init_tals, true, - pr_op_errno)) + __pr_op_err)) return pr_op_err("Invalid TAL(s) location."); /* Ignore the other checks */ @@ -1139,7 +1139,7 @@ validate_config(void) return pr_op_err("Invalid output.bgpsec file."); if (rpki_config.slurm != NULL && - !valid_file_or_dir(rpki_config.slurm, true, true, pr_op_errno)) + !valid_file_or_dir(rpki_config.slurm, true, true, __pr_op_err)) return pr_op_err("Invalid slurm location."); /* FIXME (later) Remove when sync-strategy is fully deprecated */ diff --git a/src/debug.c b/src/debug.c index 49c5f68a..5dcf2dab 100644 --- a/src/debug.c +++ b/src/debug.c @@ -4,6 +4,7 @@ #include #include #include +#include "log.h" /** * Important: -rdynamic needs to be enabled, otherwise this does not print @@ -24,10 +25,10 @@ void print_stack_trace(void) size = backtrace(array, STACK_SIZE); strings = backtrace_symbols(array, size); - fprintf(stderr, "Stack trace:\n"); + pr_op_err("Stack trace:"); for (i = 0; i < size; i++) - fprintf(stderr, " %s\n", strings[i]); - fprintf(stderr, "(Stack size was %zu.)\n", size); + pr_op_err(" %s", strings[i]); + pr_op_err("(Stack size was %zu.)", size); free(strings); } @@ -35,7 +36,7 @@ void print_stack_trace(void) static void segfault_handler(int thingy) { - fprintf(stderr, "Segmentation Fault. "); + pr_op_err("Segmentation Fault."); print_stack_trace(); exit(1); } diff --git a/src/log.c b/src/log.c index 2e797777..924116e2 100644 --- a/src/log.c +++ b/src/log.c @@ -23,19 +23,34 @@ static struct level CRT = { "CRT", "\x1B[35m" }; static struct level UNK = { "UNK", "" }; #define COLOR_RESET "\x1B[0m" -/* LOG_PERROR is not portable, apparently, so I implemented it myself */ -static bool op_fprintf_enabled; -static bool op_syslog_enabled; -static bool val_fprintf_enabled; -static bool val_syslog_enabled; +struct log_config { + bool fprintf_enabled; /* Print on the standard streams? */ + bool syslog_enabled; /* Print on syslog? */ + + uint8_t level; + char const *prefix; + bool color; + int facility; +}; -static bool op_global_log_enabled; -static bool val_global_log_enabled; +/* Configuration for the operation logs. */ +static struct log_config op_config; +/* Configuration for the validation logs. */ +static struct log_config val_config; + +static void init_config(struct log_config *cfg) +{ + cfg->fprintf_enabled = true; + cfg->syslog_enabled = true; + cfg->level = LOG_DEBUG; + cfg->prefix = NULL; + cfg->color = false; + cfg->facility = LOG_DAEMON; +} void log_setup(void) { - /* =_= */ DBG.stream = stdout; INF.stream = stdout; WRN.stream = stderr; @@ -44,107 +59,107 @@ log_setup(void) UNK.stream = stdout; openlog("fort", LOG_CONS | LOG_PID, LOG_DAEMON); - op_fprintf_enabled = true; - op_syslog_enabled = true; - val_fprintf_enabled = true; - val_syslog_enabled = true; - - op_global_log_enabled = true; - val_global_log_enabled = true; -} -static void -log_disable_op_std(void) -{ - op_fprintf_enabled = false; -} - -static void -log_disable_val_std(void) -{ - val_fprintf_enabled = false; + init_config(&op_config); + init_config(&val_config); } static void log_disable_syslog(void) { - if (op_syslog_enabled || val_syslog_enabled) { + if (op_config.syslog_enabled || val_config.syslog_enabled) { closelog(); - op_syslog_enabled = false; - val_syslog_enabled = false; + op_config.syslog_enabled = false; + val_config.syslog_enabled = false; } } void log_start(void) { - val_global_log_enabled = config_get_val_log_enabled(); - op_global_log_enabled = config_get_op_log_enabled(); - - if (val_global_log_enabled) { + if (config_get_val_log_enabled()) { switch (config_get_val_log_output()) { case SYSLOG: pr_op_info("Syslog log output configured; disabling validation logging on standard streams."); pr_op_info("(Validation Logs will be sent to syslog only.)"); - log_disable_val_std(); + val_config.fprintf_enabled = false; break; case CONSOLE: pr_op_info("Console log output configured; disabling validation logging on syslog."); pr_op_info("(Validation Logs will be sent to the standard streams only.)"); - val_syslog_enabled = false; + val_config.syslog_enabled = false; break; } } else { pr_op_info("Disabling validation logging on syslog."); pr_op_info("Disabling validation logging on standard streams."); - log_disable_val_std(); - val_syslog_enabled = false; + val_config.fprintf_enabled = false; + val_config.syslog_enabled = false; } - if (op_global_log_enabled) { + if (config_get_op_log_enabled()) { switch (config_get_op_log_output()) { case SYSLOG: pr_op_info("Syslog log output configured; disabling operation logging on standard streams."); pr_op_info("(Operation Logs will be sent to syslog only.)"); - log_disable_op_std(); + op_config.fprintf_enabled = false; break; case CONSOLE: pr_op_info("Console log output configured; disabling operation logging on syslog."); pr_op_info("(Operation Logs will be sent to the standard streams only.)"); - if (!val_syslog_enabled) - log_disable_syslog(); + if (val_config.syslog_enabled) + op_config.syslog_enabled = false; else - op_syslog_enabled = false; + log_disable_syslog(); break; } } else { pr_op_info("Disabling operation logging on syslog."); pr_op_info("Disabling operation logging on standard streams."); - log_disable_op_std(); - if (!val_syslog_enabled) - log_disable_syslog(); + op_config.fprintf_enabled = false; + if (val_config.syslog_enabled) + op_config.syslog_enabled = false; else - op_syslog_enabled = false; + log_disable_syslog(); } + + op_config.level = config_get_op_log_level(); + op_config.prefix = config_get_op_log_tag(); + op_config.color = config_get_op_log_color_output(); + op_config.facility = config_get_op_log_facility(); + val_config.level = config_get_val_log_level(); + val_config.prefix = config_get_val_log_tag(); + val_config.color = config_get_val_log_color_output(); + val_config.facility = config_get_val_log_facility(); } void log_teardown(void) { - log_disable_op_std(); - log_disable_val_std(); log_disable_syslog(); } void log_flush(void) { - if (op_fprintf_enabled || val_fprintf_enabled) { + if (op_config.fprintf_enabled || val_config.fprintf_enabled) { fflush(stdout); fflush(stderr); } } +bool +log_val_enabled(unsigned int level) +{ + return val_config.level >= level; +} + +bool +log_op_enabled(unsigned int level) +{ + return op_config.level >= level; +} + static struct level const * level2struct(int level) { @@ -165,18 +180,17 @@ level2struct(int level) } static void -__fprintf(int level, char const *prefix, bool color_output, - char const *format, ...) +__vfprintf(int level, struct log_config *cfg, char const *format, va_list args) { - struct level const *lvl; - va_list args; char time_buff[20]; + struct level const *lvl; time_t now; struct tm stm_buff; + char const *file_name; lvl = level2struct(level); - if (color_output) + if (cfg->color) fprintf(lvl->stream, "%s", lvl->color); now = time(0); @@ -187,18 +201,20 @@ __fprintf(int level, char const *prefix, bool color_output, } fprintf(lvl->stream, "%s", lvl->label); - if (prefix) - fprintf(lvl->stream, " [%s]", prefix); + if (cfg->prefix) + fprintf(lvl->stream, " [%s]", cfg->prefix); fprintf(lvl->stream, ": "); - va_start(args, format); + file_name = fnstack_peek(); + if (file_name != NULL) + fprintf(lvl->stream, "%s: ", file_name); + vfprintf(lvl->stream, format, args); - va_end(args); - if (color_output) + if (cfg->color) fprintf(lvl->stream, COLOR_RESET); - fprintf(lvl->stream, "\n"); + /* Force flush */ if (lvl->stream == stdout) fflush(lvl->stream); @@ -207,8 +223,7 @@ __fprintf(int level, char const *prefix, bool color_output, #define MSG_LEN 512 static void -pr_syslog(int level, char const *prefix, const char *format, int facility, - va_list args) +__syslog(int level, struct log_config *cfg, const char *format, va_list args) { char const *file_name; struct level const *lvl; @@ -220,145 +235,52 @@ pr_syslog(int level, char const *prefix, const char *format, int facility, /* Can't use vsyslog(); it's not portable. */ vsnprintf(msg, MSG_LEN, format, args); if (file_name != NULL) { - if (prefix != NULL) - syslog(level | facility, "%s [%s]: %s: %s", lvl->label, - prefix, file_name, msg); + if (cfg->prefix != NULL) + syslog(level | cfg->facility, "%s [%s]: %s: %s", + lvl->label, cfg->prefix, file_name, msg); else - syslog(level | facility, "%s: %s: %s", lvl->label, - file_name, msg); + syslog(level | cfg->facility, "%s: %s: %s", + lvl->label, file_name, msg); } else { - if (prefix != NULL) - syslog(level | facility, "%s [%s]: %s", lvl->label, - prefix, msg); + if (cfg->prefix != NULL) + syslog(level | cfg->facility, "%s [%s]: %s", + lvl->label, cfg->prefix, msg); else - syslog(level | facility, "%s: %s", lvl->label, msg); + syslog(level | cfg->facility, "%s: %s", + lvl->label, msg); } } -static void -pr_stream(int level, char const *prefix, const char *format, bool color_output, - va_list args) -{ - char const *file_name; - char time_buff[20]; - struct level const *lvl; - time_t now; - struct tm stm_buff; - - file_name = fnstack_peek(); - lvl = level2struct(level); - - if (color_output) - fprintf(lvl->stream, "%s", lvl->color); - - now = time(0); - if (now != ((time_t) -1)) { - localtime_r(&now, &stm_buff); - strftime(time_buff, sizeof(time_buff), "%b %e %T", &stm_buff); - fprintf(lvl->stream, "%s ", time_buff); - } - - fprintf(lvl->stream, "%s", lvl->label); - if (prefix) - fprintf(lvl->stream, " [%s]", prefix); - fprintf(lvl->stream, ": "); - - if (file_name != NULL) - fprintf(lvl->stream, "%s: ", file_name); - vfprintf(lvl->stream, format, args); - - if (color_output) - fprintf(lvl->stream, "%s", COLOR_RESET); - - fprintf(lvl->stream, "\n"); - /* Force flush */ - if (lvl->stream == stdout) - fflush(lvl->stream); -} - -#define PR_OP_SIMPLE(level) \ +#define PR_SIMPLE(lvl, config) \ do { \ va_list args; \ - char const *prefix = config_get_op_log_tag(); \ - bool color = config_get_op_log_color_output(); \ - int facility = config_get_op_log_facility(); \ - \ - if (!op_global_log_enabled) \ - break; \ \ - if (level > config_get_op_log_level()) \ + if (lvl > config.level) \ break; \ \ - if (op_syslog_enabled) { \ + if (config.syslog_enabled) { \ va_start(args, format); \ - pr_syslog(level, prefix, format, facility, \ - args); \ + __syslog(lvl, &config, format, args); \ va_end(args); \ } \ \ - if (op_fprintf_enabled) { \ + if (config.fprintf_enabled) { \ va_start(args, format); \ - pr_stream(level, prefix, format, color, args); \ + __vfprintf(lvl, &config, format, args); \ va_end(args); \ } \ } while (0) - -#define PR_VAL_SIMPLE(level) \ - do { \ - va_list args; \ - char const *prefix = config_get_val_log_tag(); \ - bool color = config_get_val_log_color_output(); \ - int facility = config_get_val_log_facility(); \ - \ - if (!val_global_log_enabled) \ - break; \ - \ - if (level > config_get_val_log_level()) \ - break; \ - \ - if (val_syslog_enabled) { \ - va_start(args, format); \ - pr_syslog(level, prefix, format, facility, \ - args); \ - va_end(args); \ - } \ - \ - if (val_fprintf_enabled) { \ - va_start(args, format); \ - pr_stream(level, prefix, format, color, args); \ - va_end(args); \ - } \ - } while (0) - -bool -log_val_debug_enabled(void) -{ - return config_get_val_log_level() >= LOG_DEBUG; -} - -bool -log_op_debug_enabled(void) -{ - return config_get_op_log_level() >= LOG_DEBUG; -} - -bool -log_op_info_enabled(void) -{ - return config_get_op_log_level() >= LOG_INFO; -} - void pr_op_debug(const char *format, ...) { - PR_OP_SIMPLE(LOG_DEBUG); + PR_SIMPLE(LOG_DEBUG, op_config); } void pr_op_info(const char *format, ...) { - PR_OP_SIMPLE(LOG_INFO); + PR_SIMPLE(LOG_INFO, op_config); } /** @@ -368,30 +290,27 @@ pr_op_info(const char *format, ...) int pr_op_warn(const char *format, ...) { - PR_OP_SIMPLE(LOG_WARNING); + PR_SIMPLE(LOG_WARNING, op_config); return 0; } -/** - * Always returs -EINVAL. - */ int -pr_op_err(const char *format, ...) +__pr_op_err(int error, const char *format, ...) { - PR_OP_SIMPLE(LOG_ERR); - return -EINVAL; + PR_SIMPLE(LOG_ERR, op_config); + return error; } void pr_val_debug(const char *format, ...) { - PR_VAL_SIMPLE(LOG_DEBUG); + PR_SIMPLE(LOG_DEBUG, val_config); } void pr_val_info(const char *format, ...) { - PR_VAL_SIMPLE(LOG_INFO); + PR_SIMPLE(LOG_INFO, val_config); } /** @@ -401,142 +320,43 @@ pr_val_info(const char *format, ...) int pr_val_warn(const char *format, ...) { - PR_VAL_SIMPLE(LOG_WARNING); + PR_SIMPLE(LOG_WARNING, val_config); return 0; } -/** - * Always returs -EINVAL. - */ int -pr_val_err(const char *format, ...) -{ - PR_VAL_SIMPLE(LOG_ERR); - return -EINVAL; -} - -static void -pr_simple_syslog(int level, int facility, char const *prefix, const char *msg) -{ - struct level const *lvl; - - lvl = level2struct(LOG_ERR); - if (prefix != NULL) - syslog(LOG_ERR | facility, "%s [%s]: - %s", lvl->label, prefix, - msg); - else - syslog(LOG_ERR | facility, "%s: - %s", lvl->label, msg); -} - -/** - * @error fulfills two functions, both of which apply only if it's nonzero: - * - * - @error's corresponding generic error message will be appended to the print. - * - @error's value will be returned. This is for the sake of error code - * propagation. - * - * If @error is zero, no error message will be appended, and the function will - * return -EINVAL. (I acknowledge that this looks convoluted at first glance. - * The purpose is to ensure that this function will propagate an error code even - * if there is no error code originally.) - * - * Always appends a newline at the end. - */ -static int -pr_errno(int error, bool syslog_enabled, bool fprintf_enabled, int facility, - bool color, char const *prefix) +__pr_val_err(int error, const char *format, ...) { - if (!error) - return -EINVAL; - - if (syslog_enabled) - pr_simple_syslog(LOG_ERR, facility, prefix, strerror(error)); - - if (fprintf_enabled) - __fprintf(LOG_ERR, prefix, color, " - %s", strerror(error)); - + PR_SIMPLE(LOG_ERR, val_config); return error; } - -int -pr_op_errno(int error, const char *format, ...) -{ - if (abs(error) == ENOMEM) - pr_enomem(); - - PR_OP_SIMPLE(LOG_ERR); - - return pr_errno(error, op_syslog_enabled, - op_fprintf_enabled, config_get_op_log_facility(), - config_get_op_log_color_output(), - config_get_op_log_tag()); -} - -int -pr_val_errno(int error, const char *format, ...) -{ - if (abs(error) == ENOMEM) - pr_enomem(); - - PR_VAL_SIMPLE(LOG_ERR); - - return pr_errno(error, val_syslog_enabled, - val_fprintf_enabled, config_get_val_log_facility(), - config_get_val_log_color_output(), - config_get_val_log_tag()); -} +struct crypto_cb_arg { + unsigned int stack_size; + int (*error_fn)(int, const char *, ...); +}; static int -log_op_crypto_error(const char *str, size_t len, void *arg) +log_crypto_error(const char *str, size_t len, void *_arg) { - if (op_syslog_enabled) - pr_simple_syslog(LOG_ERR, config_get_op_log_facility(), - config_get_op_log_tag(), str); - if (op_fprintf_enabled) - __fprintf(LOG_ERR, config_get_op_log_tag(), - config_get_op_log_color_output(), - " - %s", str); + struct crypto_cb_arg *arg = _arg; + arg->error_fn(0, "-> %s", str); + arg->stack_size++; return 1; } static int -log_val_crypto_error(const char *str, size_t len, void *arg) +crypto_err(struct log_config *cfg, int (*error_fn)(int, const char *, ...)) { - if (val_syslog_enabled) - pr_simple_syslog(LOG_ERR, config_get_val_log_facility(), - config_get_val_log_tag(), str); - if (val_fprintf_enabled) - __fprintf(LOG_ERR, config_get_val_log_tag(), - config_get_val_log_color_output(), - " - %s", str); - return 1; -} + struct crypto_cb_arg arg; -static int -crypto_err(int (*cb) (const char *str, size_t len, void *u), - bool fprintf_enabled, bool syslog_enabled, bool color_output, int facility, - const char *prefix) -{ - unsigned int stack_size; + error_fn(0, "libcrypto error stack:"); - if (syslog_enabled) - pr_simple_syslog(LOG_ERR, facility, prefix, - " libcrypto error stack:"); - if (fprintf_enabled) - __fprintf(LOG_ERR, prefix, color_output, - " libcrypto error stack:"); - - stack_size = 0; - ERR_print_errors_cb(cb, &stack_size); - if (stack_size == 0) { - if (syslog_enabled) - pr_simple_syslog(LOG_ERR, facility, prefix, - " \n"); - } + arg.stack_size = 0; + arg.error_fn = error_fn; + ERR_print_errors_cb(log_crypto_error, &arg); + if (arg.stack_size == 0) + error_fn(0, " "); return -EINVAL; } @@ -556,11 +376,8 @@ crypto_err(int (*cb) (const char *str, size_t len, void *u), int op_crypto_err(const char *format, ...) { - PR_OP_SIMPLE(LOG_ERR); - - return crypto_err(log_op_crypto_error, op_fprintf_enabled, - op_syslog_enabled, config_get_op_log_color_output(), - config_get_op_log_facility(), config_get_op_log_tag()); + PR_SIMPLE(LOG_ERR, op_config); + return crypto_err(&op_config, __pr_op_err); } /** @@ -578,11 +395,8 @@ op_crypto_err(const char *format, ...) int val_crypto_err(const char *format, ...) { - PR_VAL_SIMPLE(LOG_ERR); - - return crypto_err(log_val_crypto_error, val_fprintf_enabled, - val_syslog_enabled, config_get_val_log_color_output(), - config_get_val_log_facility(), config_get_val_log_tag()); + PR_SIMPLE(LOG_ERR, val_config); + return crypto_err(&val_config, __pr_val_err); } /** @@ -591,13 +405,7 @@ val_crypto_err(const char *format, ...) int pr_enomem(void) { - if (op_syslog_enabled) - pr_simple_syslog(LOG_ERR, config_get_op_log_facility(), - config_get_op_log_tag(), "Out of memory."); - if (op_fprintf_enabled) - __fprintf(LOG_ERR, config_get_op_log_tag(), - config_get_op_log_color_output(), - "Out of memory.\n"); + pr_op_err("Out of memory."); print_stack_trace(); exit(ENOMEM); } @@ -608,7 +416,7 @@ pr_enomem(void) __dead void pr_crit(const char *format, ...) { - PR_OP_SIMPLE(LOG_CRIT); + PR_SIMPLE(LOG_CRIT, op_config); print_stack_trace(); exit(-1); } @@ -627,10 +435,10 @@ incidence(enum incidence_id id, const char *format, ...) case INAC_IGNORE: return 0; case INAC_WARN: - PR_VAL_SIMPLE(LOG_WARNING); + PR_SIMPLE(LOG_WARNING, val_config); return 0; case INAC_ERROR: - PR_VAL_SIMPLE(LOG_ERR); + PR_SIMPLE(LOG_ERR, val_config); return -EINVAL; } diff --git a/src/log.h b/src/log.h index b9e284e0..8d215003 100644 --- a/src/log.h +++ b/src/log.h @@ -1,6 +1,8 @@ #ifndef SRC_LOG_H_ #define SRC_LOG_H_ +#include +#include #include #include "incidence/incidence.h" @@ -51,40 +53,61 @@ void log_flush(void); */ /* - * Check if debug or info are enabled, useful to avoid boilerplate code + * Check if corresponding logging is enabled. You can use these to short-circuit + * out of heavy logging code. */ -bool log_val_debug_enabled(void); -bool log_op_debug_enabled(void); -bool log_op_info_enabled(void); +bool log_val_enabled(unsigned int level); +bool log_op_enabled(unsigned int level); -/* Debug messages, useful for devs or to track a specific problem */ +/* == Operation logs == */ + +/* Status reports of no interest to the user. */ void pr_op_debug(const char *, ...) CHECK_FORMAT(1, 2); -/* Non-errors deemed useful to the user. */ +/* Status reports likely useful to the user. */ void pr_op_info(const char *, ...) CHECK_FORMAT(1, 2); -/* Issues that did not trigger RPKI object rejection. */ +/* Non-errors that suggest a problem. */ int pr_op_warn(const char *, ...) CHECK_FORMAT(1, 2); -/* Errors that trigger RPKI object rejection. */ -int pr_op_err(const char *, ...) CHECK_FORMAT(1, 2); -int pr_op_errno(int, const char *, ...) CHECK_FORMAT(2, 3); +/* Problematic situations that prevent Fort from doing its job. */ +int __pr_op_err(int, const char *, ...) CHECK_FORMAT(2, 3); +/* Like pr_op_err(), except it prints libcrypto's error stack as well. */ int op_crypto_err(const char *, ...) CHECK_FORMAT(1, 2); -/* Debug messages, useful for devs or to track a specific problem */ +#define pr_op_err(fmt, ...) \ + __pr_op_err(-EINVAL, fmt, ##__VA_ARGS__) +#define pr_op_errno(error, fmt, ...) \ + __pr_op_err(error, fmt ": %s", ##__VA_ARGS__, strerror(abs(error))) + +/* == Validation logs == */ + +/* Status reports of no interest to the user. */ void pr_val_debug(const char *, ...) CHECK_FORMAT(1, 2); -/* Non-errors deemed useful to the user. */ +/* Status reports likely useful to the user. */ void pr_val_info(const char *, ...) CHECK_FORMAT(1, 2); /* Issues that did not trigger RPKI object rejection. */ int pr_val_warn(const char *, ...) CHECK_FORMAT(1, 2); -/* Errors that trigger RPKI object rejection. */ -int pr_val_err(const char *, ...) CHECK_FORMAT(1, 2); -int pr_val_errno(int, const char *, ...) CHECK_FORMAT(2, 3); +/* Problems that trigger RPKI object rejection. */ +int __pr_val_err(int, const char *, ...) CHECK_FORMAT(2, 3); +/* Like pr_val_err(), except it prints libcrypto's error stack as well. */ int val_crypto_err(const char *, ...) CHECK_FORMAT(1, 2); +#define pr_val_err(fmt, ...) \ + __pr_val_err(-EINVAL, fmt, ##__VA_ARGS__) +#define pr_val_errno(error, fmt, ...) \ + __pr_val_err(error, fmt ": %s", ##__VA_ARGS__, strerror(abs(error))) + +/* Like pr_*_err(), specific to out-of-memory situations. */ int pr_enomem(void); /* Programming errors */ __dead void pr_crit(const char *, ...) CHECK_FORMAT(1, 2); int incidence(enum incidence_id, const char *, ...) CHECK_FORMAT(2, 3); +/* + * Quick and dirty debugging messages. + * + * These are not meant to be uploaded; remember to delete them once the bug has + * been found. + */ #define PR_DEBUG printf("%s:%d (%s())\n", __FILE__, __LINE__, __func__) #define PR_DEBUG_MSG(msg, ...) printf("%s:%d (%s()): " msg "\n", \ __FILE__, __LINE__, __func__, ##__VA_ARGS__) diff --git a/src/object/certificate.c b/src/object/certificate.c index 65fd0f10..d3f173e3 100644 --- a/src/object/certificate.c +++ b/src/object/certificate.c @@ -2,6 +2,7 @@ #include #include /* SIZE_MAX */ +#include #include #include #include @@ -109,7 +110,7 @@ validate_serial_number(X509 *cert) if (number == NULL) return val_crypto_err("Could not parse certificate serial number"); - if (log_val_debug_enabled()) + if (log_val_enabled(LOG_DEBUG)) debug_serial_number(number); error = x509stack_store_serial(validation_certstack(state), number); @@ -2020,7 +2021,7 @@ static int verify_mft_loc(struct rpki_uri *mft_uri) { if (!valid_file_or_dir(uri_get_local(mft_uri), true, false, - pr_val_errno)) + __pr_val_err)) return -EINVAL; /* Error already logged */ return 0; diff --git a/src/object/crl.c b/src/object/crl.c index ebf28332..7a746585 100644 --- a/src/object/crl.c +++ b/src/object/crl.c @@ -1,6 +1,7 @@ #include "crl.h" #include +#include #include "algorithm.h" #include "extension.h" #include "log.h" @@ -83,7 +84,7 @@ validate_revoked(X509_CRL *crl) i + 1); } - if (log_val_debug_enabled()) + if (log_val_enabled(LOG_DEBUG)) debug_revoked(serial_int); if (X509_REVOKED_get0_revocationDate(revoked) == NULL) { diff --git a/src/object/name.c b/src/object/name.c index 8354d5b3..fd64bb42 100644 --- a/src/object/name.c +++ b/src/object/name.c @@ -3,6 +3,7 @@ #include #include #include +#include #include "log.h" #include "thread_var.h" @@ -201,7 +202,7 @@ end: x509_name_put(parent_subject); void x509_name_pr_debug(const char *prefix, X509_NAME *name) { - if (!log_val_debug_enabled()) + if (!log_val_enabled(LOG_DEBUG)) return; struct rfc5280_name *printable; diff --git a/src/object/tal.c b/src/object/tal.c index 49487e44..a7bfdb34 100644 --- a/src/object/tal.c +++ b/src/object/tal.c @@ -539,7 +539,7 @@ handle_tal_uri(struct tal *tal, struct rpki_uri *uri, void *arg) if (!thread_arg->sync_files) { /* Look for local files */ if (!valid_file_or_dir(uri_get_local(uri), true, false, - pr_val_errno)) { + __pr_val_err)) { validation_destroy(state); return 0; /* Error already logged */ } diff --git a/src/reqs_errors.c b/src/reqs_errors.c index 31c528d4..1501ce0b 100644 --- a/src/reqs_errors.c +++ b/src/reqs_errors.c @@ -1,7 +1,9 @@ #include "reqs_errors.h" #include +#include #include + #include "data_structure/uthash_nonfatal.h" #include "common.h" #include "config.h" @@ -241,7 +243,7 @@ reqs_errors_log_uri(char const *uri) unsigned int config_period; int error; - if (log_op_debug_enabled()) + if (log_op_enabled(LOG_DEBUG)) return true; if (working_repo_peek_level() > LOG_REPO_LEVEL) diff --git a/src/rtr/db/vrps.c b/src/rtr/db/vrps.c index ceaa46c3..a92982ea 100644 --- a/src/rtr/db/vrps.c +++ b/src/rtr/db/vrps.c @@ -2,8 +2,10 @@ #include #include +#include #include #include + #include "clients.h" #include "common.h" #include "output_printer.h" @@ -399,7 +401,7 @@ vrps_update(bool *changed) * This wrapper is mainly for log informational data, so if there's no * need don't do unnecessary calls */ - if (!log_op_info_enabled()) + if (!log_op_enabled(LOG_INFO)) return __vrps_update(changed); pr_op_info("Starting validation."); diff --git a/src/rtr/pdu.c b/src/rtr/pdu.c index 37515c9a..4ba76c0c 100644 --- a/src/rtr/pdu.c +++ b/src/rtr/pdu.c @@ -3,6 +3,7 @@ #include #include #include +#include #include "address.h" #include "clients.h" @@ -126,7 +127,7 @@ pdu_load(int fd, struct sockaddr_storage *client_addr, return error; - if (log_op_debug_enabled()) + if (log_op_enabled(LOG_DEBUG)) pr_op_debug("Received a %s from %s.", pdutype2str(header.pdu_type), sockaddr2str(client_addr)); diff --git a/src/rtr/pdu_sender.c b/src/rtr/pdu_sender.c index 8dd9138d..1cd11317 100644 --- a/src/rtr/pdu_sender.c +++ b/src/rtr/pdu_sender.c @@ -4,6 +4,7 @@ #include #include #include +#include #include #include /* INET_ADDRSTRLEN */ @@ -128,7 +129,7 @@ send_ipv4_prefix_pdu(int fd, uint8_t version, struct vrp const *vrp, len = serialize_ipv4_prefix_pdu(&pdu, data); if (len != RTRPDU_IPV4_PREFIX_LEN) pr_crit("Serialized IPv4 Prefix is %zu bytes.", len); - if (log_op_debug_enabled()) + if (log_op_enabled(LOG_DEBUG)) pr_debug_prefix4(&pdu); return send_response(fd, pdu.header.pdu_type, data, len); @@ -164,7 +165,7 @@ send_ipv6_prefix_pdu(int fd, uint8_t version, struct vrp const *vrp, len = serialize_ipv6_prefix_pdu(&pdu, data); if (len != RTRPDU_IPV6_PREFIX_LEN) pr_crit("Serialized IPv6 Prefix is %zu bytes.", len); - if (log_op_debug_enabled()) + if (log_op_enabled(LOG_DEBUG)) pr_debug_prefix6(&pdu); return send_response(fd, pdu.header.pdu_type, data, len); diff --git a/src/rtr/rtr.c b/src/rtr/rtr.c index 24d8fda5..0a30506b 100644 --- a/src/rtr/rtr.c +++ b/src/rtr/rtr.c @@ -614,7 +614,7 @@ __handle_client_connections(struct server_fds *fds, struct thread_pool *pool) error = listen(node->id, config_get_server_queue()); if (error) return pr_op_errno(errno, - "Couldn't listen on server socket."); + "Couldn't listen on server socket"); } param = malloc(sizeof(struct rtr_task_param)); -- 2.47.2