diff options
Diffstat (limited to 'log.c')
| -rw-r--r-- | log.c | 421 |
1 files changed, 236 insertions, 185 deletions
@@ -26,17 +26,14 @@ #include <stdarg.h> #include <sys/socket.h> +#include "linux_dep.h" #include "log.h" #include "util.h" #include "passt.h" -/* LOG_EARLY means we don't know yet: log everything. LOG_EMERG is unused */ -#define LOG_EARLY LOG_MASK(LOG_EMERG) - static int log_sock = -1; /* Optional socket to system logger */ static char log_ident[BUFSIZ]; /* Identifier string for openlog() */ -static int log_mask = LOG_EARLY; /* Current log priority mask */ -static int log_opt; /* Options for openlog() */ +static int log_mask; /* Current log priority mask */ static int log_file = -1; /* Optional log file descriptor */ static size_t log_size; /* Maximum log file size in bytes */ @@ -44,50 +41,46 @@ static size_t log_written; /* Currently used bytes in log file */ static size_t log_cut_size; /* Bytes to cut at start on rotation */ static char log_header[BUFSIZ]; /* File header, written back on cuts */ -static time_t log_start; /* Start timestamp */ -int log_trace; /* --trace mode enabled */ -int log_to_stdout; /* Print to stdout instead of stderr */ +struct timespec log_start; /* Start timestamp */ -void vlogmsg(int pri, const char *format, va_list ap) -{ - bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; - bool early_print = LOG_PRI(log_mask) == LOG_EARLY; - FILE *out = log_to_stdout ? stdout : stderr; - struct timespec tp; - - if (debug_print) { - clock_gettime(CLOCK_REALTIME, &tp); - fprintf(out, "%lli.%04lli: ", - (long long int)tp.tv_sec - log_start, - (long long int)tp.tv_nsec / (100L * 1000)); - } - - if ((log_mask & LOG_MASK(LOG_PRI(pri))) || early_print) { - va_list ap2; - - va_copy(ap2, ap); /* Don't clobber ap, we need it again */ - if (log_file != -1) - logfile_write(pri, format, ap2); - else if (!(log_mask & LOG_MASK(LOG_DEBUG))) - passt_vsyslog(pri, format, ap2); +int log_trace; /* --trace mode enabled */ +bool log_conf_parsed; /* Logging options already parsed */ +bool log_stderr = true; /* Not daemonised, no shell spawned */ - va_end(ap2); - } +#define LL_STRLEN (sizeof("-9223372036854775808")) +#define LOGTIME_STRLEN (LL_STRLEN + 5) - if (debug_print || (early_print && !(log_opt & LOG_PERROR))) { - (void)vfprintf(out, format, ap); - if (format[strlen(format)] != '\n') - fprintf(out, "\n"); - } +/** + * logtime() - Get the current time for logging purposes + * @ts: Buffer into which to store the timestamp + * + * Return: pointer to @now, or NULL if there was an error retrieving the time + */ +const struct timespec *logtime(struct timespec *ts) +{ + if (clock_gettime(CLOCK_MONOTONIC, ts)) + return NULL; + return ts; } -void logmsg(int pri, const char *format, ...) +/** + * logtime_fmt() - Format timestamp into a string for the log + * @buf: Buffer into which to format the time + * @size: Size of @buf + * @ts: Time to format (or NULL on error) + * + * Return: number of characters written to @buf (excluding \0) + */ +static int logtime_fmt(char *buf, size_t size, const struct timespec *ts) { - va_list ap; + if (ts) { + int64_t delta = timespec_diff_us(ts, &log_start); - va_start(ap, format); - vlogmsg(pri, format, ap); - va_end(ap); + return snprintf(buf, size, "%lli.%04lli", delta / 1000000LL, + (delta / 100LL) % 10000); + } + + return snprintf(buf, size, "<error>"); } /* Prefixes for log file messages, indexed by priority */ @@ -101,126 +94,11 @@ const char *logfile_prefix[] = { }; /** - * trace_init() - Set log_trace depending on trace (debug) mode - * @enable: Tracing debug mode enabled if non-zero - */ -void trace_init(int enable) -{ - log_trace = enable; -} - -/** - * __openlog() - Non-optional openlog() implementation, for custom vsyslog() - * @ident: openlog() identity (program name) - * @option: openlog() options - * @facility: openlog() facility (LOG_DAEMON) - */ -void __openlog(const char *ident, int option, int facility) -{ - struct timespec tp; - - clock_gettime(CLOCK_REALTIME, &tp); - log_start = tp.tv_sec; - - if (log_sock < 0) { - struct sockaddr_un a = { .sun_family = AF_UNIX, }; - - log_sock = socket(AF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0); - if (log_sock < 0) - return; - - strncpy(a.sun_path, _PATH_LOG, sizeof(a.sun_path)); - if (connect(log_sock, (const struct sockaddr *)&a, sizeof(a))) { - close(log_sock); - log_sock = -1; - return; - } - } - - log_mask |= facility; - strncpy(log_ident, ident, sizeof(log_ident) - 1); - log_opt = option; -} - -/** - * __setlogmask() - setlogmask() wrapper, to allow custom vsyslog() - * @mask: Same as setlogmask() mask - */ -void __setlogmask(int mask) -{ - log_mask = mask; - setlogmask(mask); -} - -/** - * passt_vsyslog() - vsyslog() implementation not using heap memory - * @pri: Facility and level map, same as priority for vsyslog() - * @format: Same as vsyslog() format - * @ap: Same as vsyslog() ap - */ -void passt_vsyslog(int pri, const char *format, va_list ap) -{ - int prefix_len, n; - char buf[BUFSIZ]; - - /* Send without timestamp, the system logger should add it */ - n = prefix_len = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident); - - n += vsnprintf(buf + n, BUFSIZ - n, format, ap); - - if (format[strlen(format)] != '\n') - n += snprintf(buf + n, BUFSIZ - n, "\n"); - - if (log_opt & LOG_PERROR) - fprintf(stderr, "%s", buf + prefix_len); - - if (send(log_sock, buf, n, 0) != n) - fprintf(stderr, "Failed to send %i bytes to syslog\n", n); -} - -/** - * logfile_init() - Open log file and write header with PID, version, path - * @name: Identifier for header: passt or pasta - * @path: Path to log file - * @size: Maximum size of log file: log_cut_size is calculatd here - */ -void logfile_init(const char *name, const char *path, size_t size) -{ - char nl = '\n', exe[PATH_MAX] = { 0 }; - int n; - - if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0) { - perror("readlink /proc/self/exe"); - exit(EXIT_FAILURE); - } - - log_file = open(path, O_CREAT | O_TRUNC | O_APPEND | O_RDWR | O_CLOEXEC, - S_IRUSR | S_IWUSR); - if (log_file == -1) - die("Couldn't open log file %s: %s", path, strerror(errno)); - - log_size = size ? size : LOGFILE_SIZE_DEFAULT; - - n = snprintf(log_header, sizeof(log_header), "%s " VERSION ": %s (%i)", - name, exe, getpid()); - - if (write(log_file, log_header, n) <= 0 || - write(log_file, &nl, 1) <= 0) { - perror("Couldn't write to log file\n"); - exit(EXIT_FAILURE); - } - - /* For FALLOC_FL_COLLAPSE_RANGE: VFS block size can be up to one page */ - log_cut_size = ROUND_UP(log_size * LOGFILE_CUT_RATIO / 100, PAGE_SIZE); -} - -#ifdef FALLOC_FL_COLLAPSE_RANGE -/** * logfile_rotate_fallocate() - Write header, set log_written after fallocate() * @fd: Log file descriptor * @now: Current timestamp * - * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek + * #syscalls lseek ppc64le:_llseek ppc64:_llseek arm:_llseek i686:_llseek */ static void logfile_rotate_fallocate(int fd, const struct timespec *now) { @@ -233,10 +111,8 @@ static void logfile_rotate_fallocate(int fd, const struct timespec *now) if (read(fd, buf, BUFSIZ) == -1) return; - n = snprintf(buf, BUFSIZ, - "%s - log truncated at %lli.%04lli", log_header, - (long long int)(now->tv_sec - log_start), - (long long int)(now->tv_nsec / (100L * 1000))); + n = snprintf(buf, BUFSIZ, "%s - log truncated at ", log_header); + n += logtime_fmt(buf + n, BUFSIZ - n, now); /* Avoid partial lines by padding the header with spaces */ nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1); @@ -250,14 +126,13 @@ static void logfile_rotate_fallocate(int fd, const struct timespec *now) log_written -= log_cut_size; } -#endif /* FALLOC_FL_COLLAPSE_RANGE */ /** * logfile_rotate_move() - Fallback: move recent entries toward start, then cut * @fd: Log file descriptor * @now: Current timestamp * - * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek + * #syscalls lseek ppc64le:_llseek ppc64:_llseek arm:_llseek * #syscalls ftruncate */ static void logfile_rotate_move(int fd, const struct timespec *now) @@ -266,10 +141,10 @@ static void logfile_rotate_move(int fd, const struct timespec *now) char buf[BUFSIZ]; const char *nl; - header_len = snprintf(buf, BUFSIZ, - "%s - log truncated at %lli.%04lli\n", log_header, - (long long int)(now->tv_sec - log_start), - (long long int)(now->tv_nsec / (100L * 1000))); + header_len = snprintf(buf, BUFSIZ, "%s - log truncated at ", + log_header); + header_len += logtime_fmt(buf + header_len, BUFSIZ - header_len, now); + if (lseek(fd, 0, SEEK_SET) == -1) return; if (write(fd, buf, header_len) == -1) @@ -322,21 +197,17 @@ out: * * Return: 0 on success, negative error code on failure * - * #syscalls fcntl - * - * fallocate() passed as EXTRA_SYSCALL only if FALLOC_FL_COLLAPSE_RANGE is there + * #syscalls fcntl fallocate */ static int logfile_rotate(int fd, const struct timespec *now) { if (fcntl(fd, F_SETFL, O_RDWR /* Drop O_APPEND: explicit lseek() */)) return -errno; -#ifdef FALLOC_FL_COLLAPSE_RANGE /* Only for Linux >= 3.15, extent-based ext4 or XFS, glibc >= 2.18 */ if (!fallocate(fd, FALLOC_FL_COLLAPSE_RANGE, 0, log_cut_size)) logfile_rotate_fallocate(fd, now); else -#endif logfile_rotate_move(fd, now); if (fcntl(fd, F_SETFL, O_RDWR | O_APPEND)) @@ -347,32 +218,212 @@ static int logfile_rotate(int fd, const struct timespec *now) /** * logfile_write() - Write entry to log file, trigger rotation if full + * @newline: Append newline at the end of the message, if missing + * @cont: Continuation of a previous message, on the same line * @pri: Facility and level map, same as priority for vsyslog() + * @now: Timestamp * @format: Same as vsyslog() format * @ap: Same as vsyslog() ap */ -void logfile_write(int pri, const char *format, va_list ap) +static void logfile_write(bool newline, bool cont, int pri, + const struct timespec *now, + const char *format, va_list ap) { - struct timespec now; char buf[BUFSIZ]; - int n; - - if (clock_gettime(CLOCK_REALTIME, &now)) - return; + int n = 0; - n = snprintf(buf, BUFSIZ, "%lli.%04lli: %s", - (long long int)(now.tv_sec - log_start), - (long long int)(now.tv_nsec / (100L * 1000)), - logfile_prefix[pri]); + if (!cont) { + n += logtime_fmt(buf, BUFSIZ, now); + n += snprintf(buf + n, BUFSIZ - n, ": %s", logfile_prefix[pri]); + } n += vsnprintf(buf + n, BUFSIZ - n, format, ap); - if (format[strlen(format)] != '\n') + if (newline && format[strlen(format)] != '\n') n += snprintf(buf + n, BUFSIZ - n, "\n"); - if ((log_written + n >= log_size) && logfile_rotate(log_file, &now)) + if ((log_written + n >= log_size) && logfile_rotate(log_file, now)) return; if ((n = write(log_file, buf, n)) >= 0) log_written += n; } + +/** + * vlogmsg() - Print or send messages to log or output files as configured + * @newline: Append newline at the end of the message, if missing + * @cont: Continuation of a previous message, on the same line + * @pri: Facility and level map, same as priority for vsyslog() + * @format: Message + * @ap: Variable argument list + */ +void vlogmsg(bool newline, bool cont, int pri, const char *format, va_list ap) +{ + bool debug_print = (log_mask & LOG_MASK(LOG_DEBUG)) && log_file == -1; + const struct timespec *now; + struct timespec ts; + + now = logtime(&ts); + + if (debug_print && !cont) { + char timestr[LOGTIME_STRLEN]; + + logtime_fmt(timestr, sizeof(timestr), now); + FPRINTF(stderr, "%s: ", timestr); + } + + if ((log_mask & LOG_MASK(LOG_PRI(pri))) || !log_conf_parsed) { + va_list ap2; + + va_copy(ap2, ap); /* Don't clobber ap, we need it again */ + if (log_file != -1) + logfile_write(newline, cont, pri, now, format, ap2); + else if (!(log_mask & LOG_MASK(LOG_DEBUG))) + passt_vsyslog(newline, pri, format, ap2); + + va_end(ap2); + } + + if (debug_print || !log_conf_parsed || + (log_stderr && (log_mask & LOG_MASK(LOG_PRI(pri))))) { + (void)vfprintf(stderr, format, ap); + if (newline && format[strlen(format)] != '\n') + FPRINTF(stderr, "\n"); + } +} + +/** + * logmsg() - vlogmsg() wrapper for variable argument lists + * @newline: Append newline at the end of the message, if missing + * @cont: Continuation of a previous message, on the same line + * @pri: Facility and level map, same as priority for vsyslog() + * @format: Message + */ +void logmsg(bool newline, bool cont, int pri, const char *format, ...) +{ + va_list ap; + + va_start(ap, format); + vlogmsg(newline, cont, pri, format, ap); + va_end(ap); +} + +/** + * logmsg_perror() - vlogmsg() wrapper with perror()-like functionality + * @pri: Facility and level map, same as priority for vsyslog() + * @format: Message + */ +void logmsg_perror(int pri, const char *format, ...) +{ + int errno_copy = errno; + va_list ap; + + va_start(ap, format); + vlogmsg(false, false, pri, format, ap); + va_end(ap); + + logmsg(true, true, pri, ": %s", strerror(errno_copy)); +} + +/** + * trace_init() - Set log_trace depending on trace (debug) mode + * @enable: Tracing debug mode enabled if non-zero + */ +void trace_init(int enable) +{ + log_trace = enable; +} + +/** + * __openlog() - Non-optional openlog() implementation, for custom vsyslog() + * @ident: openlog() identity (program name) + * @option: openlog() options, unused + * @facility: openlog() facility (LOG_DAEMON) + */ +void __openlog(const char *ident, int option, int facility) +{ + (void)option; + + if (log_sock < 0) { + struct sockaddr_un a = { .sun_family = AF_UNIX, }; + + log_sock = socket(AF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0); + if (log_sock < 0) + return; + + strncpy(a.sun_path, _PATH_LOG, sizeof(a.sun_path)); + if (connect(log_sock, (const struct sockaddr *)&a, sizeof(a))) { + close(log_sock); + log_sock = -1; + return; + } + } + + log_mask |= facility; + strncpy(log_ident, ident, sizeof(log_ident) - 1); +} + +/** + * __setlogmask() - setlogmask() wrapper, to allow custom vsyslog() + * @mask: Same as setlogmask() mask + */ +void __setlogmask(int mask) +{ + log_mask = mask; + setlogmask(mask); +} + +/** + * passt_vsyslog() - vsyslog() implementation not using heap memory + * @newline: Append newline at the end of the message, if missing + * @pri: Facility and level map, same as priority for vsyslog() + * @format: Same as vsyslog() format + * @ap: Same as vsyslog() ap + */ +void passt_vsyslog(bool newline, int pri, const char *format, va_list ap) +{ + char buf[BUFSIZ]; + int n; + + /* Send without timestamp, the system logger should add it */ + n = snprintf(buf, BUFSIZ, "<%i> %s: ", pri, log_ident); + + n += vsnprintf(buf + n, BUFSIZ - n, format, ap); + + if (newline && format[strlen(format)] != '\n') + n += snprintf(buf + n, BUFSIZ - n, "\n"); + + if (log_sock >= 0 && send(log_sock, buf, n, 0) != n && log_stderr) + FPRINTF(stderr, "Failed to send %i bytes to syslog\n", n); +} + +/** + * logfile_init() - Open log file and write header with PID, version, path + * @name: Identifier for header: passt or pasta + * @path: Path to log file + * @size: Maximum size of log file: log_cut_size is calculatd here + */ +void logfile_init(const char *name, const char *path, size_t size) +{ + char nl = '\n', exe[PATH_MAX] = { 0 }; + int n; + + if (readlink("/proc/self/exe", exe, PATH_MAX - 1) < 0) + die_perror("Failed to read own /proc/self/exe link"); + + log_file = output_file_open(path, O_APPEND | O_RDWR); + if (log_file == -1) + die_perror("Couldn't open log file %s", path); + + log_size = size ? size : LOGFILE_SIZE_DEFAULT; + + n = snprintf(log_header, sizeof(log_header), "%s " VERSION ": %s (%i)", + name, exe, getpid()); + + if (write(log_file, log_header, n) <= 0 || + write(log_file, &nl, 1) <= 0) + die_perror("Couldn't write to log file"); + + /* For FALLOC_FL_COLLAPSE_RANGE: VFS block size can be up to one page */ + log_cut_size = ROUND_UP(log_size * LOGFILE_CUT_RATIO / 100, PAGE_SIZE); +} |