CODEWITHSUNDEEP
iosiphonepush-notificationapple-push-notifications
anders
anders

Reputation: 4218

APNs Remote Notifications Delegate Methods Not Being Called

We have an app thats ONLY designed be run on iOS7. We have installed the PersistentConnectionLogging configuration profile to further debug our issue (as described in the Trouble Shooting Push Notifications technical note).

We have confirmed the phone has a full and valid 3G internet connection through the cellular modem (with WiFi disabled), the application is allowing remote notifications in settings and is successfully working on many other devices running the exact same build on the exact same model phone (iPhone 4S). The phone is also supervised for an MDM service.

On phones that are working it goes something like this (tried to pick out the useful console messages),

Nov 17 11:15:14 MDM-Test-Phone-2 TestApp[546] <Warning>: >>>>>>>> APP LAUNCHED <<<<<<<<

....

Nov 17 11:15:15 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:15:15 -0500 apsd[82]: peer(34) received XPC_ERROR_CONNECTION_INVALID

...

Nov 17 11:15:15 calling, [[UIApplication sharedApplication] registerForRemoteNotificationTypes:UIRemoteNotificationTypeNewsstandContentAvailability];

...

Nov 17 11:15:15 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:15:15 -0500 apsd[82]: Looking up connection on peer: 15d71590  found <APSConnectionServer: 0x15db0a00>
Nov 17 11:15:15 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:15:15 -0500 apsd[82]:    <APSCourier: 0x15d658d0>: Received request from <APSConnectionServer: 0x15db0a00> to generate token for topic "com.test.test" and identifier ""
Nov 17 11:15:15 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:15:15 -0500 apsd[82]: copyTokenForDomain sandbox.push.apple.com ,fffffff7ffffff93ffffffe039604451ffffff8cffffffccffffff80ffffffe75c0affffffe0ffffffcf5d4dffffff8cffffffa41a
Nov 17 11:15:15 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:15:15 -0500 apsd[82]: <APSCourier: 0x15d658d0> found cached token <c150ca2f 039dc8fb a642ac22 47d8f80b abc9d186 0811a083 a4820d99 d749c09b> for appSpecificIdentifier ,fffffff7ffffff93ffffffe039604451ffffff8cffffffccffffff80ffffffe75c0affffffe0ffffffcf5d4dffffff8cffffffa41a
Nov 17 11:15:15 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:15:15 -0500 apsd[82]: <APSCourier: 0x15d658d0> handleReceivedPublicToken: <c150ca2f 039dc8fb a642ac22 47d8f80b abc9d186 0811a083 a4820d99 d749c09b> forTopic com.test.test identifier 
Nov 17 11:15:15 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:15:15 -0500 apsd[82]: Dispatching low priority message: <OS_xpc_dictionary: <dictionary: 0x15dc1660> { count = 4, contents =
    "identifier" => <string: 0x15db2060> { length = 0, contents = "" }
    "message-type" => <int64: 0x15dbb460>: 21
    "topic" => <string: 0x15d9a800> { length = 22, contents = "com.test.test" }
    "token" => <data: 0x15dbd9d0>: { length = 32 bytes, contents = 0xc150ca2f039dc8fba642ac2247d8f80babc9d1860811a083... }
}>

...

didRegisterForRemoteNotificationsWithDeviceToken successfully called

...

Nov 17 11:24:41 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-11-17 11:24:41 -0500 apsd[82]: _getClientIdentity: already had identity: <SecIdentityRef: 0x15da1850>

However, on phones that are not working it goes something like this,

Oct 23 10:50:55 MDM-Test-Phone-2 TestApp[145] <Warning>: >>>>>>>> APP LAUNCHED <<<<<<<<
Oct 23 10:50:56 MDM-Test-Phone-3 apsd[82] <Warning>: 2014-10-23 10:50:56 -0400 apsd[82]: peer(34) received XPC_ERROR_CONNECTION_INVALID
Oct 23 10:50:56 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:50:56 -0400 apsd[82]: _getClientIdentity: already had identity: <SecIdentityRef: 0x14dbcc20>
Oct 23 10:50:56 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:50:56 -0400 apsd[82]: peer(34) received XPC_ERROR_CONNECTION_INVALID

...

Oct 23 10:50:56 calling, [[UIApplication sharedApplication] registerForRemoteNotificationTypes:UIRemoteNotificationTypeNewsstandContentAvailability];

...

Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82]: Interface manager: WWAN radio power level notification; DCH status changed to inactive
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82]: <APSCourier: 0x14db94b0> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to NO
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82]: <APSTopicManager: 0x14db9930> isPowerEfficientToSendFilter changed to NO
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82]: <APSCourier: 0x14d74090> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to NO
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82]: <PCInterfaceUsabilityMonitor: 0x14d44ad0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Device is plugged in, overriding earlyFireProportion to be 1.0
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Calculated minimum fire date [2014-10-23 16:50:34 -0400] (98.1318%) with fire date [2014-10-23 16:57:34 -0400], start date [2014-10-23 10:42:52 -0400], minimum early fire proportion 0.981318, power state detection supported: yes, in high power state: no
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82]: <PCInterfaceUsabilityMonitor: 0x14d44ad0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> Device is plugged in, overriding earlyFireProportion to be 1.0
Oct 23 10:51:05 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:05 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> Calculated minimum fire date [2014-10-23 11:24:44 -0400] (100%) with fire date [2014-10-23 11:24:44 -0400], start date [2014-10-23 10:43:51 -0400], minimum early fire proportion 0, power state detection supported: yes, in high power state: no
Oct 23 10:51:07 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:07 -0400 apsd[82] interfacemanager-wifiautoassoc: SimpleTimer <PCSimpleTimer: 0x14d72cd0> has fired
Oct 23 10:51:07 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:07 -0400 apsd[82] interfacemanager-wifiautoassoc: Invalidating simple timer <PCSimpleTimer: 0x14d72cd0>
Oct 23 10:51:07 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:07 -0400 apsd[82]: Disabling power monitoring for <PCSimpleTimer: 0x14d72cd0> - 5 timers
Oct 23 10:51:20 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:20 -0400 apsd[82] interfacemanager-wow: SimpleTimer <PCSimpleTimer: 0x14d561e0> has fired
Oct 23 10:51:20 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:20 -0400 apsd[82] interfacemanager-wow: Invalidating simple timer <PCSimpleTimer: 0x14d561e0>
Oct 23 10:51:20 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:20 -0400 apsd[82]: Disabling power monitoring for <PCSimpleTimer: 0x14d561e0> - 4 timers
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82]: Interface manager: WWAN radio power level notification; DCH status changed to active
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82]: <APSCourier: 0x14db94b0> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to YES
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82]: <APSTopicManager: 0x14db9930> isPowerEfficientToSendFilter changed to YES
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82]: <APSCourier: 0x14d74090> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to YES
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82]: <PCInterfaceUsabilityMonitor: 0x14d44ad0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Device is plugged in, overriding earlyFireProportion to be 1.0
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Calculated minimum fire date [2014-10-23 16:50:34 -0400] (98.1318%) with fire date [2014-10-23 16:57:34 -0400], start date [2014-10-23 10:42:52 -0400], minimum early fire proportion 0.981318, power state detection supported: yes, in high power state: yes
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82]: <PCInterfaceUsabilityMonitor: 0x14d44ad0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> Device is plugged in, overriding earlyFireProportion to be 1.0
Oct 23 10:51:28 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:28 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> Calculated minimum fire date [2014-10-23 11:24:44 -0400] (100%) with fire date [2014-10-23 11:24:44 -0400], start date [2014-10-23 10:43:51 -0400], minimum early fire proportion 0, power state detection supported: yes, in high power state: yes
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82]: Interface manager: WWAN radio power level notification; DCH status changed to inactive
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82]: <APSCourier: 0x14db94b0> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to NO
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82]: <APSTopicManager: 0x14db9930> isPowerEfficientToSendFilter changed to NO
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82]: <APSCourier: 0x14d74090> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to NO
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82]: <PCInterfaceUsabilityMonitor: 0x14d44ad0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Device is plugged in, overriding earlyFireProportion to be 1.0
Oct 23 10:51:36 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:36 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Calculated minimum fire date [2014-10-23 16:50:34 -0400] (98.1318%) with fire date [2014-10-23 16:57:34 -0400], start date [2014-10-23 10:42:52 -0400], minimum early fire proportion 0.981318, power state detection supported: yes, in high power state: no
Oct 23 10:51:37 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:37 -0400 apsd[82]: <PCInterfaceUsabilityMonitor: 0x14d44ad0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO
Oct 23 10:51:37 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:37 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))
Oct 23 10:51:37 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:37 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> Device is plugged in, overriding earlyFireProportion to be 1.0
Oct 23 10:51:37 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:37 -0400 apsd[82] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x14d5bad0> Calculated minimum fire date [2014-10-23 11:24:44 -0400] (100%) with fire date [2014-10-23 11:24:44 -0400], start date [2014-10-23 10:43:51 -0400], minimum early fire proportion 0, power state detection supported: yes, in high power state: no
Oct 23 10:51:55 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:55 -0400 apsd[82]: Screen did lock (Was unlocked for 100.329434 seconds)
Oct 23 10:51:55 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:55 -0400 apsd[82]: Delivering systemDidLock to <APSNetworkMonitor: 0x14d7da10>
Oct 23 10:51:55 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:55 -0400 apsd[82]: <APSNetworkMonitor: 0x14d7da10> systemDidLock, refreshing state
Oct 23 10:51:55 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:55 -0400 apsd[82]: Delivering systemDidLock to <APSNetworkMonitor: 0x14db95c0>
Oct 23 10:51:55 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:55 -0400 apsd[82]: <APSNetworkMonitor: 0x14db95c0> systemDidLock, refreshing state
Oct 23 10:51:55 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:55 -0400 apsd[82]: Delivering systemDidLock to <APSCourier: 0x14d74090>
Oct 23 10:51:55 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:55 -0400 apsd[82]: Delivering systemDidLock to <APSCourier: 0x14db94b0>
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82]: Interface manager: WWAN radio power level notification; DCH status changed to active
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82]: <APSCourier: 0x14db94b0> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to YES
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82]: <APSTopicManager: 0x14db9930> isPowerEfficientToSendFilter changed to YES
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82]: <APSCourier: 0x14d74090> <PCInterfaceMonitor: 0x14d7c5f0> interface radio hotness changed to YES
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82]: <PCInterfaceUsabilityMonitor: 0x14d44ad0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Device is plugged in, overriding earlyFireProportion to be 1.0
Oct 23 10:51:57 MDM-Test-Phone-2 apsd[82] <Warning>: 2014-10-23 10:51:57 -0400 apsd[82] com.apple.Duet.APLSScheduler: <PCPersistentTimer: 0x14dac940> Calculated minimum fire date [2014-10-23 16:50:34 -0400] (98.1318%) with fire date [2014-10-23 16:57:34 -0400], start date [2014-10-23 10:42:52 -0400], minimum early

So its pretty clear that on the phones that are working the "looking up connection on peer" is triggered immediately after registering for remote notifications. If someone with more expertise in debugging APNs console messages notices anything that stands out or has any suggestions on how to proceed debugging I'd love to hear from you!

Upvotes: 0

Views: 1712

Answers (1)

Chad Podoski
Chad Podoski

Reputation: 1003

I'm seeing the exact same problem and have a working theory that it is related to background power usage, and potentially the use of beginBackgroundTaskWithExpirationHandler. iOS potentially making decision on whether to wake up the app based on some type of power usage metric it keeps.

Related: iOS UIBackgroundMode remote-notification doesn't work on 4G

Or it is just a bug in iOS. Definitely undocumented either way and a major pita.

Upvotes: 1

Related Questions