Collect logs from OSLog during app background transition cause crash

We use OSLog to log message in our iOS app and retrieve logs to save into local file when app goes to background. This way we will be able to persist logs after app terminated. However, when logs become large, retrieving logs takes more than 5 seconds during background transition that cause our app being killed by the system with below info:

Exception Type: EXC_CRASH (SIGKILL) Exception Codes: 0x0000000000000000, 0x0000000000000000 Termination Reason: FRONTBOARD 2343432205 <RBSTerminateContext| domain:10 code:0x8BADF00D explanation:scene-update watchdog transgression: app<com.cisco.secureclient.zta(B7AB7300-8A17-4C71-88BC-BA3D55AF6666)>:1261 exhausted real (wall clock) time allowance of 10.00 seconds ProcessVisibility: Background ProcessState: Running WatchdogEvent: scene-update WatchdogVisibility: Background WatchdogCPUStatistics: ( "Elapsed total CPU time (seconds): 13.500 (user 10.890, system 2.610), 21% CPU", "Elapsed application CPU time (seconds): 2.119, 3% CPU" ) reportType:CrashLog maxTerminationResistance:Interactive>

Triggered by Thread: 0

Thread 0 name: Dispatch queue: com.apple.main-thread Thread 0 Crashed: 0 libsystem_kernel.dylib 0x1ed6e01d8 mach_msg2_trap + 8 1 libsystem_kernel.dylib 0x1ed6dff70 mach_msg2_internal + 80 2 libsystem_kernel.dylib 0x1ed6dfe88 mach_msg_overwrite + 436 3 libsystem_kernel.dylib 0x1ed6dfcc8 mach_msg + 24 4 libdispatch.dylib 0x1aea4df00 _dispatch_mach_send_and_wait_for_reply + 540 5 libdispatch.dylib 0x1aea4e2a0 dispatch_mach_send_with_result_and_wait_for_reply + 60 6 libxpc.dylib 0x20fd406d0 xpc_connection_send_message_with_reply_sync + 264 7 Foundation 0x1a5ad96c0 NSXPCCONNECTION_IS_WAITING_FOR_A_SYNCHRONOUS_REPLY + 16 8 Foundation 0x1a5ac13bc -[NSXPCConnection _sendInvocation:orArguments:count:methodSignature:selector:withProxy:] + 2160 9 Foundation 0x1a5aec6cc -[NSXPCConnection _sendSelector:withProxy:arg1:] + 116 10 Foundation 0x1a5aec604 _NSXPCDistantObjectSimpleMessageSend1 + 60 11 OSLog 0x1f4b98118 -[OSLogCurrentProcessEnumerator nextObject] + 192 12 libswiftOSLog.dylib 0x213983270 OSLogStore.PrivateIterator.next() + 32 13 libswiftOSLog.dylib 0x213983324 protocol witness for IteratorProtocol.next() in conformance OSLogStore.PrivateIterator + 28 14 libswiftCore.dylib 0x1a0050ed0 _IteratorBox.next() + 108 15 MyApp 0x104359e28 static MyLogger.getFormattedLogs() (in MyApp ) (MyLogger.swift:63) + 122408

Here is our code to retrieve logs:

struct MyLogger {

public var log: Logger

init(subsystem: String = getSubsystem(),
     file: String = #file,
     function: String = #function,
     line: Int = #line,
     context: String = "myapp")
{
    let category = "\(context): \(file): \(line): \(function): "
    log = Logger(subsystem: subsystem, category: category)
}

static func getFormattedLogs() -> [String]
{
    do {
        // Combine log message with timestamp and category with
        // file/line/function information
        let df = DateFormatter()
        df.dateFormat = ZtaConstants.DATE_FORMAT
        let store = try OSLogStore.init(scope: .currentProcessIdentifier)
        let logEntries = try store.getEntries()
            .compactMap{ $0 as? OSLogEntryLog}
            .filter { $0.subsystem.contains(getSubsystem() }
            .map{df.string(from: $0.date) + "  " +
                String(format:"0x%02x", $0.threadIdentifier) + "  " +
                String(format:"0x%x", $0.activityIdentifier) + "  " +
                String($0.processIdentifier) + "  " +
                $0.category + " " + $0.composedMessage}
        return formattedLogs
    } catch let err {
        ZtaLogger().log.error("Failed to collect log: \(err)")
        return []
    }
}

}

It looks like getFormattedLogs() takes long time because we use filter to get message that logged by our app and format the log entry. Since compactMap is O(m+n) complexity, filter and map are O(n) that cause performance issue. Is there a better way to get logs from our app via OSLog? Could retrieving logs be called in appDidEnterBackground()?

Thanks, Ying

Accepted Reply

There are a bunch of issues with .currentProcessIdentifier that prevent you from solving this problem properly. Your Friend the System Log has the relevant bug numbers.

getEntries(with:at:matching:) returns a sequence rather than just an array. It’s possible that iterating that sequence in chunks might allow you to break out of the loop when you run out of background execution time.

Regardless, I recommend that you do this on a secondary thread rather than on the main thread. That’ll protect you from the watchdog. You can then use a UIApplication background task to hold off suspension while you’re doing this work. Make sure you have an expiry handler to handle the case where the work takes more time than you have.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"

Replies

There are a bunch of issues with .currentProcessIdentifier that prevent you from solving this problem properly. Your Friend the System Log has the relevant bug numbers.

getEntries(with:at:matching:) returns a sequence rather than just an array. It’s possible that iterating that sequence in chunks might allow you to break out of the loop when you run out of background execution time.

Regardless, I recommend that you do this on a secondary thread rather than on the main thread. That’ll protect you from the watchdog. You can then use a UIApplication background task to hold off suspension while you’re doing this work. Make sure you have an expiry handler to handle the case where the work takes more time than you have.

Share and Enjoy

Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"