Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Introduce log.h to decouple serverLog from server.h. #664

Closed
wants to merge 2 commits into from
Closed

Introduce log.h to decouple serverLog from server.h. #664

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
9d2b67e
Introduce log.h to decouple serverLog to server.h.
lipzhu Jun 18, 2024
9198234
clang-format.
lipzhu Jun 18, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion src/Makefile
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -401,7 +401,7 @@ endif
ENGINE_NAME=valkey
SERVER_NAME=$(ENGINE_NAME)-server$(PROG_SUFFIX)
ENGINE_SENTINEL_NAME=$(ENGINE_NAME)-sentinel$(PROG_SUFFIX)
ENGINE_SERVER_OBJ=threads_mngr.o adlist.o quicklist.o ae.o anet.o dict.o kvstore.o server.o sds.o zmalloc.o lzf_c.o lzf_d.o pqsort.o zipmap.o sha1.o ziplist.o release.o networking.o util.o object.o db.o replication.o rdb.o t_string.o t_list.o t_set.o t_zset.o t_hash.o config.o aof.o pubsub.o multi.o debug.o sort.o intset.o syncio.o cluster.o cluster_legacy.o crc16.o endianconv.o slowlog.o eval.o bio.o rio.o rand.o memtest.o syscheck.o crcspeed.o crccombine.o crc64.o bitops.o sentinel.o notify.o setproctitle.o blocked.o hyperloglog.o latency.o sparkline.o valkey-check-rdb.o valkey-check-aof.o geo.o lazyfree.o module.o evict.o expire.o geohash.o geohash_helper.o childinfo.o defrag.o siphash.o rax.o t_stream.o listpack.o localtime.o lolwut.o lolwut5.o lolwut6.o acl.o tracking.o socket.o tls.o sha256.o timeout.o setcpuaffinity.o monotonic.o mt19937-64.o resp_parser.o call_reply.o script_lua.o script.o functions.o function_lua.o commands.o strl.o connection.o unix.o logreqres.o
ENGINE_SERVER_OBJ=threads_mngr.o adlist.o quicklist.o ae.o anet.o dict.o kvstore.o server.o sds.o zmalloc.o lzf_c.o lzf_d.o pqsort.o zipmap.o sha1.o ziplist.o release.o networking.o util.o object.o db.o replication.o rdb.o t_string.o t_list.o t_set.o t_zset.o t_hash.o config.o aof.o pubsub.o multi.o debug.o sort.o intset.o syncio.o cluster.o cluster_legacy.o crc16.o endianconv.o slowlog.o eval.o bio.o rio.o rand.o memtest.o syscheck.o crcspeed.o crccombine.o crc64.o bitops.o sentinel.o notify.o setproctitle.o blocked.o hyperloglog.o latency.o sparkline.o valkey-check-rdb.o valkey-check-aof.o geo.o lazyfree.o module.o evict.o expire.o geohash.o geohash_helper.o childinfo.o defrag.o siphash.o rax.o t_stream.o listpack.o localtime.o lolwut.o lolwut5.o lolwut6.o acl.o tracking.o socket.o tls.o sha256.o timeout.o setcpuaffinity.o monotonic.o mt19937-64.o resp_parser.o call_reply.o script_lua.o script.o functions.o function_lua.o commands.o strl.o connection.o unix.o logreqres.o log.o
ENGINE_CLI_NAME=$(ENGINE_NAME)-cli$(PROG_SUFFIX)
ENGINE_CLI_OBJ=anet.o adlist.o dict.o valkey-cli.o zmalloc.o release.o ae.o serverassert.o crcspeed.o crccombine.o crc64.o siphash.o crc16.o monotonic.o cli_common.o mt19937-64.o strl.o cli_commands.o
ENGINE_BENCHMARK_NAME=$(ENGINE_NAME)-benchmark$(PROG_SUFFIX)
Expand Down
128 changes: 128 additions & 0 deletions src/log.c
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,128 @@
#include "log.h"

#include "util.h"

#include <fcntl.h>
#include <stdarg.h>
#include <string.h>

/* We use a private localtime implementation which is fork-safe. The logging
* function of the server may be called from other threads. */
void nolocks_localtime(struct tm *tmp, time_t t, time_t tz, int dst);

/* Low level logging from signal handler. Should be used with pre-formatted strings.
See serverLogFromHandler. */
void valkeyLogRawFromHandler(int level, int daemonize, const char *logfile, const char *msg) {
int fd;
int log_to_stdout = logfile[0] == '\0';
char buf[64];

if (log_to_stdout && daemonize) return;
fd = log_to_stdout ? STDOUT_FILENO : open(logfile, O_APPEND | O_CREAT | O_WRONLY, 0644);
if (fd == -1) return;
if (level & LL_RAW) {
if (write(fd, msg, strlen(msg)) == -1) goto err;
} else {
ll2string(buf, sizeof(buf), getpid());
if (write(fd, buf, strlen(buf)) == -1) goto err;
if (write(fd, ":signal-handler (", 17) == -1) goto err;
ll2string(buf, sizeof(buf), time(NULL));
if (write(fd, buf, strlen(buf)) == -1) goto err;
if (write(fd, ") ", 2) == -1) goto err;
if (write(fd, msg, strlen(msg)) == -1) goto err;
if (write(fd, "\n", 1) == -1) goto err;
}
err:
if (!log_to_stdout) close(fd);
}

/* An async-signal-safe version of serverLog. if LL_RAW is not included in level flags,
* The message format is: <pid>:signal-handler (<time>) <msg> \n
* with LL_RAW flag only the msg is printed (with no new line at the end)
*
* We actually use this only for signals that are not fatal from the point
* of view of the server. Signals that are going to kill the server anyway and
* where we need printf-alike features are served by serverLog(). */
void valkeyLogFromHandler(int level, int daemonize, const char *logfile, const char *fmt, ...) {
va_list ap;
char msg[LOG_MAX_LEN];

va_start(ap, fmt);
vsnprintf_async_signal_safe(msg, sizeof(msg), fmt, ap);
va_end(ap);

valkeyLogRawFromHandler(level, daemonize, logfile, msg);
}

/* Low level logging. To use only for very big messages, otherwise
* valkeyLog() is to prefer. */
void valkeyLogRaw(int level,
int syslog_enabled,
time_t timezone,
int daylight_active,
int sentinel_mode,
pid_t server_pid,
const char *primary_host,
const char *logfile,
const char *msg) {
const int syslogLevelMap[] = {LOG_DEBUG, LOG_INFO, LOG_NOTICE, LOG_WARNING};
const char *c = ".-*#";
FILE *fp;
char buf[64];
int rawmode = (level & LL_RAW);
int log_to_stdout = logfile[0] == '\0';

fp = log_to_stdout ? stdout : fopen(logfile, "a");
if (!fp) return;

if (rawmode) {
fprintf(fp, "%s", msg);
} else {
int off;
struct timeval tv;
int role_char;
pid_t pid = getpid();

gettimeofday(&tv, NULL);
struct tm tm;
nolocks_localtime(&tm, tv.tv_sec, 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 (sentinel_mode) {
role_char = 'X'; /* Sentinel. */
} else if (pid != server_pid) {
role_char = 'C'; /* RDB / AOF writing child. */
} else {
role_char = (primary_host ? 'S' : 'M'); /* replica or Primary. */
}
fprintf(fp, "%d:%c %s %c %s\n", (int)getpid(), role_char, buf, c[level], msg);
}
fflush(fp);

if (!log_to_stdout) fclose(fp);
if (syslog_enabled) syslog(syslogLevelMap[level], "%s", msg);
}

/* Like valkeyLogRaw() but with printf-alike support. This is the function that
* is used across the code. The raw version is only used in order to dump
* the INFO output on crash. */
void valkeyLog(int level,
int syslog_enabled,
time_t timezone,
int daylight_active,
int sentinel_mode,
pid_t server_pid,
const char *primary_host,
const char *logfile,
const char *fmt,
...) {
va_list ap;
char msg[LOG_MAX_LEN];

va_start(ap, fmt);
vsnprintf(msg, sizeof(msg), fmt, ap);
va_end(ap);

valkeyLogRaw(level, syslog_enabled, timezone, daylight_active, sentinel_mode, server_pid, primary_host, logfile,
msg);
}
89 changes: 89 additions & 0 deletions src/log.h
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,89 @@
#ifndef VALKEY_LOG_H
#define VALKEY_LOG_H

#include <ctype.h>
#include <stddef.h>
#include <stdio.h>
#include <sys/syslog.h>
#include <sys/time.h>
#include <time.h>
#include <unistd.h>

#define LOG_MAX_LEN 1024 /* Default maximum length of syslog messages.*/

/* Log levels */
#define LL_DEBUG 0
#define LL_VERBOSE 1
#define LL_NOTICE 2
#define LL_WARNING 3
#define LL_NOTHING 4
#define LL_RAW (1 << 10) /* Modifier to log without timestamp */

/* Use macro for checking log level to avoid evaluating arguments in cases log
* should be ignored due to low level. */
#define serverLog(level, ...) \
do { \
if (((level) & 0xff) < server.verbosity) break; \
valkeyLog(level, server.syslog_enabled, server.timezone, server.daylight_active, server.sentinel_mode, \
server.pid, server.primary_host, server.logfile, __VA_ARGS__); \
} while (0)

#define serverLogRaw(level, ...) \
do { \
if (((level) & 0xff) < server.verbosity) break; \
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
if (((level) & 0xff) < server.verbosity) break; \
if (((level) & 0xff) < server.verbosity) break; \

This feels a bit like fake decoupling, since you can't import log.h without server.h, since we are accessing the server structure here.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, the existing log implementation seems relied server and server config too much, its not straightforward to split it from server.h. Let's open an issue to discuss the code refactor work.

valkeyLogRaw(level, server.syslog_enabled, server.timezone, server.daylight_active, server.sentinel_mode, \
server.pid, server.primary_host, server.logfile, __VA_ARGS__); \
} while (0)

#define serverLogFromHandler(level, fmt, ...) \
do { \
if (((level) & 0xff) < server.verbosity) break; \
valkeyLogFromHandler(level, server.daemonize, server.logfile, fmt, __VA_ARGS__); \
} while (0)

#define serverLogRawFromHandler(level, msg) \
do { \
if (((level) & 0xff) < server.verbosity) break; \
valkeyLogRawFromHandler(level, server.daemonize, server.logfile, msg); \
} while (0)

#define serverDebug(fmt, ...) printf("DEBUG %s:%d > " fmt "\n", __FILE__, __LINE__, __VA_ARGS__)
#define serverDebugMark() printf("-- MARK %s:%d --\n", __FILE__, __LINE__)

#ifdef __GNUC__
void valkeyLog(int level,
int syslog_enabled,
time_t timezone,
int daylight_active,
int sentinel_mode,
pid_t pid,
const char *primary_host,
const char *logfile,
const char *fmt,
...) __attribute__((format(printf, 9, 10)));
void valkeyLogFromHandler(int level, int daemonize, const char *logfile, const char *fmt, ...)
__attribute__((format(printf, 4, 5)));
#else
void valkeyLog(int level,
int syslog_enabled,
time_t timezone,
int daylight_active,
int sentinel_mode,
pid_t pid,
const char *primary_host,
const char *logfile,
const char *fmt,
...);
void valkeyLogFromHandler(int level, int daemonize, const char *logfile, const char *fmt, ...);
#endif
void valkeyLogRawFromHandler(int level, int daemonize, const char *logfile, const char *msg);
void valkeyLogRaw(int level,
int syslog_enabled,
time_t timezone,
int daylight_active,
int sentinel_mode,
pid_t pid,
const char *primary_host,
const char *logfile,
const char *msg);
#endif
106 changes: 0 additions & 106 deletions src/server.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -102,112 +102,6 @@ const char *replstateToString(int replstate);
/* This macro tells if we are in the context of loading an AOF. */
#define isAOFLoadingContext() ((server.current_client && server.current_client->id == CLIENT_ID_AOF) ? 1 : 0)

/* We use a private localtime implementation which is fork-safe. The logging
* function of the server may be called from other threads. */
void nolocks_localtime(struct tm *tmp, time_t t, time_t tz, int dst);

/* 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 = ".-*#";
FILE *fp;
char buf[64];
int rawmode = (level & LL_RAW);
int log_to_stdout = server.logfile[0] == '\0';

level &= 0xff; /* clear flags */
if (level < server.verbosity) return;

fp = log_to_stdout ? stdout : fopen(server.logfile, "a");
if (!fp) return;

if (rawmode) {
fprintf(fp, "%s", msg);
} else {
int off;
struct timeval tv;
int role_char;
pid_t pid = getpid();

gettimeofday(&tv, NULL);
struct tm tm;
nolocks_localtime(&tm, tv.tv_sec, server.timezone, server.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. */
}
fprintf(fp, "%d:%c %s %c %s\n", (int)getpid(), role_char, buf, c[level], msg);
}
fflush(fp);

if (!log_to_stdout) fclose(fp);
if (server.syslog_enabled) syslog(syslogLevelMap[level], "%s", msg);
}

/* Like serverLogRaw() but with printf-alike support. This is the function that
* is used across the code. The raw version is only used in order to dump
* the INFO output on crash. */
void _serverLog(int level, const char *fmt, ...) {
va_list ap;
char msg[LOG_MAX_LEN];

va_start(ap, fmt);
vsnprintf(msg, sizeof(msg), fmt, ap);
va_end(ap);

serverLogRaw(level, msg);
}

/* Low level logging from signal handler. Should be used with pre-formatted strings.
See serverLogFromHandler. */
void serverLogRawFromHandler(int level, const char *msg) {
int fd;
int log_to_stdout = server.logfile[0] == '\0';
char buf[64];

if ((level & 0xff) < server.verbosity || (log_to_stdout && server.daemonize)) return;
fd = log_to_stdout ? STDOUT_FILENO : open(server.logfile, O_APPEND | O_CREAT | O_WRONLY, 0644);
if (fd == -1) return;
if (level & LL_RAW) {
if (write(fd, msg, strlen(msg)) == -1) goto err;
} else {
ll2string(buf, sizeof(buf), getpid());
if (write(fd, buf, strlen(buf)) == -1) goto err;
if (write(fd, ":signal-handler (", 17) == -1) goto err;
ll2string(buf, sizeof(buf), time(NULL));
if (write(fd, buf, strlen(buf)) == -1) goto err;
if (write(fd, ") ", 2) == -1) goto err;
if (write(fd, msg, strlen(msg)) == -1) goto err;
if (write(fd, "\n", 1) == -1) goto err;
}
err:
if (!log_to_stdout) close(fd);
}

/* An async-signal-safe version of serverLog. if LL_RAW is not included in level flags,
* The message format is: <pid>:signal-handler (<time>) <msg> \n
* with LL_RAW flag only the msg is printed (with no new line at the end)
*
* We actually use this only for signals that are not fatal from the point
* of view of the server. Signals that are going to kill the server anyway and
* where we need printf-alike features are served by serverLog(). */
void serverLogFromHandler(int level, const char *fmt, ...) {
va_list ap;
char msg[LOG_MAX_LEN];

va_start(ap, fmt);
vsnprintf_async_signal_safe(msg, sizeof(msg), fmt, ap);
va_end(ap);

serverLogRawFromHandler(level, msg);
}

/* Return the UNIX time in microseconds */
long long ustime(void) {
struct timeval tv;
Expand Down
Loading
Loading