BGTask expiry is never called for the requested BGTask.

We have a push-to-talk client, Part of Push APNS, app never received the BG task expiry.

  • The app is suspended.
  • Received Push-To-Talk APNS
  • Here requested a BGTask and it got successfully registered
  • Since it is a PTT call path, it ended immediately(via code) due to internal restrictions Ex: DND mode for client specific. The client allowed BG time more than 30 seconds and looks client has been suspended but Never received a BG task expiration handler from OS

In sys diagnose logs confirmed, BGTask registered successfully 2024-09-03 16:18:47.331890 +0530 default AT&T EPTT <private>: Created background task <private>.

But never got fired expiration handler.

Feedback - FB15145380

We have a push-to-talk client, Part of Push APNS, app never received the BG task expiry.

Correct. From a relatively brief look at the log, it appears that your app has an active Audio Session, which is what's keeping it awake:

2024-09-03 16:18:47.352+0530  [as_client]     AVAudioSession_iOS.mm:2654  Activated session 0x6800c

That active audio session is keeping your app awake, which also means background tasks don't expire.

You can actually see this dynamic play out in your own logging :

2024-09-03 16:18:53.970+0530 ...requestBackgroundTask_block_invoke_2 After 10sec Start Remaining BG time: <GIANT NUMBER>

The giant number I left out is "infinity", meaning the assertion (from the audio system) keeping your app awake does not have a fixed expiration time.

Note on this point:

The client allowed BG time more than 30 seconds and looks client has been suspended but Never received a BG task expiration handler from OS

The systems "default" expiration is 30s, but that doesn't mean your tasks will actually expire in 30s. That's what will happen assuming nothing else changes before the task expires. As the simplest example of this, if your foreground your app before the task expires then the task will expire.

Note that this also works in "reverse"- if you start a background task while your in the audio session is active, the system does NOT guarantee that you'll get 30s past the creation time. If you're audio session deactivates before 30s, you'll get much less time than that. Quoting "UIApplication Background Task Notes":

IMPORTANT The value returned by backgroundTimeRemaining is an estimate and can change at any time. You must design your app to function correctly regardless of the value returned. It’s reasonable to use this property for debugging but we strongly recommend that you avoid using as part of your app’s logic.

IMPORTANT Basing app behaviour on the value returned by backgroundTimeRemaining is the number two cause of background task problems on iOS.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Client explicitly never does the Audio activate session: Looks OS on behalf of the client and expects the deactivation as well and also unable to find the root cause of the audio session activation. Please find the detailed use case for the time the issue occurred:

Application is in suspended and received PTT push notification: 2024-09-03 16:18:43.258467 +0530 default AT&T EPTT <ALA_SIGNAL>: [OS-CCF] <PushToTalkInterface> -[PushToTalkInterface incomingPushResultForChannelManager:channelUUID:pushPayload:]

Part of PTT call - didActivateAudioSession activated 2024-09-03 16:18:43.570734 +0530 default AT&T EPTT <PushToTalk> <ALA_SIGNAL>: Enter -[PushNotificationManager didActivateAudioSession:]

Due to internal settings/constraint, client ended the call by setting setActiveRemoteParticipant to null 2024-09-03 16:18:43.601432 +0530 default AT&T EPTT <PushToTalk> <ALA_SIGNAL>: Enter -[PushNotificationManager setActiveRemoteParticipant:useCallerThread:image:] [talkerName = (null)]

2024-09-03 16:18:43.603754 +0530 default AT&T EPTT <CallStateFSM> Enter -[KN_CallStateMachine cleanUp] [current state = STATE_CALL_DISCONNECTED]

2024-09-03 16:18:43.606457 +0530 default AT&T EPTT Provider <CXXPCChannelProvider: 0x301ed4180> reports channel with UUID 46FA76CB-A956-4FDF-9DC1-A435C8576D4E ended an incoming transmission with reason 0

Part of PTT call end - didDeactivateAudioSession deactivated 2024-09-03 16:18:43.948898 +0530 default AT&T EPTT <PushToTalk> <ALA_SIGNAL>: Enter -[PushNotificationManager didDeactivateAudioSession:] 2024-09-03 16:18:43.410607 +0530 default callservicesd AVAudioSession_iOS.mm:2774 Deactivated session 0x6800c

2024-09-03 16:18:43.948975 +0530 error runningboardd [app<com.msikodiak.eptt(35408D99-1B85-4B85-A639-D03A7D98DE18)>:282] client not entitled to get limitationsForInstance: <Error Domain=RBSServiceErrorDomain Code=1 "Client not entitled" UserInfo={RBSEntitlement=com.apple.runningboard.process-state, NSLocalizedFailureReason=Client not entitled, RBSPermanent=false}>

And later in BG , received the Audio route change and seen audio activate session for the client, please let us what is causing the activate session also suppose to be deactivated by OS since it is activate behalf of client: 2024-09-03 16:18:47.351851 +0530 default AT&T EPTT [IOS] audioRouteChangeEventNotification Exit 2024-09-03 16:18:47.352385 +0530 default AT&T EPTT AVAudioSession_iOS.mm:2654 Activated session 0x6800c

Client explicitly never does the Audio activate session:

Here is the large log sequence leading to that activate:

2024-09-03 16:18:47.347+0530 Thread-> 31345] [as_client]     AVAudioSession_iOS.mm:516   Session 0x6800c posting AVAudioSessionRouteChangeNotification. Reason: AVAudioSessionRouteChangeReasonOverride
2024-09-03 16:18:47.349+0530 Thread-> 3986] <CallKit> -[CallKitInterface getCallKitInterfaceState]: [callKitInterfaceState 1]
2024-09-03 16:18:47.350+0530 Thread-> 3986] <CallKit> Enter -[CallKitManager isCallKitActive] [callkitState: 1]
2024-09-03 16:18:47.352+0530 Thread-> 3986] audioRouteChangeEventNotification Route Change Info {
    AVAudioSessionRouteChangePreviousRouteKey = "<AVAudioSessionRouteDescription: 0x3008bd130, \ninputs = (\n); \noutputs = (\n    \"<AVAudioSessionPortDescription: 0x3008bd1e0, type = Speaker; name = Speaker; UID = Speaker; selectedDataSource = (null)>\"\n)>";
    AVAudioSessionRouteChangeReasonKey = 4;
}
2024-09-03 16:18:47.352+0530 Thread-> 3986] <CallKit> -[CallKitInterface getCallKitInterfaceState]: [callKitInterfaceState 1]
2024-09-03 16:18:47.352+0530 Thread-> 3986] <CallKit> -[CallKitManager isAudioSessionActivated]: [value: 0]
2024-09-03 16:18:47.352+0530 Thread-> 3986] [IOS] audioRouteChangeEventNotification Exit
2024-09-03 16:18:47.352+0530 Thread-> 31349] [as_client]     AVAudioSession_iOS.mm:2654  Activated session 0x6800c

That sequence is basically exactly what I'd expect when an app call "setActive" in a notification handler. "setActive" an asynchronous call, so the active call gets kicked off on one thread and the audio system see the activate complete on a different thread.

Aside from that, there are two other things I noticed:

  1. You appear to be using WebKit fairly heavily. I'm not sure what WebKit's role in your app is, but trying to integrate it with the PTT/CallKit framework is not something I'd expect to work very well. The consequence of trying to get this working are... really hard to predict.

  2. Your app is also the Now Playing app. That's supported, but the timing makes me wonder if the activate call was tied to restoring your "Now Playing" status. Also, your app had to have called "setActive" to become the Now Playing app, so there is at least one code path that does call "setActive". Note this log sequence, which I think is the same sequence "play" triggers.

2024-09-03 16:18:47.394+0530 audiomxd[104:31391] [Session] -CMSessionMgr- cmsSetIsPlaying:5473 'sid:0x6800c, AT&T EPTT(282), 'prim'' with [PlayAndRecord_WithBluetooth/VoiceChat] [NonMixable] [System Audio] starting playing to output VAD: VirtualAudioDevice_Default and input VAD: VirtualAudioDevice_Default. Ringer switch state: Device is not silenced, Session is unmuted. RoutingContextUUID=<private> NowPlayingApp:NO IsPlayingOutput:YES IsSharedAVAudioSessionInstance:YES
...
2024-09-03 16:18:47.520+0530 mediaremoted[39:1370] [NowPlaying] Set: MRDMediaServerNowPlayingDataSource setting nowPlayingApplications to <<private>>
2024-09-03 16:18:47.540+0530 mediaremoted[39:1370] [MediaRemote] MRDMediaServerNowPlayingDataSource pid: 282 | bundle id: (null) | session id: 425996 | consolidated info: (
        {
        CurrentlyPlayingChannelCount = 1;
        CurrentlyPlayingContentIsEligibleForSpatialization = 0;
        CurrentlyPlayingContentIsSpatialized = 0;
        CurrentlyPlayingFormat = 1819304813;
    }
)

Finally, what else do you "know" about what was actually happening here? What was the user doing? What audio devices were they interacting? Did anything else happen at the time? One of the basic questions to look at here isn't "why is this happening?", it's "why ISN'T this happening?". In other words, what made this particular run different than all the other runs. Often the answer to that question is the key to sorting out the entire issue.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

BGTask expiry is never called for the requested BGTask.
 
 
Q