ringlogger: support mpsc for singlefile

Signed-off-by: Jason A. Donenfeld <Jason@zx2c4.com>

5 files changed, 154 insertions, 75 deletions

diff --git a/WireGuard/Shared/FileManager+Extension.swift b/WireGuard/Shared/FileManager+Extension.swift
index edd764f..d52ec0b 100644
--- a/WireGuard/Shared/FileManager+Extension.swift
+++ b/WireGuard/Shared/FileManager+Extension.swift
@@ -27,7 +27,7 @@ extension FileManager {
         return sharedFolderURL
     }
 
-    static var networkExtensionLogFileURL: URL? {
+    static var logFileURL: URL? {
         return sharedFolderURL?.appendingPathComponent("tunnel-log.bin")
     }
 
@@ -35,14 +35,6 @@ extension FileManager {
         return sharedFolderURL?.appendingPathComponent("last-error.txt")
     }
 
-    static var appLogFileURL: URL? {
-        guard let documentDirURL = FileManager.default.urls(for: .cachesDirectory, in: .userDomainMask).first else {
-            wg_log(.error, message: "Cannot obtain app documents folder URL")
-            return nil
-        }
-        return documentDirURL.appendingPathComponent("app-log.bin")
-    }
-
     static func deleteFile(at url: URL) -> Bool {
         do {
             try FileManager.default.removeItem(at: url)
diff --git a/WireGuard/Shared/Logging/Logger.swift b/WireGuard/Shared/Logging/Logger.swift
index 23cc719..345fc10 100644
--- a/WireGuard/Shared/Logging/Logger.swift
+++ b/WireGuard/Shared/Logging/Logger.swift
@@ -12,10 +12,12 @@ public class Logger {
     static var global: Logger?
 
     var log: OpaquePointer
+    var tag: String
 
-    init(withFilePath filePath: String) throws {
+    init(tagged tag: String, withFilePath filePath: String) throws {
         guard let log = open_log(filePath) else { throw LoggerError.openFailure }
         self.log = log
+        self.tag = tag
     }
 
     deinit {
@@ -23,17 +25,14 @@ public class Logger {
     }
 
     func log(message: String) {
-        write_msg_to_log(log, message.trimmingCharacters(in: .newlines))
+        write_msg_to_log(log, tag, message.trimmingCharacters(in: .newlines))
     }
 
-    func writeLog(called ourTag: String, mergedWith otherLogFile: String, called otherTag: String, to targetFile: String) -> Bool {
-        guard let other = open_log(otherLogFile) else { return false }
-        let ret = write_logs_to_file(targetFile, log, ourTag, other, otherTag)
-        close_log(other)
-        return ret == 0
+    func writeLog(to targetFile: String) -> Bool {
+        return write_log_to_file(targetFile, self.log) == 0
     }
 
-    static func configureGlobal(withFilePath filePath: String?) {
+    static func configureGlobal(tagged tag: String, withFilePath filePath: String?) {
         if Logger.global != nil {
             return
         }
@@ -41,7 +40,7 @@ public class Logger {
             os_log("Unable to determine log destination path. Log will not be saved to file.", log: OSLog.default, type: .error)
             return
         }
-        guard let logger = try? Logger(withFilePath: filePath) else {
+        guard let logger = try? Logger(tagged: tag, withFilePath: filePath) else {
             os_log("Unable to open log file for writing. Log will not be saved to file.", log: OSLog.default, type: .error)
             return
         }
@@ -52,7 +51,6 @@ public class Logger {
         }
         let goBackendVersion = WIREGUARD_GO_VERSION
         Logger.global?.log(message: "App version: \(appVersion); Go backend version: \(goBackendVersion)")
-
     }
 }
 
diff --git a/WireGuard/Shared/Logging/ringlogger.c b/WireGuard/Shared/Logging/ringlogger.c
index fcdc19d..440a269 100644
--- a/WireGuard/Shared/Logging/ringlogger.c
+++ b/WireGuard/Shared/Logging/ringlogger.c
@@ -6,6 +6,8 @@
 #include <string.h>
 #include <stdio.h>
 #include <stdint.h>
+#include <stdlib.h>
+#include <stdatomic.h>
 #include <stdbool.h>
 #include <time.h>
 #include <errno.h>
@@ -19,100 +21,121 @@
 
 enum {
 	MAX_LOG_LINE_LENGTH = 512,
-	MAX_LINES = 1024,
-	MAGIC = 0xbeefbabeU
+	MAX_LINES = 2048,
+	MAGIC = 0xabadbeefU
 };
 
 struct log_line {
-	struct timeval tv;
+	atomic_uint_fast64_t time_ns;
 	char line[MAX_LOG_LINE_LENGTH];
 };
 
 struct log {
-	struct { uint32_t first, len; } header;
+	atomic_uint_fast32_t next_index;
 	struct log_line lines[MAX_LINES];
 	uint32_t magic;
 };
 
-void write_msg_to_log(struct log *log, const char *msg)
+void write_msg_to_log(struct log *log, const char *tag, const char *msg)
 {
-	struct log_line *line = &log->lines[(log->header.first + log->header.len) % MAX_LINES];
+	uint32_t index;
+	struct log_line *line;
+	struct timespec ts;
 
-	if (log->header.len == MAX_LINES)
-		log->header.first = (log->header.first + 1) % MAX_LINES;
-	else
-		++log->header.len;
+	clock_gettime(CLOCK_REALTIME, &ts);
 
-	gettimeofday(&line->tv, NULL);
-	strncpy(line->line, msg, MAX_LOG_LINE_LENGTH - 1);
-	line->line[MAX_LOG_LINE_LENGTH - 1] = '\0';
+	index = atomic_fetch_add(&log->next_index, 1);
+	line = &log->lines[index % MAX_LINES];
 
-	msync(&log->header, sizeof(log->header), MS_ASYNC);
-	msync(line, sizeof(*line), MS_ASYNC);
-}
+	atomic_store(&line->time_ns, 0);
+	memset(line->line, 0, MAX_LOG_LINE_LENGTH);
 
-static bool first_before_second(const struct log_line *line1, const struct log_line *line2)
-{
-	if (line1->tv.tv_sec <= line2->tv.tv_sec)
-		return true;
-	if (line1->tv.tv_sec == line2->tv.tv_sec)
-		return line1->tv.tv_usec <= line2->tv.tv_usec;
-	return false;
+	snprintf(line->line, MAX_LOG_LINE_LENGTH, "[%s] %s", tag, msg);
+	atomic_store(&line->time_ns, ts.tv_sec * 1000000000ULL + ts.tv_nsec);
+
+	msync(&log->next_index, sizeof(log->next_index), MS_ASYNC);
+	msync(line, sizeof(*line), MS_ASYNC);
 }
 
-int write_logs_to_file(const char *file_name, const struct log *log1, const char *tag1, const struct log *log2, const char *tag2)
+int write_log_to_file(const char *file_name, const struct log *input_log)
 {
-	uint32_t i1, i2, len1 = log1->header.len, len2 = log2->header.len;
+	struct log *log;
+	uint32_t l, i;
 	FILE *file;
 	int ret;
 
-	if (len1 > MAX_LINES)
-		len1 = MAX_LINES;
-	if (len2 > MAX_LINES)
-		len2 = MAX_LINES;
+	log = malloc(sizeof(*log));
+	if (!log)
+		return -errno;
+	memcpy(log, input_log, sizeof(*log));
 
 	file = fopen(file_name, "w");
-	if (!file)
+	if (!file) {
+		free(log);
 		return -errno;
+	}
 
-	for (i1 = 0, i2 = 0;;) {
+	for (l = 0, i = log->next_index; l < MAX_LINES; ++l, ++i) {
+		const struct log_line *line = &log->lines[i % MAX_LINES];
+		time_t seconds = line->time_ns / 1000000000ULL;
+		uint32_t useconds = (line->time_ns % 1000000000ULL) / 1000ULL;
 		struct tm tm;
-		char buf[MAX_LOG_LINE_LENGTH];
-		const struct log_line *line1 = &log1->lines[(log1->header.first + i1) % MAX_LINES];
-		const struct log_line *line2 = &log2->lines[(log2->header.first + i2) % MAX_LINES];
-		const struct log_line *line;
-		const char *tag;
-
-		if (i1 < len1 && (i2 >= len2 || first_before_second(line1, line2))) {
-			line = line1;
-			tag = tag1;
-			++i1;
-		} else if (i2 < len2 && (i1 >= len1 || first_before_second(line2, line1))) {
-			line = line2;
-			tag = tag2;
-			++i2;
-		} else {
-			break;
-		}
 
-		memcpy(buf, line->line, MAX_LOG_LINE_LENGTH);
-		buf[MAX_LOG_LINE_LENGTH - 1] = '\0';
-		if (!localtime_r(&line->tv.tv_sec, &tm))
+		if (!line->time_ns)
+			continue;
+
+		if (!localtime_r(&seconds, &tm))
 			goto err;
-		if (fprintf(file, "%04d-%02d-%02d %02d:%02d:%02d.%06d: [%s] %s\n",
+
+		if (fprintf(file, "%04d-%02d-%02d %02d:%02d:%02d.%06d: %s\n",
 				  tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
-				  tm.tm_hour, tm.tm_min, tm.tm_sec, line->tv.tv_usec,
-				  tag, buf) < 0)
+				  tm.tm_hour, tm.tm_min, tm.tm_sec, useconds,
+				  line->line) < 0)
 			goto err;
+
+
 	}
 	errno = 0;
 
 err:
 	ret = -errno;
 	fclose(file);
+	free(log);
 	return ret;
 }
 
+uint32_t view_lines_from_cursor(const struct log *input_log, uint32_t cursor, void(*cb)(const char *, uint64_t))
+{
+	struct log *log;
+	uint32_t l, i = cursor;
+
+	log = malloc(sizeof(*log));
+	if (!log)
+		return cursor;
+	memcpy(log, input_log, sizeof(*log));
+
+	if (i == -1)
+		i = log->next_index;
+
+	for (l = 0; l < MAX_LINES; ++l, ++i) {
+		const struct log_line *line = &log->lines[i % MAX_LINES];
+
+		if (cursor != -1 && i % MAX_LINES == log->next_index % MAX_LINES)
+			break;
+
+		if (!line->time_ns) {
+			if (cursor == -1)
+				continue;
+			else
+				break;
+		}
+		cb(line->line, line->time_ns);
+		cursor = (i + 1) % MAX_LINES;
+	}
+	free(log);
+	return cursor;
+}
+
 struct log *open_log(const char *file_name)
 {
 	int fd;
diff --git a/WireGuard/Shared/Logging/ringlogger.h b/WireGuard/Shared/Logging/ringlogger.h
index 0ee202d..7f5b074 100644
--- a/WireGuard/Shared/Logging/ringlogger.h
+++ b/WireGuard/Shared/Logging/ringlogger.h
@@ -6,9 +6,12 @@
 #ifndef RINGLOGGER_H
 #define RINGLOGGER_H
 
+#include <stdint.h>
+
 struct log;
-void write_msg_to_log(struct log *log, const char *msg);
-int write_logs_to_file(const char *file_name, const struct log *log1, const char *tag1, const struct log *log2, const char *tag2);
+void write_msg_to_log(struct log *log, const char *tag, const char *msg);
+int write_log_to_file(const char *file_name, const struct log *input_log);
+uint32_t view_lines_from_cursor(const struct log *input_log, uint32_t cursor, void(*)(const char *, uint64_t));
 struct log *open_log(const char *file_name);
 void close_log(struct log *log);
 
diff --git a/WireGuard/Shared/Logging/test_ringlogger.c b/WireGuard/Shared/Logging/test_ringlogger.c
new file mode 100644
index 0000000..ae3f4a9
--- /dev/null
+++ b/WireGuard/Shared/Logging/test_ringlogger.c
@@ -0,0 +1,63 @@
+#include "ringlogger.h"
+#include <stdio.h>
+#include <stdbool.h>
+#include <string.h>
+#include <unistd.h>
+#include <inttypes.h>
+#include <sys/wait.h>
+
+static void forkwrite(void)
+{
+	struct log *log = open_log("/tmp/test_log");
+	char c[512];
+	int i, base;
+	bool in_fork = !fork();
+
+	base = 10000 * in_fork;
+	for (i = 0; i < 1024; ++i) {
+		snprintf(c, 512, "bla bla bla %d", base + i);
+		write_msg_to_log(log, "HMM", c);
+	}
+
+
+	if (in_fork)
+		_exit(0);
+	wait(NULL);
+
+	write_log_to_file("/dev/stdout", log);
+	close_log(log);
+}
+
+static void writetext(const char *text)
+{
+	struct log *log = open_log("/tmp/test_log");
+	write_msg_to_log(log, "TXT", text);
+	close_log(log);
+}
+
+static void show_line(const char *line, uint64_t time_ns)
+{
+	printf("%" PRIu64 ": %s\n", time_ns, line);
+}
+
+static void follow(void)
+{
+	uint32_t cursor = -1;
+	struct log *log = open_log("/tmp/test_log");
+
+	for (;;) {
+		cursor = view_lines_from_cursor(log, cursor, show_line);
+		usleep(1000 * 300);
+	}
+}
+
+int main(int argc, char *argv[])
+{
+	if (!strcmp(argv[1], "fork"))
+		forkwrite();
+	else if (!strcmp(argv[1], "write"))
+		writetext(argv[2]);
+	else if (!strcmp(argv[1], "follow"))
+		follow();
+	return 0;
+}