From 33e10df9112b9ffa7b2ed0f1f102eff7ab153e2e Mon Sep 17 00:00:00 2001 From: Alberto Leiva Popper Date: Fri, 21 May 2021 13:30:32 -0500 Subject: [PATCH] Logging: More refactors 1. Merges the log and debug modules. I think their separation was the reason why they forgot to add stack traces to syslog when they added syslog to the project. Not risking that mistake again. 2. Removes as many obstacles as possible from stack trace printing on critical errors. 3. Add mutexes to logging. This should prevent messages from mixing on top of each other when there are threads. --- src/Makefile.am | 1 - src/debug.c | 58 ----------------- src/debug.h | 7 -- src/log.c | 166 +++++++++++++++++++++++++++++++++++++++++++----- src/log.h | 49 ++++++++------ src/main.c | 9 +-- 6 files changed, 186 insertions(+), 104 deletions(-) delete mode 100644 src/debug.c delete mode 100644 src/debug.h diff --git a/src/Makefile.am b/src/Makefile.am index 73b980b1..ef6dfa1f 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -14,7 +14,6 @@ fort_SOURCES += clients.c clients.h fort_SOURCES += common.c common.h fort_SOURCES += config.h config.c fort_SOURCES += daemon.h daemon.c -fort_SOURCES += debug.h debug.c fort_SOURCES += delete_dir_daemon.h delete_dir_daemon.c fort_SOURCES += extension.h extension.c fort_SOURCES += file.h file.c diff --git a/src/debug.c b/src/debug.c deleted file mode 100644 index 5dcf2dab..00000000 --- a/src/debug.c +++ /dev/null @@ -1,58 +0,0 @@ -#include "debug.h" - -#include -#include -#include -#include -#include "log.h" - -/** - * Important: -rdynamic needs to be enabled, otherwise this does not print - * function names. See LDFLAGS_DEBUG in Makefile.am. - * Also: Only non-static functions will be labeled. - * - * During a segfault, the first three printed entries are usually not - * meaningful. Outside of a segfault, the first entry is not meaningful. - */ -void print_stack_trace(void) -{ -#define STACK_SIZE 64 - void *array[STACK_SIZE]; - size_t size; - char **strings; - size_t i; - - size = backtrace(array, STACK_SIZE); - strings = backtrace_symbols(array, size); - - pr_op_err("Stack trace:"); - for (i = 0; i < size; i++) - pr_op_err(" %s", strings[i]); - pr_op_err("(Stack size was %zu.)", size); - - free(strings); -} - -static void -segfault_handler(int thingy) -{ - pr_op_err("Segmentation Fault."); - print_stack_trace(); - exit(1); -} - -/** - * If you get a Segmentation Fault after calling this, the stack trace will be - * automatically printed in standard error. - * Remember to enable -rdynamic (See print_stack_trace()). - */ -void -print_stack_trace_on_segfault(void) -{ - struct sigaction handler; - - handler.sa_handler = segfault_handler; - sigemptyset(&handler.sa_mask); - handler.sa_flags = 0; - sigaction(SIGSEGV, &handler, NULL); -} diff --git a/src/debug.h b/src/debug.h deleted file mode 100644 index e4a3ba7e..00000000 --- a/src/debug.h +++ /dev/null @@ -1,7 +0,0 @@ -#ifndef SRC_DEBUG_H_ -#define SRC_DEBUG_H_ - -void print_stack_trace(void); -void print_stack_trace_on_segfault(void); - -#endif /* SRC_DEBUG_H_ */ diff --git a/src/log.c b/src/log.c index 924116e2..501946df 100644 --- a/src/log.c +++ b/src/log.c @@ -1,12 +1,13 @@ #include "log.h" +#include #include #include +#include #include #include #include "config.h" -#include "debug.h" #include "thread_var.h" struct level { @@ -38,6 +39,77 @@ static struct log_config op_config; /* Configuration for the validation logs. */ static struct log_config val_config; +/* + * Note: Normally, fprintf and syslog would have separate locks. + * + * However, fprintf and syslog are rarely enabled at the same time, so I don't + * think it's worth it. So I'm reusing the lock. + */ +static pthread_mutex_t lock; + +/** + * Important: -rdynamic needs to be enabled, otherwise this does not print + * function names. See LDFLAGS_DEBUG in Makefile.am. + * Also: Only non-static functions will be labeled. + * + * During a segfault, the first three printed entries are usually not + * meaningful. Outside of a segfault, the first entry is not meaningful. + * (But I'm printing everything anyway due to paranoia.) + * + * @title is allowed to be NULL. If you need locking, do it outside. (And be + * aware that pthread_mutex_lock() can return error codes, which shouldn't + * prevent critical stack traces from printing.) + */ +void +print_stack_trace(char const *title) +{ + /* + * Keep this as low-level as possible. Do not employ helper functions, + * even if this causes small inconsistencies. + * Helper functions (ie. any functions declared by Fort) might end up + * attempting to write another stack trace and cause infinite recursion. + */ + +#define STACK_SIZE 64 + + void *array[STACK_SIZE]; + size_t size; + char **strings; + size_t i; + int fp; + + size = backtrace(array, STACK_SIZE); + strings = backtrace_symbols(array, size); + + if (op_config.fprintf_enabled) { + if (title != NULL) + fprintf(ERR.stream, "%s\n", title); + fprintf(ERR.stream, "Stack trace:\n"); + for (i = 0; i < size; i++) + fprintf(ERR.stream, " %s\n", strings[i]); + fprintf(ERR.stream, "(End of stack trace)\n"); + } + + if (op_config.syslog_enabled) { + fp = LOG_ERR | op_config.facility; + if (title != NULL) + syslog(fp, "%s", title); + syslog(fp, "Stack trace:"); + for (i = 0; i < size; i++) + syslog(fp, " %s", strings[i]); + syslog(fp, "(End of stack trace)"); + } + + free(strings); +} + +static void +segfault_handler(int thingy) +{ + print_stack_trace("Segmentation Fault."); + exit(1); +} + static void init_config(struct log_config *cfg) { cfg->fprintf_enabled = true; @@ -48,9 +120,17 @@ static void init_config(struct log_config *cfg) cfg->facility = LOG_DAEMON; } -void +int log_setup(void) { + /* + * Remember not to use any actual logging functions until logging has + * been properly initialized. + */ + + struct sigaction handler; + int error; + DBG.stream = stdout; INF.stream = stdout; WRN.stream = stderr; @@ -62,6 +142,27 @@ log_setup(void) init_config(&op_config); init_config(&val_config); + + error = pthread_mutex_init(&lock, NULL); + if (error) { + fprintf(ERR.stream, "pthread_mutex_init() returned %d: %s\n", + error, strerror(abs(error))); + syslog(LOG_ERR | op_config.facility, + "pthread_mutex_init() returned %d: %s", + error, strerror(abs(error))); + return error; + } + + /* + * Register stack trace printer on segmentation fault listener. + * Remember to enable -rdynamic (See print_stack_trace()). + */ + handler.sa_handler = segfault_handler; + sigemptyset(&handler.sa_mask); + handler.sa_flags = 0; + sigaction(SIGSEGV, &handler, NULL); + + return 0; } static void @@ -137,6 +238,7 @@ void log_teardown(void) { log_disable_syslog(); + pthread_mutex_destroy(&lock); } void @@ -179,6 +281,36 @@ level2struct(int level) return &UNK; } +static void +lock_mutex(void) +{ + int error; + + error = pthread_mutex_lock(&lock); + if (error) { + /* + * Despite being supposed to be impossible, failing to lock the + * mutex is not fatal; it just means we might log some mixed + * messages, which is better than dying. + * + * Furthermore, this might have been called while logging + * another critical. We must absolutely not get in the way of + * that critical's print. + */ + print_stack_trace(strerror(error)); + } +} + +static void +unlock_mutex(void) +{ + int error; + + error = pthread_mutex_unlock(&lock); + if (error) + print_stack_trace(strerror(error)); /* Same as above. */ +} + static void __vfprintf(int level, struct log_config *cfg, char const *format, va_list args) { @@ -190,6 +322,8 @@ __vfprintf(int level, struct log_config *cfg, char const *format, va_list args) lvl = level2struct(level); + lock_mutex(); + if (cfg->color) fprintf(lvl->stream, "%s", lvl->color); @@ -218,20 +352,24 @@ __vfprintf(int level, struct log_config *cfg, char const *format, va_list args) /* Force flush */ if (lvl->stream == stdout) fflush(lvl->stream); + + unlock_mutex(); } -#define MSG_LEN 512 +#define MSG_LEN 1024 static void __syslog(int level, struct log_config *cfg, const char *format, va_list args) { + static char msg[MSG_LEN]; char const *file_name; struct level const *lvl; - char msg[MSG_LEN]; file_name = fnstack_peek(); lvl = level2struct(level); + lock_mutex(); + /* Can't use vsyslog(); it's not portable. */ vsnprintf(msg, MSG_LEN, format, args); if (file_name != NULL) { @@ -249,6 +387,8 @@ __syslog(int level, struct log_config *cfg, const char *format, va_list args) syslog(level | cfg->facility, "%s: %s", lvl->label, msg); } + + unlock_mutex(); } #define PR_SIMPLE(lvl, config) \ @@ -356,7 +496,9 @@ crypto_err(struct log_config *cfg, int (*error_fn)(int, const char *, ...)) arg.error_fn = error_fn; ERR_print_errors_cb(log_crypto_error, &arg); if (arg.stack_size == 0) - error_fn(0, " "); + error_fn(0, " "); + else + error_fn(0, "End of libcrypto stack."); return -EINVAL; } @@ -399,25 +541,17 @@ val_crypto_err(const char *format, ...) return crypto_err(&val_config, __pr_val_err); } -/** - * This is an operation log - **/ int pr_enomem(void) { - pr_op_err("Out of memory."); - print_stack_trace(); - exit(ENOMEM); + pr_crit("Out of memory."); } -/** - * This is an operation log - **/ __dead void pr_crit(const char *format, ...) { - PR_SIMPLE(LOG_CRIT, op_config); - print_stack_trace(); + PR_SIMPLE(LOG_ERR, op_config); + print_stack_trace(NULL); exit(-1); } diff --git a/src/log.h b/src/log.h index 8d215003..22fce170 100644 --- a/src/log.h +++ b/src/log.h @@ -39,19 +39,22 @@ #define CHECK_FORMAT(str, args) /* Nothing */ #endif -/* Only call this group of functions when you know there's only one thread. */ -void log_setup(void); +/* + * Only call this group of functions when you know there's only one thread. + * + * log_setup() is an incomplete initialization meant to be called when the + * program starts. Logging can be performed after log_setup(), but it will use + * default values. + * log_init() finishes initialization by loading the user's intended config. + * log_teardown() reverts initialization. + */ +int log_setup(void); void log_start(void); void log_teardown(void); /* Call to flush the stdout/stderr streams */ void log_flush(void); -/* - * Please note: The log message (excluding pr_errno's strerror and libcrypto's - * error stack) cannot exceed 512 bytes at present. - */ - /* * Check if corresponding logging is enabled. You can use these to short-circuit * out of heavy logging code. @@ -67,15 +70,22 @@ void pr_op_debug(const char *, ...) CHECK_FORMAT(1, 2); void pr_op_info(const char *, ...) CHECK_FORMAT(1, 2); /* Non-errors that suggest a problem. */ int pr_op_warn(const char *, ...) CHECK_FORMAT(1, 2); -/* Problematic situations that prevent Fort from doing its job. */ +/* Do not use this; see pr_op_err() and pr_op_errno(). */ int __pr_op_err(int, const char *, ...) CHECK_FORMAT(2, 3); +/* + * Problematic situations that prevent Fort from doing its job. + * (Always returns -EINVAL.) + */ +#define pr_op_err(fmt, ...) __pr_op_err(-EINVAL, fmt, ##__VA_ARGS__) +/* + * Like pr_op_err(), but also prints strerror(error). + * (Always returns error). + */ +#define pr_op_errno(error, fmt, ...) \ + __pr_op_err(error, fmt ": %s", ##__VA_ARGS__, strerror(abs(error))) /* Like pr_op_err(), except it prints libcrypto's error stack as well. */ int op_crypto_err(const char *, ...) CHECK_FORMAT(1, 2); -#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 == */ @@ -85,15 +95,18 @@ void pr_val_debug(const char *, ...) CHECK_FORMAT(1, 2); 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); -/* Problems that trigger RPKI object rejection. */ +/* Do not use this; see pr_val_err() and pr_val_errno(). */ 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__) +/* Problems that trigger RPKI object rejection. */ +#define pr_val_err(fmt, ...) __pr_val_err(-EINVAL, fmt, ##__VA_ARGS__) +/* + * Like pr_val_err(), but also prints strerror(error). + * (Always returns error). + */ #define pr_val_errno(error, fmt, ...) \ __pr_val_err(error, fmt ": %s", ##__VA_ARGS__, strerror(abs(error))) +/* Like pr_val_err(), except it prints libcrypto's error stack as well. */ +int val_crypto_err(const char *, ...) CHECK_FORMAT(1, 2); /* Like pr_*_err(), specific to out-of-memory situations. */ int pr_enomem(void); diff --git a/src/main.c b/src/main.c index c0b99feb..0b18a20d 100644 --- a/src/main.c +++ b/src/main.c @@ -1,6 +1,5 @@ #include "clients.h" #include "config.h" -#include "debug.h" #include "extension.h" #include "internal_pool.h" #include "nid.h" @@ -45,8 +44,6 @@ __main(int argc, char **argv) { int error; - print_stack_trace_on_segfault(); - error = thvar_init(); if (error) return error; @@ -96,8 +93,12 @@ main(int argc, char **argv) { int error; - log_setup(); + error = log_setup(); + if (error) + return error; + error = __main(argc, argv); + log_teardown(); return error; -- 2.47.3