Skip to content

Commit

Permalink
Configurable log and timestamp formats (logfmt, ISO8601) (valkey-io#1022
Browse files Browse the repository at this point in the history 
)

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 valkey-io#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 jemalloc/jemalloc#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 <[email protected]>
  • Loading branch information
@azuredream
azuredream authored Oct 24, 2024
1 parent 2956367 commit 55bbbe0
Show file tree
Hide file tree
Showing 3 changed files with 127 additions and 18 deletions.
9 changes: 9 additions & 0 deletions src/config.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand Down Expand Up @@ -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),
Expand Down
103 changes: 96 additions & 7 deletions src/server.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
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_char = 'X'; /* Sentinel. */
role_index = 0; /* Sentinel. */
} else if (pid != server.pid) {
role_char = 'C'; /* RDB / AOF writing child. */
role_index = 1; /* RDB / AOF writing child. */
} else {
role_char = (server.primary_host ? 'S' : 'M'); /* replica or Primary. */
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);

Expand Down
33 changes: 22 additions & 11 deletions src/server.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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. */
Expand Down

0 comments on commit 55bbbe0

Please sign in to comment.