log, conf: Add support for logging to file

In some environments, such as KubeVirt pods, we might not have a
system logger available. We could choose to run in foreground, but
this takes away the convenient synchronisation mechanism derived from
forking to background when interfaces are ready.

Add optional logging to file with -l/--log-file and --log-size.

Unfortunately, this means we need to duplicate features that are more
appropriately implemented by a system logger, such as rotation. Keep
that reasonably simple, by using fallocate() with range collapsing
where supported (Linux kernel >= 3.15, extent-based ext4 and XFS) and
falling back to an unsophisticated block-by-block moving of entries
toward the beginning of the file once we reach the (mandatory) size
limit.

While at it, clarify the role of LOG_EMERG in passt.c.

Signed-off-by: Stefano Brivio <sbrivio@redhat.com>
Reviewed-by: David Gibson <david@gibson.dropbear.id.au>

1 files changed, 240 insertions, 18 deletions

diff --git a/log.c b/log.c
index 54a7cbb..d769a33 100644
--- a/log.c
+++ b/log.c
@@ -12,7 +12,12 @@
  * Author: Stefano Brivio <sbrivio@redhat.com>
  */
 
+#include <arpa/inet.h>
+#include <limits.h>
+#include <errno.h>
+#include <fcntl.h>
 #include <stdio.h>
+#include <stdint.h>
 #include <stdlib.h>
 #include <unistd.h>
 #include <string.h>
@@ -20,36 +25,49 @@
 #include <syslog.h>
 #include <stdarg.h>
 #include <sys/socket.h>
-#include <sys/un.h>
 
 #include "log.h"
+#include "util.h"
+#include "passt.h"
 
-/* For __openlog() and __setlogmask() wrappers, and passt_vsyslog() */
-static int	log_mask;
-static int	log_sock = -1;
-static char	log_ident[BUFSIZ];
-static int	log_opt;
-static time_t	log_debug_start;
-int		log_trace;
+static int	log_sock = -1;		/* Optional socket to system logger */
+static char	log_ident[BUFSIZ];	/* Identifier string for openlog() */
+static int	log_mask;		/* Current log priority mask */
+static int	log_opt;		/* Options for openlog() */
+
+static int	log_file = -1;		/* Optional log file descriptor */
+static size_t	log_size;		/* Maximum log file size in bytes */
+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 */
 
 #define logfn(name, level)						\
 void name(const char *format, ...) {					\
 	struct timespec tp;						\
 	va_list args;							\
 									\
-	if (setlogmask(0) & LOG_MASK(LOG_DEBUG)) {			\
+	if (setlogmask(0) & LOG_MASK(LOG_DEBUG) && log_file == -1) {	\
 		clock_gettime(CLOCK_REALTIME, &tp);			\
 		fprintf(stderr, "%li.%04li: ",				\
-			tp.tv_sec - log_debug_start,			\
+			tp.tv_sec - log_start,				\
 			tp.tv_nsec / (100L * 1000));			\
-	} else {							\
+	}								\
+									\
+	if ((LOG_MASK(LOG_PRI(level)) & log_mask) ||			\
+	    setlogmask(0) == LOG_MASK(LOG_EMERG)) {			\
 		va_start(args, format);					\
-		passt_vsyslog(level, format, args);			\
+		if (log_file != -1)					\
+			logfile_write(level, format, args);		\
+		else if (!(setlogmask(0) & LOG_MASK(LOG_DEBUG)))	\
+			passt_vsyslog(level, format, args);		\
 		va_end(args);						\
 	}								\
 									\
-	if (setlogmask(0) & LOG_MASK(LOG_DEBUG) ||			\
-	    setlogmask(0) == LOG_MASK(LOG_EMERG)) {			\
+	if ((setlogmask(0) & LOG_MASK(LOG_DEBUG) ||			\
+	     setlogmask(0) == LOG_MASK(LOG_EMERG)) && log_file == -1) {	\
 		va_start(args, format);					\
 		(void)vfprintf(stderr, format, args); 			\
 		va_end(args);						\
@@ -58,6 +76,16 @@ void name(const char *format, ...) {					\
 	}								\
 }
 
+/* Prefixes for log file messages, indexed by priority */
+const char *logfile_prefix[] = {
+	NULL, NULL, NULL,	/* Unused: LOG_EMERG, LOG_ALERT, LOG_CRIT */
+	"ERROR:   ",
+	"WARNING: ",
+	NULL,			/* Unused: LOG_NOTICE */
+	"info:    ",
+	"         ",		/* LOG_DEBUG */
+};
+
 logfn(err,   LOG_ERR)
 logfn(warn,  LOG_WARNING)
 logfn(info,  LOG_INFO)
@@ -79,7 +107,7 @@ void __openlog(const char *ident, int option, int facility)
 	struct timespec tp;
 
 	clock_gettime(CLOCK_REALTIME, &tp);
-	log_debug_start = tp.tv_sec;
+	log_start = tp.tv_sec;
 
 	if (log_sock < 0) {
 		struct sockaddr_un a = { .sun_family = AF_UNIX, };
@@ -124,9 +152,6 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
 	char buf[BUFSIZ];
 	int n;
 
-	if (!(LOG_MASK(LOG_PRI(pri)) & log_mask))
-		return;
-
 	/* Send without name and timestamp, the system logger should add them */
 	n = snprintf(buf, BUFSIZ, "<%i> ", pri);
 
@@ -141,3 +166,200 @@ void passt_vsyslog(int pri, const char *format, va_list ap)
 	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 and 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) {
+		err("Couldn't open log file %s: %s", path, strerror(errno));
+		exit(EXIT_FAILURE);
+	}
+
+	log_size = size ? size : LOGFILE_SIZE_DEFAULT;
+
+	n = snprintf(log_header, sizeof(log_header), "%s: %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
+ * @ts:		Current timestamp
+ *
+ * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek
+ */
+static void logfile_rotate_fallocate(int fd, struct timespec *ts)
+{
+	char buf[BUFSIZ], *nl;
+	int n;
+
+	if (lseek(fd, 0, SEEK_SET) == -1)
+		return;
+	if (read(fd, buf, BUFSIZ) == -1)
+		return;
+
+	n = snprintf(buf, BUFSIZ,
+		     "%s - log truncated at %li.%04li", log_header,
+		     ts->tv_sec - log_start, ts->tv_nsec / (100L * 1000));
+
+	/* Avoid partial lines by padding the header with spaces */
+	nl = memchr(buf + n + 1, '\n', BUFSIZ - n - 1);
+	if (nl)
+		memset(buf + n, ' ', nl - (buf + n));
+
+	if (lseek(fd, 0, SEEK_SET) == -1)
+		return;
+	if (write(fd, buf, BUFSIZ) == -1)
+		return;
+
+	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
+ * @ts:		Current timestamp
+ *
+ * #syscalls lseek ppc64le:_llseek ppc64:_llseek armv6l:_llseek armv7l:_llseek
+ * #syscalls ftruncate
+ */
+static void logfile_rotate_move(int fd, struct timespec *ts)
+{
+	int header_len, write_offset, end, discard, n;
+	char buf[BUFSIZ], *nl;
+
+	header_len = snprintf(buf, BUFSIZ,
+			      "%s - log truncated at %li.%04li\n", log_header,
+			      ts->tv_sec - log_start,
+			      ts->tv_nsec / (100L * 1000));
+	if (lseek(fd, 0, SEEK_SET) == -1)
+		return;
+	if (write(fd, buf, header_len) == -1)
+		return;
+
+	end = write_offset = header_len;
+	discard = log_cut_size + header_len;
+
+	/* Try to cut cleanly at newline */
+	if (lseek(fd, discard, SEEK_SET) == -1)
+		goto out;
+	if ((n = read(fd, buf, BUFSIZ)) <= 0)
+		goto out;
+	if ((nl = memchr(buf, '\n', n)))
+		discard += (nl - buf) + 1;
+
+	/* Go to first block to be moved */
+	if (lseek(fd, discard, SEEK_SET) == -1)
+		goto out;
+
+	while ((n = read(fd, buf, BUFSIZ)) > 0) {
+		end = header_len;
+
+		if (lseek(fd, write_offset, SEEK_SET) == -1)
+			goto out;
+		if ((n = write(fd, buf, n)) == -1)
+			goto out;
+		write_offset += n;
+
+		if ((n = lseek(fd, 0, SEEK_CUR)) == -1)
+			goto out;
+
+		if (lseek(fd, discard - header_len, SEEK_CUR) == -1)
+			goto out;
+
+		end = n;
+	}
+
+out:
+	if (ftruncate(fd, end))
+		return;
+
+	log_written = end;
+}
+
+/**
+ * logfile_rotate() - "Rotate" log file once it's full
+ * @fd:		Log file descriptor
+ * @ts:		Current timestamp
+ *
+ * Return: 0 on success, negative error code on failure
+ *
+ * #syscalls fcntl
+ *
+ * fallocate() passed as EXTRA_SYSCALL only if FALLOC_FL_COLLAPSE_RANGE is there
+ */
+static int logfile_rotate(int fd, struct timespec *ts)
+{
+	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, ts);
+	else
+#endif
+		logfile_rotate_move(fd, ts);
+
+	if (fcntl(fd, F_SETFL, O_RDWR | O_APPEND))
+		return -errno;
+
+	return 0;
+}
+
+/**
+ * logfile_write() - Write entry to log file, trigger rotation if full
+ * @pri:	Facility and level map, same as priority for vsyslog()
+ * @format:	Same as vsyslog() format
+ * @ap:		Same as vsyslog() ap
+ */
+void logfile_write(int pri, const char *format, va_list ap)
+{
+	struct timespec ts;
+	char buf[BUFSIZ];
+	int n;
+
+	if (clock_gettime(CLOCK_REALTIME, &ts))
+		return;
+
+	n = snprintf(buf, BUFSIZ, "%li.%04li: %s",
+		     ts.tv_sec - log_start, ts.tv_nsec / (100L * 1000),
+		     logfile_prefix[pri]);
+
+	n += vsnprintf(buf + n, BUFSIZ - n, format, ap);
+
+	if (format[strlen(format)] != '\n')
+		n += snprintf(buf + n, BUFSIZ - n, "\n");
+
+	if ((log_written + n >= log_size) && logfile_rotate(log_file, &ts))
+		return;
+
+	if ((n = write(log_file, buf, n)) >= 0)
+		log_written += n;
+}