From 55bbbe09a3b37a98c907dbfbc225768ff253e84f Mon Sep 17 00:00:00 2001 From: zixuan zhao Date: Thu, 24 Oct 2024 18:36:32 -0400 Subject: [PATCH] Configurable log and timestamp formats (logfmt, ISO8601) (#1022) Add ability to configure log output format and timestamp format in the logs. This change adds two new configs: * `log-format`: Either legacy or logfmt (See https://brandur.org/logfmt) * `log-timestamp-format`: legacy, iso8601 or milliseconds (since the eppch). Related to #1006. Example: ``` $ ./valkey-server /home/zhaoz12/git/valkey/valkey/valkey.conf pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=warning message="WARNING Memory overcommit must be enabled! Without it, a background save or replication may fail under low memory condition. Being disabled, it can also cause failures without low memory condition, see https://github.com/jemalloc/jemalloc/issues/1328. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect." pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="oO0OoO0OoO0Oo Valkey is starting oO0OoO0OoO0Oo" pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="Valkey version=255.255.255, bits=64, commit=affbea5d, modified=1, pid=109463, just started" pid=109463 role=RDB/AOF timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="Configuration loaded" pid=109463 role=master timestamp="2024-09-10T20:37:25.738-04:00" level=notice message="monotonic clock: POSIX clock_gettime" pid=109463 role=master timestamp="2024-09-10T20:37:25.739-04:00" level=warning message="Failed to write PID file: Permission denied" ``` --------- Signed-off-by: azuredream --- src/config.c | 9 +++++ src/server.c | 109 ++++++++++++++++++++++++++++++++++++++++++++++----- src/server.h | 33 ++++++++++------ 3 files changed, 130 insertions(+), 21 deletions(-) diff --git a/src/config.c b/src/config.c index 7bee87946..b3d760dd5 100644 --- a/src/config.c +++ b/src/config.c @@ -152,6 +152,13 @@ configEnum propagation_error_behavior_enum[] = { {"panic-on-replicas", PROPAGATION_ERR_BEHAVIOR_PANIC_ON_REPLICAS}, {NULL, 0}}; +configEnum log_format_enum[] = {{"legacy", LOG_FORMAT_LEGACY}, {"logfmt", LOG_FORMAT_LOGFMT}, {NULL, 0}}; + +configEnum log_timestamp_format_enum[] = {{"legacy", LOG_TIMESTAMP_LEGACY}, + {"iso8601", LOG_TIMESTAMP_ISO8601}, + {"milliseconds", LOG_TIMESTAMP_MILLISECONDS}, + {NULL, 0}}; + /* Output buffer limits presets. */ clientBufferLimitsConfig clientBufferLimitsDefaults[CLIENT_TYPE_OBUF_COUNT] = { {0, 0, 0}, /* normal */ @@ -3190,6 +3197,8 @@ standardConfig static_configs[] = { createEnumConfig("propagation-error-behavior", NULL, MODIFIABLE_CONFIG, propagation_error_behavior_enum, server.propagation_error_behavior, PROPAGATION_ERR_BEHAVIOR_IGNORE, NULL, NULL), createEnumConfig("shutdown-on-sigint", NULL, MODIFIABLE_CONFIG | MULTI_ARG_CONFIG, shutdown_on_sig_enum, server.shutdown_on_sigint, 0, isValidShutdownOnSigFlags, NULL), createEnumConfig("shutdown-on-sigterm", NULL, MODIFIABLE_CONFIG | MULTI_ARG_CONFIG, shutdown_on_sig_enum, server.shutdown_on_sigterm, 0, isValidShutdownOnSigFlags, NULL), + createEnumConfig("log-format", NULL, MODIFIABLE_CONFIG, log_format_enum, server.log_format, LOG_FORMAT_LEGACY, NULL, NULL), + createEnumConfig("log-timestamp-format", NULL, MODIFIABLE_CONFIG, log_timestamp_format_enum, server.log_timestamp_format, LOG_TIMESTAMP_LEGACY, NULL, NULL), /* Integer configs */ createIntConfig("databases", NULL, IMMUTABLE_CONFIG, 1, INT_MAX, server.dbnum, 16, INTEGER_CONFIG, NULL, NULL), diff --git a/src/server.c b/src/server.c index 531fb07b7..f5ce4d21e 100644 --- a/src/server.c +++ b/src/server.c @@ -109,11 +109,69 @@ const char *replstateToString(int replstate); * function of the server may be called from other threads. */ void nolocks_localtime(struct tm *tmp, time_t t, time_t tz, int dst); +/* Formats the timezone offset into a string. daylight_active indicates whether dst is active (1) + * or not (0). */ +void formatTimezone(char *buf, size_t buflen, int timezone, int daylight_active) { + serverAssert(buflen >= 7); + serverAssert(timezone >= -50400 && timezone <= 43200); + // Adjust the timezone for daylight saving, if active + int total_offset = (-1) * timezone + 3600 * daylight_active; + int hours = abs(total_offset / 3600); + int minutes = abs(total_offset % 3600) / 60; + buf[0] = total_offset >= 0 ? '+' : '-'; + buf[1] = '0' + hours / 10; + buf[2] = '0' + hours % 10; + buf[3] = ':'; + buf[4] = '0' + minutes / 10; + buf[5] = '0' + minutes % 10; + buf[6] = '\0'; +} + +bool hasInvalidLogfmtChar(const char *msg) { + if (msg == NULL) return false; + + for (int i = 0; msg[i] != '\0'; i++) { + if (msg[i] == '"' || msg[i] == '\n' || msg[i] == '\r') { + return true; + } + } + return false; +} + +/* Modifies the input string by: + * replacing \r and \n with whitespace + * replacing " with ' + * + * Parameters: + * safemsg - A char pointer where the modified message will be stored + * safemsglen - size of safemsg + * msg - The original message */ +void filterInvalidLogfmtChar(char *safemsg, size_t safemsglen, const char *msg) { + serverAssert(safemsglen == LOG_MAX_LEN); + if (msg == NULL) return; + + size_t index = 0; + while (index < safemsglen - 1 && msg[index] != '\0') { + if (msg[index] == '"') { + safemsg[index] = '\''; + } else if (msg[index] == '\n' || msg[index] == '\r') { + safemsg[index] = ' '; + } else { + safemsg[index] = msg[index]; + } + index++; + } + safemsg[index] = '\0'; +} + /* Low level logging. To use only for very big messages, otherwise * serverLog() is to prefer. */ void serverLogRaw(int level, const char *msg) { const int syslogLevelMap[] = {LOG_DEBUG, LOG_INFO, LOG_NOTICE, LOG_WARNING}; const char *c = ".-*#"; + const char *verbose_level[] = {"debug", "info", "notice", "warning"}; + const char *roles[] = {"sentinel", "RDB/AOF", "replica", "primary"}; + const char *role_chars = "XCSM"; FILE *fp; char buf[64]; int rawmode = (level & LL_RAW); @@ -133,23 +191,54 @@ void serverLogRaw(int level, const char *msg) { } else { int off; struct timeval tv; - int role_char; pid_t pid = getpid(); int daylight_active = atomic_load_explicit(&server.daylight_active, memory_order_relaxed); gettimeofday(&tv, NULL); struct tm tm; nolocks_localtime(&tm, tv.tv_sec, server.timezone, daylight_active); - off = strftime(buf, sizeof(buf), "%d %b %Y %H:%M:%S.", &tm); - snprintf(buf + off, sizeof(buf) - off, "%03d", (int)tv.tv_usec / 1000); - if (server.sentinel_mode) { - role_char = 'X'; /* Sentinel. */ - } else if (pid != server.pid) { - role_char = 'C'; /* RDB / AOF writing child. */ - } else { - role_char = (server.primary_host ? 'S' : 'M'); /* replica or Primary. */ + switch (server.log_timestamp_format) { + case LOG_TIMESTAMP_LEGACY: + off = strftime(buf, sizeof(buf), "%d %b %Y %H:%M:%S.", &tm); + snprintf(buf + off, sizeof(buf) - off, "%03d", (int)tv.tv_usec / 1000); + break; + + case LOG_TIMESTAMP_ISO8601: + off = strftime(buf, sizeof(buf), "%Y-%m-%dT%H:%M:%S.", &tm); + char tzbuf[7]; + formatTimezone(tzbuf, sizeof(tzbuf), server.timezone, server.daylight_active); + snprintf(buf + off, sizeof(buf) - off, "%03d%s", (int)tv.tv_usec / 1000, tzbuf); + break; + + case LOG_TIMESTAMP_MILLISECONDS: + snprintf(buf, sizeof(buf), "%lld", (long long)tv.tv_sec * 1000 + (long long)tv.tv_usec / 1000); + break; + } + int role_index; + if (server.sentinel_mode) { + role_index = 0; /* Sentinel. */ + } else if (pid != server.pid) { + role_index = 1; /* RDB / AOF writing child. */ + } else { + role_index = (server.primary_host ? 2 : 3); /* Replica or Primary. */ + } + switch (server.log_format) { + case LOG_FORMAT_LOGFMT: + if (hasInvalidLogfmtChar(msg)) { + char safemsg[LOG_MAX_LEN]; + filterInvalidLogfmtChar(safemsg, LOG_MAX_LEN, msg); + fprintf(fp, "pid=%d role=%s timestamp=\"%s\" level=%s message=\"%s\"\n", (int)getpid(), roles[role_index], + buf, verbose_level[level], safemsg); + } else { + fprintf(fp, "pid=%d role=%s timestamp=\"%s\" level=%s message=\"%s\"\n", (int)getpid(), roles[role_index], + buf, verbose_level[level], msg); + } + break; + + case LOG_FORMAT_LEGACY: + fprintf(fp, "%d:%c %s %c %s\n", (int)getpid(), role_chars[role_index], buf, c[level], msg); + break; } - fprintf(fp, "%d:%c %s %c %s\n", (int)getpid(), role_char, buf, c[level], msg); } fflush(fp); diff --git a/src/server.h b/src/server.h index 280c43932..5cf56e9c8 100644 --- a/src/server.h +++ b/src/server.h @@ -567,6 +567,15 @@ typedef enum { #define PAUSE_ACTION_EVICT (1 << 3) #define PAUSE_ACTION_REPLICA (1 << 4) /* pause replica traffic */ +/* Sets log format */ +typedef enum { LOG_FORMAT_LEGACY = 0, + LOG_FORMAT_LOGFMT } log_format_type; + +/* Sets log timestamp format */ +typedef enum { LOG_TIMESTAMP_LEGACY = 0, + LOG_TIMESTAMP_ISO8601, + LOG_TIMESTAMP_MILLISECONDS } log_timestamp_type; + /* common sets of actions to pause/unpause */ #define PAUSE_ACTIONS_CLIENT_WRITE_SET \ (PAUSE_ACTION_CLIENT_WRITE | PAUSE_ACTION_EXPIRE | PAUSE_ACTION_EVICT | PAUSE_ACTION_REPLICA) @@ -1978,17 +1987,19 @@ struct valkeyServer { serverOpArray also_propagate; /* Additional command to propagate. */ int replication_allowed; /* Are we allowed to replicate? */ /* Logging */ - char *logfile; /* Path of log file */ - int syslog_enabled; /* Is syslog enabled? */ - char *syslog_ident; /* Syslog ident */ - int syslog_facility; /* Syslog facility */ - int crashlog_enabled; /* Enable signal handler for crashlog. - * disable for clean core dumps. */ - int crashed; /* True if the server has crashed, used in catClientInfoString - * to indicate that no wait for IO threads is needed. */ - int memcheck_enabled; /* Enable memory check on crash. */ - int use_exit_on_panic; /* Use exit() on panic and assert rather than - * abort(). useful for Valgrind. */ + char *logfile; /* Path of log file */ + int syslog_enabled; /* Is syslog enabled? */ + char *syslog_ident; /* Syslog ident */ + int syslog_facility; /* Syslog facility */ + int crashlog_enabled; /* Enable signal handler for crashlog. + * disable for clean core dumps. */ + int crashed; /* True if the server has crashed, used in catClientInfoString + * to indicate that no wait for IO threads is needed. */ + int memcheck_enabled; /* Enable memory check on crash. */ + int use_exit_on_panic; /* Use exit() on panic and assert rather than + * abort(). useful for Valgrind. */ + int log_format; /* Print log in specific format */ + int log_timestamp_format; /* Timestamp format in log */ /* Shutdown */ int shutdown_timeout; /* Graceful shutdown time limit in seconds. */ int shutdown_on_sigint; /* Shutdown flags configured for SIGINT. */