blank e-mission-phone prompts after upgrade from iOS 10 to iOS 11

[shankari]

This was reported by Randy, and I tried to reproduce it. First, I ensured that push notifications were working properly by turning on visible notifications. Then I upgraded to iOS 11. Then I just left the app untouched for several hours. When I next checked the phone, it appeared to have the e-mission-phone prompts.

But before I could download the logs, another silent push occurred, and the only messages were about the successful push. It even said "No more messages". So I am not sure whether the previous logs were lost or not.

[shankari]

Related logs:

• before upgrade (e-mission logs): loggerDB.before_upgrade.withdate.log.gz

• during + after upgrade (device logs): during_upgrade.log.gz

• during + after upgrade (e-mission logs) loggerDB.after_upgrade.withdate.log.gz

[shankari]

just got the next push, basically we get a bunch of messages related to a successful push, and one notification that is just e-mission-phone. Turning off "Simulate user" to confirm behavior that Randy sees.

[shankari]

Confirmed that when "Simulate user" is turned off, we get a blank notification.

Repro 1	Repro with many more calls

Now that I know that this is reproducible, and that it is not fixed by just opening the app, I can investigate further.

[shankari]

Basic checks: the login seems to be correct. I know that the silent push is working because of the previous messages with "Simulate user" = true Just to confirm - went to the dashboard and refreshed, and it seems to be working just fine

[shankari]

Looking at the logs, this was the last successful push before the upgrade.

1298,1506207610.43,2017-09-23 16:00:10.432920-07:53,"After clear complete, cache has entries stats/client_nav_event, trip_ended, connection_settings, stats/client_time, config/consent, statemachine/transition, background/battery, intro_done, config/sensor_config, config/sync_config, diary/trips-2017-08-30, diary/trips-2017-08-28, diary/trips-2017-08-29, common-trips"
1299,1506207610.52,2017-09-23 16:00:10.518710-07:53,Received platform-specific notification T_DATA_PUSHED
1300,1506207610.53,2017-09-23 16:00:10.533820-07:53,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
1301,1506207610.59,2017-09-23 16:00:10.588220-07:53,Received notification T_DATA_PUSHED while processing silent push notification
1302,1506207610.68,2017-09-23 16:00:10.676750-07:53,"Data pushed, fetch result = new data"
1303,1506207610.69,2017-09-23 16:00:10.690880-07:53,"in handleSilentPush, sending result to id DataCollection835259036"
1304,1506207610.71,2017-09-23 16:00:10.708750-07:53,"in handleSilentPush, sending result to id DataCollection835259036"
1305,1506207610.81,2017-09-23 16:00:10.805100-07:53,"silent push finished successfully, calling push.finish"

Then there was a big gap and then the app restarted at 21:17 (9:17pm). Consent is still present, which is good, because we don't have to solve this problem, but is not that good because it means that the root cause is not that easy to understand.

1308,1506226670.86,2017-09-23 21:17:50.857760-07:53,"reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14"
1309,1506226670.87,2017-09-23 21:17:50.874750-07:53,isConsented = YES

1314,1506226671.02,2017-09-23 21:17:51.016500-07:53,"intro_done result = {
    ""INTRO_DONE_KEY"" = ""2017-09-22T21:32:02-07:00"";
}"

Aha! It looks like we receive the silent push notification, and it has title = "e-mission-phone" and no message. pre-iOS 11, the content-available:1 field would indicate that it is a silent push notification. But in iOS11, it looks like it is displayed anyway.

1372,1506226678.39,2017-09-23 21:17:58.385110-07:53,"data = {""message"":{""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506225601705592},""foreground"":false,""coldstart"":false,""notId"":1506225601705592}},""title"":""e-mission-phone"",""app"":{""asleep"":true,""closed"":false},""payload"":{""notId"":1506225601705592}},""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506225601705592},""foreground"":false,""coldstart"":false,""notId"":1506225601705592}}}"
1373,1506226678.41,2017-09-23 21:17:58.406050-07:53,"data = {""message"":{""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506225601705592},""foreground"":false,""coldstart"":false,""notId"":1506225601705592}},""title"":""e-mission-phone"",""app"":{""asleep"":true,""closed"":false},""payload"":{""notId"":1506225601705592}},""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506225601705592},""foreground"":false,""coldstart"":false,""notId"":1506225601705592}}}"
1374,1506226678.43,2017-09-23 21:17:58.434310-07:53,"Found silent push notification, for platform ios"
1375,1506226678.45,2017-09-23 21:17:58.451010-07:53,"Platform is ios, calling handleSilentPush on DataCollection"
1376,1506226678.55,2017-09-23 21:17:58.553650-07:53,handleSilentPush outside the try block = DataCollection1562452109
1377,1506226678.57,2017-09-23 21:17:58.573120-07:53,"Before invoking launchTripEndCheckAndRemoteSync, id = DataCollection1562452109"
1378,1506226678.59,2017-09-23 21:17:58.587420-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"

Let's see if this behavior was changed in iOS 11

[shankari]

The logs pre-iOS11 upgrade are identical

1155,1506197005.7,2017-09-23 13:03:25.703360-07:53,Application went to the background
1156,1506200408.54,2017-09-23 14:00:08.543800-07:53,"data = {""message"":{""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506200401611756},""foreground"":false,""coldstart"":false,""notId"":1506200401611756}},""title"":""e-mission-phone"",""app"":{""asleep"":true,""closed"":false},""payload"":{""notId"":1506200401611756}},""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506200401611756},""foreground"":false,""coldstart"":false,""notId"":1506200401611756}}}"
1157,1506200408.56,2017-09-23 14:00:08.563350-07:53,"data = {""message"":{""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506200401611756},""foreground"":false,""coldstart"":false,""notId"":1506200401611756}},""title"":""e-mission-phone"",""app"":{""asleep"":true,""closed"":false},""payload"":{""notId"":1506200401611756}},""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506200401611756},""foreground"":false,""coldstart"":false,""notId"":1506200401611756}}}"
1158,1506200408.61,2017-09-23 14:00:08.610060-07:53,"Found silent push notification, for platform ios"
1159,1506200408.63,2017-09-23 14:00:08.630310-07:53,"Platform is ios, calling handleSilentPush on DataCollection"
1160,1506200408.68,2017-09-23 14:00:08.675910-07:53,handleSilentPush outside the try block = DataCollection835259016
1161,1506200408.7,2017-09-23 14:00:08.700820-07:53,"Before invoking launchTripEndCheckAndRemoteSync, id = DataCollection835259016"
1162,1506200408.72,2017-09-23 14:00:08.721360-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"

and

1206,1506204007.88,2017-09-23 15:00:07.884080-07:53,"data = {""message"":{""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506204001792803},""foreground"":false,""coldstart"":false,""notId"":1506204001792803}},""title"":""e-mission-phone"",""app"":{""asleep"":true,""closed"":false},""payload"":{""notId"":1506204001792803}},""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506204001792803},""foreground"":false,""coldstart"":false,""notId"":1506204001792803}}}"
1207,1506204007.9,2017-09-23 15:00:07.902470-07:53,"data = {""message"":{""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506204001792803},""foreground"":false,""coldstart"":false,""notId"":1506204001792803}},""title"":""e-mission-phone"",""app"":{""asleep"":true,""closed"":false},""payload"":{""notId"":1506204001792803}},""raw"":{""title"":""e-mission-phone"",""additionalData"":{""content-available"":1,""payload"":{""notId"":1506204001792803},""foreground"":false,""coldstart"":false,""notId"":1506204001792803}}}"
1208,1506204007.96,2017-09-23 15:00:07.962590-07:53,"Found silent push notification, for platform ios"
1209,1506204007.98,2017-09-23 15:00:07.983200-07:53,"Platform is ios, calling handleSilentPush on DataCollection"
1210,1506204008.04,2017-09-23 15:00:08.041520-07:53,handleSilentPush outside the try block = DataCollection835259026
1211,1506204008.07,2017-09-23 15:00:08.067440-07:53,"Before invoking launchTripEndCheckAndRemoteSync, id = DataCollection835259026"
1212,1506204008.09,2017-09-23 15:00:08.091350-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"

[shankari]

The format of the actual messages also appears to be identical. The only difference is in the notification ID

$ diff -wy /tmp/clipboard.before /tmp/clipboard.after
"data = {""message"":{""raw"":{""title"":""e-mission-phone""    "data = {""message"":{""raw"":{""title"":""e-mission-phone""
""additionalData"":{""content-available"":1         ""additionalData"":{""content-available"":1
""payload"":{""notId"":1506146401609485}              | ""payload"":{""notId"":1506225601705592}
""foreground"":false                        ""foreground"":false
""coldstart"":false                     ""coldstart"":false
""notId"":1506146401609485}}                      | ""notId"":1506225601705592}}
""title"":""e-mission-phone""                   ""title"":""e-mission-phone""
""app"":{""asleep"":true                    ""app"":{""asleep"":true
""closed"":false}                       ""closed"":false}
""payload"":{""notId"":1506146401609485}}             | ""payload"":{""notId"":1506225601705592}}
""raw"":{""title"":""e-mission-phone""              ""raw"":{""title"":""e-mission-phone""
""additionalData"":{""content-available"":1         ""additionalData"":{""content-available"":1
""payload"":{""notId"":1506146401609485}              | ""payload"":{""notId"":1506225601705592}
""foreground"":false                        ""foreground"":false
""coldstart"":false                     ""coldstart"":false
""notId"":1506146401609485}}}"                    | ""notId"":1506225601705592}}}"

[shankari]

I am now running the code through the debugger. Here's the complete set of logs.

2017-09-25 07:00:23.388253-0700 emission[534:99933] didReceiveNotification with fetchCompletionHandler
2017-09-25 07:00:23.388353-0700 emission[534:99933] app in-active
2017-09-25 07:00:23.388390-0700 emission[534:99933] this should be a silent push
2017-09-25 07:00:23.388452-0700 emission[534:99933] Push Plugin notId 1506348002152486
2017-09-25 07:00:23.388489-0700 emission[534:99933] Notification received
2017-09-25 07:00:23.388893-0700 emission[534:99933] Push Plugin key: alert
2017-09-25 07:00:23.388957-0700 emission[534:99933] Push Plugin key: content-available
2017-09-25 07:00:23.503588-0700 emission[534:99933] DEBUG:data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 07:00:23.503885-0700 emission[534:99933] DEBUG: data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 07:00:23.522537-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '18.724121' ms. Plugin should use a background thread.
2017-09-25 07:00:23.522897-0700 emission[534:99933] DEBUG:data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 07:00:23.523440-0700 emission[534:99933] DEBUG: data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 07:00:23.541734-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '18.489990' ms. Plugin should use a background thread.
2017-09-25 07:00:23.542748-0700 emission[534:99933] DEBUG:Found silent push notification, for platform ios
2017-09-25 07:00:23.543659-0700 emission[534:99933] DEBUG: Found silent push notification, for platform ios
2017-09-25 07:00:23.562916-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '19.490234' ms. Plugin should use a background thread.
2017-09-25 07:00:23.563336-0700 emission[534:99933] DEBUG:Platform is ios, calling handleSilentPush on DataCollection
2017-09-25 07:00:23.564010-0700 emission[534:99933] DEBUG: Platform is ios, calling handleSilentPush on DataCollection
2017-09-25 07:00:23.580306-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '16.403809' ms. Plugin should use a background thread.
2017-09-25 07:00:23.671776-0700 emission[534:99933] handleSilentPush outside the try block = DataCollection717236111
2017-09-25 07:00:23.672629-0700 emission[534:99933] DEBUG: handleSilentPush outside the try block = DataCollection717236111
2017-09-25 07:00:23.695601-0700 emission[534:99933] THREAD WARNING: ['DataCollection'] took '23.848877' ms. Plugin should use a background thread.
2017-09-25 07:00:23.696809-0700 emission[534:99933] Before invoking launchTripEndCheckAndRemoteSync, id = DataCollection717236111
2017-09-25 07:00:23.697451-0700 emission[534:99933] DEBUG: Before invoking launchTripEndCheckAndRemoteSync, id = DataCollection717236111
2017-09-25 07:00:23.719380-0700 emission[534:99933] Received background sync call when useRemotePush = 1, about to check whether a trip has ended
2017-09-25 07:00:23.722834-0700 emission[534:99933] DEBUG: Received background sync call when useRemotePush = 1, about to check whether a trip has ended

It looks like the silent push is detected correctly and we don't "put it into the shade"

[shankari]

Also, when I do swipe the notification, the code gets triggered again.

2017-09-25 08:19:35.566405-0700 emission[534:99933] DEBUG: Application will enter the foreground
2017-09-25 08:19:36.278432-0700 emission[534:99933] didReceiveNotification with fetchCompletionHandler
2017-09-25 08:19:36.278782-0700 emission[534:99933] app in-active
2017-09-25 08:19:36.278995-0700 emission[534:99933] this should be a silent push
2017-09-25 08:19:36.279254-0700 emission[534:99933] Push Plugin notId 1506348002152486
2017-09-25 08:19:36.279540-0700 emission[534:99933] Warning: Application delegate received call to -application:didReceiveRemoteNotification:fetchCompletionHandler: but the completion handler was never called.
2017-09-25 08:19:36.279915-0700 emission[534:99933] Notification received
2017-09-25 08:19:36.280282-0700 emission[534:99933] Push Plugin key: alert
2017-09-25 08:19:36.286941-0700 emission[534:99933] Push Plugin key: content-available
2017-09-25 08:19:36.291620-0700 emission[534:99933] active
2017-09-25 08:19:36.292623-0700 emission[534:99933] PushPlugin clearing badge
2017-09-25 08:19:36.470395-0700 emission[534:99933] DEBUG:data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 08:19:36.470816-0700 emission[534:99933] DEBUG: data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 08:19:36.489237-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '18.530029' ms. Plugin should use a background thread.
2017-09-25 08:19:36.489705-0700 emission[534:99933] DEBUG:data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 08:19:36.489897-0700 emission[534:99933] DEBUG: data = {"message":{"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}},"title":"e-mission-phone","app":{"asleep":true,"closed":false},"payload":{"notId":1506348002152486}},"raw":{"title":"e-mission-phone","additionalData":{"content-available":1,"payload":{"notId":1506348002152486},"foreground":false,"coldstart":false,"notId":1506348002152486}}}
2017-09-25 08:19:36.507147-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '17.279053' ms. Plugin should use a background thread.
2017-09-25 08:19:36.507879-0700 emission[534:99933] DEBUG:Found silent push notification, for platform ios
2017-09-25 08:19:36.508083-0700 emission[534:99933] DEBUG: Found silent push notification, for platform ios
2017-09-25 08:19:36.522197-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '14.181152' ms. Plugin should use a background thread.
2017-09-25 08:19:36.522473-0700 emission[534:99933] DEBUG:Platform is ios, calling handleSilentPush on DataCollection
2017-09-25 08:19:36.522672-0700 emission[534:99933] DEBUG: Platform is ios, calling handleSilentPush on DataCollection
2017-09-25 08:19:36.555424-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '32.805908' ms. Plugin should use a background thread.
2017-09-25 08:19:36.560400-0700 emission[534:99933] handleSilentPush outside the try block = DataCollection717236117
2017-09-25 08:19:36.560544-0700 emission[534:99933] DEBUG: handleSilentPush outside the try block = DataCollection717236117
2017-09-25 08:19:36.575558-0700 emission[534:99933] THREAD WARNING: ['DataCollection'] took '15.156982' ms. Plugin should use a background thread.
2017-09-25 08:19:36.575968-0700 emission[534:99933] Before invoking launchTripEndCheckAndRemoteSync, id = DataCollection717236117
2017-09-25 08:19:36.576077-0700 emission[534:99933] DEBUG: Before invoking launchTripEndCheckAndRemoteSync, id = DataCollection717236117
2017-09-25 08:19:36.588499-0700 emission[534:99933] Received background sync call when useRemotePush = 1, about to check whether a trip has ended
2017-09-25 08:19:36.588726-0700 emission[534:99933] DEBUG: Received background sync call when useRemotePush = 1, about to check whether a trip has ended
2017-09-25 08:19:36.602365-0700 emission[534:99933] About to check whether a trip has ended
2017-09-25 08:19:36.607386-0700 emission[534:99933] In TripDiaryStateMachine, received transition T_RECEIVED_SILENT_PUSH in state STATE_START
2017-09-25 08:19:36.607539-0700 emission[534:99933] DEBUG: In TripDiaryStateMachine, received transition T_RECEIVED_SILENT_PUSH in state STATE_START
2017-09-25 08:19:36.625081-0700 emission[534:99933] data has 88 bytes, str has size 88
2017-09-25 08:19:36.641987-0700 emission[534:99933] data has 68 bytes, str has size 68
2017-09-25 08:19:36.656824-0700 emission[534:99933] In TripDiaryStateMachine, received transition T_NOP in state STATE_START
2017-09-25 08:19:36.657145-0700 emission[534:99933] DEBUG: In TripDiaryStateMachine, received transition T_NOP in state STATE_START
2017-09-25 08:19:36.674900-0700 emission[534:99933] data has 71 bytes, str has size 71
2017-09-25 08:19:36.691643-0700 emission[534:99933] data has 67 bytes, str has size 67
2017-09-25 08:19:36.704685-0700 emission[534:99933] Got unexpected transition T_NOP in state STATE_START, ignoring
2017-09-25 08:19:36.705212-0700 emission[534:99933] Received notification T_NOP while processing silent push notification
2017-09-25 08:19:36.705522-0700 emission[534:99933] DEBUG: Received notification T_NOP while processing silent push notification
2017-09-25 08:19:36.717594-0700 emission[534:99933] Remote push state machine ignored the silent push, fetch result = new data
2017-09-25 08:19:36.717741-0700 emission[534:99933] DEBUG: Remote push state machine ignored the silent push, fetch result = new data
2017-09-25 08:19:36.733666-0700 emission[534:99933] in handleSilentPush, sending result to id DataCollection717236111
2017-09-25 08:19:36.733835-0700 emission[534:99933] INFO: in handleSilentPush, sending result to id DataCollection717236111
2017-09-25 08:19:36.751566-0700 emission[534:99933] Received platform-specific notification T_NOP
2017-09-25 08:19:36.751764-0700 emission[534:99933] DEBUG: Received platform-specific notification T_NOP
2017-09-25 08:19:36.765714-0700 emission[534:99933] Added SILENT_PUSH handler block <__NSMallocBlock__: 0x1c0672400> to list, new size = 1
2017-09-25 08:19:36.765884-0700 emission[534:99933] DEBUG: Added SILENT_PUSH handler block <__NSMallocBlock__: 0x1c0672400> to list, new size = 1
2017-09-25 08:19:36.779715-0700 emission[534:99933] Received notification T_RECEIVED_SILENT_PUSH while processing silent push notification
2017-09-25 08:19:36.779903-0700 emission[534:99933] DEBUG: Received notification T_RECEIVED_SILENT_PUSH while processing silent push notification
2017-09-25 08:19:36.798877-0700 emission[534:99933] Handler block has already been set, ignoring SILENT_PUSH in the silent push handler
2017-09-25 08:19:36.799070-0700 emission[534:99933] DEBUG: Handler block has already been set, ignoring SILENT_PUSH in the silent push handler
2017-09-25 08:19:36.815404-0700 emission[534:99933] Received platform-specific notification T_RECEIVED_SILENT_PUSH
2017-09-25 08:19:36.815583-0700 emission[534:99933] DEBUG: Received platform-specific notification T_RECEIVED_SILENT_PUSH
2017-09-25 08:19:36.835737-0700 emission[534:99933] reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14
2017-09-25 08:19:36.835921-0700 emission[534:99933] DEBUG: reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14
2017-09-25 08:19:36.847772-0700 emission[534:99933] isConsented = YES
2017-09-25 08:19:36.847926-0700 emission[534:99933] DEBUG: isConsented = YES
2017-09-25 08:19:36.869423-0700 emission[534:99933] DEBUG:silent push finished successfully, calling push.finish
2017-09-25 08:19:36.869633-0700 emission[534:99933] DEBUG: silent push finished successfully, calling push.finish
2017-09-25 08:19:36.892370-0700 emission[534:99933] THREAD WARNING: ['UnifiedLogger'] took '22.777100' ms. Plugin should use a background thread.
2017-09-25 08:19:36.895025-0700 emission[534:99933] Push Plugin finish called
2017-09-25 08:19:36.996619-0700 emission[534:99933] Push Plugin stopBackgroundTask called
2017-09-25 08:19:36.996796-0700 emission[534:99933] Push Plugin handlerObj
2017-09-25 08:19:36.999317-0700 emission[534:99933] Push Plugin: stopBackgroundTask (remaining t: 179769313486231570814527423731704356798070567525844996598917476803157260780028538760589558632766878171540458953514382464234321326889464182768467546703537516986049910576551282076245490090389328944075868508455133942304583236903222948165808559332123348274797826204144723168738177180919299881250404026184124858368.000000)
2017-09-25 08:19:37.003990-0700 emission[534:99933] Finished refreshing token in background, new expiry is 2017-09-25 16:19:37 +0000
2017-09-25 08:19:37.004120-0700 emission[534:99933] DEBUG: Finished refreshing token in background, new expiry is 2017-09-25 16:19:37 +0000
2017-09-25 08:19:37.010217-0700 emission[534:103800] TIC Read Status [8:0x0]: 1:57
2017-09-25 08:19:37.010318-0700 emission[534:103800] TIC Read Status [8:0x0]: 1:57

[shankari]

Final proof that this is not related to the remote notification processing.

I put a breakpoint at the very first line of didReceiveRemoteNotification

- (void)application:(UIApplication *)application didReceiveRemoteNotification:(NSDictionary *)userInfo fetchCompletionHandler:(void (^)(UIBackgroundFetchResult))completionHandler {
---> NSLog(@"didReceiveNotification with fetchCompletionHandler");

so the only line in the log was

2017-09-25 09:00:06.560020-0700 emission[642:133597] [] nw_socket_get_input_frames recvmsg(fd 17, 1024 bytes): [57] Socket is not connected

And I still see the notification

After 6 mins	After 7 mins

[shankari]

posted question to stackoverflow https://stackoverflow.com/questions/46410201/regression-in-ios11-push-notifications-are-displayed-although-content-availabl

[shankari]

Hm found this interesting message on stackoverflow. https://stackoverflow.com/questions/19239737/silent-push-notification-in-ios-7-does-not-work

In iOS7 it works great even without sound/alert keys. Content-avalable is sufficient key! But in iOS8 we have really strange behavior when even we set alert key with non-empty string in addition to "content-available" : 1 we get only banner with "alert" string, but "content-available" is ignoring for some reasons

But I don't have an alert in the config that I generate on the server.

    message_dict = {
        "tokens": token_list,
        "profile": profile_to_use,
        "notification": {
            "android": {
                "content_available": 1,
                "data": json_data,
                "payload": json_data
            },
            "ios": {
                "content_available": 1,
                "priority": 10,
                "data": ios_raw_data,
                "payload": ios_raw_data
            }
        }
    }

So it must be added automatically by ionic.

[shankari]

From the same stackoverflow message: https://developer.apple.com/library/content/documentation/NetworkingInternet/Conceptual/RemoteNotificationsPG/CommunicatingwithAPNs.html

 The priority of the notification. Specify one of the following values:

    10–Send the push message immediately. Notifications with this priority must trigger an alert, sound, or badge on the target device. It is an error to use this priority for a push notification that contains only the content-available key.

    5—Send the push message at a time that takes into account power considerations for the device. Notifications with this priority might be grouped and delivered in bursts. They are throttled, and in some cases are not delivered.

If you omit this header, the APNs server sets the priority to 10

Maybe ionic adds the alert automatically for priority 10? Let's try setting to priority 5.

[shankari]

After switching the priority to 5, the userInfo parameter in didReceiveRemoteNotification is the same, but there is no visible notification. It looks like:

• if no title is specified, ionic always adds an alert payload with the name of the app as the title
• iOS11 assumes that high priority (priority = 10) messages with an alert message should be displayed even if they have content-available set. And this is a change from iOS10 -> iOS11.

{
    aps =     {
        alert =         {
            title = "e-mission-phone";
        };
        "content-available" = 1;
    };
    notId = 1506362401598341;
    payload =     {
        notId = 1506362401598341;
    };
}

Let's experiment with some other options.

[shankari]

title = "", message = "", priority = 10

Idea from https://stackoverflow.com/questions/19239737/silent-push-notification-in-ios-7-does-not-work#20144934

    message_dict = {
        "tokens": token_list,
        "profile": profile_to_use,
        "notification": {
            "title": "",
            "message": "",
            "android": {
                "content_available": 1,
                "data": json_data,
                "payload": json_data
            },
            "ios": {
                "content_available": 1,
                "priority": 10,
                "data": ios_raw_data,
                "payload": ios_raw_data
            }
        }
    }

There is still an alert title and it still gets displayed.

{
    aps =     {
        alert =         {
            title = "e-mission-phone";
        };
        "content-available" = 1;
    };
    notId = 1506364822739206;
    payload =     {
        notId = 1506364822739206;
    };
}

no title and message, badge = 1, priority = 10

Idea from https://stackoverflow.com/questions/19239737/silent-push-notification-in-ios-7-does-not-work#23917593

    message_dict = {
        "tokens": token_list,
        "profile": profile_to_use,
        "notification": {
            "android": {
                "content_available": 1,
                "data": json_data,
                "payload": json_data
            },
            "ios": {
                "badge": 1,
                "content_available": 1,
                "priority": 10,
                "data": ios_raw_data,
                "payload": ios_raw_data
            }
        }
    }

There is still an alert title and it still gets displayed. Note the new badge field, which doesn't seem to help much...

{
    aps =     {
        alert =         {
            title = "e-mission-phone";
        };
        badge = 1;
        "content-available" = 1;
    };
    notId = 1506365183838794;
    payload =     {
        notId = 1506365183838794;
    };
}

[shankari]

So to summarize:

• ionic adds an alert title to all messages, irrespective of the badge status or priority
• iOS11, in a departure from iOS10, displays high priority messages with alerts on the screen, irrespective of the state of the content-available tag.

[shankari]

This means that we have three potential solutions:

1. complain to ionic about their adding an alert. This is unlikely to be very useful since they plan to deprecate ionic push in January
2. switch to a different push service that does not add spurious alert messages. We need to do this anyway before Jan, but it will require an update to the client code to integrate with the new service.
3. switch to priority = 5. This can work without any client changes, but how reliable are the pushes?

The easiest short term solution is really (3), which will stop annoying all iOS users right now and requires no client side changes.

Once I implement that, I can turn on "Simulate User Interaction" and see how reliable priority = 5 is in the real world, which will determine how quickly I need to make the long-term fix.

[shankari]

From https://github.com/e-mission/e-mission-phone/issues/290#issuecomment-331967689

After switching the priority to 5, the userInfo parameter in didReceiveRemoteNotification is the same, but there is no visible notification. It looks like:

This is not correct. We seem to get the visible notification anyway. ionic needs to fix this.

[shankari]

In order to see whether other workarounds are possible, I try configuring some more values. In particular, when we specify a visible push notification, it looks like the title is overridden, so can we use something similar for silent push notifications as well.

Visible notification with common title and message

message_dict = {
    "tokens": token_list,
    "profile": profile_to_use,
    "notification": {
        "title": "Bike lanes along Hearst?",
        "message": "1 question survey - approx 10 secs",
        "android": {
            "data": json_data,
            "payload": json_data,
        },
        "ios": {
            "data": json_data,
            "payload": json_data
        }
    }
}

{
    "alert_type" = survey;
    aps =     {
        alert =         {
            body = "1 question survey - approx 10 secs";
            title = "Bike lanes along Hearst?";
        };
    };
    image = icon;
    message = "1 question survey - approx 10 secs";
    payload =     {
        "alert_type" = survey;
        image = icon;
        message = "1 question survey - approx 10 secs";
        spec =         {
            url = "https://berkeley.qualtrics.com/SE/?SID=SV_9t6KnGlK1qxOGGN";
            uuidElementId = "QR~QID3";
        };
        title = "Bike lanes along Hearst?";
    };
    spec =     {
        url = "https://berkeley.qualtrics.com/SE/?SID=SV_9t6KnGlK1qxOGGN";
        uuidElementId = "QR~QID3";
    };
    title = "Bike lanes along Hearst?";
}

Silent push with blank common title and message

message_dict = {
    "tokens": token_list,
    "profile": profile_to_use,
    "notification": {
        "title": "",
        "message": "",
        "android": {
            "content_available": 1,
            "data": json_data,
            "payload": json_data
        },
        "ios": {
            "content_available": 1,
            "priority": 5,
            "data": ios_raw_data,
            "payload": ios_raw_data
        }
    }
}

{
    aps =     {
        alert =         {
            title = "e-mission-phone";
        };
        "content-available" = 1;
    };
    notId = 1506380401867744;
    payload =     {
        notId = 1506380401867744;
    };
}

Silent push with non-blank common and specific title and message

    message_dict = {
        "tokens": token_list,
        "profile": profile_to_use,
        "notification": {
            "title": "silent title",
            "message": "silent message",
            "android": {
                "content_available": 1,
                "data": json_data,
                "payload": json_data
            },
            "ios": {
                "title": "silent title in iOS",
                "message": "silent message in iOS",
                "content_available": 1,
                "priority": 5,
                "data": ios_raw_data,
                "payload": ios_raw_data
            }
        }
    }

{
    aps =     {
        alert =         {
            body = "silent message in iOS";
            title = "silent title in iOS";
        };
        "content-available" = 1;
    };
    notId = 1506384551395868;
    payload =     {
        notId = 1506384551395868;
    };
}

Silent push with blank, specific title and message

    message_dict = {
        "tokens": token_list,
        "profile": profile_to_use,
        "notification": {
            "android": {
                "content_available": 1,
                "data": json_data,
                "payload": json_data
            },
            "ios": {
                "title": "",
                "message": "",
                "content_available": 1,
                "priority": 5,
                "data": ios_raw_data,
                "payload": ios_raw_data
            }
        }
    }

{
    aps =     {
        alert =         {
            title = "e-mission-phone";
        };
        "content-available" = 1;
    };
    notId = 1506384695457089;
    payload =     {
        notId = 1506384695457089;
    };
}

Basically, the ionic push code appears to introduce a title if content_available: 1 and the there is no existing title.

This is a strong argument for switching to an open source version when the inevitable switch occurs. I know the issue and the fix, but I can't try it because I don't control the server. This is very frustrating.

[shankari]

Tried switching to AWS, based on recommendations from ionic. But ran into several issues:

• their instructions (https://aws.amazon.com/blogs/mobile/push-notifications-with-ionic-and-amazon-pinpoint/) only cover android, and sending events via the console
• tried to use the iOS console, and it turns out that the console doesn't support configuring the sandbox channel (https://stackoverflow.com/questions/43973351/amazon-pinpoint-message-not-delivered-in-ios)
• configured the production certificate, and sent a visible notification via the console (WORKS)
• configured the aws cli and python SDK (albeit with some difficulty, https://serverfault.com/questions/875627/aws-iam-user-credentials-for-accessing-pinpoint-through-script-causes-internals) and sent a visible notification via a python script (WORKS)
• tried to switch it to a silent push notification by toggling the SilentPush flag (DOESN'T WORK)

  silentPushJSON = {
      'Addresses': {
          '129b4c3f7924ad0064bdb78165f62f6b776ef25a07b5dd6bcd6bc3a6820089da': {
              'ChannelType': 'APNS',
          }
      },
      'MessageConfiguration': {
          'APNSMessage': {
              'Badge': 1,
              'Sound': 'blank',
          },
          'DefaultPushNotificationMessage': {
              'Action': 'OPEN_APP',
              'Body': 'powered by python',
              'Data': {
                  'notId': '1'
              },
              'SilentPush': True,
              'Title': 'push from script',
          },
      }
  }

  The silent push notification is received only when the app is in the foreground, it does not come back from the background. I've installed the version from the store, which clearly gets notifications in the background from ionic, so it can't be a client issue

• tried to configure the sandbox channel so that I could attach breakpoints, but could not because it requires a separate cert and public key and I only have a .p12 file which combines both. Tried to separate them using OpenSSL and upload, but that didn't work, even after stripping out headers.

  BadRequestException: An error occurred (BadRequestException) when calling the UpdateApnsSandboxChannel operation: The certificate provided is not a valid Apple certificate

May have to download values from apple directly. But might also be time to switch to an open source server or to FireBase.

Only in foreground	Works

Experiment with AWS pinpoint.ipynb.gz

[shankari]

Tried switching to Firebase. You have to "register" an app. Made a new project to experiment with that. That allows you to download a plist which has ads enabled! Won't that mess with ratings on iOS?

<dict>
    <key>AD_UNIT_ID_FOR_BANNER_TEST</key>
    <string>ca-app-pub-3940256099942544/2934735716</string>
    <key>AD_UNIT_ID_FOR_INTERSTITIAL_TEST</key>
    <string>ca-app-pub-3940256099942544/4411468910</string>

    <key>IS_ADS_ENABLED</key>
    <true></true>
    <key>IS_ANALYTICS_ENABLED</key>
    <false></false>
    <key>IS_APPINVITE_ENABLED</key>
    <false></false>
    <key>IS_GCM_ENABLED</key>
    <true></true>
    <key>IS_SIGNIN_ENABLED</key>
    <true></true>

And now it is not clear how we should specify the new key. In the old version, we set the server key into the ionic console, but now we won't use ionic any more. It looks like we can just specify the config files that we download from google, but only from version 2.0.0 onwards.

As of version 2.0.0 the SENDER_ID parameter has been removed at install time. Instead you put your google-services.json (Android) and/or GoogleService-Info.plist in the root folder of your project and then add the following lines into your config.xml.

But our version is at 1.9.4

phonegap-plugin-push 1.9.4 "PushPlugin"

and 2.0.0, with support for iOS push through FCM was only checked in at the end of 2016 (https://github.com/phonegap/phonegap-plugin-push/issues/929). So

• updating will require client changes
• updating will require a heck of a lot more testing

And the documentation also says:

First it is kind of a misnomer as GCM does not send push messages directly to devices running iOS. What happens is on the device side is that it registers with APNS, then that registration ID is sent to GCM which returns a different GCM specific ID. That is the ID you get from the push plugin registration event.

So we can't even use the tokens that we have directly, AND

Note: The integration between GCM and APNS is a bit finicky. Personally, I feel it is much better to send pushes to Android using GCM and pushes to iOS using APNS which this plugin does support.

So I am not going to explore this solution either.

[shankari]

oh wait, I can convert APNS tokens to FCM tokens https://www.thepolyglotdeveloper.com/2017/06/apns-tokens-fcm-tokens-simple-http/

But will there be FCM tokens? We haven't integrated with the FCM SDK and are not making all the callbacks. In fact, without changing the app implementation, the first that FCM will hear about the APNS token is when we ask for the conversion.

But is there a way to call out from the update code to FCM to establish that mapping?

[shankari]

Next up: investigate open source servers: https://github.com/aerogear/aerogear-unifiedpush-server and https://github.com/uniqush/uniqush-push

[shankari]

Ok so the option of importing tokens into FCM and then invoking them from FCM seems to work fine. I still need to work out some issues with the notId callback, but I don't see a visible alert any more. Current state of code uploaded as ipython notebook.

fcm_push_test_v1.ipynb.gz

[shankari]

So I now try to pass in the data like so:

notid_data = {
    'notId': 100
}
push_service.notify_single_device(registration_id=test_fcm_token,
                                           data_message=notid_data,
                                           content_available=True)

and it maps to

{
    aps =     {
        "content-available" = 1;
    };
    "gcm.message_id" = "0:1506664290036599%697a1786697a1786";
    notId = 100;
}

But it actually needs to map to

{
    "aps": {
        "data": "Test silent background push",
        "moredata": "Do more stuff",
        "content-available": 1
    },
    "notId": 2 // unique ID you generate
}

It looks like the main difference is that "notId" is a string in one case and nothing in the other case? No, that is what it was for ionic as well.

{
    aps =     {
        alert =         {
            title = "e-mission-phone";
        };
        "content-available" = 1;
    };
    notId = 1506384695457089;
    payload =     {
        notId = 1506384695457089;
    };
}

[shankari]

Recognized as silent push, with the correct notId from the code

2017-09-28 22:52:14.617768-0700 emission[1628:517602] this should be a silent push
2017-09-28 22:52:14.618013-0700 emission[1628:517602] Push Plugin notId 100

Warning received - completion handler will be called soon enough. 30 secs have not passed!

Received in javascript

2017-09-28 22:56:46.354339-0700 emission[1628:517602] Notification received
2017-09-28 22:56:46.354444-0700 emission[1628:517602] Push Plugin key: content-available
2017-09-28 22:56:46.424830-0700 emission[1628:517602] DEBUG:data = {"message":{"raw":{"additionalData":{"content-available":"1"
"foreground":false
"coldstart":false
"notId":"100"
"gcm.message_id":"0:1506664290036599%697a1786697a1786"}}
"app":{"asleep":true
"closed":false}}
"raw":{"additionalData":{"content-available":"1"
"foreground":false
"coldstart":false
"notId":"100"
"gcm.message_id":"0:1506664290036599%697a1786697a1786"}}}

We recognize it as a silent push and call handleSilentPush on the datacollection plugin

2017-09-28 22:56:46.488666-0700 emission[1628:517602] DEBUG:Found silent push notification, for platform ios
2017-09-28 22:56:46.512720-0700 emission[1628:517602] DEBUG: Platform is ios, calling handleSilentPush on DataCollection

but then we don't get any more messages. Unclear whether that method is actually called.

Let's connect with a debugger to see what's going on.

[shankari]

Ah yes, the client code is looking for the notId in the payload

redirectSilentPush@file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/js/splash/pushnotify.js:62:41
file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/js/splash/pushnotify.js:102:30
$broadcast@file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/lib/ionic/js/ionic.bundle.js:30718:33
emit@file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/manual_lib/ionic.cloud.min.js:1:16969
file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/manual_lib/ionic.cloud.min.js:11:16918
emit@file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/plugins/phonegap-plugin-push/www/push.js:268:27
success@file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/plugins/phonegap-plugin-push/www/push.js:55:22
callbackFromNative@file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/cordova.js:293:63
nc2@file:///var/containers/Bundle/Application/7E91B7AA-4910-4F0C-B1AC-D484BBE636E1/emission.app/www/cordova.js:1046:39

Ok so adding an extra "payload" field to the data as well.

notid_data = {
    'notId': 100,
    'payload': {
        'notId': 100
    }
}

Works now.

clipboard.gz

Ok so that is what we are going with now, although we should really investigate https://github.com/aerogear/aerogear-unifiedpush-server, an apache project that is integrated with keystone and can allow people to create their own clients.

If only we could hook up deploy into that workflow, we can get out of the upload business...

[shankari]

Couple of other observations to figure out how to implement:

• if we pass in an android token instead of an iOS token, we get

{u'results': [{u'apns_token': <android token>,
   u'status': u'INVALID_ARGUMENT'}]}

If we pass in the wrong sandbox flag (e.g. set sandbox: False for a sandbox token), then we get a token, but using it doesn't work.

This does not generate a visible push notification on a debug build.

{u'results': [{u'apns_token': u'doi_4Y2sfjk:APA91bEkhiQdmdhQ7YouPXmualTVOSpllr8GNqaP0VodhXXBuIEC4xPVUorkBPxBvlkzknPJuHwy1n-5wZhSU9gW2yyvJXJIC0TFytBe0QCNUGcvwkmEpsBzTyDpAzLVS05zLsK8kuDs',
   u'status': u'INVALID_ARGUMENT'}]}
importResponse = requests.post("https://iid.googleapis.com/iid/v1:batchImport", headers=importHeaders, json=importMessage)
test_fcm_token = importResponse.json()["results"][0]["registration_token"]
ctT7wI_J1KI:APA91bGUjKBZT96DqExGeFkAqbMvuY3bTDqgkLTDPI3AM_NFGVhRJ2nHtDbVCtlRkqkR4HRvuFtePj5M36cWkVevlJrRvf_izaPG7psxUDqNpdjXEDSYq72Io_yqoDHbn_WCWYBpwQ1J
result = push_service.notify_single_device(registration_id=test_fcm_token,
                                           message_body="powered by python",
                                           message_title="sent from FCM")

But this does.

importMessage = {
    'application': 'edu.berkeley.eecs.emission',
    "sandbox": True,
    "apns_tokens":[
        "dd9ad31260004335e2a8f98614425061b5b7d04d792e6d43773ce2d1e2a812b6"
    ]
}
importResponse = requests.post("https://iid.googleapis.com/iid/v1:batchImport", headers=importHeaders, json=importMessage)
test_fcm_token = importResponse.json()["results"][0]["registration_token"]
test_fcm_token

u'f8dmGRHdDhM:APA91bHZQoj7VrYdvNqVzkJfFU9XZidVGNMYTLCWbTw_Xv6tzHs4f5juc-WtPiwE8Bme1Dt8jiDbbngFTPkMVvn-Rm2QnASjT1kmMoCvv71HEgN0W827zLqk6Cd3xjU5a0KntPTWIIG_'

result = push_service.notify_single_device(registration_id=test_fcm_token,
                                           message_body="powered by python",
                                           message_title="sent from FCM")

Re-running the token import with the same parameters returns the same value, so this is not so much an import as it is a mapping.

test_fcm_token == test_fcm_run_1

True

[shankari]

Given the findings in https://github.com/e-mission/e-mission-phone/issues/290#issuecomment-333051344, we have a simple workaround for tonight. Simply try to import all user tokens and for the ones for which we get a result, replace with the mapped token.

[shankari]

One weird issue encountered in testing - when the app is connected via the debugger, remote notifications are delivered with 100% reliability. But when it is not connected via the debugger, with the same installed app, the delivery is more... flaky.

Here's what I observed today morning:

• sent push at around 7:15, received around 7:20
• sent push around 7:25, received around 7:30
• sent pushes around 7:45 and 7:55 - did not receive them

The phone was plugged in to the laptop during this time. We know that the in-store app reliably got pushes for over a day (albeit with the visible notifications) when we were using ionic. So this is a bit disturbing. And I can't debug it because if I connect to the debugger, it works reliably.

Will test further on the trip in to Berkeley. I've pulled device logs.

It could be that the alert text was what was ensuring delivery. In which case, I should experiment with blank sound and/or badge.

[shankari]

Hm. I see this in the logs, which is consistent with other commments online (e.g. )

Sep 29 07:52:27 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:9B581B:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

In order to understand the differences, and figure out how to make this be more reliable, let's compare the times when it worked with the times when it didn't.

Re-ran some careful tests for that.

Send push at 12:21pm

• First with title (saw notification)
• Second without title (missing notification)

Send push at 12:40pm

• First with title (saw notification)
• Second without title (missing notification)

Restart in the debugger at 12:55 with a breakpoint in didReceiveRemoteNotification Should get a regular push at 1:00pm Hit the breakpoint

Sent a visual push and regular push at 1:04pm (hit the breakpoint) Sent a visual push and regular push at 1:20pm (hit the breakpoint)

[shankari]

Looking closely at the logs, we see a lot of messages like this

Sep 29 12:19:23 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:017A28:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

Sep 29 12:19:34 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:017A28:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

Sep 29 12:20:12 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:017A28:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

What we see from the logs attached below is:

visible notification appears to be at higher priority.

Sep 29 12:21:07 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Received message for enabled topic '<private>' onInterface: WWAN with payload '<private>' with priority 10 for device token: NO

Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Received message for enabled topic '<private>' onInterface: WWAN with payload '<private>' with priority 5 for device token: NO

APSD stores one message, deletes the other.

Sep 29 12:21:07 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Calling into AWD for PushReceived
Sep 29 12:21:07 ucb-sdb-iphone-2 apsd[86] <Notice>: APSMessageStore - New message record [<private>] has ID [6204].
Sep 29 12:21:07 ucb-sdb-iphone-2 apsd[86] <Notice>: submitted metric <private>
Sep 29 12:21:07 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: AWD for PushReceived finished

Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Calling into AWD for PushReceived
Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> deleting low-priority incoming messages for topic <private> environment development
Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: submitted metric <private>
Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: AWD for PushReceived finished

Both messages are acknowledged (so we can't know anything on the server)

Sep 29 12:21:07 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Sending acknowledgement message with response 0 and messageId <private> (2522217355)

Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Sending acknowledgement message with response 0 and messageId <private> (36869304)

Notification service receives the message

But by this time, the silent push is down to priority 1

Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(ApplePushService)[55] <Notice>: <private> returned from <private> connection:didReceiveIncomingMessage:
Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: Received incoming message on topic edu.berkeley.eecs.emission at priority 10

Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(ApplePushService)[55] <Notice>: <private> returned from <private> connection:didReceiveIncomingMessage:
Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: Received incoming message on topic edu.berkeley.eecs.emission at priority 1

Both are received as remote notifications

Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Received remote notification request DE7C-939B [ hasAlertContent: 1, hasSound: 0 hasBadge: 0 hasContentAvailable: 0 hasMutableContent: 0 ]
Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Deliver push notification request DE7C-939B

Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Received remote notification request EA94-2011 [ hasAlertContent: 0, hasSound: 0 hasBadge: 0 hasContentAvailable: 1 hasMutableContent: 0 ]
Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Deliver push notification request EA94-2011

But the visible notification does not go to duet, the silent one does

which then ignores it because it has no user-facing content

Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Saving notification DE7C-939B: 1 [ hasAlertContent: 1, shouldPresentAlert: 1 isTransient: 0 ]
Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: Saving notification list at /var/mobile/Library/SpringBoard/PushStore/edu.berkeley.eecs.emission.pushstore with 14 items

Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Passing content-available push to Duet
Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(DuetActivityScheduler)[55] <Notice>: SUBMITTING: <private>
Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Error>: Ignoring notification with no alert, sound or badge (edu.berkeley.eecs.emission): EA94-2011
Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Not saving push notification EA94-2011 to store [ error=Error Domain=UNErrorDomain Code=1401 "Notification has no user-facing content" UserInfo={NSLocalizedDescription=Notification has no user-facing content} ]

Visible one queues, silent is deleted

Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Adding notification DE7C-939B to destinations 14 [ hasAlertContent: 1, shouldPresentAlert: 1 hasSound: 0 shouldPlaySound: 1 ]
Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: BBDataProviderProxy edu.berkeley.eecs.emission has enqueued a bulletin request
Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: BBDataProviderProxy edu.berkeley.eecs.emission is now sending enqueued bulletin request to BBServer

Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> Removing incoming message with guid <private>
Sep 29 12:21:21 ucb-sdb-iphone-2 apsd[86] <Notice>: APSMessageStore - APSIncomingMessageRecordDeleteMessageForGUID <private>

Visible one is displayed, silent is cancelled

Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(UserNotificationsUIKit)[55] <Notice>: <private> adding bulletin DE7C-939B for feed 43
Sep 29 12:21:07 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Bulletin with bulletinID <398839ED-06FC-4756-B6A4-0014CA59B7F0>, expiration date <Fri Oct  6 12:21:07 2017> inserted in expiring bulletins array at index 18

Sep 29 12:21:21 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Daemon Canceling Activities: {(
    com.apple.pushLaunch.edu.berkeley.eecs.emission:017A28
)}
Sep 29 12:21:21 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: CANCELED: com.apple.pushLaunch.edu.berkeley.eecs.emission:017A28 <private>!

silent_push_12_21.log.gz visible_push_12_21.log.gz

[shankari]

Couple of things to try:

• manually set the priority of the silent push notification to 10 instead of using the default (which is supposed to be 10)
• try adding a badge or sound to see whether

  Sep 29 12:21:21 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Error>: Ignoring notification with no alert, sound or badge (edu.berkeley.eecs.emission): EA94-2011

  is not triggered

[shankari]

Rerunning with spec below at 10:24

result = push_service.notify_single_device(registration_id=test_fcm_token,
                                           data_message=notid_data,
                                           content_available=True,
                                           low_priority=False,
                                           sound="default")

And the spec below at 10:29 (no sound). No silent push in either case.

result = push_service.notify_single_device(registration_id=test_fcm_token,
                                           data_message=notid_data,
                                           content_available=True,
                                           low_priority=False)

[shankari]

I now have a sense of when low priority notifications do make it through:

• 2am
• 6:30am

at 6:30	at 2am

[shankari]

Rerunning with spec below at 10:24 and 7:30 and 7:35

result = push_service.notify_single_device(registration_id=test_fcm_token,
                                           data_message=notid_data,
                                           content_available=True,
                                           low_priority=False,
                                           sound="default")

And the spec below at 10:29 (no sound) and 7:40 No silent push in either case.

result = push_service.notify_single_device(registration_id=test_fcm_token,
                                           data_message=notid_data,
                                           content_available=True,
                                           low_priority=False)

Basically, if you have no user facing elements (sound/badge), the priority will automatically be lowered and you will not get it.

And if you do have user facing notification, the priority will be high, but it still may not be delivered depending on what the dasd thinks.

With sound, high priority

Ok so now priority is 10

Sep 29 22:24:39 ucb-sdb-iphone-2 apsd[86] <Notice>: copyAppSpecificTokensWithDomain - sandbox.push.apple.com for topic <private> account <private>
Sep 29 22:24:39 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> receivedPushWithTopic <private> token <private> payload <private> timestamp Fri Sep 29 22:24:37 2017
Sep 29 22:24:39 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Received message for enabled topic '<private>' onInterface: WWAN with payload '<private>' with priority 10 for device token: NO
Sep 29 22:24:39 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> asked to store incoming message <private> with guid <private> environment <private>

Still at priority 10

Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(ApplePushService)[55] <Notice>: <private> calling <private> connection:didReceiveIncomingMessage:
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(ApplePushService)[55] <Notice>: <private> returned from <private> connection:didReceiveIncomingMessage:
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: Received incoming message on topic edu.berkeley.eecs.emission at priority 10

But it gets passed to duet anyway, ostensibly because it is a content-available push. I wish I could see the source code around this...

Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Received remote notification request 92B0-B91A [ hasAlertContent: 0, hasSound: 1 hasBadge: 0 hasContentAvailable: 1 hasMutableContent: 0 ]
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Deliver push notification request 92B0-B91A
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Passing content-available push to Duet
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(DuetActivityScheduler)[55] <Notice>: SUBMITTING: <private>

hm, unsure if this matters

Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Saved push notification 92B0-B91A to store
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Error>: Could not load data at /var/mobile/Library/SpringBoard/PushStore/edu.berkeley.eecs.emission.pushstore

and now the final decision is to proceed

Sep 29 22:24:39 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Activity <private>: Optimal Score 0.8572 at <private> (Valid Until: <private>)
Sep 29 22:24:39 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:D245E1:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Can Proceed, Score: 0.50}}
    {name: DeviceActivityPolicy, policyWeight: 5.000, response: {Decision: Can Proceed, Score: 0.10}}
 ] sumScores:51.310000, denominator:80.810000, FinalDecision: Can Proceed FinalScore: 0.634946}

but then there is another decision step where apparently it doesn't meet a threshold

Sep 29 22:24:39 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: 'com.apple.pushLaunch.edu.berkeley.eecs.emission:D245E1' CurrentScore: 0.634946, ThresholdScore: 0.814355 DecisionToRun:0

but then it does say that the bulletin is delivered to a feed

Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsUIKit)[55] <Notice>: <private> adding bulletin 92B0-B91A for feed 16

and it is now deciding whether to display or not. why is the hasSound: 1?

Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsKit)[55] <Notice>: Posting notification id: 92B0-B91A; section: edu.berkeley.eecs.emission; thread: 64F2-B4DF; category: ; timestamp: 2017-09-30 05:24:37 +0000; actions: [ minimal: 0 (0 text), default: 0 (0 text) ]; destinations: [ {(
)} ]
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: Alerting on post for request 92B0-B91A. uiLocked=1 activeAlertDestinations=0 shouldSuppressAlert=0
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: Sound can be played for notification 92B0-B91A: 1 [ hasRequest: 1 hasSound: 1 canPlaySound: 1 isQuietModeEnabledAndActive: 0 overridesQuietMode: 0 isInLostMode: 0 isDeviceUILocked: 1 alertsWhenLocked: 1 ]
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: Play sound for notification 92B0-B91A

Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: SBSoundController: played sound - environments=1 -> <SBUISound: 0x1c488e740>
{  SoundType: ToneAlert
   hasCompletionBlock: NO
    Alert Configuration: <TLAlertConfiguration: 0x1c46d4ba0; type = app notification>

}

So it plays the sound right then BUT does not launch the app (we got no silent push handling notifications)

But maybe the content delivery actually happens later? I see these messages earlier. Let's look at them for the morning when I know that the notification was in fact delivered later.

Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Next expire bulletins date = Sun Oct  1 23:12:57 2017; current fire date = Sun Oct  1 23:12:57 2017
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsUIKit)[55] <Notice>: <private> adding bulletin 92B0-B91A for feed 16
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Not adjusting expiration timer. Next fire date = Sun Oct  1 23:12:57 2017
Sep 29 22:24:39 ucb-sdb-iphone-2 SpringBoard(UserNotificationsUIKit)[55] <Notice>: Unhandled BBObserver feed: 16

With sound, next morning, 7:30

Sep 30 07:30:30 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> incoming message is for proxy slave that is *not* connected. baseToken <private>  destToken <private>  publicToken <private>
Sep 30 07:30:30 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Received message for enabled topic '<private>' onInterface: WWAN with payload '<private>' with priority 10 for device token: NO

Ok so there is some stuff about the next fire date but seems kind of inconsistent...

Sep 30 07:30:30 ucb-sdb-iphone-2 apsd(PersistentConnection)[86] <Notice>: <PCPersistentTimer: 0x100b2f0c0> Calculated minimum fire date [2017-09-30 08:03:54 -0700] (100%) with fire date [2017-09-30 08:03:54 -0700], start date [2017-09-30 07:28:03 -0700], minimum early fire proportion 0, power state detection supported: yes, in high power state: yes
Sep 30 07:30:30 ucb-sdb-iphone-2 apsd(PersistentConnection)[86] <Notice>: <PCPersistentTimer: 0x100c87d40> Calculated minimum fire date [2017-09-30 07:39:57 -0700] (100%) with fire date [2017-09-30 07:39:57 -0700], start date [2017-09-30 07:11:40 -0700], minimum early fire proportion 0, power state detection supported: yes, in high power state: yes

And we now get to dasd

Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Received remote notification request 3D3A-1849 [ hasAlertContent: 0, hasSound: 1 hasBadge: 0 hasContentAvailable: 1 hasMutableContent: 0 ]
Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Passing content-available push to Duet

But this time, it must not proceed

Sep 30 07:30:30 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:EFADF0:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

But the bulletin is delivered anyway

Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Sending add bulletin with lights and sirens YES for transactionID 1, bulletin 58FB0A63-C63B-4BD5-9E40-FC16B62FA11A
Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Bulletin with bulletinID <58FB0A63-C63B-4BD5-9E40-FC16B62FA11A>, expiration date <Sat Oct  7 07:30:28 2017> inserted in expiring bulletins array at index 21

And the fire date is now Sunday!!

Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Next expire bulletins date = Sun Oct  1 23:12:57 2017; current fire date = Sun Oct  1 23:12:57 2017
Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Not adjusting expiration timer. Next fire date = Sun Oct  1 23:12:57 2017

ok so the sound is alerted

Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard(UserNotificationsKit)[55] <Notice>: Posting notification id: 3D3A-1849; section: edu.berkeley.eecs.emission; thread: FF5D-EE18; category: ; timestamp: 2017-09-30 14:30:28 +0000; actions: [ minimal: 0 (0 text), default: 0 (0 text) ]; destinations: [ {(
)} ]
Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: Alerting on post for request 3D3A-1849. uiLocked=1 activeAlertDestinations=0 shouldSuppressAlert=0
Sep 30 07:30:30 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: Sound can be played for notification 3D3A-1849: 1 [ hasRequest: 1 hasSound: 1 canPlaySound: 1 isQuietModeEnabledAndActive: 0 overridesQuietMode: 0 isInLostMode: 0 isDeviceUILocked: 1 alertsWhenLocked: 1 ]

DASD decision for the second with sound post

Must not proceed again.

Sep 30 07:35:46 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Trigger: <private> is now [<private>]
Sep 30 07:35:46 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Received remote notification request E7A3-36FA [ hasAlertContent: 0, hasSound: 1 hasBadge: 0 hasContentAvailable: 1 hasMutableContent: 0 ]
Sep 30 07:35:46 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Activity <private>: Optimal Score 0.5478 at <private> (Valid Until: <private>)
Sep 30 07:35:46 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:40551D:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

Fire date is still Sun

Sep 30 07:35:46 ucb-sdb-iphone-2 SpringBoard(BulletinBoard)[55] <Notice>: Next expire bulletins date = Sun Oct  1 23:12:57 2017; current fire date = Sun Oct  1 23:12:57 2017

So then what did generate that 8:15 notification? I have no idea, because the phone was not plugged in. Could it be the 8:00 push from the server? Let's see what happened to our 7:40 silent push with no sound.

No sound

Note that although I had manually set high priority, it automatically gets converted to low priority internally (probably because of no user visible components).

Sep 30 07:41:33 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> incoming message is for proxy slave that is *not* connected. baseToken <private>  destToken <private>  publicToken <private>
Sep 30 07:41:33 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Received message for enabled topic '<private>' onInterface: WWAN with payload '<private>' with priority 5 for device token: NO
Sep 30 07:41:33 ucb-sdb-iphone-2 apsd[86] <Notice>: Dispatching low priority message: <xpc object>

Just like before, it gets marked down to priority 1

Sep 30 07:41:33 ucb-sdb-iphone-2 SpringBoard(ApplePushService)[55] <Notice>: <private> calling <private> connection:didReceiveIncomingMessage:
Sep 30 07:41:33 ucb-sdb-iphone-2 SpringBoard(ApplePushService)[55] <Notice>: <private> returned from <private> connection:didReceiveIncomingMessage:
Sep 30 07:41:33 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: Received incoming message on topic edu.berkeley.eecs.emission at priority 1

And cancelled

Sep 30 07:41:33 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Not saving push notification A70F-77E6 to store [ error=Error Domain=UNErrorDomain Code=1401 "Notification has no user-facing content" UserInfo={NSLocalizedDescription=Notification has no user-facing content} ]
Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Submitted Activity: com.apple.pushLaunch.edu.berkeley.eecs.emission:401DE7 <private>
Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Adding a launch request (<private>) for application <private> by activity <private>
Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Launch requests for <private>: <private>
Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Daemon Canceling Activities: {(
    com.apple.pushLaunch.edu.berkeley.eecs.emission:40551D
)}

silent_push_no_sound_no_ui.sat.log.gz silent_push_sound_no_ui.sat.1.log.gz silent_push_sound_no_ui.sat.2.log.gz

[shankari]

So after I sent the notifications in https://github.com/e-mission/e-mission-phone/issues/290#issuecomment-333319443 and had them ignored, I found that some notifications were delivered, but later.

The first notification received and processed at 8:15. unfortunately the phone was not connected, so I didn't receive logs for this time

But another notification was received and processed at 9:09 and I did have the phone connected. Woohoo!

So let's look at these logs and see if there is anything around 9:09 or 9:10

Hmm. there is something about firing a timer at 09:09:51. Interesting...

Sep 30 09:02:51 ucb-sdb-iphone-2 apsd(PersistentConnection)[86] <Notice>: Started simple timer <PCSimpleTimer: 0x100c80dc0> with fire date [2017-09-30 09:09:51 -0700]

But that is probably not relevant because apsd has a bunch of timers before that

/tmp/push_finally_delivered_9_10_sat.log:Sep 30 08:55:41 ucb-sdb-iphone-2 apsd(PersistentConnection)[86] <Notice>: Started simple timer <PCSimpleTimer: 0x100ca4660> with fire date [2017-09-30 08:56:41 -0700]
/tmp/push_finally_delivered_9_10_sat.log:Sep 30 08:55:41 ucb-sdb-iphone-2 apsd(PersistentConnection)[86] <Notice>: Started simple timer <PCSimpleTimer: 0x100c4ec70> with fire date [2017-09-30 09:31:31 -0700]
/tmp/push_finally_delivered_9_10_sat.log:Sep 30 08:55:51 ucb-sdb-iphone-2 apsd(PersistentConnection)[86] <Notice>: Started simple timer <PCSimpleTimer: 0x100c51bf0> with fire date [2017-09-30 09:02:51 -0700]
/tmp/push_finally_delivered_9_10_sat.log:Sep 30 09:00:21 ucb-sdb-iphone-2 apsd(PersistentConnection)[86] <Notice>: Started simple timer <PCSimpleTimer: 0x100c4d9e0> with fire date [2017-09-30 09:28:36 -0700]

and none of them triggered anything

We received a silent push notification at 9 and ignored it

Sep 30 09:00:16 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> incoming message is for proxy slave that is *not* connected. baseToken <private>  destToken <private>  publicToken <private>
Sep 30 09:00:16 ucb-sdb-iphone-2 apsd[86] <Notice>: <private>: Received message for enabled topic '<private>' onInterface: WWAN with payload '<private>' with priority 5 for device token: NO
Sep 30 09:00:16 ucb-sdb-iphone-2 apsd[86] <Notice>: <private> deleting low-priority incoming messages for topic <private> environment development
Sep 30 09:00:16 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: Received incoming message on topic edu.berkeley.eecs.emission at priority 1
Sep 30 09:00:16 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Error>: Ignoring notification with no alert, sound or badge (edu.berkeley.eecs.emission): 8302-2FE7
Sep 30 09:00:16 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Not saving push notification 8302-2FE7 to store [ error=Error Domain=UNErrorDomain Code=1401 "Notification has no user-facing content" UserInfo={NSLocalizedDescription=Notification has no user-facing content} ]
Sep 30 09:00:16 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

Hm, but I don't actually see a cancelled message like last time. And... it turns out that this is gone but not forgotten. dasd peridoically checks to see whether to display this and finally at 9:09, it moves to Can Proceed

Sep 30 09:03:57 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}
Sep 30 09:04:09 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}
Sep 30 09:09:44 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Can Proceed, Score: 0.50}}
    {name: DeviceActivityPolicy, policyWeight: 5.000, response: {Decision: Can Proceed, Score: 0.33}}
 ] sumScores:53.076667, denominator:81.410000, FinalDecision: Can Proceed FinalScore: 0.651967}

And it can match the cloud sync, so there is finally a DecisionToRun

Sep 30 09:09:44 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: 'com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998' has compatibility score of 1.000000 with 'com.apple.healthd.sync.cloud.periodic:8526B6'. Relaxing scores.
Sep 30 09:09:44 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: 'com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998' CurrentScore: 0.651967, ThresholdScore: 0.472450 DecisionToRun:1

and the app is launched

Sep 30 09:09:44 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: Received trusted open application request for "edu.berkeley.eecs.emission" from <FBProcess: 0x1c431d7f0; dasd (com.apple.dasd); pid: 139>.
Sep 30 09:09:44 ucb-sdb-iphone-2 SpringBoard[55] <Notice>: Executing suspended-activation immediately: OpenApplication(edu.berkeley.eecs.emission)ForRequester(dasd.139)

And it looks like now we only get 10 secs background duration

Sep 30 09:09:44 ucb-sdb-iphone-2 assertiond[66] <Notice>: [emission:2537] timedAssertionReferenceTime: 163712.601619 permittedBackgroundDurationForThisAssertion: 10.000000 oldTimedAssertionPermittedDuration: 0.000000 newTimedAssertionPermittedDuration: 10.000000 _timedAssertionDeadlineActive: YES

and the push notification is delivered to us

Sep 30 09:09:44 ucb-sdb-iphone-2 emission[2537] <Notice>: didReceiveNotification with fetchCompletionHandler

So basically, it looks like they want to sync the actual launch with a cloud sync. But why didn't this happen to our 7:40 silent push? I guess the one at 8:00 was displayed at 8:15.

But why did I have only two syncs overnight? because it wasn't plugged in? Because cloud sync was not happening?

Let's see what happens at 10:00.

push_finally_delivered_9_10_sat.log.gz

[shankari]

Differences between earlier pushes and this one

9am silent push

Sep 30 09:00:16 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Error>: Ignoring notification with no alert, sound or badge (edu.berkeley.eecs.emission): 8302-2FE7
Sep 30 09:00:16 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Not saving push notification 8302-2FE7 to store [ error=Error Domain=UNErrorDomain Code=1401 "Notification has no user-facing content" UserInfo={NSLocalizedDescription=Notification has no user-facing content} ]

Not proceeding with launch now

Sep 30 09:00:16 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Adding a launch request (<private>) for application <private> by activity <private>
Sep 30 09:00:16 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Launch requests for <private>: <private>
Sep 30 09:00:16 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Activity <private>: Optimal Score 0.5384 at <private> (Valid Until: <private>)
Sep 30 09:00:16 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

But will proceed later

Sep 30 09:09:44 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F6F998:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Can Proceed, Score: 0.50}}
    {name: DeviceActivityPolicy, policyWeight: 5.000, response: {Decision: Can Proceed, Score: 0.33}}
 ] sumScores:53.076667, denominator:81.410000, FinalDecision: Can Proceed FinalScore: 0.651967}

Earlier silent push

No user-facing content

Sep 30 07:41:33 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Error>: Ignoring notification with no alert, sound or badge (edu.berkeley.eecs.emission): A70F-77E6
Sep 30 07:41:33 ucb-sdb-iphone-2 SpringBoard(UserNotificationsServer)[55] <Notice>: [edu.berkeley.eecs.emission] Not saving push notification A70F-77E6 to store [ error=Error Domain=UNErrorDomain Code=1401 "Notification has no user-facing content" UserInfo={NSLocalizedDescription=Notification has no user-facing content} ]

cancelling the launch. Ah but note that this is a different launch! This is launch 40551D, not 401DE7. This must be the launch from the previous push that was not yet scheduled.

Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Adding a launch request (<private>) for application <private> by activity <private>
Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Launch requests for <private>: <private>
Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Daemon Canceling Activities: {(
    com.apple.pushLaunch.edu.berkeley.eecs.emission:40551D
)}

Checking the policy now

Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Activity <private>: Optimal Score 0.5438 at <private> (Valid Until: <private>)
Sep 30 07:41:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:401DE7:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

And still not proceed. And then we stopped logging...

Sep 30 07:41:34 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:401DE7:[
    {name: ApplicationPolicy, policyWeight: 50.000, response: {Decision: Must Not Proceed, Score: 0.00}}
 ], FinalDecision: Must Not Proceed}

[shankari]

Ok so here's are all the dasd checks between 10:00 and 11:00. The first one is the main push, and then there are checks at varying intervals - sometimes one minute apart and sometimes closer to 5 minutes and one 10 minute interval. Maybe it was closer when I was moving? I don't really remember.

Sep 30 10:00:14 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:01:03 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:08:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:13:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:17:56 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:18:46 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:19:13 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:19:24 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:28:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:30:23 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:35:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:38:53 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:47:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:49:17 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:49:29 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:53:02 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[
Sep 30 10:58:03 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211:[

Then at 11, we got a new launch request, cancelled this one, and then kept trying...

Sep 30 11:00:15 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Submitted Activity: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889 <private>
Sep 30 11:00:15 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: CANCELED: com.apple.pushLaunch.edu.berkeley.eecs.emission:E0E211 <private>!
Sep 30 11:00:15 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:03:46 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:08:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:12:50 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:13:01 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:13:51 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:14:13 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:15:47 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:17:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:19:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:19:53 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:22:53 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:23:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:28:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:30:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:38:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:43:47 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:48:46 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:49:54 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:50:05 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:51:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[
Sep 30 11:58:03 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889:[

Similarly, at noon

Sep 30 12:00:19 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: Submitted Activity: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C <private>
Sep 30 12:00:19 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: CANCELED: com.apple.pushLaunch.edu.berkeley.eecs.emission:AAE889 <private>!
Sep 30 12:00:19 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:03:47 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:08:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:13:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:18:38 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:18:47 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:19:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:19:44 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:21:53 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:25:03 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:30:33 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[
Sep 30 12:38:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C:[

except that this time, the stars do align

Sep 30 12:38:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: 'com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C' has compatibility score of 1.000000 with 'com.apple.healthd.sync.cloud.periodic:F124DB'. Relaxing scores.
Sep 30 12:38:43 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: 'com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C' CurrentScore: 0.634566, ThresholdScore: 0.465102 DecisionToRun:1
Sep 30 12:39:13 ucb-sdb-iphone-2 dasd(DuetActivitySchedulerDaemon)[139] <Notice>: COMPLETED com.apple.pushLaunch.edu.berkeley.eecs.emission:F2252C <private>!

It looks like the process is only run when it has a compatibility score of 1.000 with the healthd.sync.

This is pretty bad. If we have to wait for hours at a time to align with the healthd.sync, we cannot use push notifications that launch the UI for pretty much anything.

all_logs_from_10am_noon.log.gz

[shankari]

Stackoverflow (https://stackoverflow.com/questions/44796613/silent-pushes-not-delivered-to-the-app-on-ios-11) says that this might be better in iOS11.

iOS 11.1 beta release notes include: Notifications Resolved Issues Silent push notifications are processed more frequently. (33278611) I did some tests and it seems to be indeed fixed:

I am currently on 11.0. Upgrading to 11.1 to see if it helps...

[shankari]

11.1 is in beta and the beta was just released yesterday. Have to try updating to it to test the fix.

[shankari]

Updated to 11.1 and it seems to work, but time delayed by ~ 10 mins.

Most recent	An hour before that

[shankari]

the xcode console no longer displays the dasd logs, but here's what I got from the regular console.

We can see that the push launches occur a bit after the hour, and the delay keeps increasing

Now it is 7 mins.

/tmp/after_11.1_upgrade.log:dasd    Submitted Activity: com.apple.pushLaunch.edu.berkeley.eecs.emission:68E314 <private>    2017-09-30 17:07:11.612024 -0700
/tmp/after_11.1_upgrade.log:dasd    com.apple.pushLaunch.edu.berkeley.eecs.emission:68E314:[
/tmp/after_11.1_upgrade.log:dasd    'com.apple.pushLaunch.edu.berkeley.eecs.emission:68E314' DecisionToRun:1 (Bypasses Predictions)    2017-09-30 17:07:11.627706 -0700
/tmp/after_11.1_upgrade.log:dasd    COMPLETED com.apple.pushLaunch.edu.berkeley.eecs.emission:68E314 <private>!    2017-09-30 17:07:41.817207 -0700

Now it is 10 mins.

/tmp/after_11.1_upgrade.log:dasd    Submitted Activity: com.apple.pushLaunch.edu.berkeley.eecs.emission:E90EFB <private>    2017-09-30 18:10:03.730083 -0700
/tmp/after_11.1_upgrade.log:dasd    com.apple.pushLaunch.edu.berkeley.eecs.emission:E90EFB:[
/tmp/after_11.1_upgrade.log:dasd    'com.apple.pushLaunch.edu.berkeley.eecs.emission:E90EFB' DecisionToRun:1 (Bypasses Predictions)    2017-09-30 18:10:03.732579 -0700
/tmp/after_11.1_upgrade.log:dasd    COMPLETED com.apple.pushLaunch.edu.berkeley.eecs.emission:E90EFB <private>!    2017-09-30 18:10:33.956336 -0700

Let's look at the rest of the logs and see when the push was actually received. It looks like it was actually only received at 17:07

apsd    <private> incoming message is for proxy slave that is *not* connected. baseToken <private>  destToken <private>  publicToken <private>    2017-09-30 17:07:11.545106 -0700
dasd    Launch requests for <private>: <private>    2017-09-30 17:07:11.617861 -0700
SpringBoard    Ignoring notification with no alert, sound or badge (edu.berkeley.eecs.emission): FA3D-0D04    2017-09-30 17:07:11.618695 -0700
SpringBoard    [edu.berkeley.eecs.emission] Not saving push notification FA3D-0D04 to store [ error=Error Domain=UNErrorDomain Code=1401 "Notification has no user-facing content" UserInfo={NSLocalizedDescription=Notification has no user-facing content} ]    2017-09-30 17:07:11.619448 -0700
dasd    com.apple.pushLaunch.edu.berkeley.eecs.emission:68E314:[
    {name: DeviceActivityPolicy, policyWeight: 5.000, response: {Decision: Can Proceed, Score: 0.05}}
 ] sumScores:26.660000, denominator:31.410000, FinalDecision: Can Proceed FinalScore: 0.848774}    2017-09-30 17:07:11.626804 -0700
dasd    'com.apple.pushLaunch.edu.berkeley.eecs.emission:68E314' DecisionToRun:1 (Bypasses Predictions)    2017-09-30 17:07:11.627706 -0700

And similarly

apsd    <private> incoming message is for proxy slave that is *not* connected. baseToken <private>  destToken <private>  publicToken <private>    2017-09-30 18:10:03.639052 -0700
SpringBoard    Ignoring notification with no alert, sound or badge (edu.berkeley.eecs.emission): CA8F-A34A    2017-09-30 18:10:03.729549 -0700
dasd    Submitted Activity: com.apple.pushLaunch.edu.berkeley.eecs.emission:E90EFB <private>    2017-09-30 18:10:03.730083 -0700
SpringBoard    [edu.berkeley.eecs.emission] Not saving push notification CA8F-A34A to store [ error=Error Domain=UNErrorDomain Code=1401 "Notification has no user-facing content" UserInfo={NSLocalizedDescription=Notification has no user-facing content} ]    2017-09-30 18:10:03.730475 -0700
dasd    Adding a launch request (<private>) for application <private> by activity <private>    2017-09-30 18:10:03.731218 -0700
dasd    Launch requests for <private>: <private>    2017-09-30 18:10:03.731567 -0700
dasd    com.apple.pushLaunch.edu.berkeley.eecs.emission:E90EFB:[
    {name: DeviceActivityPolicy, policyWeight: 5.000, response: {Decision: Can Proceed, Score: 0.05}}
 ] sumScores:26.660000, denominator:31.410000, FinalDecision: Can Proceed FinalScore: 0.848774}    2017-09-30 18:10:03.731913 -0700
dasd    'com.apple.pushLaunch.edu.berkeley.eecs.emission:E90EFB' DecisionToRun:1 (Bypasses Predictions)    2017-09-30 18:10:03.732579 -0700

[shankari]

ported over all the hacky changes and added a non-default unit test. (https://github.com/e-mission/e-mission-server/pull/528)

[shankari]

found some issues with running from the send_survey script during (embarrassingly!) a demo. Also, the migration to firebase broke visible notifications. Fixes will be checked in soon

[shankari]

Closing this since pushes work successfully now