[Bug]: ~30s delays displaying push notifications when using OneSignalExtension.didReceiveNotificationExtensionRequest

[johnmalatras]

What happened?

We've been trying to debug some sort of delay or throttling of our push notifications that occurs when a user gets > 1 communication notification in a row. The first one arrives instantly and then each one after arrives about 30 seconds after the last. After debugging through, it seems that this function call:

OneSignalExtension.didReceiveNotificationExtensionRequest(
    receivedRequest,
    with: bestAttemptContent,
    withContentHandler: contentHandler
)

causes the hang. If I directly call contentHandler?(bestAttemptContent) instead the notifications all show instantly.

I've tried to debug further by setting a verbose log level but OneSignal.Debug.setLogLevel(.LL_VERBOSE) doesn't appear to be available in OneSignalExtension. Also, serviceExtensionTimeWillExpire is not hit at any point.

Steps to reproduce?

1. Build an `INSendMessageIntent` for a communication notification
2. Create an `INInteraction` with the intent and donate it
3. Update the notification content with the intent
4. Call OneSignalExtension.didReceiveNotificationExtensionRequest with the updated notification contents

What did you expect to happen?

Push notifications are displayed as soon as they're received.

OneSignal iOS SDK version

3.12.7

iOS version

17

Specific iOS version

iOS 17.2

Relevant log output

No response

Code of Conduct

• I agree to follow this project's Code of Conduct

[emawby]

@johnmalatras Thank you for reaching out we will investigate. In order for debug logs to show up you must debug the NotificationServiceExtension target rather than the app target. The easiest way to do this is to start debugging the app and send the device a notification. Then go to "Debug" -> "Attach to Process" -> "OneSignalNotificationServiceExtension". Now you can send more notifications to the device and should get debug logs/breakpoints enabled.

If you need to get logs from the first push a device receives you can also use Mac's Console app to search for the logs.

[johnmalatras]

Hi, I've been debugging the NotificationServiceExtension target without issue. That's how I pinpointed that OneSignalExtension.didReceiveNotificationExtensionRequest is the cause of the delay.

The logging issue I mentioned is specifically around getting the OneSignal SDK to output verbose logging in the extension. The documentation mentions setting OneSignal.Debug.setLogLevel(.LL_VERBOSE) but that is not available in OneSignalExtension. I was hoping this logging might indicate what the issue in the SDK is as we found some code that manually adds a delay:

OneSignal-iOS-SDK/iOS_SDK/OneSignalSDK/OneSignalExtension/OneSignalNotificationServiceExtensionHandler.m

Line 146 in 5e3d8e4

[OneSignalLog onesignalLog:ONE_S_LL_VERBOSE message:[NSString stringWithFormat:@"OneSignal onNotificationReceived sendReceiveReceipt with delay: %i", randomDelay]];

[emawby]

Ah I see the issue is that the OneSignal class is likely not available in the notification service extension so you can use OneSignalLog.Debug.setLogLevel(.LL_VERBOSE) instead.

[emawby]

The issue appears to be that the random delay for sending confirmed deliveries is run on the main thread which could be blocking delivery of subsequent notifications to the NSE until the delay has ended.

However, I am not able to reproduce this behavior. I added logging before and after OneSignal processes the notification send and this was my result sending 3 notifications subsequently:

######## Start NotificationService!
START!!!!!! request.content.userInfo: {
aps = {
alert = "Subsequent notification test 1";
"mutable-content" = 1;
sound = default;
};
}
######## Start NotificationService!
START!!!!!! request.content.userInfo: {
aps = {
alert = "Subsequent notification test 2";
"mutable-content" = 1;
sound = default;
};
}
######## Start NotificationService!
START!!!!!! request.content.userInfo: {
aps = {
alert = "Subsequent notification test 3";
"mutable-content" = 1;
sound = default;
};
}
######## END NotificationService!
######## END NotificationService!
######## END NotificationService!

Each notification was delivered immediately regardless of the delay in confirmed delivery processing.

[johnmalatras]

Are you displaying these as a communication notifications in the extension? To be clear they're delivered immediately for us too when it's a plain notification. The delays only occur for communication notifications (aka notifications where we update the contents with let content = try request.content.updating(from: intent) where intent is a INSendMessageIntent before calling OneSignalExtension.didReceiveNotificationExtensionRequest

[emawby]

@johnmalatras I am still not able to reproduce using the below (objective-c not swift)

INPersonHandle *handle = [[INPersonHandle alloc] initWithValue:@"test" type:INPersonHandleTypeUnknown];
INPerson *sender = [[INPerson alloc] initWithPersonHandle:handle nameComponents:nil displayName:@"test" image:nil contactIdentifier:nil customIdentifier:nil];
INSendMessageIntent *messageIntent = [[INSendMessageIntent alloc] initWithRecipients:nil content:@"test content" groupName:nil serviceName:nil sender:sender];
if (@available(iOS 15.0, *)) {
    self.bestAttemptContent = [[request.content contentByUpdatingWithProvider:messageIntent error:nil] mutableCopy];
} else {
    // Fallback on earlier versions
}

[johnmalatras]

Weird. The only notable differences I see are that:

1. Our sender has an image that's a INImage initialized from a URL
2. We're donating the intent via an INInteraction before updating the content and hitting OneSignalExtension.didReceiveNotificationExtensionRequest:

let interaction = INInteraction(intent: intent, response: nil)
interaction.direction = .incoming

interaction.donate { [weak self] error in
    if let error {
        Analytics.trackError(
            error,
            context: "Error updating notification with intent"
        )
        return
    }

    guard let self else { return }

    do {
        let content = try request.content.updating(from: intent)
        if let mutableUpdated = content.mutableCopy()
                as? UNMutableNotificationContent
        {
            mutableUpdated.body = bodyOverride ?? mutableUpdated.body
            self.bestAttemptContent = mutableUpdated
        }
    } catch {
        Analytics.trackError(
            error,
            context: "Error updating notification with intent"
        )
    }
    
    self.forwardRequestToExtension()
}

[emawby]

@johnmalatras Does self.forwardRequestToExtension() need to be called inside of the intent donation completion block? I am able to reproduce the issue if it is inside of the completion block, but if I move it outside of the intent donation it works as normal.

[johnmalatras]

@emawby If the call is outside of the intent donation completion block then the notification isn't rendered as a communication notification

[emawby]

@johnmalatras Instead of calling it inside the completion can you await on the donation and then call it afterwards like they do in the documentation here?

[johnmalatras]

Interesting, I actually don't see an async version of func didReceive(_ request: UNNotificationRequest, withContentHandler contentHandler: @escaping (UNNotificationContent) -> Void) available despite it being in that doc. If I kick off a Task though and await the donation instead of using the completion handler the bug persists though.

[emawby]

I am still working in Objective-C, but it works for me if I mock await behavior using dispatch semaphores. This allowed me to make sure the interaction was donated and still have notifications delivered immediately. You can try something similar in Swift as a workaround.

The issue is that in order to have a random delay for confirmed deliveries we need to keep the process alive. To do this we are waiting on a dispatch_semaphore after submitting the notification content to the handler. It looks like doing this while in the completion block hangs the entire service extension process. We will look for other ways to get the desired behavior.

dispatch_semaphore_t semaphore = dispatch_semaphore_create(0);
[interaction donateInteractionWithCompletion:^(NSError * _Nullable error) {
    self.bestAttemptContent = [[request.content contentByUpdatingWithProvider:messageIntent error:nil] mutableCopy];
    dispatch_semaphore_signal(semaphore);
}];
dispatch_semaphore_wait(semaphore, dispatch_time(DISPATCH_TIME_NOW, 30 * NSEC_PER_SEC));
[OneSignalExtension didReceiveNotificationExtensionRequest:self.receivedRequest
                       withMutableNotificationContent:self.bestAttemptContent
                                   withContentHandler:self.contentHandler];

[johnmalatras]

@emawby I have what I believe should be similar semaphore functionality in Swift but still no cigar; doesn't fix the delay:

let semaphore = DispatchSemaphore(value: 0)
interaction.donate { [weak self] error in
    defer {
        semaphore.signal()
    }

    if let error {
        Analytics.trackError(
            error,
            context: "Error updating notification with intent"
        )
        return
    }

    guard let self else { return }

    do {
        let content = try request.content.updating(from: intent)
        if let bodyOverride,
            let mutableUpdated = content.mutableCopy()
                as? UNMutableNotificationContent
        {
            mutableUpdated.body = bodyOverride
            self.bestAttemptContent = mutableUpdated
        }
    } catch {
        Analytics.trackError(
            error,
            context: "Error updating notification with intent"
        )
    }
}

semaphore.wait()
self.forwardRequestToExtension()

[emawby]

Interesting your code works for me in Swift, and I am able to reproduce the issue without the semaphore. The only thing I changed was removing the analytics error tracking code and the bodyOverride code.

[emawby]

@johnmalatras Fixing this issue for communication notifications will likely require an update to the SDK's public interface to either separate the confirmed delivery call from the notification processing, or marking a notification as a communication notification which I don't believe we can detect automatically today. However the option we go with is somewhat dependent on whether or not the dispatch semaphore workaround noted above works for all cases. If you were never able to get that to work please let me know!

[johnmalatras]

Sorry for the delayed follow up @emawby - we had a potential fix out yet and wanted to let it bake for a bit to ensure nothing was unexpectedly going wrong. We were indeed able to fix with a conceptually similar solution to what you proposed. Directly using a semaphore didn't work but running our handleNotificationReceived explicitly in a detached task (Task.detached) did seem to fix it! I'm not exactly sure if there's other consequences of this but I haven't noticed any yet.