Buffer messages and attempt to reopen log file descriptor on failure

This should cover the case where log file cannot be open on boot when file system is still locked (until the first device unlock)

4 files changed, 174 insertions, 103 deletions

diff --git a/ios/MullvadLogging/LogFileOutputStream.swift b/ios/MullvadLogging/LogFileOutputStream.swift
new file mode 100644
index 0000000000..0ffd434c65
--- /dev/null
+++ b/ios/MullvadLogging/LogFileOutputStream.swift
@@ -0,0 +1,168 @@
+//
+//  LogFileOutputStream.swift
+//  MullvadVPN
+//
+//  Created by pronebird on 02/08/2020.
+//  Copyright © 2020 Mullvad VPN AB. All rights reserved.
+//
+
+import Foundation
+
+/// Interval used for reopening the log file descriptor in the event of failure to open it in
+/// the first place, or when writing to it.
+private let reopenFileLogInterval: TimeInterval = 5
+
+class LogFileOutputStream: TextOutputStream {
+    private let queue = DispatchQueue(label: "LogFileOutputStreamQueue", qos: .utility)
+
+    private let fileURL: URL
+    private let encoding: String.Encoding
+    private let maxBufferCapacity: Int
+
+    private var state: State = .closed {
+        didSet {
+            switch (oldValue, state) {
+            case (.opened, .waitingToReopen), (.closed, .waitingToReopen):
+                startTimer()
+
+            case (.waitingToReopen, .opened), (.waitingToReopen, .closed):
+                stopTimer()
+
+            default:
+                break
+            }
+        }
+    }
+
+    private var timer: DispatchSourceTimer?
+    private var buffer = Data()
+
+    private enum State {
+        case closed
+        case opened(FileHandle)
+        case waitingToReopen
+    }
+
+    init(fileURL: URL, encoding: String.Encoding = .utf8, maxBufferCapacity: Int = 16 * 1024) {
+        self.fileURL = fileURL
+        self.encoding = encoding
+        self.maxBufferCapacity = maxBufferCapacity
+    }
+
+    deinit {
+        stopTimer()
+    }
+
+    func write(_ string: String) {
+        queue.async {
+            self.writeNoQueue(string)
+        }
+    }
+
+    private func writeNoQueue(_ string: String) {
+        guard let data = string.data(using: encoding) else { return }
+
+        switch state {
+        case .closed:
+            do {
+                let fileHandle = try openFile()
+                state = .opened(fileHandle)
+                try write(fileHandle: fileHandle, data: data)
+            } catch {
+                bufferData(data)
+                state = .waitingToReopen
+            }
+
+        case let .opened(fileHandle):
+            do {
+                try write(fileHandle: fileHandle, data: data)
+            } catch {
+                bufferData(data)
+                state = .waitingToReopen
+            }
+
+        case .waitingToReopen:
+            bufferData(data)
+        }
+    }
+
+    @discardableResult private func write(fileHandle: FileHandle, data: Data) throws -> Int {
+        let bytesWritten = data.withUnsafeBytes { buffer -> Int in
+            guard let ptr = buffer.baseAddress else { return 0 }
+
+            return Darwin.write(fileHandle.fileDescriptor, ptr, buffer.count)
+        }
+
+        if bytesWritten == -1 {
+            let code = POSIXErrorCode(rawValue: errno)!
+            throw POSIXError(code)
+        } else {
+            return bytesWritten
+        }
+    }
+
+    private func openFile() throws -> FileHandle {
+        let oflag: Int32 = O_WRONLY | O_CREAT
+        let mode: mode_t = S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH
+
+        let fd = fileURL.path.withCString { Darwin.open($0, oflag, mode) }
+
+        if fd == -1 {
+            let code = POSIXErrorCode(rawValue: errno)!
+            throw POSIXError(code)
+        } else {
+            return FileHandle(fileDescriptor: fd, closeOnDealloc: true)
+        }
+    }
+
+    private func startTimer() {
+        timer?.cancel()
+
+        let timer = DispatchSource.makeTimerSource(queue: queue)
+        timer.setEventHandler { [weak self] in
+            self?.reopenFile()
+        }
+        timer.schedule(
+            wallDeadline: .now() + reopenFileLogInterval,
+            repeating: reopenFileLogInterval
+        )
+        timer.activate()
+
+        self.timer = timer
+    }
+
+    private func stopTimer() {
+        timer?.cancel()
+        timer = nil
+    }
+
+    private func reopenFile() {
+        do {
+            let fileHandle = try openFile()
+
+            // Write a message indicating that the file was reopened.
+            let messageData =
+                "<Log file re-opened after failure. Buffered \(buffer.count) bytes of messages>\n"
+                    .data(using: encoding, allowLossyConversion: true)!
+            try write(fileHandle: fileHandle, data: messageData)
+
+            // Write all buffered messages.
+            if !buffer.isEmpty {
+                try write(fileHandle: fileHandle, data: buffer)
+                buffer.removeAll()
+            }
+
+            state = .opened(fileHandle)
+        } catch {
+            state = .waitingToReopen
+        }
+    }
+
+    private func bufferData(_ data: Data) {
+        buffer.append(data)
+
+        if buffer.count > maxBufferCapacity {
+            buffer.removeFirst(buffer.count - maxBufferCapacity)
+        }
+    }
+}
diff --git a/ios/MullvadLogging/Logging.swift b/ios/MullvadLogging/Logging.swift
index b13328999a..be5c46b08b 100644
--- a/ios/MullvadLogging/Logging.swift
+++ b/ios/MullvadLogging/Logging.swift
@@ -10,7 +10,7 @@ import Foundation
 @_exported import Logging
 
 private enum LoggerOutput {
-    case fileOutput(_ fileOutput: TextOutputStream)
+    case fileOutput(_ fileOutput: LogFileOutputStream)
     case osLogOutput(_ subsystem: String)
 }
 
@@ -20,12 +20,6 @@ public struct MissingSharedContainerError: LocalizedError {
     }
 }
 
-public struct OpenFileStreamError: LocalizedError {
-    public var errorDescription: String? {
-        return "Failed to open file stream."
-    }
-}
-
 public struct LoggerBuilder {
     private(set) var logRotationErrors: [Error] = []
     private var outputs: [LoggerOutput] = []
@@ -57,11 +51,7 @@ public struct LoggerBuilder {
             logRotationErrors.append(error)
         }
 
-        if let outputStream = TextFileOutputStream(fileURL: logFileURL, createFile: true) {
-            outputs.append(.fileOutput(outputStream))
-        } else {
-            throw OpenFileStreamError()
-        }
+        outputs.append(.fileOutput(LogFileOutputStream(fileURL: logFileURL)))
     }
 
     public mutating func addOSLogOutput(subsystem: String) {
diff --git a/ios/MullvadLogging/TextFileOutputStream.swift b/ios/MullvadLogging/TextFileOutputStream.swift
deleted file mode 100644
index 95387b53ec..0000000000
--- a/ios/MullvadLogging/TextFileOutputStream.swift
+++ /dev/null
@@ -1,87 +0,0 @@
-//
-//  TextFileOutputStream.swift
-//  MullvadVPN
-//
-//  Created by pronebird on 02/08/2020.
-//  Copyright © 2020 Mullvad VPN AB. All rights reserved.
-//
-
-import Foundation
-
-class TextFileOutputStream: TextOutputStream {
-    private let writer: DispatchIO
-    private let encoding: String.Encoding
-    private let queue = DispatchQueue.global(qos: .utility)
-
-    class func standardOutputStream(encoding: String.Encoding = .utf8) -> TextFileOutputStream {
-        return TextFileOutputStream(
-            fileDescriptor: FileHandle.standardOutput.fileDescriptor,
-            encoding: encoding
-        )
-    }
-
-    init(fileDescriptor: Int32, encoding: String.Encoding = .utf8) {
-        self.encoding = encoding
-        writer = DispatchIO(type: .stream, fileDescriptor: fileDescriptor, queue: queue) { errno in
-            if errno != 0 {
-                print("TextFileOutputStream: closed channel with error: \(errno)")
-            }
-        }
-    }
-
-    init?(
-        fileURL: URL,
-        createFile: Bool,
-        filePermissions: mode_t = S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH,
-        encoding: String.Encoding = .utf8
-    ) {
-        var oflag: Int32 = O_WRONLY
-        var mode: mode_t = .zero
-        if createFile {
-            oflag |= O_CREAT
-            mode = filePermissions
-        }
-
-        let queue = queue
-        let writer = fileURL.path.withCString { filePathPointer -> DispatchIO? in
-            return DispatchIO(
-                type: .stream,
-                path: filePathPointer,
-                oflag: oflag,
-                mode: mode,
-                queue: queue,
-                cleanupHandler: { errno in
-                    if errno != 0 {
-                        print("TextFileOutputStream: closed channel with error: \(errno)")
-                    }
-                }
-            )
-        }
-
-        if let writer = writer {
-            self.writer = writer
-            self.encoding = encoding
-        } else {
-            return nil
-        }
-    }
-
-    deinit {
-        writer.close()
-    }
-
-    func write(_ string: String) {
-        string.data(using: encoding)?.withUnsafeBytes { bytes in
-            writer
-                .write(
-                    offset: .zero,
-                    data: DispatchData(bytes: bytes),
-                    queue: queue
-                ) { done, data, errno in
-                    if errno != 0 {
-                        print("TextFileOutputStream: write error: \(errno)")
-                    }
-                }
-        }
-    }
-}
diff --git a/ios/MullvadVPN.xcodeproj/project.pbxproj b/ios/MullvadVPN.xcodeproj/project.pbxproj
index b4d42f55c9..44ab78144f 100644
--- a/ios/MullvadVPN.xcodeproj/project.pbxproj
+++ b/ios/MullvadVPN.xcodeproj/project.pbxproj
@@ -274,7 +274,7 @@
 		58D223F9294C8FF00029F5F8 /* MullvadLogging.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 58D223F3294C8FF00029F5F8 /* MullvadLogging.framework */; };
 		58D223FA294C8FF10029F5F8 /* MullvadLogging.framework in Embed Frameworks */ = {isa = PBXBuildFile; fileRef = 58D223F3294C8FF00029F5F8 /* MullvadLogging.framework */; settings = {ATTRIBUTES = (CodeSignOnCopy, RemoveHeadersOnCopy, ); }; };
 		58D223FE294C90050029F5F8 /* Error+LogFormat.swift in Sources */ = {isa = PBXBuildFile; fileRef = 581943E128F8010300B0CB5E /* Error+LogFormat.swift */; };
-		58D223FF294C90050029F5F8 /* TextFileOutputStream.swift in Sources */ = {isa = PBXBuildFile; fileRef = 581943DE28F8010300B0CB5E /* TextFileOutputStream.swift */; };
+		58D223FF294C90050029F5F8 /* LogFileOutputStream.swift in Sources */ = {isa = PBXBuildFile; fileRef = 581943DE28F8010300B0CB5E /* LogFileOutputStream.swift */; };
 		58D22400294C90050029F5F8 /* OSLogHandler.swift in Sources */ = {isa = PBXBuildFile; fileRef = 581943E428F8010400B0CB5E /* OSLogHandler.swift */; };
 		58D22401294C90050029F5F8 /* CustomFormatLogHandler.swift in Sources */ = {isa = PBXBuildFile; fileRef = 581943E328F8010400B0CB5E /* CustomFormatLogHandler.swift */; };
 		58D22402294C90050029F5F8 /* Logger+Errors.swift in Sources */ = {isa = PBXBuildFile; fileRef = 581943E028F8010300B0CB5E /* Logger+Errors.swift */; };
@@ -659,7 +659,7 @@
 		581813A428E09DE2002817DE /* BlockCondition.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = BlockCondition.swift; sourceTree = "<group>"; };
 		581813A628E09DF2002817DE /* MutuallyExclusive.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = MutuallyExclusive.swift; sourceTree = "<group>"; };
 		581943DD28F8010300B0CB5E /* LogRotation.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = LogRotation.swift; sourceTree = "<group>"; };
-		581943DE28F8010300B0CB5E /* TextFileOutputStream.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = TextFileOutputStream.swift; sourceTree = "<group>"; };
+		581943DE28F8010300B0CB5E /* LogFileOutputStream.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = LogFileOutputStream.swift; sourceTree = "<group>"; };
 		581943DF28F8010300B0CB5E /* Logging.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = Logging.swift; sourceTree = "<group>"; };
 		581943E028F8010300B0CB5E /* Logger+Errors.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = "Logger+Errors.swift"; sourceTree = "<group>"; };
 		581943E128F8010300B0CB5E /* Error+LogFormat.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = "Error+LogFormat.swift"; sourceTree = "<group>"; };
@@ -1561,7 +1561,7 @@
 				581943DF28F8010300B0CB5E /* Logging.swift */,
 				581943DD28F8010300B0CB5E /* LogRotation.swift */,
 				581943E428F8010400B0CB5E /* OSLogHandler.swift */,
-				581943DE28F8010300B0CB5E /* TextFileOutputStream.swift */,
+				581943DE28F8010300B0CB5E /* LogFileOutputStream.swift */,
 			);
 			path = MullvadLogging;
 			sourceTree = "<group>";
@@ -2545,7 +2545,7 @@
 				58D22404294C90050029F5F8 /* Date+LogFormat.swift in Sources */,
 				58D22403294C90050029F5F8 /* Logging.swift in Sources */,
 				58D223FE294C90050029F5F8 /* Error+LogFormat.swift in Sources */,
-				58D223FF294C90050029F5F8 /* TextFileOutputStream.swift in Sources */,
+				58D223FF294C90050029F5F8 /* LogFileOutputStream.swift in Sources */,
 				58D22400294C90050029F5F8 /* OSLogHandler.swift in Sources */,
 				58D22405294C90050029F5F8 /* LogRotation.swift in Sources */,
 				58D22401294C90050029F5F8 /* CustomFormatLogHandler.swift in Sources */,