Logging improvements, incorrect version number fix

LibSession-Util

@@ -1 +1 @@
-Subproject commit dfcd3ae009dd68b8ca9f32a8b1fe5da46b793c99
+Subproject commit c0cf732e1e64451476d39e1ee79547e56dcfd2e8

Scripts/LintLocalizableStrings.swift

@@ -44,6 +44,7 @@ extension ProjectState {
         .contains("Log.warn(", caseSensitive: false),
         .contains("Log.error(", caseSensitive: false),
         .contains("Log.critical(", caseSensitive: false),
+        .contains("Log.Category =", caseSensitive: false),
         .contains("logMessage:", caseSensitive: false),
         .contains("owsFailDebug(", caseSensitive: false),
         .contains("#imageLiteral(resourceName:", caseSensitive: false),

Session.xcodeproj/xcshareddata/xcschemes/Session.xcscheme

@@ -205,11 +205,6 @@
          </BuildableReference>
       </BuildableProductRunnable>
       <EnvironmentVariables>
-         <EnvironmentVariable
-            key = "OS_ACTIVITY_MODE"
-            value = "disable"
-            isEnabled = "YES">
-         </EnvironmentVariable>
          <EnvironmentVariable
             key = "UBSAN_OPTIONS"
             value = "suppressions=SignalUBSan.supp"
@@ -225,6 +220,11 @@
             value = "1"
             isEnabled = "YES">
          </EnvironmentVariable>
+         <EnvironmentVariable
+            key = "IDEPreferLogStreaming"
+            value = "YES"
+            isEnabled = "YES">
+         </EnvironmentVariable>
       </EnvironmentVariables>
    </LaunchAction>
    <ProfileAction

Session/Settings/Views/VersionFooterView.swift

@@ -16,7 +16,7 @@ class VersionFooterView: UIView {
         )
         result.setContentHuggingPriority(.required, for: .vertical)
         result.setContentCompressionResistancePriority(.required, for: .vertical)
-        result.themeTintColor = .textSecondary// .value(.textPrimary, alpha: Values.mediumOpacity)
+        result.themeTintColor = .textSecondary
         result.contentMode = .scaleAspectFit
         result.set(.height, to: VersionFooterView.logoHeight)
         
@@ -28,14 +28,14 @@ class VersionFooterView: UIView {
         result.setContentHuggingPriority(.required, for: .vertical)
         result.setContentCompressionResistancePriority(.required, for: .vertical)
         result.font = .systemFont(ofSize: Values.verySmallFontSize)
-        result.themeTextColor = .textSecondary//.value(.textPrimary, alpha: Values.mediumOpacity)
+        result.themeTextColor = .textSecondary
         result.textAlignment = .center
         result.lineBreakMode = .byCharWrapping
         result.numberOfLines = 0
         
         let infoDict = Bundle.main.infoDictionary
         let version: String = ((infoDict?["CFBundleShortVersionString"] as? String) ?? "0.0.0")   // stringlint:disable
-        let buildNumber: String? = (infoDict?["CFBundleShortVersionString"] as? String)           // stringlint:disable
+        let buildNumber: String? = (infoDict?["CFBundleVersion"] as? String)                      // stringlint:disable
         let commitInfo: String? = (infoDict?["GitCommitHash"] as? String)                         // stringlint:disable
         let buildInfo: String = [buildNumber, commitInfo]
             .compactMap { $0 }

SessionMessagingKit/Database/Migrations/_003_YDBToGRDBMigration.swift

@@ -19,7 +19,7 @@ enum _003_YDBToGRDBMigration: Migration {
             Identity.userExists(db)
         else { return Storage.update(progress: 1, for: self, in: target) }
         
-        Log.info("[Migration Error] Attempted to perform legacy migation", silenceForTests: true)
+        Log.info("[Migration Error] Attempted to perform legacy migation")
         throw StorageError.migrationNoLongerSupported
     }
 }

SessionSnodeKit/Database/Migrations/_003_YDBToGRDBMigration.swift

@@ -19,7 +19,7 @@ enum _003_YDBToGRDBMigration: Migration {
             Identity.userExists(db)
         else { return Storage.update(progress: 1, for: self, in: target) }
         
-        Log.info("[Migration Error] Attempted to perform legacy migation", silenceForTests: true)
+        Log.info("[Migration Error] Attempted to perform legacy migation")
         throw StorageError.migrationNoLongerSupported
     }
 }

SessionUtilitiesKit/Database/Migrations/_003_YDBToGRDBMigration.swift

@@ -18,7 +18,7 @@ enum _003_YDBToGRDBMigration: Migration {
             Identity.userExists(db)
         else { return Storage.update(progress: 1, for: self, in: target) }
         
-        Log.info("[Migration Error] Attempted to perform legacy migation", silenceForTests: true)
+        Log.error("[Migration] Attempted to perform legacy migation")
         throw StorageError.migrationNoLongerSupported
     }
 }

SessionUtilitiesKit/Database/Storage.swift

@@ -481,8 +481,8 @@ open class Storage {
                     $0.invalidate()
                     
                     // Don't want to log on the main thread as to avoid confusion when debugging issues
-                    DispatchQueue.global(qos: .default).async {
+                    DispatchQueue.global(qos: .background).async {
-                        SNLog("[Storage\(fileName)] Slow \(actionName) taking longer than \(Storage.writeWarningThreadshold, format: ".2", omitZeroDecimal: true)s - \(info.function)")
+                        Log.warn("[Storage\(fileName)] Slow \(actionName) taking longer than \(Storage.writeWarningThreadshold, format: ".2", omitZeroDecimal: true)s - \(info.function)")
                     }
                 }
             }()
@@ -493,8 +493,8 @@ open class Storage {
                 if timeout != nil && timeout?.isValid == false {
                     let end: CFTimeInterval = CACurrentMediaTime()
                     
-                    DispatchQueue.global(qos: .default).async {
+                    DispatchQueue.global(qos: .background).async {
-                        SNLog("[Storage\(fileName)] Slow \(actionName) completed after \(end - start, format: ".2", omitZeroDecimal: true)s")
+                        Log.warn("[Storage\(fileName)] Slow \(actionName) completed after \(end - start, format: ".2", omitZeroDecimal: true)s")
                     }
                 }
                 

SessionUtilitiesKit/Database/Types/Migration.swift

@@ -33,13 +33,13 @@ public extension Migration {
         using dependencies: Dependencies
     ) -> ((_ db: Database) throws -> ()) {
         return { (db: Database) in
-            Log.info("[Migration Info] Starting \(targetIdentifier.key(with: self))", silenceForTests: true)
+            Log.info("[Migration Info] Starting \(targetIdentifier.key(with: self))")
             storage?.willStartMigration(db, self)
             storage?.internalCurrentlyRunningMigration.mutate { $0 = (targetIdentifier, self) }
             defer { storage?.internalCurrentlyRunningMigration.mutate { $0 = nil } }
             
             try migrate(db, using: dependencies)
-            Log.info("[Migration Info] Completed \(targetIdentifier.key(with: self))", silenceForTests: true)
+            Log.info("[Migration Info] Completed \(targetIdentifier.key(with: self))")
         }
     }
 }

SessionUtilitiesKit/General/Logging.swift

@@ -3,12 +3,13 @@
 // stringlint:disable
 
 import Foundation
+import OSLog
 import SignalCoreKit
 
 // MARK: - Log
 
 public enum Log {
-    fileprivate typealias LogInfo = (level: Log.Level, message: String, withPrefixes: Bool, silenceForTests: Bool)
+    fileprivate typealias LogInfo = (level: Log.Level, categories: [Category], message: String)
     
     public enum Level: Comparable {
         case verbose
@@ -20,15 +21,31 @@ public enum Log {
         case off
     }
     
+    public struct Category: ExpressibleByStringLiteral, ExpressibleByExtendedGraphemeClusterLiteral, ExpressibleByUnicodeScalarLiteral {
+        public typealias StringLiteralType = String
+        
+        fileprivate let rawValue: String
+        
+        public init(stringLiteral value: String) {
+            self.rawValue = value
+        }
+        
+        public init(unicodeScalarLiteral value: Character) {
+            self.rawValue = String(value)
+        }
+    }
+    
     private static var logger: Atomic<Logger?> = Atomic(nil)
     private static var pendingStartupLogs: Atomic<[LogInfo]> = Atomic([])
     
     public static func setup(with logger: Logger) {
-        logger.retrievePendingStartupLogs = {
+        logger.retrievePendingStartupLogs.mutate {
-            pendingStartupLogs.mutate { pendingStartupLogs in
+            $0 = {
-                let logs: [LogInfo] = pendingStartupLogs
+                pendingStartupLogs.mutate { pendingStartupLogs in
-                pendingStartupLogs = []
+                    let logs: [LogInfo] = pendingStartupLogs
-                return logs
+                    pendingStartupLogs = []
+                    return logs
+                }
             }
         }
         Log.logger.mutate { $0 = logger }
@@ -116,79 +133,54 @@ public enum Log {
         }
     }
     
-    public static func verbose(
+    public static func verbose(_ msg: String) { custom(.verbose, [], msg) }
-        _ message: String,
+    public static func verbose(_ cat: Category, _ msg: String) { custom(.verbose, [cat], msg) }
-        withPrefixes: Bool = true,
+    public static func verbose(_ cats: [Category], _ msg: String) { custom(.verbose, cats, msg) }
-        silenceForTests: Bool = false
-    ) {
-        custom(.verbose, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
-    }
     
-    public static func debug(
+    public static func debug(_ msg: String) { custom(.debug, [], msg) }
-        _ message: String,
+    public static func debug(_ cat: Category, _ msg: String) { custom(.debug, [cat], msg) }
-        withPrefixes: Bool = true,
+    public static func debug(_ cats: [Category], _ msg: String) { custom(.debug, cats, msg) }
-        silenceForTests: Bool = false
-    ) {
-        custom(.debug, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
-    }
     
-    public static func info(
+    public static func info(_ msg: String) { custom(.info, [], msg) }
-        _ message: String,
+    public static func info(_ cat: Category, _ msg: String) { custom(.info, [cat], msg) }
-        withPrefixes: Bool = true,
+    public static func info(_ cats: [Category], _ msg: String) { custom(.info, cats, msg) }
-        silenceForTests: Bool = false
-    ) {
-        custom(.info, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
-    }
     
-    public static func warn(
+    public static func warn(_ msg: String) { custom(.warn, [], msg) }
-        _ message: String,
+    public static func warn(_ cat: Category, _ msg: String) { custom(.warn, [cat], msg) }
-        withPrefixes: Bool = true,
+    public static func warn(_ cats: [Category], _ msg: String) { custom(.warn, cats, msg) }
-        silenceForTests: Bool = false
-    ) {
-        custom(.warn, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
-    }
     
-    public static func error(
+    public static func error(_ msg: String) { custom(.error, [], msg) }
-        _ message: String,
+    public static func error(_ cat: Category, _ msg: String) { custom(.error, [cat], msg) }
-        withPrefixes: Bool = true,
+    public static func error(_ cats: [Category], _ msg: String) { custom(.error, cats, msg) }
-        silenceForTests: Bool = false
-    ) {
-        custom(.error, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
-    }
     
-    public static func critical(
+    public static func critical(_ msg: String) { custom(.critical, [], msg) }
-        _ message: String,
+    public static func critical(_ cat: Category, _ msg: String) { custom(.critical, [cat], msg) }
-        withPrefixes: Bool = true,
+    public static func critical(_ cats: [Category], _ msg: String) { custom(.critical, cats, msg) }
-        silenceForTests: Bool = false
-    ) {
-        custom(.critical, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
-    }
     
     public static func custom(
         _ level: Log.Level,
-        _ message: String,
+        _ categories: [Category],
-        withPrefixes: Bool,
+        _ message: String
-        silenceForTests: Bool
     ) {
         guard
             let logger: Logger = logger.wrappedValue,
             !logger.isSuspended.wrappedValue
-        else { return pendingStartupLogs.mutate { $0.append((level, message, withPrefixes, silenceForTests)) } }
+        else { return pendingStartupLogs.mutate { $0.append((level, categories, message)) } }
         
-        logger.log(level, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
+        logger.log(level, categories, message)
     }
 }
 
 // MARK: - Logger
 
 public class Logger {
-    private let isRunningTests: Bool = (ProcessInfo.processInfo.environment["XCTestConfigurationFilePath"] == nil)
     private let primaryPrefix: String
-    private var level: Log.Level
     private let forceNSLog: Bool
+    private let level: Atomic<Log.Level>
+    private let systemLoggers: Atomic<[String: SystemLoggerType]> = Atomic([:])
     fileprivate let fileLogger: DDFileLogger
     fileprivate let isSuspended: Atomic<Bool> = Atomic(true)
-    fileprivate var retrievePendingStartupLogs: (() -> [Log.LogInfo])?
+    fileprivate let retrievePendingStartupLogs: Atomic<(() -> [Log.LogInfo])?> = Atomic(nil)
     
     public init(
         primaryPrefix: String,
@@ -197,7 +189,7 @@ public class Logger {
         forceNSLog: Bool = false
     ) {
         self.primaryPrefix = primaryPrefix
-        self.level = level
+        self.level = Atomic(level)
         self.forceNSLog = forceNSLog
         
         switch customDirectory {
@@ -318,13 +310,19 @@ public class Logger {
     private func completeResumeLogging(error: String? = nil) {
         let pendingLogs: [Log.LogInfo] = isSuspended.mutate { isSuspended in
             isSuspended = false
-            return (retrievePendingStartupLogs?() ?? [])
+            
+            // Retrieve any logs that were added during
+            return retrievePendingStartupLogs.mutate { retriever in
+                let result: [Log.LogInfo] = (retriever?() ?? [])
+                retriever = nil
+                return result
+            }
         }
         
         // If we had an error loading the extension logs then actually log it
         if let error: String = error {
             Log.empty()
-            log(.error, error, withPrefixes: true, silenceForTests: false)
+            log(.error, [], error)
         }
         
         // After creating a new logger we want to log two empty lines to make it easier to read
@@ -332,30 +330,27 @@ public class Logger {
         Log.empty()
         
         // Add any logs that were pending during the startup process
-        pendingLogs.forEach { level, message, withPrefixes, silenceForTests in
+        pendingLogs.forEach { level, categories, message in
-            log(level, message, withPrefixes: withPrefixes, silenceForTests: silenceForTests)
+            log(level, categories, message)
         }
     }
     
     fileprivate func log(
         _ level: Log.Level,
-        _ message: String,
+        _ categories: [Log.Category],
-        withPrefixes: Bool,
+        _ message: String
-        silenceForTests: Bool
     ) {
-        guard !silenceForTests || !isRunningTests else { return }
+        guard level >= self.level.wrappedValue else { return }
-        guard level >= self.level else { return }
         
         // Sort out the prefixes
         let logPrefix: String = {
-            guard withPrefixes else { return "" }
-            
             let prefixes: String = [
                 primaryPrefix,
                 (Thread.isMainThread ? "Main" : nil),
                 (DispatchQueue.isDBWriteQueue ? "DBWrite" : nil)
             ]
             .compactMap { $0 }
+            .appending(contentsOf: categories.map { $0.rawValue })
             .joined(separator: ", ")
             
             return "[\(prefixes)] "
@@ -376,19 +371,71 @@ public class Logger {
             case .info: OWSLogger.info(logMessage)
             case .warn: OWSLogger.warn(logMessage)
             case .error, .critical: OWSLogger.error(logMessage)
-            
         }
         
-        #if DEBUG
+        let mainCategory: String = (categories.first?.rawValue ?? "[General]")
-        print(logMessage)
+        var systemLogger: SystemLoggerType? = systemLoggers.wrappedValue[mainCategory]
-        #else
+        
-        if forceNSLog {
+        if systemLogger == nil {
-            NSLog(message)
+            systemLogger = systemLoggers.mutate {
+                if #available(iOS 14.0, *) {
+                    $0[mainCategory] = SystemLogger(category: mainCategory)
+                }
+                else {
+                    $0[mainCategory] = LegacySystemLogger(forceNSLog: forceNSLog)
+                }
+                return $0[mainCategory]
+            }
         }
+        
+        #if DEBUG
+        systemLogger?.log(level, logMessage)
         #endif
     }
 }
 
+// MARK: - SystemLogger
+
+private protocol SystemLoggerType {
+    func log(_ level: Log.Level, _ log: String)
+}
+
+private class LegacySystemLogger: SystemLoggerType {
+    private let forceNSLog: Bool
+    
+    init(forceNSLog: Bool) {
+        self.forceNSLog = forceNSLog
+    }
+    
+    public func log(_ level: Log.Level, _ log: String) {
+        guard !forceNSLog else { return NSLog(log) }
+        
+        print(log)
+    }
+}
+
+@available(iOSApplicationExtension 14.0, *)
+private class SystemLogger: SystemLoggerType {
+    private static let subsystem: String = Bundle.main.bundleIdentifier!
+    private let logger: os.Logger
+    
+    init(category: String) {
+        logger = os.Logger(subsystem: SystemLogger.subsystem, category: category)
+    }
+    
+    public func log(_ level: Log.Level, _ log: String) {
+        switch level {
+            case .off: return
+            case .verbose: logger.trace("\(log)")
+            case .debug: logger.debug("\(log)")
+            case .info: logger.info("\(log)")
+            case .warn: logger.warning("\(log)")
+            case .error: logger.error("\(log)")
+            case .critical: logger.critical("\(log)")
+        }
+    }
+}
+
 // MARK: - Convenience
 
 private enum ExtensionType {

SessionUtilitiesKit/JobRunner/JobRunner.swift

@@ -1304,7 +1304,7 @@ public final class JobQueue: Hashable {
         
         // Run the first job in the pendingJobsQueue
         if !wasAlreadyRunning {
-            Log.info("[JobRunner] Starting \(queueContext) with (\(jobCount) job\(jobCount != 1 ? "s" : ""))", silenceForTests: true)
+            Log.info("[JobRunner] Starting \(queueContext) with (\(jobCount) job\(jobCount != 1 ? "s" : ""))")
         }
         runNextJob(using: dependencies)
     }

SessionUtilitiesKit/LibSession/LibSession.swift

@@ -34,10 +34,7 @@ extension LibSession {
         
         /// Finally register the actual logger callback
         session_add_logger_full({ msgPtr, msgLen, catPtr, catLen, lvl in
-            guard
+            guard let msg: String = String(pointer: msgPtr, length: msgLen, encoding: .utf8) else { return }
-                let msg: String = String(pointer: msgPtr, length: msgLen, encoding: .utf8),
-                let cat: String = String(pointer: catPtr, length: catLen, encoding: .utf8)
-            else { return }
             
             /// Logs from libSession come through in the format:
             /// `[yyyy-MM-dd hh:mm:ss] [+{lifetime}s] [{cat}:{lvl}|log.hpp:{line}] {message}`
@@ -49,30 +46,36 @@ extension LibSession {
                 
                 let message: String = String(logParts[3]).trimmingCharacters(in: .whitespacesAndNewlines)
                 
-                return "[libSession:\(cat)] \(logParts[1])] \(message)"
+                return "\(logParts[1])] \(message)"
             }()
             
-            Log.custom(
+            Log.custom(Log.Level(lvl), [LogCategory(catPtr, catLen).logCat], processedMessage)
-                Log.Level(lvl),
-                processedMessage,
-                withPrefixes: true,
-                silenceForTests: false
-            )
         })
     }
     
     // MARK: - Internal
     
     fileprivate enum LogCategory: String {
+        case libSession
         case config
         case network
         case quic
         case manual
         
-        init?(_ catPtr: UnsafePointer<CChar>?, _ catLen: Int) {
+        var logCat: Log.Category {
+            switch self {
+                case .libSession: return "libSession"
+                case .config: return "libSession:config"
+                case .network: return "libSession:network"
+                case .quic: return "libSession:quic"
+                case .manual: return "libSession:manual"
+            }
+        }
+        
+        init(_ catPtr: UnsafePointer<CChar>?, _ catLen: Int) {
             switch String(pointer: catPtr, length: catLen, encoding: .utf8).map({ LogCategory(rawValue: $0) }) {
                 case .some(let cat): self = cat
-                case .none: return nil
+                case .none: self = .libSession
             }
         }
     }