Merge branch 'ensure-log-file-sizes-stay-below-a-certain-threshold-io…

…s-635'
mullvad · May 6, 2024 · 82b1aeb · 82b1aeb
2 parents 957d0bd + 9e909cf
commit 82b1aeb
Show file tree

Hide file tree

Showing 16 changed files with 171 additions and 66 deletions.
diff --git a/ios/MullvadLogging/CustomFormatLogHandler.swift b/ios/MullvadLogging/CustomFormatLogHandler.swift
@@ -16,14 +16,6 @@ public struct CustomFormatLogHandler: LogHandler {
     private let label: String
     private let streams: [TextOutputStream]
 
-    private let dateFormatter = Self.makeDateFormatter()
-
-    public static func makeDateFormatter() -> DateFormatter {
-        let dateFormatter = DateFormatter()
-        dateFormatter.dateFormat = "YYYY-MM-dd HH:mm:ss.SSS"
-        return dateFormatter
-    }
-
     public init(label: String, streams: [TextOutputStream]) {
         self.label = label
         self.streams = streams
@@ -54,7 +46,7 @@ public struct CustomFormatLogHandler: LogHandler {
             }
         let prettyMetadata = Self.formatMetadata(mergedMetadata)
         let metadataOutput = prettyMetadata.isEmpty ? "" : " \(prettyMetadata)"
-        let timestamp = dateFormatter.string(from: Date())
+        let timestamp = Date().logFormatted
         let formattedMessage = "[\(timestamp)][\(label)][\(level)]\(metadataOutput) \(message)\n"
 
         for var stream in streams {

diff --git a/ios/MullvadLogging/Date+LogFormat.swift b/ios/MullvadLogging/Date+LogFormat.swift
@@ -9,16 +9,22 @@
 import Foundation
 
 extension Date {
-    public func logFormatDate() -> String {
+    public var logFormatted: String {
         let formatter = DateFormatter()
+
         formatter.dateFormat = "dd/MM/yyyy @ HH:mm:ss"
+        formatter.locale = Locale(identifier: "en_US_POSIX")
+        formatter.timeZone = TimeZone(abbreviation: "UTC")
 
         return formatter.string(from: self)
     }
 
-    public func logFormatFilename() -> String {
+    public var logFileFormatted: String {
         let formatter = DateFormatter()
+
         formatter.dateFormat = "dd-MM-yyyy'T'HH:mm:ss"
+        formatter.locale = Locale(identifier: "en_US_POSIX")
+        formatter.timeZone = TimeZone(abbreviation: "UTC")
 
         return formatter.string(from: self)
     }

diff --git a/ios/MullvadLogging/LogFileOutputStream.swift b/ios/MullvadLogging/LogFileOutputStream.swift
@@ -16,10 +16,14 @@ private let reopenFileLogInterval: Duration = .seconds(5)
 class LogFileOutputStream: TextOutputStream {
     private let queue = DispatchQueue(label: "LogFileOutputStreamQueue", qos: .utility)
 
-    private let fileURL: URL
+    private let baseFileURL: URL
+    private var fileURL: URL
     private let encoding: String.Encoding
-    private let maxBufferCapacity: Int
+    private let maximumBufferCapacity: Int
     private let fileHeader: String
+    private let fileSizeLimit: UInt64
+    private var partialFileSizeCounter: UInt64 = 0
+    private var partialFileNameCounter = 1
 
     private var state: State = .closed {
         didSet {
@@ -45,11 +49,20 @@ class LogFileOutputStream: TextOutputStream {
         case waitingToReopen
     }
 
-    init(fileURL: URL, header: String, encoding: String.Encoding = .utf8, maxBufferCapacity: Int = 16 * 1024) {
+    init(
+        fileURL: URL,
+        header: String,
+        fileSizeLimit: UInt64 = ApplicationConfiguration.logMaximumFileSize,
+        encoding: String.Encoding = .utf8,
+        maxBufferCapacity: Int = 16 * 1024
+    ) {
         self.fileURL = fileURL
-        self.encoding = encoding
-        self.maxBufferCapacity = maxBufferCapacity
         self.fileHeader = header
+        self.fileSizeLimit = fileSizeLimit
+        self.encoding = encoding
+        self.maximumBufferCapacity = maxBufferCapacity
+
+        baseFileURL = fileURL.deletingPathExtension()
     }
 
     deinit {
@@ -58,11 +71,11 @@ class LogFileOutputStream: TextOutputStream {
 
     func write(_ string: String) {
         queue.async {
-            self.writeNoQueue(string)
+            self.writeOnQueue(string)
         }
     }
 
-    private func writeNoQueue(_ string: String) {
+    private func writeOnQueue(_ string: String) {
         guard let data = string.data(using: encoding) else { return }
 
         switch state {
@@ -89,7 +102,26 @@ class LogFileOutputStream: TextOutputStream {
         }
     }
 
-    @discardableResult private func write(fileHandle: FileHandle, data: Data) throws -> Int {
+    private func write(fileHandle: FileHandle, data: Data) throws {
+        dispatchPrecondition(condition: .onQueue(queue))
+
+        let incomingDataSize = UInt64(data.count)
+
+        // Make sure incoming data chunks are not larger than the file size limit.
+        // Failure to handle this leads to data neither being written nor buffered/trimmed.
+        guard incomingDataSize <= fileSizeLimit else {
+            throw POSIXError(.EDQUOT)
+        }
+
+        let predictedFileSize = partialFileSizeCounter + incomingDataSize
+
+        // Rotate file if threshold has been met, then rerun the write operation.
+        guard predictedFileSize <= fileSizeLimit else {
+            try rotateFile(handle: fileHandle)
+            write(String(data: data, encoding: encoding) ?? "")
+            return
+        }
+
         let bytesWritten = data.withUnsafeBytes { buffer -> Int in
             guard let ptr = buffer.baseAddress else { return 0 }
 
@@ -99,9 +131,17 @@ class LogFileOutputStream: TextOutputStream {
         if bytesWritten == -1 {
             let code = POSIXErrorCode(rawValue: errno)!
             throw POSIXError(code)
-        } else {
-            return bytesWritten
         }
+
+        partialFileSizeCounter += UInt64(bytesWritten)
+    }
+
+    private func rotateFile(handle: FileHandle) throws {
+        try handle.close()
+
+        state = .closed
+        partialFileSizeCounter = 0
+        fileURL = try incrementFileName()
     }
 
     private func openFile() throws -> FileHandle {
@@ -171,8 +211,18 @@ class LogFileOutputStream: TextOutputStream {
     private func bufferData(_ data: Data) {
         buffer.append(data)
 
-        if buffer.count > maxBufferCapacity {
-            buffer.removeFirst(buffer.count - maxBufferCapacity)
+        if buffer.count > maximumBufferCapacity {
+            buffer.removeFirst(buffer.count - maximumBufferCapacity)
+        }
+    }
+
+    private func incrementFileName() throws -> URL {
+        partialFileNameCounter += 1
+
+        if let url = URL(string: baseFileURL.relativePath + "_\(partialFileNameCounter).log") {
+            return url
+        } else {
+            throw POSIXError(.ENOENT)
         }
     }
 }
diff --git a/ios/MullvadLogging/LogRotation.swift b/ios/MullvadLogging/LogRotation.swift
@@ -36,7 +36,7 @@ public enum LogRotation {
         public var errorDescription: String? {
             switch self {
             case .rotateLogFiles:
-                return "Failure to rotate the source log file to backup."
+                return "Failure to rotate logs"
             }
         }
 
@@ -74,30 +74,23 @@ public enum LogRotation {
                 log1.creationDate > log2.creationDate
             }
 
-            try deleteLogsOlderThan(options.oldestAllowedDate, in: logs)
-            try deleteLogsWithCombinedSizeLargerThan(options.storageSizeLimit, in: logs)
+            try deleteLogs(dateThreshold: options.oldestAllowedDate, sizeThreshold: options.storageSizeLimit, in: logs)
         } catch {
             throw Error.rotateLogFiles(error)
         }
     }
 
-    private static func deleteLogsOlderThan(_ dateThreshold: Date, in logs: [LogData]) throws {
+    private static func deleteLogs(dateThreshold: Date, sizeThreshold: Int, in logs: [LogData]) throws {
         let fileManager = FileManager.default
 
-        for log in logs where log.creationDate < dateThreshold {
-            try fileManager.removeItem(at: log.path)
-        }
-    }
-
-    private static func deleteLogsWithCombinedSizeLargerThan(_ sizeThreshold: Int, in logs: [LogData]) throws {
-        let fileManager = FileManager.default
-
-        // Delete all logs outside maximum capacity (ordered newest to oldest).
         var fileSizes = UInt64.zero
         for log in logs {
             fileSizes += log.size
 
-            if fileSizes > sizeThreshold {
+            let logIsTooOld = log.creationDate < dateThreshold
+            let logCapacityIsExceeded = fileSizes > sizeThreshold
+
+            if logIsTooOld || logCapacityIsExceeded {
                 try fileManager.removeItem(at: log.path)
             }
         }

diff --git a/ios/MullvadLogging/Logging.swift b/ios/MullvadLogging/Logging.swift
@@ -78,7 +78,7 @@ public struct LoggerBuilder {
             let rotationLogger = Logger(label: "LogRotation")
 
             for error in logRotationErrors {
-                rotationLogger.error(error: error, message: "Failed to rotate log")
+                rotationLogger.error(error: error, message: error.localizedDescription)
             }
         }
     }

diff --git a/ios/MullvadVPN.xcodeproj/project.pbxproj b/ios/MullvadVPN.xcodeproj/project.pbxproj
@@ -603,6 +603,8 @@
 		7ADCB2D82B6A6EB300C88F89 /* AnyRelay.swift in Sources */ = {isa = PBXBuildFile; fileRef = 7ADCB2D72B6A6EB300C88F89 /* AnyRelay.swift */; };
 		7ADCB2DA2B6A730400C88F89 /* IPOverrideRepositoryStub.swift in Sources */ = {isa = PBXBuildFile; fileRef = 7ADCB2D92B6A730400C88F89 /* IPOverrideRepositoryStub.swift */; };
 		7AE044BB2A935726003915D8 /* Routing.h in Headers */ = {isa = PBXBuildFile; fileRef = 7A88DCD02A8FABBE00D2FF0E /* Routing.h */; settings = {ATTRIBUTES = (Public, ); }; };
+		7AED35CC2BD13F60002A67D1 /* ApplicationConfiguration.swift in Sources */ = {isa = PBXBuildFile; fileRef = 58BFA5CB22A7CE1F00A6173D /* ApplicationConfiguration.swift */; };
+		7AED35CD2BD13FC4002A67D1 /* ApplicationTarget.swift in Sources */ = {isa = PBXBuildFile; fileRef = 58C76A072A33850E00100D75 /* ApplicationTarget.swift */; };
 		7AEF7F1A2AD00F52006FE45D /* AppMessageHandler.swift in Sources */ = {isa = PBXBuildFile; fileRef = 7AEF7F192AD00F52006FE45D /* AppMessageHandler.swift */; };
 		7AF10EB22ADE859200C090B9 /* AlertViewController.swift in Sources */ = {isa = PBXBuildFile; fileRef = 7AF10EB12ADE859200C090B9 /* AlertViewController.swift */; };
 		7AF10EB42ADE85BC00C090B9 /* RelayFilterCoordinator.swift in Sources */ = {isa = PBXBuildFile; fileRef = 7AF10EB32ADE85BC00C090B9 /* RelayFilterCoordinator.swift */; };
@@ -5732,6 +5734,8 @@
 			isa = PBXSourcesBuildPhase;
 			buildActionMask = 2147483647;
 			files = (
+				7AED35CC2BD13F60002A67D1 /* ApplicationConfiguration.swift in Sources */,
+				7AED35CD2BD13FC4002A67D1 /* ApplicationTarget.swift in Sources */,
 				58D22402294C90050029F5F8 /* Logger+Errors.swift in Sources */,
 				58D22404294C90050029F5F8 /* Date+LogFormat.swift in Sources */,
 				58D22403294C90050029F5F8 /* Logging.swift in Sources */,

diff --git a/ios/MullvadVPN/AddressCacheTracker/AddressCacheTracker.swift b/ios/MullvadVPN/AddressCacheTracker/AddressCacheTracker.swift
@@ -65,7 +65,7 @@ final class AddressCacheTracker {
 
         let scheduleDate = _nextScheduleDate()
 
-        logger.debug("Schedule address cache update at \(scheduleDate.logFormatDate()).")
+        logger.debug("Schedule address cache update at \(scheduleDate.logFormatted).")
 
         scheduleEndpointsUpdate(startTime: .now() + scheduleDate.timeIntervalSinceNow)
     }
@@ -165,7 +165,7 @@ final class AddressCacheTracker {
             let scheduleDate = self._nextScheduleDate()
 
             self.logger
-                .debug("Schedule next address cache update at \(scheduleDate.logFormatDate()).")
+                .debug("Schedule next address cache update at \(scheduleDate.logFormatted).")
 
             self.scheduleEndpointsUpdate(startTime: .now() + scheduleDate.timeIntervalSinceNow)
         }

diff --git a/ios/MullvadVPN/AppDelegate.swift b/ios/MullvadVPN/AppDelegate.swift
@@ -307,7 +307,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
             let request = BGAppRefreshTaskRequest(identifier: BackgroundTask.appRefresh.identifier)
             request.earliestBeginDate = date
 
-            logger.debug("Schedule app refresh task at \(date.logFormatDate()).")
+            logger.debug("Schedule app refresh task at \(date.logFormatted).")
 
             try BGTaskScheduler.shared.submit(request)
         } catch {
@@ -325,7 +325,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
             request.requiresNetworkConnectivity = true
             request.earliestBeginDate = date
 
-            logger.debug("Schedule key rotation task at \(date.logFormatDate()).")
+            logger.debug("Schedule key rotation task at \(date.logFormatted).")
 
             try BGTaskScheduler.shared.submit(request)
         } catch {
@@ -341,7 +341,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate, UNUserNotificationCenterD
             request.requiresNetworkConnectivity = true
             request.earliestBeginDate = date
 
-            logger.debug("Schedule address cache update task at \(date.logFormatDate()).")
+            logger.debug("Schedule address cache update task at \(date.logFormatted).")
 
             try BGTaskScheduler.shared.submit(request)
         } catch {

diff --git a/ios/MullvadVPN/Classes/ConsolidatedApplicationLog.swift b/ios/MullvadVPN/Classes/ConsolidatedApplicationLog.swift
@@ -8,7 +8,6 @@
 
 import Foundation
 
-private let kLogMaxReadBytes: UInt64 = 128 * 1024
 private let kLogDelimiter = "===================="
 private let kRedactedPlaceholder = "[REDACTED]"
 private let kRedactedAccountPlaceholder = "[REDACTED ACCOUNT NUMBER]"
@@ -93,7 +92,7 @@ class ConsolidatedApplicationLog: TextOutputStreamable {
         let path = fileURL.path
         let redactedPath = redact(string: path)
 
-        if let lossyString = Self.readFileLossy(path: path, maxBytes: kLogMaxReadBytes) {
+        if let lossyString = Self.readFileLossy(path: path, maxBytes: ApplicationConfiguration.logMaximumFileSize) {
             let redactedString = redact(string: lossyString)
 
             logs.append(LogAttachment(label: redactedPath, content: redactedString))
@@ -126,7 +125,7 @@ class ConsolidatedApplicationLog: TextOutputStreamable {
             fileHandle.seek(toFileOffset: 0)
         }
 
-        let data = fileHandle.readData(ofLength: Int(kLogMaxReadBytes))
+        let data = fileHandle.readData(ofLength: Int(ApplicationConfiguration.logMaximumFileSize))
         let replacementCharacter = Character(UTF8.decode(UTF8.encodedReplacementCharacter))
         let lossyString = String(
             String(decoding: data, as: UTF8.self)

diff --git a/ios/MullvadVPN/StorePaymentManager/SendStoreReceiptOperation.swift b/ios/MullvadVPN/StorePaymentManager/SendStoreReceiptOperation.swift
@@ -140,7 +140,7 @@ class SendStoreReceiptOperation: ResultOperation<REST.CreateApplePaymentResponse
                     """
                     AppStore receipt was processed. \
                     Time added: \(response.timeAdded), \
-                    New expiry: \(response.newExpiry.logFormatDate())
+                    New expiry: \(response.newExpiry.logFormatted)
                     """
                 )
                 self.finish(result: .success(response))

diff --git a/ios/MullvadVPN/TunnelManager/TunnelManager.swift b/ios/MullvadVPN/TunnelManager/TunnelManager.swift
@@ -172,7 +172,7 @@ final class TunnelManager: StorePaymentObserver {
 
         privateKeyRotationTimer = timer
 
-        logger.debug("Schedule next private key rotation at \(scheduleDate.logFormatDate()).")
+        logger.debug("Schedule next private key rotation at \(scheduleDate.logFormatted).")
     }
 
     // MARK: - Public methods

diff --git a/ios/MullvadVPN/View controllers/ProblemReport/ProblemReportInteractor.swift b/ios/MullvadVPN/View controllers/ProblemReport/ProblemReportInteractor.swift
@@ -30,6 +30,10 @@ final class ProblemReportInteractor {
         return report
     }()
 
+    var reportString: String {
+        consolidatedLog.string
+    }
+
     init(apiProxy: APIQuerying, tunnelManager: TunnelManager) {
         self.apiProxy = apiProxy
         self.tunnelManager = tunnelManager
@@ -55,8 +59,4 @@ final class ProblemReportInteractor {
             completionHandler: completion
         )
     }
-
-    var reportString: String {
-        consolidatedLog.string
-    }
 }