How to debug complicated background task bug?

I have a fairly complicated application with lots of Pods/modules doing network requests and possibly background activities.


Recently, we started noticing the app crashing in the background due to background duration expiry. As this particular scenario is not unit tested, its hard to find the exact culprit. It could have been introduced months ago.



<BKNewProcess: 0x100331a00; com.app.app; pid: 392; hostpid: -1> has active assertions beyond permitted time:
{(
    <BKProcessAssertion: 0x100222ed0> id: 392-AA97D7E3-7BE3-4A43-BC88-A5601EBD76D6 name: Called by UIKit, from <redacted> process: <BKNewProcess: 0x100331a00; com.app.app; pid: 392; hostpid: -1> permittedBackgroundDuration: 180.000000 reason: finishTask owner pid:392 preventSuspend  preventIdleSleep  preventSuspendOnSleep ,
    <BKProcessAssertion: 0x100337b40> id: 392-1572EDBD-EE61-4939-A315-6CD82DEF3354 name: Called by UIKit, from <redacted> process: <BKNewProcess: 0x100331a00; com.app.app; pid: 392; hostpid: -1> permittedBackgroundDuration: 180.000000 reason: finishTask owner pid:392 preventSuspend  preventIdleSleep  preventSuspendOnSleep
)}


The question is, is there a way to debug which tasks exist in the background (e.g. enumerating all background tasks) or say a way to kill all background tasks when entering background? How would you go about debugging this issue?

Accepted Reply

Debugging stuff like this can be tricky. Regardless of what else you do, I recommend that you file an enhancement request for better debugging infrastructure. For example, it’d be cool if there was an instrument that recorded background task asserts being taken, released and expiring, with backtraces.

If you do file a bug about this, please post your bug number, just for the record.

The first thing I do in this situation is take a good long look at the BKProcessAssertion. I’ve pulled one apart to make it easier to see:

<BKProcessAssertion: 0x100222ed0>
id: 392-AA97D7E3-7BE3-4A43-BC88-A5601EBD76D6
name: Called by UIKit, from <redacted>
process: <BKNewProcess: 0x100331a00; …>
permittedBackgroundDuration: 180.000000
reason: finishTask
owner pid:392
preventSuspend
preventIdleSleep
preventSuspendOnSleep

There are three things you’ll note here:

  • The

    permittedBackgroundDuration
    ‘field’ is 3 minutes, which is what you’d expect for an assertion taken out why your app is in the foreground. If this assertion had been taken out while your app was in the background, you’d probably see a 30 second expiry time.
  • The

    reason
    field contains
    finishTask
    , which strongly indicates a UIApplication background task or NSProcessInfo expiring activity.
  • The

    name
    field further suggests a UIApplication background task.

One technique I use in situations like this is to deliberately trigger a specific failure and then compare that crash log with the one I got from the field. For example, this code:

self.task = UIApplication.shared.beginBackgroundTask {
    // BUG: We don't end the background task.
}

produces a crash log that very closely matches the above.

Be aware that UIApplication background tasks now support a

name
parameter. If you supply that name, it shows up in the crash log. For example, this code:
self.task = UIApplication.shared.beginBackgroundTask(withName: "QQQ Background Task") {
    // BUG: We don't end the background task.
}

produces this crash log:

<BKProcessAssertion: 0x1004294e0>
id: 1198-98DEC332-FC56-4C6D-BE15-FFEDA865E3D8
name: QQQ Background Task
process: <BKNewProcess: 0x100415410; …>
permittedBackgroundDuration: 180.000000
reason: finishTask
owner pid:1198
preventSuspend
preventIdleSleep
preventSuspendOnSleep

So, the first thing I’d do in your situation is search the entire code based for

beginBackgroundTask
and update those calls to supply a meaningful name.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Replies

I quickly swizzled out the UIApplication methods


beginBackgroundTaskWithName:expirationHandler:

endBackgroundTask:

beginBackgroundTaskWithExpirationHandler:


and put my own logging in to diagnose an issue which turned out to be in Googles Cast SDK.


Sorry the code is far too embarassing / hacky for me to share.....

Debugging stuff like this can be tricky. Regardless of what else you do, I recommend that you file an enhancement request for better debugging infrastructure. For example, it’d be cool if there was an instrument that recorded background task asserts being taken, released and expiring, with backtraces.

If you do file a bug about this, please post your bug number, just for the record.

The first thing I do in this situation is take a good long look at the BKProcessAssertion. I’ve pulled one apart to make it easier to see:

<BKProcessAssertion: 0x100222ed0>
id: 392-AA97D7E3-7BE3-4A43-BC88-A5601EBD76D6
name: Called by UIKit, from <redacted>
process: <BKNewProcess: 0x100331a00; …>
permittedBackgroundDuration: 180.000000
reason: finishTask
owner pid:392
preventSuspend
preventIdleSleep
preventSuspendOnSleep

There are three things you’ll note here:

  • The

    permittedBackgroundDuration
    ‘field’ is 3 minutes, which is what you’d expect for an assertion taken out why your app is in the foreground. If this assertion had been taken out while your app was in the background, you’d probably see a 30 second expiry time.
  • The

    reason
    field contains
    finishTask
    , which strongly indicates a UIApplication background task or NSProcessInfo expiring activity.
  • The

    name
    field further suggests a UIApplication background task.

One technique I use in situations like this is to deliberately trigger a specific failure and then compare that crash log with the one I got from the field. For example, this code:

self.task = UIApplication.shared.beginBackgroundTask {
    // BUG: We don't end the background task.
}

produces a crash log that very closely matches the above.

Be aware that UIApplication background tasks now support a

name
parameter. If you supply that name, it shows up in the crash log. For example, this code:
self.task = UIApplication.shared.beginBackgroundTask(withName: "QQQ Background Task") {
    // BUG: We don't end the background task.
}

produces this crash log:

<BKProcessAssertion: 0x1004294e0>
id: 1198-98DEC332-FC56-4C6D-BE15-FFEDA865E3D8
name: QQQ Background Task
process: <BKNewProcess: 0x100415410; …>
permittedBackgroundDuration: 180.000000
reason: finishTask
owner pid:1198
preventSuspend
preventIdleSleep
preventSuspendOnSleep

So, the first thing I’d do in your situation is search the entire code based for

beginBackgroundTask
and update those calls to supply a meaningful name.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

Thank you Quinn. That was very insightful. I had followed roughly the same steps and I realised that my application is using GSDAppIndexing (Google app indexing SDK) from Google (v2.0.1). It was added in the app somewhere in late 2015. Now this is a pre-compiled library and I have no way of finding any clues here. So I swizzled beginTask* endTask* and print out the task Identifier. Then I looked at Console with my phone attached, launched the application - backgrounded it, waited 3 minutes for it to crash. Then I filtered starting task IDs, end task IDs - matched them and found the missing task ID that wasn't ending. Then I printed backtrace in my swizzled methods and found out that it was coming from a weird method signature. Since these frameworks are precompiled, the debug symbols were not available. I started commenting out these frameworks one by one and repeat the process. Eventually, I found out that Google App Indexing framework was the culprit. It turns out I don't even need that framework so I removed it from the project and problem solved.


Enhacement report ID: 30340953

My issue turned out to be with one of Google's SDKs too. Thanks