Closed Bug 909270 Opened 6 years ago Closed 6 years ago

Only one alarm must be set in the same moment

Categories

(Core :: DOM: Push Notifications, defect)

x86
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla26
blocking-b2g leo+
Tracking Status
firefox24 --- wontfix
firefox25 --- wontfix
firefox26 --- fixed
b2g18 --- fixed
b2g18-v1.0.0 --- wontfix
b2g18-v1.0.1 --- wontfix
b2g-v1.1hd --- fixed

People

(Reporter: willyaranda, Assigned: nsm)

References

Details

Attachments

(1 file, 1 obsolete file)

STR:

1) Register a lot of channelIDs
2) Disconnect the device
3) Send notifications to all channels
4) Connect the device

Expected: only one alarm should be set

Actual: two alarms are set, and older is not cleared.

We should have a unique transaction for setting alarms

08-26 12:49:27.259 I/Gecko   (  108): -*- PushService.jsm: Send hello: {"messageType":"hello","uaid":"26b85a63-5e3a-446c-bfa5-0c60284668e5@c499491712198e4c25b4465b9750545c3bc25ab5","channelIDs":["01bab9ca-3d7f-4432-8202-18e8031ecc2a","020bceee-6bd3-46de-8346-6d5e33573d25","08671434-e01a-424f-99c9-055d64189223","150a3e0b-52d0-48c7-9b80-52bd607385e0","15c80ac8-5d85-487b-801c-5d86f8447f23","1bb8aac6-fedd-4d0f-8e14-3762dbd623d3","1dc3f508-6353-4bfb-bc67-ce77f8a4cc8b","419838d4-efed-402a-95df-ba5d1f3bed18","49443723-dc20-4b4f-a69f-eb0d7905cba7","4ae62659-e55b-476f-a4c1-df7d46ff623a","72b9b8aa-cea9-435f-b16c-437b3eb3ae61","78fddbe6-074e-4dab-8443-02dc83696d5f","7b5841a1-128b-43bb-a6a9-8f1804f507d2","84c16d7a-b0ff-4b3c-9a62-7688ae04e9a4","9f85ff86-7c81-42b4-9b64-9a6993699d35","a0a9602b-5b3e-4349-b5d1-8e6f1ea0ebd4","a391864f-c38c-4ed0-865c-0d68a518a2a6","ab846b8d-2c1f-4194-922d-68dace74fe2c","b866c248-7e46-4f40-b86b-78197cb71a33","bd016bc1-5826-4227-b2b4-0d3077a6b3d8","c30d094e-929a-4671-9c1c-4885587daf96","ca80a35e-e458-4c88-aeaf-03fc1de20ca9","dfb8e4f
08-26 12:49:27.439 I/Gecko   (  108): -*- PushService.jsm: wsOnMessageAvailable() {"messageType":"hello","uaid":"26b85a63-5e3a-446c-bfa5-0c60284668e5@c499491712198e4c25b4465b9750545c3bc25ab5","status":200}
08-26 12:49:27.459 I/Gecko   (  108): -*- PushService.jsm: handleHelloReply()
08-26 12:49:27.459 I/Gecko   (  108): -*- PushService.jsm: New _UAID: 26b85a63-5e3a-446c-bfa5-0c60284668e5@c499491712198e4c25b4465b9750545c3bc25ab5
08-26 12:49:27.459 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.459 I/Gecko   (  108): -*- PushService.jsm: Request queue empty
08-26 12:49:27.469 I/Gecko   (  108): -*- PushService.jsm: wsOnMessageAvailable() {"messageType":"notification","updates":[{"channelID":"1bb8aac6-fedd-4d0f-8e14-3762dbd623d3","version":"48"},{"channelID":"dfb8e4f4-016b-4aa3-b56e-b683b644836a","version":"47"},{"channelID":"1dc3f508-6353-4bfb-bc67-ce77f8a4cc8b","version":"45"},{"channelID":"a0a9602b-5b3e-4349-b5d1-8e6f1ea0ebd4","version":"44"},{"channelID":"01bab9ca-3d7f-4432-8202-18e8031ecc2a","version":"820"}]}
08-26 12:49:27.469 I/Gecko   (  108): -*- PushService.jsm: handleNotificationReply()
08-26 12:49:27.469 I/Gecko   (  108): -*- PushService.jsm: Reply updates: 5
08-26 12:49:27.479 I/Gecko   (  108): -*- PushService.jsm: Update: 1bb8aac6-fedd-4d0f-8e14-3762dbd623d3: 48
08-26 12:49:27.479 I/Gecko   (  108): -*- PushService.jsm: Updating: 1bb8aac6-fedd-4d0f-8e14-3762dbd623d3 -> 48
08-26 12:49:27.479 I/Gecko   (  108): -*- PushService.jsm: getByChannelID()
08-26 12:49:27.479 I/Gecko   (  108): -*- PushService.jsm: sendAck()
08-26 12:49:27.479 I/Gecko   (  108): -*- PushService.jsm: send()
08-26 12:49:27.479 I/Gecko   (  108): -*- PushService.jsm: Queued ack
08-26 12:49:27.479 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: Update: dfb8e4f4-016b-4aa3-b56e-b683b644836a: 47
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: Updating: dfb8e4f4-016b-4aa3-b56e-b683b644836a -> 47
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: getByChannelID()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: sendAck()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: send()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: Queued ack
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: Update: 1dc3f508-6353-4bfb-bc67-ce77f8a4cc8b: 45
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: Updating: 1dc3f508-6353-4bfb-bc67-ce77f8a4cc8b -> 45
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: getByChannelID()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: sendAck()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: send()
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: Queued ack
08-26 12:49:27.489 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: Update: a0a9602b-5b3e-4349-b5d1-8e6f1ea0ebd4: 44
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: Updating: a0a9602b-5b3e-4349-b5d1-8e6f1ea0ebd4 -> 44
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: getByChannelID()
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: sendAck()
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: send()
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: Queued ack
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: Update: 01bab9ca-3d7f-4432-8202-18e8031ecc2a: 820
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: Updating: 01bab9ca-3d7f-4432-8202-18e8031ecc2a -> 820
08-26 12:49:27.499 I/Gecko   (  108): -*- PushService.jsm: getByChannelID()
08-26 12:49:27.509 I/Gecko   (  108): -*- PushService.jsm: sendAck()
08-26 12:49:27.509 I/Gecko   (  108): -*- PushService.jsm: send()
08-26 12:49:27.509 I/Gecko   (  108): -*- PushService.jsm: Queued ack
08-26 12:49:27.509 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Fetch successful [object Object]
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Request queue empty
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Fetch successful [object Object]
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Request queue empty
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Request queue empty
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Fetch successful [object Object]
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Request queue empty
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Request queue empty
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Fetch successful [object Object]
08-26 12:49:27.519 I/Gecko   (  108): -*- PushService.jsm: Fetch successful [object Object]
08-26 12:49:27.529 I/Gecko   (  108): -*- PushService.jsm: compareRecordVersionAndNotify()
08-26 12:49:27.529 I/Gecko   (  108): -*- PushService.jsm: Version changed, notifying app and updating DB
08-26 12:49:27.529 I/Gecko   (  108): -*- PushService.jsm: notifyApp() app://webapp_b.gaiamobile.org/index.html  app://webapp_b.gaiamobile.org/manifest.webapp
08-26 12:49:27.609 I/Gecko   (  108): -*- PushService.jsm: updatePushRecord()
08-26 12:49:27.609 I/Gecko   (  108): -*- PushService.jsm: put()
08-26 12:49:27.609 I/Gecko   (  108): -*- PushService.jsm: Going to put 1bb8aac6-fedd-4d0f-8e14-3762dbd623d3
08-26 12:49:27.609 I/Gecko   (  108): -*- PushService.jsm: compareRecordVersionAndNotify()
08-26 12:49:27.609 I/Gecko   (  108): -*- PushService.jsm: Version changed, notifying app and updating DB
08-26 12:49:27.609 I/Gecko   (  108): -*- PushService.jsm: notifyApp() app://webapp_b.gaiamobile.org/index.html  app://webapp_b.gaiamobile.org/manifest.webapp
08-26 12:49:27.629 I/Gecko   (  108): -*- PushService.jsm: updatePushRecord()
08-26 12:49:27.629 I/Gecko   (  108): -*- PushService.jsm: put()
08-26 12:49:27.629 I/Gecko   (  108): -*- PushService.jsm: Going to put dfb8e4f4-016b-4aa3-b56e-b683b644836a
08-26 12:49:27.629 I/Gecko   (  108): -*- PushService.jsm: compareRecordVersionAndNotify()
08-26 12:49:27.629 I/Gecko   (  108): -*- PushService.jsm: Version changed, notifying app and updating DB
08-26 12:49:27.629 I/Gecko   (  108): -*- PushService.jsm: notifyApp() app://webapp_b.gaiamobile.org/index.html  app://webapp_b.gaiamobile.org/manifest.webapp
08-26 12:49:27.649 I/Gecko   (  108): -*- PushService.jsm: updatePushRecord()
08-26 12:49:27.649 I/Gecko   (  108): -*- PushService.jsm: put()
08-26 12:49:27.649 I/Gecko   (  108): -*- PushService.jsm: Going to put 1dc3f508-6353-4bfb-bc67-ce77f8a4cc8b
08-26 12:49:27.659 I/Gecko   (  108): -*- PushService.jsm: compareRecordVersionAndNotify()
08-26 12:49:27.659 I/Gecko   (  108): -*- PushService.jsm: Version changed, notifying app and updating DB
08-26 12:49:27.659 I/Gecko   (  108): -*- PushService.jsm: notifyApp() app://webapp_b.gaiamobile.org/index.html  app://webapp_b.gaiamobile.org/manifest.webapp
08-26 12:49:27.679 I/Gecko   (  108): -*- PushService.jsm: updatePushRecord()
08-26 12:49:27.679 I/Gecko   (  108): -*- PushService.jsm: put()
08-26 12:49:27.679 I/Gecko   (  108): -*- PushService.jsm: Going to put a0a9602b-5b3e-4349-b5d1-8e6f1ea0ebd4
08-26 12:49:27.689 I/Gecko   (  108): -*- PushService.jsm: compareRecordVersionAndNotify()
08-26 12:49:27.689 I/Gecko   (  108): -*- PushService.jsm: Version changed, notifying app and updating DB
08-26 12:49:27.689 I/Gecko   (  108): -*- PushService.jsm: notifyApp() app://webapp_a.gaiamobile.org/index.html  app://webapp_a.gaiamobile.org/manifest.webapp
08-26 12:49:27.799 I/Gecko   (  108): -*- PushService.jsm: updatePushRecord()
08-26 12:49:27.799 I/Gecko   (  108): -*- PushService.jsm: put()
08-26 12:49:27.799 I/Gecko   (  108): -*- PushService.jsm: Going to put 01bab9ca-3d7f-4432-8202-18e8031ecc2a
08-26 12:49:27.819 I/Gecko   (  108): -*- PushService.jsm: Set alarm 1800000 in the future 1038
08-26 12:49:27.869 I/Gecko   (  108): -*- PushService.jsm: Request successful. Updated record ID: 1bb8aac6-fedd-4d0f-8e14-3762dbd623d3
08-26 12:49:27.939 I/Gecko   (  108): -*- PushService.jsm: Set alarm 1800000 in the future 1039
08-26 12:49:28.000 I/Gecko   (  108): -*- PushService.jsm: Request successful. Updated record ID: dfb8e4f4-016b-4aa3-b56e-b683b644836a
08-26 12:49:28.150 I/Gecko   (  108): -*- PushService.jsm: Request successful. Updated record ID: 1dc3f508-6353-4bfb-bc67-ce77f8a4cc8b
08-26 12:49:28.240 I/Gecko   (  108): -*- PushService.jsm: Request successful. Updated record ID: a0a9602b-5b3e-4349-b5d1-8e6f1ea0ebd4
08-26 12:49:28.360 I/Gecko   (  108): -*- PushService.jsm: Request successful. Updated record ID: 01bab9ca-3d7f-4432-8202-18e8031ecc2a
08-26 12:49:28.560 I/GeckoDump(  416): [DEBUG] PushApp_B: Init
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: receiveMessage(): Push:Register
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: register()
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: sendRequest() register
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: send()
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: Queued register
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: _processNextRequestInQueue()
08-26 12:49:28.670 I/Gecko   (  108): -*- PushService.jsm: Request queue empty
08-26 12:49:28.710 I/GeckoDump(  416): [DEBUG] PushApp_B: New Message: {"pushEndpoint":"https://push-nv.srv.openwebdevice.com:443/v1/notify/f0c104f12679cc862b33abecc337ea561451f655e0a9e44461c3312e31838fbd","version":48}
08-26 12:49:28.800 I/GeckoDump(  416): [DEBUG] PushApp_B: New Message: {"pushEndpoint":"https://push-nv.srv.openwebdevice.com:443/v1/notify/d1264115ed6b3c47a54ba72529e46f98b081aee9903c782e81ff9daf25fa6500","version":47}
08-26 12:49:28.800 I/GeckoDump(  416): [DEBUG] PushApp_B: New Message: {"pushEndpoint":"https://push-nv.srv.openwebdevice.com:443/v1/notify/fb1c63a51fe9ab0fc7f031e3807b44fbd79037ce52d72ef7a974ce38a3645d35","version":45}
08-26 12:49:28.840 I/GeckoDump(  416): [DEBUG] PushApp_B: New Message: {"pushEndpoint":"https://push-nv.srv.openwebdevice.com:443/v1/notify/a835697da103ac50c2fc94d0e0a61a7c94d446540b774fbf68db24ae1c29b15f","version":44}
08-26 12:49:28.840 I/Gecko   (  108): -*- PushService.jsm: wsOnMessageAvailable() {"messageType":"register","status":200,"pushEndpoint":"https://push-nv.srv.openwebdevice.com:443/v1/notify/95903c5b35588b7ca80991dfd194585b64ff705f5416a28b8f60be0b6664757c","channelID":"356aee93-8f4f-4e18-aacd-f959b11bbc66"}
08-26 12:49:28.840 I/Gecko   (  108): -*- PushService.jsm: Stopped existing alarm 1039

(a bunch more of notifications with their new alarms, like
08-26 13:08:21.135 I/Gecko   (  108): -*- PushService.jsm: Set alarm 1800000 in the future 1059
08-26 13:08:40.013 I/Gecko   (  108): -*- PushService.jsm: Set alarm 10000 in the future 1061
08-26 13:09:07.851 I/Gecko   (  108): -*- PushService.jsm: Set alarm 1800000 in the future 1065
)

And then 30 minutes after 12:49:27 is fired the not stopped alarm:
08-26 13:19:27.015 I/Gecko   (  108): -*- PushService.jsm: Stopped existing alarm 1070
08-26 13:19:27.335 I/Gecko   (  108): -*- PushService.jsm: Set alarm 60000 in the future 1071
08-26 13:19:28.886 I/Gecko   (  108): -*- PushService.jsm: wsOnMessageAvailable() {}
08-26 13:19:28.886 I/Gecko   (  108): -*- PushService.jsm: Stopped existing alarm 1071
08-26 13:19:28.907 I/Gecko   (  108): -*- PushService.jsm: messageType not a string undefined
08-26 13:19:29.067 I/Gecko   (  108): -*- PushService.jsm: Set alarm 1800000 in the future 1072
08-26 13:21:10.996 I/Gecko   (  108): -*- PushService.jsm: Stopped existing alarm 1072
08-26 13:21:11.326 I/Gecko   (  108): -*- PushService.jsm: Set alarm 60000 in the future 1073
08-26 13:21:12.928 I/Gecko   (  108): -*- PushService.jsm: wsOnMessageAvailable() {}
08-26 13:21:12.928 I/Gecko   (  108): -*- PushService.jsm: Stopped existing alarm 1073
08-26 13:21:12.948 I/Gecko   (  108): -*- PushService.jsm: messageType not a string undefined
08-26 13:21:13.108 I/Gecko   (  108): -*- PushService.jsm: Set alarm 1800000 in the future 1074

Alarm 1038 and 1039 are set on the same time, but only a reference to 1039 is hold, so 1038 is never stopped, and then fires when is not desired.
Flags: needinfo?(nsm.nikhil)
Just to be clear, is 908621 a dupe of this bug?
So the reason this seems to be happening is because of async and sync calls clashing.

When there are pending notifications, this is what happens:
1) The "hello" message from the server causes the ping alarm to be set. This queues a request to alarm API add() which is async.
2) The "notification" message is received, which causes PushService._setAlarm() to be called again. The async add() from (1) has not finished yet, so _stopAlarm() does not do anything. another alarm is added.
3) add() from (1) finishes, giving 1038.
4) add() from (2) finishes, giving 1039. 1039 overwrites 1038 as PushService._alarmID.

This is a good catch. The solution will be to ensure that only one add() call is active at a time. I'll have to see if add() calls can be queued up as events instead.
Flags: needinfo?(nsm.nikhil)
Attached patch Queue PushService alarms. (obsolete) — Splinter Review
Attachment #796988 - Flags: review?(justin.lebar+bug)
Assignee: nobody → nsm.nikhil
Comment on attachment 796988 [details] [diff] [review]
Queue PushService alarms.

Guillermo, please try this change. It should also fix the double alarm issue.
Attachment #796988 - Flags: feedback?(willyaranda)
Attachment #796988 - Attachment is obsolete: true
Attachment #796988 - Flags: review?(justin.lebar+bug)
Attachment #796988 - Flags: feedback?(willyaranda)
Comment on attachment 796989 [details] [diff] [review]
Queue PushService alarms.

Removed code that exercised the change.
Attachment #796989 - Flags: review?(justin.lebar+bug)
Attachment #796989 - Flags: feedback?(willyaranda)
What if setAlarm() is called three times in quick succession?
Comment on attachment 796989 [details] [diff] [review]
Queue PushService alarms.

Popping this review back to nsm per irl conversation so he can convince himself that this works.  I think I'm pretty close to convinced (because we want last-writer-wins, which is what we get here).
Attachment #796989 - Flags: review?(justin.lebar+bug) → review?(nsm.nikhil)
Comment on attachment 796989 [details] [diff] [review]
Queue PushService alarms.

This is the right thing to do.
Attachment #796989 - Flags: review?(nsm.nikhil) → review?(justin.lebar+bug)
Agreed, but could you clarify the comment to say that what we're aiming for is exactly one alarm with "last-writer-wins" semantics?
Attachment #796989 - Flags: review?(justin.lebar+bug) → review+
Comment on attachment 796989 [details] [diff] [review]
Queue PushService alarms.

I just tested this and only one alarm is set at a given time.

Thanks
Attachment #796989 - Flags: feedback?(willyaranda) → feedback+
blocking-b2g: --- → leo?
Duplicate of this bug: 908621
https://hg.mozilla.org/mozilla-central/rev/40d877c1ee90
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla26
Fernando, please add an explanation required for leo approval.
Flags: needinfo?(frsela)
This is a low risk patch with a high user impact if declined, as it would increase both battery & network usage, that the main purpose of push notifications is to save both battery & network usage
Flags: needinfo?(frsela)
leo+ for user experience.
blocking-b2g: leo? → leo+
You need to log in before you can comment on or make changes to this bug.