]> git.ipfire.org Git - thirdparty/FORT-validator.git/commitdiff
Logging: More refactors
authorAlberto Leiva Popper <ydahhrk@gmail.com>
Fri, 21 May 2021 18:30:32 +0000 (13:30 -0500)
committerAlberto Leiva Popper <ydahhrk@gmail.com>
Fri, 21 May 2021 18:30:32 +0000 (13:30 -0500)
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
src/debug.c [deleted file]
src/debug.h [deleted file]
src/log.c
src/log.h
src/main.c

index 73b980b1b19b0ab468a6050f114b6e7750ab4d66..ef6dfa1fa039d55ee7145e48a5a5c7055ca85fa9 100644 (file)
@@ -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 (file)
index 5dcf2da..0000000
+++ /dev/null
@@ -1,58 +0,0 @@
-#include "debug.h"
-
-#include <execinfo.h>
-#include <signal.h>
-#include <stdio.h>
-#include <stdlib.h>
-#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 (file)
index e4a3ba7..0000000
+++ /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_ */
index 924116e2ed71741d741c52fbdd7832710b82e58f..501946df7eed8ced07d0ae1b7b2a37b384ce3d10 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -1,12 +1,13 @@
 #include "log.h"
 
+#include <execinfo.h>
 #include <openssl/bio.h>
 #include <openssl/err.h>
+#include <signal.h>
 #include <syslog.h>
 #include <time.h>
 
 #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,  "   <Empty>");
+               error_fn(0, "   <Empty>");
+       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);
 }
 
index 8d215003cb6034099d6d1a4dc84abf58caab4804..22fce17054b18564ac6a14b09c6dd506a57ea247 100644 (file)
--- a/src/log.h
+++ b/src/log.h
 #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);
index c0b99feb408fcb4e98c0495d141abe694b862cc8..0b18a20d3146472d309ff9cf24131b92e3d432c1 100644 (file)
@@ -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;