VoIP push notifications may not be received

Users of my app have reported that they are sometimes unable to receive Voice-over-IP (VoIP) push notifications when using a SIM. (There is no problem when using WiFi)

VoIP push notifications were not received during the following period. Could you confirm diagnostic logs and could you please tell me why my app can't receive VoIP push?

[diagnostic logs] https://drive.google.com/drive/folders/1gSAbr1Fy1SrjlmRXuAzoXqiaxnNbFhj8?usp=sharing

[Problem period] 2024/06/17 05:34:59 - 2024/06/17 09:04:42 Number of times that the push server pushed and it received a normal APNs response: 31 Number of times that iPhone received pushes: 0 2024/06/17 23:05:03 - 2024/06/18 09:02:16 Number of times that the push server pushed and it received a normal APNs response: 192 Number of times that iPhone received pushes: 0

2024/06/15 00:35:56 - 2024/06/15 09:55:57 Number of times that the push server pushed and it received a normal APNs response: 138 Number of times that iPhone received pushes: 0

Answered by DTS Engineer in 798118022

I tried grep "apsd[131:", 15:45:11.000+0900","15:34:22.998+0900", and "09:06:19.991+0900" for *.txt *.log in all sysdiagnoses, but there were no hits. How can I read sysdiagnose? Do I need to do any further processing on the resulting files after decompress tar? Also, is it OK for developers to read sysdiagnose?

A sysdiagnose archive is a standard zip archive with a bunch of files it. Of those files, the largest and most useful file is by FAR the file named "system_logs.logarchive". In the vast majority of cases, "sysdiagnose analysis" actually means "open the console logarchive and try to figure out what happened".

The post "Your Friend the System Log" has some good background on how else that file can be processed and manipulated but most of the time you'll be opening an viewing the file with Console.app. That's what will open it by default if you just double click on the archive.

The actual analysis process isn't easy to quickly summarize, as it relies as much on becoming familiar with how the system operates and logs, as well as inferring what's gone on using the information at hand. However, here's my informal "guide" to using Console.app for this sort of analysis:

a) In Big Sur, Console.app got a HUGE but easy to overlook feature. In the bottom left corner of the console window, the "Showing" popup now has an extra item called "Custom", which allows you to specify a particular time range. That SINGLE feature is a absolutely essential, as the total log size is often SO large that it's impossible to make useful progress by simply "scrolling blind".

b) On a related note, you can right click on the table header to customize exactly what fields are shown and hidden. Exactly what columns you use is entirely up to you, but my basic list in order is:

  • Time -> "when" is obviously critical in this entire process

  • Process/Library/subsystem-> all of these can be used to change the change exactly what subset of the log data you're looking at.

  • PID:Thread ID-> PID is critical because it let you differentiate between different launches of the same component, as well as filtering down to a specific process launch. Thread ID is a bit less critical, but it can let you trace a thread of "logic" inside a component that's processing multiple things at a time. These can be shown as seperate columns, but I generally combine them to reduce the column count.

  • Message-> What the system logged, which is obviously critical.

In terms of basic the basic "flow" I use for an looking at this sort of log, this is what I actually do, as well as some tips/tricks:

  1. Narrowing the time range to what's "interesting" is the single most critical step. This is also why any kind of external information is so helpful. Knowing that an issue occurred within a 5 min. range is enormously helpful

  2. Ruthlessly trim the remaining data until I find something "interesting". Note that you can "right click" on any entry and use that to refine/prune what's being shown. For a voip/CallKit issue, right clicking on a callservicesd and selecting "Show process callservicesd" is often the first place I start. If the issue is less clearcut I'll often work the other way and just hide processes that don't seem "interesting" until something catches my eye.

  3. The other columns give you other tools you can manipulate the data with. For example, "Library" can be very useful, since it will let you trace activity across processes. If you chose "CallKit", you'd see any message the CallKit framework logged inside your app AND the actual CallKit usage inside callservicesd, which can let you trace things across frameworks. Similarly, if you "know" the problem isn't going to involve any sort of networking you can simply hide the libraries that aren't relevant.

  4. The analysis process generally involves narrowing and expanding your search terms and time range as you try and sort out what actually happened. One trick here is that you can cut and paste the contents of the "search". I actually leave a text editor open and use it as a "scratch pad" as I'm working. I'll copy out log message that seem important, but I'll also save the search string itself, then continue narrowing. I can then go "back" to the previous state by building out the search box myself, instead of doing each to the steps manually.

On the "tip" side:

  • If you have any sort of in app logging (and if you don't, you should) make sure you're log prints into the general console as well as to whatever other source/location you use. If you do this right, your individual log will have EXACTLY the same timestamps as the console log, which means you can use to standalone log as an "index" into the system log, using the data in your app log to find "interesting" times in console log.

  • Also, I'd recommend logging the "pid" in your own logs as well as whatever else your logging. That makes it easy to differentiate between different launches of your app and can also be used to quickly narrow data in the same way other metadata can.

  • Be aware of what the system can and cannot tell you. The log will tell you what happened in the system and what went wrong in the system. It cannot tell you what happened outside of the system. It can tell you when a push arrived and it can show you how that push was processed. You MIGHT be able to tell you whether or not the device had an active network connection. It CANNOT tell you why a push didn't arrive or what was "wrong" with the network it was connected to.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

////////

I'll correct the line feed and repost it.

////////

Users of my app have reported that they are sometimes unable to receive Voice-over-IP (VoIP) push notifications when using a SIM. (There is no problem when using WiFi)

VoIP push notifications were not received during the following period. Could you confirm diagnostic logs and could you please tell me why my app can't receive VoIP push?

[diagnostic logs] https://drive.google.com/drive/folders/1gSAbr1Fy1SrjlmRXuAzoXqiaxnNbFhj8?usp=sharing

[Problem period]

  • 2024/06/17 05:34:59 - 2024/06/17 09:04:42

Number of times that the push server pushed and it received a normal APNs response: 31

Number of times that iPhone received pushes: 0

  • 2024/06/17 23:05:03 - 2024/06/18 09:02:16

Number of times that the push server pushed and it received a normal APNs response: 192

Number of times that iPhone received pushes: 0

  • 2024/06/15 00:35:56 - 2024/06/15 09:55:57

Number of times that the push server pushed and it received a normal APNs response: 138

Number of times that iPhone received pushes: 0

You uploaded 4 sysdiagnose files, but none of them contain useful information. More specifically:

The timestamps on the last message of this log:

sysdiagnose_2024.06.14_15-43-50+0900_iPhone-OS_iPhone_21D61
...
2024-06-14 15:45:11.000+0900 wifid[49:15341] []....

And this log:

sysdiagnose_2024.06.14_15-33-02+0900_iPhone-OS_iPhone_21D61
...
2024-06-14 15:34:22.998+0900 SafariBookmarksSyncAgent[344:5498]...

Are both much earlier than the earliest data you listed:

2024/06/15 00:35:56 - 2024/06/15 09:55:57
At the other extreme, this log the earliest message in this log:

sysdiagnose_2024.06.19_14-05-21+0900_iPhone-OS_iPhone_21D61
...
2024-06-18 09:06:19.991+0900 fairplayd.H2[93:1372] ...

Is shortly after the last time frame you referenced: 2024/06/17 23:05:03 - 2024/06/18 09:02:16

The last sysdiagnose did cover that time window:

sysdiagnose_2024.06.19_14-01-41+0900_iPhone-OS_iPhone_21D61

However, the log has fairly clearly been heavily purged during that time window, probably because of device reboot at some point after the relavant window. For future reference, it's very fairly easy to determine that the log has been purged just by looking at the data logged inside the time window. Notable:

  • The total log value will be much smaller than you'd normally expect. In the time window above, there were only ~900 log message, when several 100,000 would be normal.

  • Critical components (kernel, springboardd, runningboardd, apsd, callservicesd...) that generate high log volume will be completely absent.

You did specifically mention that this was a cellular issue:

Users of my app have reported that they are sometimes unable to receive Voice-over-IP (VoIP) push notifications when using a SIM

So, out of curiosity, I did look to see if apsd might have an indication of what's going on. If I filter out everything but apsd and search for "Interface Manager: WWAN", what I get is 172 alternating log message that start here:

2024-06-19 07:57:01.601+0900 apsd[131:1547567] [usabilityMonitor] <PCInterfaceUsabilityMonitor: 0xd5c840f40> Interface Manager: WWAN(pdp_ip0) LinkQuality changed from good to poor (50)
2024-06-19 07:57:47.681+0900 apsd[131:1547897] [usabilityMonitor] <PCInterfaceUsabilityMonitor: 0xd5c840f40> Interface Manager: WWAN(pdp_ip0) LinkQuality changed from poor to good (100)

And end here:

2024-06-19 13:38:42.046+0900 apsd[131:1655081] [usabilityMonitor] <PCInterfaceUsabilityMonitor: 0xd5c840f40> Interface Manager: WWAN(pdp_ip0) LinkQuality changed from poor to good (100)
2024-06-19 14:01:53.418+0900 apsd[131:1662233] [usabilityMonitor] <PCInterfaceUsabilityMonitor: 0xd5c840f40> Interface Manager: WWAN(pdp_ip0) LinkQuality changed from good to poor (50)

Note that the time window there is fairly narrow (~5 1/2 hours). Assuming even distribution (which they're almost certainly not), that works out to ~32 transitions per hour or ~1 transition every 2 minutes. with more work you could use the timestamps to determine when cellular was available and when it was not, but the fact they're happening at all is a pretty clear indication that their cellular connectivity is not great.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

I tried grep "apsd[131:", 15:45:11.000+0900","15:34:22.998+0900", and "09:06:19.991+0900" for *.txt *.log in all sysdiagnoses, but there were no hits. How can I read sysdiagnose? Do I need to do any further processing on the resulting files after decompress tar? Also, is it OK for developers to read sysdiagnose?

I would like to confirm myself start/end time of logs on next time, so could you tell me about it?

I tried grep "apsd[131:", 15:45:11.000+0900","15:34:22.998+0900", and "09:06:19.991+0900" for *.txt *.log in all sysdiagnoses, but there were no hits. How can I read sysdiagnose? Do I need to do any further processing on the resulting files after decompress tar? Also, is it OK for developers to read sysdiagnose?

A sysdiagnose archive is a standard zip archive with a bunch of files it. Of those files, the largest and most useful file is by FAR the file named "system_logs.logarchive". In the vast majority of cases, "sysdiagnose analysis" actually means "open the console logarchive and try to figure out what happened".

The post "Your Friend the System Log" has some good background on how else that file can be processed and manipulated but most of the time you'll be opening an viewing the file with Console.app. That's what will open it by default if you just double click on the archive.

The actual analysis process isn't easy to quickly summarize, as it relies as much on becoming familiar with how the system operates and logs, as well as inferring what's gone on using the information at hand. However, here's my informal "guide" to using Console.app for this sort of analysis:

a) In Big Sur, Console.app got a HUGE but easy to overlook feature. In the bottom left corner of the console window, the "Showing" popup now has an extra item called "Custom", which allows you to specify a particular time range. That SINGLE feature is a absolutely essential, as the total log size is often SO large that it's impossible to make useful progress by simply "scrolling blind".

b) On a related note, you can right click on the table header to customize exactly what fields are shown and hidden. Exactly what columns you use is entirely up to you, but my basic list in order is:

  • Time -> "when" is obviously critical in this entire process

  • Process/Library/subsystem-> all of these can be used to change the change exactly what subset of the log data you're looking at.

  • PID:Thread ID-> PID is critical because it let you differentiate between different launches of the same component, as well as filtering down to a specific process launch. Thread ID is a bit less critical, but it can let you trace a thread of "logic" inside a component that's processing multiple things at a time. These can be shown as seperate columns, but I generally combine them to reduce the column count.

  • Message-> What the system logged, which is obviously critical.

In terms of basic the basic "flow" I use for an looking at this sort of log, this is what I actually do, as well as some tips/tricks:

  1. Narrowing the time range to what's "interesting" is the single most critical step. This is also why any kind of external information is so helpful. Knowing that an issue occurred within a 5 min. range is enormously helpful

  2. Ruthlessly trim the remaining data until I find something "interesting". Note that you can "right click" on any entry and use that to refine/prune what's being shown. For a voip/CallKit issue, right clicking on a callservicesd and selecting "Show process callservicesd" is often the first place I start. If the issue is less clearcut I'll often work the other way and just hide processes that don't seem "interesting" until something catches my eye.

  3. The other columns give you other tools you can manipulate the data with. For example, "Library" can be very useful, since it will let you trace activity across processes. If you chose "CallKit", you'd see any message the CallKit framework logged inside your app AND the actual CallKit usage inside callservicesd, which can let you trace things across frameworks. Similarly, if you "know" the problem isn't going to involve any sort of networking you can simply hide the libraries that aren't relevant.

  4. The analysis process generally involves narrowing and expanding your search terms and time range as you try and sort out what actually happened. One trick here is that you can cut and paste the contents of the "search". I actually leave a text editor open and use it as a "scratch pad" as I'm working. I'll copy out log message that seem important, but I'll also save the search string itself, then continue narrowing. I can then go "back" to the previous state by building out the search box myself, instead of doing each to the steps manually.

On the "tip" side:

  • If you have any sort of in app logging (and if you don't, you should) make sure you're log prints into the general console as well as to whatever other source/location you use. If you do this right, your individual log will have EXACTLY the same timestamps as the console log, which means you can use to standalone log as an "index" into the system log, using the data in your app log to find "interesting" times in console log.

  • Also, I'd recommend logging the "pid" in your own logs as well as whatever else your logging. That makes it easy to differentiate between different launches of your app and can also be used to quickly narrow data in the same way other metadata can.

  • Be aware of what the system can and cannot tell you. The log will tell you what happened in the system and what went wrong in the system. It cannot tell you what happened outside of the system. It can tell you when a push arrived and it can show you how that push was processed. You MIGHT be able to tell you whether or not the device had an active network connection. It CANNOT tell you why a push didn't arrive or what was "wrong" with the network it was connected to.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Thank you for your detailed explanation. This problem reappeard and I received a new sysdiagnose, so I checked the log myself based on your advice. The complaint from my customer this time was that an APNs PUSH was sent during the following times 1 to 3, but the PUSH did not arrive and VoIP calls could not be received.

  1. 2024-08-08 03:47:16
  2. 2024/08/08 15:32:09
  3. 2024/08/08 15:32:24

I read the sysdiagnose and found that there was no sysdiagnose during the following periods. This is coincides with the time when PUSH was not received.

2024-08-08 01:53:01.925793 +0900 to 2024 - 08-08 05:35:43.505458 +0900

2024-08-08 15:31:33.819839 +0900 to 2024 - 08-08 15:32:35.081712 +0900

Why is there no sysdiagnose?

[sysdiagnose]

https://drive.google.com/file/d/1bT4rix7Y4BqqJX-EW4Zp4peiC7ygED2f/view?usp=sharing

I feel the iPhone may have been turned off, so if there is a log that proves this, I want to tell it to customer, if yes, please tell me the keywords to search in the log. Also, I understood that when the iPhone is turned off, the sysdiagnose before the power was turned off disappears, but is this a misunderstanding? If the period without sysdiagnose above indicates that the power was turned off, the sysdiagnose of this will contain the log before the power was turned off.

Best Regards,

This customer is using local push in a Wi-Fi Area, And using APNs push out of a Wi-Fi Area(=in a LTE) The following issues were reported in each area.

About local push issue

Could you tell me mean of following error in a sysdiagnose202408.zip > localpush-sysdiagnose?


2024-08-08 09:42:39.411505+900: nssessionmanager NESMAppPushSession[LocalPushDefaultConfiguration:CF5370FF-878F-4B2E-B39A-8B672E9F678F] failed to report incoming call to CallKit, error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.callkit.networkextension.messagecontrollerhost was invalidated from this process." UserInfo={NSDebugDescription=The connection to service named com.apple.callkit.networkextension.messagecontrollerhost was invalidated from this process.}


Extention called reportIncomingCall at 2024-08-08 09:42:39.406(I confirmed it from my VoIP app log), but iOS doesn't kick my VoIP application. Does above log specify cause of this behaviour? (Not only this, but even for 182 calls from 2024-08-08 09:29:20.256 to 2024-08-08 15:33:45.096, iOS did not kick my VoIP application.)

About APNs push issue

Between 2024-08-08 19:34:16.813 and 2024-08-09 09:27:29.415, Customer is reporting that used my VoIP app via LTE connection. And during that time the server sent a PUSH request 144 times to APNs(I confirmd this from my server log), but the APNs PUSH was not received on an iPhone. (didReceiveIncomingPushWithPayload was not called). Why? Can I confirm below about this from sysdiagnos? If yes, please tell me keyword of sysdiagnose filter. I will confirm sysdiagnose202408.zip > apnspush-sysdiagnose.

  • Did iPhone have an active LTE network connection during this time?
  • If there is evidence that customer were using a Wi-Fi network instead of LTE during this time?(If there is a Wi-Fi without Internet connectivity and local push unregistered, I think they will not receive APNs push.)

sysdiagnose202408.zip

https://drive.google.com/file/d/1zT0r7cOSgESbwX0X1ekgGUjZG4309Ysy/view?usp=drive_link

Best Regards,

Between 2024-08-08 19:34:16.813 and 2024-08-09 09:27:29.415, Customer is reporting that used my VoIP app via LTE connection. And during that time the server sent a PUSH request 144 times to APNs(I confirmd this from my server log), but the APNs PUSH was not received on an iPhone. (didReceiveIncomingPushWithPayload was not called). Why?

A few different issues:

  • An update had been installed and the device had not been unlocked. Note messages like:
2024-08-08 19:34:55.328+0900 routined[38:1637] [DATA PROTECTION] unlocked since boot, NO
2024-08-08 19:34:56.329+0900 atc[47:2598] [Default] Device locked, waiting for first unlock.
2024-08-08 19:34:58.530+0900 carkitd[153:2177] [DNDWD] Not fetching vehicle state - device has not unlocked since boot.
2024-08-08 19:34:59.066+0900 sharingd[68:3068] [AutoUnlock] ### Device not unlocked on start up after retry (state: <private>)
2024-08-08 19:35:00.546+0900 itunesstored[202:3664] [StoreServices] SSXPCServer: Invalidating connection; device has not been unlocked since boot

and then later:


2024-08-09 09:27:25.112+0900 sharingd[68:1354] [PairedUnlock] Transitioned out of lock screen.

2024-08-09 09:27:25.112+0900 sharingd[68:1354] [PairedUnlock] Transitioned out of lock screen.


  • apsd launch, but is unable to register properly because of the protection state:
2024-08-08 19:34:47.734+0900 apsd[134:1862] [xpc] Requesting container lookup; class = 12, identifier = <private>, group_identifier = <private>, create = 1, temp = 0, euid = 501, uid = 501
2024-08-08 19:34:47.734+0900 apsd[134:1862] [xpc] Query; euid = 501, uid = 501, class = 12, identifier = [(null)](0), flags = 900000003
2024-08-08 19:34:47.738+0900 apsd[134:1862] [unspecified] container_query_get_single_result: success
2024-08-08 19:34:47.738+0900 apsd[134:1862] [sandbox] Consumed sandbox extension; path = [<private>], handle = 1
2024-08-08 19:34:47.738+0900 apsd[134:1862] [unspecified] container_system_path_for_identifier: success
2024-08-08 19:34:47.754+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()
2024-08-08 19:34:47.761+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()
2024-08-08 19:34:47.766+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()
2024-08-08 19:34:47.770+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()

Could you tell me mean of following error in a sysdiagnose202408.zip > localpush-sysdiagnose?

If you search for "failed to report", the cause is fairly clear. The messages occur in alternating pairs between callservicesd and nesessionmanager:

2024-08-09 09:54:39.235+0900 nesessionmanager[228:62692] [] NESMAppPushSession[LocalPushDefaultConfiguration:7EC72C65-84F2-4167-A654-11B9CEEE5953] failed to report incoming call to CallKit, error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.callkit.networkextension.messagecontrollerhost was invalidated from this process." UserInfo={NSDebugDescription=The connection to service named com.apple.callkit.networkextension.messagecontrollerhost was invalidated from this process.}
2024-08-09 09:54:39.239+0900 callservicesd[133:62552] [Default] Application <bundle id> will not be launched because it failed to report an incoming call too many times (or repeatedly crashed.)

Later message don't pair up quite as clearly, but I think that's mainly because callservicesd is logging slightly differently:

2024-08-09 11:39:12.367+0900 callservicesd[133:88002] [Default] VoIP push for app <bundle id> dropped on the floor

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Thank you for your comment

About APNs push issue

To sum up , I understand that the content is as follows, is this correct? Please let me know if I have misunderstood anything.

  1. In order to make a VoIP call via APNs PUSH, we must unlock the iPhone at least once after turning on an iPhone.
  2. If the iPhone remains in a locked state after being turned on an iPhone, we will not be able to make VoIP calls via APNs PUSH.
  3. If an iPhone continues to receive calls in state "2" and the number of calls exceeds a certain number, it will no longer be able to receive calls even after unlocking.

Points 1 to 3 above are iPhone specifications and cannot be avoided by modifying the application. So, when using a VoIP application that uses APNs PUSH, customer must unlock their iPhone immediately after turning on an iPhone.

About local push issue

How about this issue?

Could this also be because customer doesn't unlock an iPhone? I think that unless custmer unlock an iPhone, iPhone will not detect that it is in Wi-Fi range, Extension will not start, But Extention had started when problem happen. so, I guess that custmer unlock an iPhone.

Or if there is a problem(above point3 problem) with APN push, will Local push also become unavailable?

To sum up , I understand that the content is as follows, is this correct? Please let me know if I have misunderstood anything.

In order to make a VoIP call via APNs PUSH, we must unlock the iPhone at least once after turning on an iPhone.

Strictly speaking, the EXACT behavior here is complicated and has not been consistent from system version to system version. In particular:

  1. On more recent system/device, it is possible for the device to "reboot" itself WITHOUT performing a full security "reset". The result is that it is possible for a device to install an update WITHOUT returning to "prior to first unlock".

  2. The standard behavior of the system is that it should NOT run apps "prior to first unlock".

  3. Historically, I have seen case where voip apps WERE run prior to first unlock.

Note that it can be difficult to differentiate #1 and #3, so it isn't always clear "why" incoming calls are working on a specific system version. Given that reality, my best advice is that:

  • voip apps should be prepared to run prior to first unlock and be prepared to handle that case "gracefully".

  • voip apps should NOT assume that they WILL "always" run prior to first unlock, as the behavior has not been consistent.

If the iPhone remains in a locked state after being turned on an iPhone, we will not be able to make VoIP calls via APNs PUSH.

Yes, that's what the log showed.

If an iPhone continues to receive calls in state "2" and the number of calls exceeds a certain number, it will no longer be able to receive calls even after unlocking.

No, that is NOT correct.

Please refer to the log again. During the ENTIRE period prior to first unlock, both apnsd and callservicesd showed almost no activity and the ONLY logging from apnsd was about it's FAILURE to properly register topics with the apns server. No pushes whatsoever were received at ANY point prior to first unlock.

Your app could not have been penalized for failing to report a call during that time, as no push ever reached the device.

One point I want to be very clear on here issue is that, in my experience, the sequence that transfers a push from:

apnsd-> callservicesd-> <target app>

...is one of the most reliable sequences I've ever seen in the system. Have worked with PushKit since its introduction in iOS 8 and looked at 100s (possibly 1000s) of call failure sysdiagnose logs, I have NEVER seen the process fail. The ONLY reasons I have EVER seen a voip push "fail" on iOS are:

  1. The push never reached the device at all, generally due to a network or system level issue.

  2. callservicesd was unable to deliver the push due to an app level failure. Common failures include:

  • Crashing on launch
  • Expecting the user to log in before initializing PushKit (which can't occur for a background launch).
  • Other app bugs during early launch or push processing.
  1. (post iOS 13) The app had failed to report to many calls, so callservicesd stopped push delivery.

Notably, this sequence has worked fine in every "prior to first unlock" log I've seen. Every problem I've investigated in that case has been caused by the app failing to work properly prior to first unlock, NOT the system failing to handle the push correctly.

Points 1 to 3 above are iPhone specifications and cannot be avoided by modifying the application. So, when using a VoIP application that uses APNs PUSH, customer must unlock their iPhone immediately after turning on an iPhone.

Customer's may need to unlock their phone after a total power failure or major system update before they can receive voip calls.

Could this also be because customer doesn't unlock an iPhone?

Yes. Similar to voip, I suspect the exact behavior here is likely to vary, but your local push extension did not launch until after first unlock.

Or if there is a problem(above point3 problem) with APN push, will Local push also become unavailable?

If your app fails to report PushKit calls, then this can also effect the delivery of local push connectivity. However, simply receiving voip pushes prior to first unlock will not cause your app to fail or be penalized.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

I have asked the customer to do unlock the iPhone as soon as it is turned on, and they are supposed to do so, but we have received additional questions about this behavior.

Because APNs push and local push are mixed up in my logs, I am a bit confused and unable to answer the customer yet now.

For this reason, I have separated APNs push and local push, and arranged the app and iPhone operations in chronological order.

Looking at this, could you please answer the following three questions?

[Question 1]

If my arrange the app and iPhone operations in chronological order, they would look like this. Do you agree with me on this?

[Question 2]

In this log, should I suspect that the inability to receive APNs PUSH at point 5 is due to a network problem? There was no problem with the network, and the iPhone was not unlocked, so did it simply discard the PUSH received from the network? (From what I understand, I assume it's the latter.)

[Question 3]

I believe that the sysdiagnose log at points 8 and 10 is a log for local push incoming calls, but do you know why they are failing?

/////////////////////////////////////////

For LOCAL PUSH INFO: point1(My app log info)

Stop Extention (Moved to Wi-Fi out of area)

2024-08-08 19:34:16.813+0900  

For APNS PUSH INFO: point2(sysdiagnose log info)

An update had been installed and the device had not been unlocked. Note messages like:

2024-08-08 19:34:55.328+0900 routined[38:1637] [DATA PROTECTION] unlocked since boot, NO
2024-08-08 19:34:56.329+0900 atc[47:2598] [Default] Device locked, waiting for first unlock.
2024-08-08 19:34:58.530+0900 carkitd[153:2177] [DNDWD] Not fetching vehicle state - device has not unlocked since boot.
2024-08-08 19:34:59.066+0900 sharingd[68:3068] [AutoUnlock] ### Device not unlocked on start up after retry (state: <private>)
2024-08-08 19:35:00.546+0900 itunesstored[202:3664] [StoreServices] SSXPCServer: Invalidating connection; device has not been unlocked since boot

For APNS PUSH INFO: point3(sysdiagnose log info)

and then later

2024-08-09 09:27:25.112+0900 sharingd[68:1354] [PairedUnlock] Transitioned out of lock screen.
2024-08-09 09:27:25.112+0900 sharingd[68:1354] [PairedUnlock] Transitioned out of lock screen.

For APNS PUSH INFO: point4(sysdiagnose log info)

apsd launch, but is unable to register properly because of the protection state

2024-08-08 19:34:47.734+0900 apsd[134:1862] [xpc] Requesting container lookup; class = 12, identifier = <private>, group_identifier = <private>, create = 1, temp = 0, euid = 501, uid = 501
2024-08-08 19:34:47.734+0900 apsd[134:1862] [xpc] Query; euid = 501, uid = 501, class = 12, identifier = [(null)](0), flags = 900000003
2024-08-08 19:34:47.738+0900 apsd[134:1862] [unspecified] container_query_get_single_result: success
2024-08-08 19:34:47.738+0900 apsd[134:1862] [sandbox] Consumed sandbox extension; path = [<private>], handle = 1
2024-08-08 19:34:47.738+0900 apsd[134:1862] [unspecified] container_system_path_for_identifier: success
2024-08-08 19:34:47.754+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()
2024-08-08 19:34:47.761+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()
2024-08-08 19:34:47.766+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()
2024-08-08 19:34:47.770+0900 apsd[134:1862] [connectionServer] Attempt to set push wake topics without dark wake enabled: ()

For APNS PUSH INFO: point5(My push server log info)

sent VoIP push 144 times.

from
2024-08-08 19:56:25.046+0900 
to
2024-08-09 09:27:01.206+0900 

For LOCAL PUSH INFO: point6(My app log info)

Start Extention (Moved to Wi-Fi in area)

2024-08-09 09:27:29.415+0900 

For LOCAL PUSH INFO: point7(My app log info)

My app log info: Incomming call

2024-08-09 09:54:39.209+0900 

For LOCAL PUSH INFO??: point8(sysdiagnose log info)

If you search for "failed to report", the cause is fairly clear.
The messages occur in alternating pairs between callservicesd and nesessionmanager:

2024-08-09 09:54:39.235+0900 nesessionmanager[228:62692] [] NESMAppPushSession[LocalPushDefaultConfiguration:7EC72C65-84F2-4167-A654-11B9CEEE5953] failed to report incoming call to CallKit, error: Error Domain=NSCocoaErrorDomain Code=4099 "The connection to service named com.apple.callkit.networkextension.messagecontrollerhost was invalidated from this process." UserInfo={NSDebugDescription=The connection to service named com.apple.callkit.networkextension.messagecontrollerhost was invalidated from this process.}
2024-08-09 09:54:39.239+0900 callservicesd[133:62552] [Default] Application <bundle id> will not be launched because it failed to report an incoming call too many times (or repeatedly crashed.)

For LOCAL PUSH INFO: point9(My app log info)

My app log info: Incomming call

2024-08-09 11:39:12.336+0900 

For LOCAL PUSH INFO??: point10(sysdiagnose log info)

Later message don't pair up quite as clearly, but I think that's mainly because callservicesd is logging slightly differently

2024-08-09 11:39:12.367+0900 callservicesd[133:88002] [Default] VoIP push for app <bundle id> dropped on the floor

Best Regards,

[Question 1] If my arrange the app and iPhone operations in chronological order, they would look like this. Do you agree with me on this?

No. Point "3" is in the wrong place. In your sequence, it would occur between point5 and point6. Also, the likely cause of this:

Stop Extention (Moved to Wi-Fi out of area)

...was the device powering down (why it transitioned to "prior to first unlock").

Similarly, note the timing of events here:

2024-08-09 09:27:25.112+0900 sharingd[68:1354] [PairedUnlock] Transitioned out of lock screen.

And then here:

Start Extention (Moved to Wi-Fi in area)
2024-08-09 09:27:29.415+0900 

What happened here wasn't that that the device moved into Wi-Fi range, it's that the device unlock gave the system access to WiFi credentials, which then lead to your extension running.

[Question 2] In this log, should I suspect that the inability to receive APNs PUSH at point 5 is due to a network problem?

The issue here is step 4:

apsd launch, but is unable to register properly because of the protection state

apsd needs token data from the keychain in order to properly register (you could also think of this as "logging in") with the push server, so without proper registration it can't receive pushes. Breaking that down in more detail, the device needs to be able to tell the push server "who" it is, so the push server knows what pushes to send it. If apsd knows it can't do that (because the data is protected and the device is still "prior to first unlock") then it doesn't even try to connect to the push server, as there wouldn't be any point. Once the device goes through first unlock, apsd will the connect and the push server will then start sending pushes.

There was no problem with the network, and the iPhone was not unlocked, so did it simply discard the PUSH received from the network?

Answering that question from the two different perspectives:

  1. From the servers perspective, the device was simply "gone" until it was unlocked and apsd registered with our servers. Our server could not send any pushes to the target device because the device wasn't connected to our servers. The server discarded undelivered pushes using the same processing logic it uses for any undelivered push.

  2. The iPhone never received any pushes at all until the device was unlocked.

[Question 3] I believe that the sysdiagnose log at points 8 and 10 is a log for local push incoming calls, but do you know why they are failing?

Because you've failed to report calls to CallKit to many times. The logging is different because of slightly different app states and code paths, but the basic issue is exactly the same.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

VoIP push notifications may not be received
 
 
Q