diff --git a/docs/OPERATIONS.md b/docs/OPERATIONS.md index 58642e7b9..652cbaf19 100644 --- a/docs/OPERATIONS.md +++ b/docs/OPERATIONS.md @@ -85,6 +85,26 @@ Alerts are sent to PagerDuty and Slack (#ops-alerts channel). | DBConnectionPool | Pool exhaustion risk | Critical | 10 minutes | | QueueBacklog | Queue depth > 10000 for 5 minutes | Warning | 15 minutes | +### Frailbox Legacy Logger File Failures + +The C frailbox components still use the legacy logger in +`frailbox/src/logger.c`. When `LOG_FILE` points to a path that cannot be +opened, configured for line buffering, written, flushed, or closed, the logger +prints a diagnostic message to `stderr` and continues logging to `stderr` +instead of aborting the process. + +Operators can check whether the fallback path was used by calling +`log_get_fallback_count()` from a test harness or diagnostic build. The +repository includes a focused harness for the common failure modes: + +```bash +cd frailbox +make test-logger-errors +``` + +The harness verifies normal file logging, fallback when the configured log file +cannot be opened, and fallback when writes fail after a file was opened. + ## Incident Response ### Severity Levels diff --git a/frailbox/Makefile b/frailbox/Makefile index d4383d853..55b72120f 100644 --- a/frailbox/Makefile +++ b/frailbox/Makefile @@ -37,7 +37,14 @@ distclean: clean test: $(TARGET) ./$(TARGET) --sandbox-type seccomp --memory-limit 64 --verbose +test-logger-errors: $(BUILDDIR)/tests/test_logger_errors + ./$(BUILDDIR)/tests/test_logger_errors + +$(BUILDDIR)/tests/test_logger_errors: tests/test_logger_errors.c $(SRCDIR)/logger.c include/logger.h + @mkdir -p $(dir $@) + $(CC) $(CFLAGS) -I$(INCDIR) tests/test_logger_errors.c $(SRCDIR)/logger.c -o $@ $(LDFLAGS) + valgrind: $(TARGET) valgrind --leak-check=full --show-leak-kinds=all ./$(TARGET) -.PHONY: all clean distclean test valgrind +.PHONY: all clean distclean test test-logger-errors valgrind diff --git a/frailbox/include/logger.h b/frailbox/include/logger.h index b9e2248c5..e6ad19c6e 100644 --- a/frailbox/include/logger.h +++ b/frailbox/include/logger.h @@ -229,6 +229,15 @@ void log_set_level(int level); */ int log_get_level(void); +/** + * Get the number of times the legacy logger had to fall back to stderr. + * This is primarily useful for diagnostics and regression tests around + * file-open, write, flush, and close failures. + * + * @return Number of fallback events observed in this process + */ +unsigned int log_get_fallback_count(void); + /** * Log a formatted message at the specified level. * This is the core logging function. All LOG_* macros call this. diff --git a/frailbox/src/logger.c b/frailbox/src/logger.c index f1a7aa1a3..92b3201d6 100644 --- a/frailbox/src/logger.c +++ b/frailbox/src/logger.c @@ -128,6 +128,8 @@ static int g_log_level = DEFAULT_LOG_LEVEL; * TODO: Add automatic log file reopening after SIGHUP. */ static FILE *g_log_file = NULL; +static int g_log_file_is_stderr = 1; +static unsigned int g_log_fallback_count = 0; /** * Whether to include timestamps in log output. @@ -177,6 +179,24 @@ static char g_module_name[64] = "frailbox"; */ static pid_t g_pid = 0; +static void logger_fallback_to_stderr(const char *operation, + const char *path, + int errnum) +{ + const char *safe_operation = operation != NULL ? operation : "log file operation"; + const char *safe_path = path != NULL ? path : ""; + + fprintf(stderr, "Legacy logger: %s failed for '%s': %s; falling back to stderr\n", + safe_operation, safe_path, strerror(errnum)); + + if (g_log_file != NULL && g_log_file != stderr) { + fclose(g_log_file); + } + g_log_file = stderr; + g_log_file_is_stderr = 1; + g_log_fallback_count++; +} + /* ------------------------------------------------------------------ */ /* INTERNAL HELPERS */ /* ------------------------------------------------------------------ */ @@ -377,15 +397,18 @@ int log_init(void) const char *env_log_file = getenv("LOG_FILE"); if (env_log_file != NULL && strlen(env_log_file) > 0) { + errno = 0; g_log_file = fopen(env_log_file, "a"); if (g_log_file == NULL) { - fprintf(stderr, "Failed to open log file '%s': %s\n", - env_log_file, strerror(errno)); - /* Fall back to stderr */ - g_log_file = stderr; + logger_fallback_to_stderr("open", env_log_file, errno); + } else if (setvbuf(g_log_file, NULL, _IOLBF, 0) != 0) { + logger_fallback_to_stderr("configure buffering", env_log_file, errno); + } else { + g_log_file_is_stderr = 0; } } else { g_log_file = stderr; + g_log_file_is_stderr = 1; } const char *env_module = getenv("LOG_MODULE"); @@ -445,6 +468,15 @@ int log_get_level(void) return level; } +unsigned int log_get_fallback_count(void) +{ + unsigned int count; + pthread_mutex_lock(&log_mutex); + count = g_log_fallback_count; + pthread_mutex_unlock(&log_mutex); + return count; +} + /** * Core logging function. All log macros call this function. * @@ -525,13 +557,18 @@ void log_message(int level, const char *file, int line, const char *fmt, ...) buffer[total_len + 1] = '\0'; } - /* Write to output */ - if (g_log_file != NULL) { - fputs(buffer, g_log_file); - fflush(g_log_file); - } else { - fputs(buffer, stderr); - fflush(stderr); + /* Write to output; fall back to stderr if the configured file fails. */ + FILE *target = g_log_file != NULL ? g_log_file : stderr; + errno = 0; + if (fputs(buffer, target) == EOF || fflush(target) == EOF) { + int write_errno = errno != 0 ? errno : EIO; + if (!g_log_file_is_stderr) { + logger_fallback_to_stderr("write", getenv("LOG_FILE"), write_errno); + fputs(buffer, stderr); + fflush(stderr); + } else { + fprintf(stderr, "Legacy logger: stderr write failed: %s\n", strerror(write_errno)); + } } pthread_mutex_unlock(&log_mutex); @@ -551,10 +588,19 @@ void log_shutdown(void) pthread_mutex_lock(&log_mutex); if (g_log_file != NULL && g_log_file != stderr) { - fflush(g_log_file); - fclose(g_log_file); + if (fflush(g_log_file) == EOF) { + logger_fallback_to_stderr("flush during shutdown", getenv("LOG_FILE"), errno != 0 ? errno : EIO); + } else if (fclose(g_log_file) == EOF) { + fprintf(stderr, "Legacy logger: close during shutdown failed for '%s': %s; falling back to stderr\n", + getenv("LOG_FILE") != NULL ? getenv("LOG_FILE") : "", + strerror(errno != 0 ? errno : EIO)); + g_log_file = stderr; + g_log_file_is_stderr = 1; + g_log_fallback_count++; + } g_log_file = NULL; } + g_log_file_is_stderr = 1; g_log_level = LOG_LEVEL_NONE; diff --git a/frailbox/tests/test_logger_errors.c b/frailbox/tests/test_logger_errors.c new file mode 100644 index 000000000..3095e1eb8 --- /dev/null +++ b/frailbox/tests/test_logger_errors.c @@ -0,0 +1,58 @@ +#include +#include +#include +#include + +#include "../include/logger.h" + +static int expect_true(int condition, const char *message) +{ + if (!condition) { + fprintf(stderr, "FAIL: %s\n", message); + return 1; + } + return 0; +} + +int main(void) +{ + int failures = 0; + char template_path[] = "/tmp/frailbox-logger-XXXXXX"; + int fd = mkstemp(template_path); + if (fd < 0) { + perror("mkstemp"); + return 1; + } + close(fd); + + setenv("LOG_LEVEL", "info", 1); + setenv("LOG_FILE", template_path, 1); + failures += expect_true(log_init() == 0, "log_init succeeds for writable file"); + LOG_INFO("normal file write"); + failures += expect_true(log_get_fallback_count() == 0, "writable file does not trigger fallback"); + log_shutdown(); + + setenv("LOG_LEVEL", "info", 1); + setenv("LOG_FILE", "/tmp/frailbox-missing-dir/logger.log", 1); + failures += expect_true(log_init() == 0, "log_init succeeds with stderr fallback"); + failures += expect_true(log_get_fallback_count() >= 1, "open failure increments fallback count"); + LOG_WARN("fallback after open failure"); + log_shutdown(); + + setenv("LOG_LEVEL", "info", 1); + setenv("LOG_FILE", "/dev/full", 1); + unsigned int before = log_get_fallback_count(); + failures += expect_true(log_init() == 0, "log_init succeeds for /dev/full"); + LOG_ERROR("write should fall back from /dev/full"); + failures += expect_true(log_get_fallback_count() > before, "write failure increments fallback count"); + log_shutdown(); + + unlink(template_path); + unsetenv("LOG_FILE"); + unsetenv("LOG_LEVEL"); + + if (failures == 0) { + printf("logger error handling tests passed\n"); + } + return failures == 0 ? 0 : 1; +}