963518 - Only the first WapPush message can be accessed

Status: RESOLVED DUPLICATE of bug 942080

(Firefox OS Graveyard :: Gaia::System, defect)

Description

[:gerard-majax]

Testing WapPush in emulator, I noticed that you can get to a strange state where you tap a notification but another is triggered.

STR:
 1. Build an emulator making dure depends patches are applied
 2. Trigger a wappush message (cf below)
 3. Check that the notification is correctly displayed, do not tap on it
 4. Restart B2G
 5. Trigger a second wappush message
 6. New notification is displayed
 7. Tap on the notification

Expected:
 You get the message you just sent.

Actual:
 You get "message expired" error.

Triggering a WapPush message with emulator:
 1. telnet localhost 5554
 2. sms pdu 07911326040000F0400B911346610089F6000420806291731408350605040B8423F0010603AEAF8203056A0045C60D036F7265696C6C7900850103436865636B20746869732077656273697465000101
 3. you should get a 'OK' reply

Comment 1

[:gerard-majax]

Console output of the first sms pdu payload:
I/Gecko   (  756): -*- NotificationStorage.js: PUT: {e20226da-0479-415d-b28e-4bbc9478c7e7}: [phone]
I/Gecko   (  643): -*- NotificationDB component: Received message:Notification:Save
I/Gecko   (  643): -*- NotificationDB component: Queueing task: save
I/Gecko   (  643): -*- NotificationDB component: Queue status: save => this.runningTask=false
I/Gecko   (  643): -*- NotificationDB component: loading notifications
I/Gecko   (  643): OS Controller Posting message {"fun":"read","args":[{"string":"/data/b2g/mozilla/xqyuk9ts.default/notificationstore.json"},null,{}],"id":1}
E/GeckoConsole(  756): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:186 in wpm_gotApp: Sending notification: {"icon":"app://wappush.gaiamobile.org/style/icons/wappush.png","body":"Check this website http://www.oreilly.com/","tag":"1390565062666"}
E/GeckoConsole(  756): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:191 in wpm_gotApp: Calling finish()
I/GeckoDump(  643): XXX FIXME : Got a mozContentEvent: desktop-notification-show
I/Gecko   (  643): -*- NotificationDB component: Directory creation failed:Unix error 2 during operation open (No such file or directory)
I/Gecko   (  643): OS Controller Posting message {"fun":"open","args":[{"string":"/data/b2g/mozilla/xqyuk9ts.default/notificationstore.json"},{"create":true},null],"id":3}
I/Gecko   (  643): -*- NotificationDB component: Task, saving
I/Gecko   (  643): -*- NotificationDB component: Task: notifications={}
I/Gecko   (  643): -*- NotificationDB component: Task: origin="app://wappush.gaiamobile.org/manifest.webapp"
I/Gecko   (  643): -*- NotificationDB component: Task: notifications[origin]=undefined
I/Gecko   (  643): -*- NotificationDB component: Task: this.byTag[origin]={}
I/Gecko   (  643): -*- NotificationDB component: save: IN
I/Gecko   (  643): -*- NotificationDB component: save: will OS.File.writeAtomic()
I/Gecko   (  643): OS Controller Posting message {"fun":"writeAtomic","args":[{"string":"/data/b2g/mozilla/xqyuk9ts.default/notificationstore.json"},{"ptr":"1172613264"},{"bytes":321}],"id":5}
I/Gecko   (  643): -*- NotificationDB component: save: promise executed: [object Object]
I/Gecko   (  643): -*- NotificationDB component: save: promise onSuccess: [object Object]
I/Gecko   (  643): -*- NotificationDB component: save: promise onSuccess: JSON={}
I/Gecko   (  643): -*- NotificationDB component: Finishing task: save
I/Gecko   (  643): -*- NotificationDB component: Will call callback on task: function
I/Gecko   (  643): -*- NotificationDB component: receiveMessage: returnMessage: sending Notification:Save:Return:OK
I/Gecko   (  643): -*- NotificationDB component: Return message failed, Notification:Save:Return:OK
I/Gecko   (  643): -*- NotificationDB component: Callback on task called: save
I/Gecko   (  643): -*- NotificationDB component: this.runNextTask() called: save

Comment 2

[:gerard-majax]

Console output of the second sms pdu payload:
I/Gecko   (  936): -*- NotificationStorage.js: PUT: {5b07a3c5-2bbe-42e1-8b92-8f31b13abfe7}: [phone]
I/Gecko   (  837): -*- NotificationDB component: Received message:Notification:Save
I/Gecko   (  837): -*- NotificationDB component: Queueing task: save
I/Gecko   (  837): -*- NotificationDB component: Queue status: save => this.runningTask=false
I/Gecko   (  837): -*- NotificationDB component: loading notifications
I/Gecko   (  837): OS Controller Posting message {"fun":"read","args":[{"string":"/data/b2g/mozilla/xqyuk9ts.default/notificationstore.json"},null,{}],"id":1}
E/GeckoConsole(  936): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:186 in wpm_gotApp: Sending notification: {"icon":"app://wappush.gaiamobile.org/style/icons/wappush.png","body":"Check this website http://www.oreilly.com/","tag":"1390565170029"}
E/GeckoConsole(  936): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:191 in wpm_gotApp: Calling finish()
I/GeckoDump(  837): XXX FIXME : Got a mozContentEvent: desktop-notification-show
I/Gecko   (  837): -*- NotificationDB component: load: onSuccess
I/Gecko   (  837): -*- NotificationDB component: load: onSuccess: parsing notifications
I/Gecko   (  837): -*- NotificationDB component: load: onSuccess: parsing notifications successfully
I/Gecko   (  837): -*- NotificationDB component: load: onSuccess: have notifications
I/Gecko   (  837): -*- NotificationDB component: load: origin=app://wappush.gaiamobile.org/manifest.webapp
I/Gecko   (  837): -*- NotificationDB component: load: origin=app://wappush.gaiamobile.org/manifest.webapp -- id={e20226da-0479-415d-b28e-4bbc9478c7e7}
I/Gecko   (  837): -*- NotificationDB component: load: notification tag: 1390565062666
I/Gecko   (  837): -*- NotificationDB component: load: byTag={"app://wappush.gaiamobile.org/manifest.webapp":{"1390565062666":{"id":"{e20226da-0479-415d-b28e-4bbc9478c7e7}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390565062666","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}}}
I/Gecko   (  837): -*- NotificationDB component: Task, saving
I/Gecko   (  837): -*- NotificationDB component: Task: notifications={"app://wappush.gaiamobile.org/manifest.webapp":{"{e20226da-0479-415d-b28e-4bbc9478c7e7}":{"id":"{e20226da-0479-415d-b28e-4bbc9478c7e7}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390565062666","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}}}
I/Gecko   (  837): -*- NotificationDB component: Task: origin="app://wappush.gaiamobile.org/manifest.webapp"
I/Gecko   (  837): -*- NotificationDB component: Task: notifications[origin]={"{e20226da-0479-415d-b28e-4bbc9478c7e7}":{"id":"{e20226da-0479-415d-b28e-4bbc9478c7e7}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390565062666","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}}
I/Gecko   (  837): -*- NotificationDB component: Task: this.byTag[origin]={"1390565062666":{"id":"{e20226da-0479-415d-b28e-4bbc9478c7e7}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390565062666","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}}
I/Gecko   (  837): -*- NotificationDB component: save: IN
I/Gecko   (  837): -*- NotificationDB component: save: will OS.File.writeAtomic()
I/Gecko   (  837): OS Controller Posting message {"fun":"writeAtomic","args":[{"string":"/data/b2g/mozilla/xqyuk9ts.default/notificationstore.json"},{"ptr":"1212979216"},{"bytes":592}],"id":2}
I/Gecko   (  837): -*- NotificationDB component: save: promise executed: [object Object]
I/Gecko   (  837): -*- NotificationDB component: save: promise onSuccess: [object Object]
I/Gecko   (  837): -*- NotificationDB component: save: promise onSuccess: JSON={}
I/Gecko   (  837): -*- NotificationDB component: Finishing task: save
I/Gecko   (  837): -*- NotificationDB component: Will call callback on task: function
I/Gecko   (  837): -*- NotificationDB component: receiveMessage: returnMessage: sending Notification:Save:Return:OK
I/Gecko   (  837): -*- NotificationDB component: Return message failed, Notification:Save:Return:OK
I/Gecko   (  837): -*- NotificationDB component: Callback on task called: save
I/Gecko   (  837): -*- NotificationDB component: this.runNextTask() called: save

Comment 3

[:gerard-majax]

Console output of the notification click:
E/GeckoConsole( 1025): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:234 in wpm_displayWapPushMessage: displayWapPushMessage: IN: 1390565170029
I/Gecko   ( 1025): -*- NotificationStorage.js: GET: 1390565170029
I/Gecko   (  837): -*- NotificationDB component: Received message:Notification:GetAll
I/Gecko   (  837): -*- NotificationDB component: Queueing task: getall
I/Gecko   (  837): -*- NotificationDB component: Queue status: getall => this.runningTask=false
I/Gecko   (  837): -*- NotificationDB component: Task, getting all
I/Gecko   (  837): -*- NotificationDB component: Finishing task: getall
I/Gecko   (  837): -*- NotificationDB component: Will call callback on task: function
I/Gecko   (  837): -*- NotificationDB component: receiveMessage: returnMessage: sending Notification:GetAll:Return:OK
I/Gecko   (  837): -*- NotificationDB component: Callback on task called: getall
I/Gecko   (  837): -*- NotificationDB component: this.runNextTask() called: getall
E/GeckoConsole( 1025): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:237 in wpm_loadSuccess: displayWapPushMessage: loaded: null
E/GeckoConsole( 1025): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:238 in wpm_loadSuccess: displayWapPushMessage: get: 1390565170029
E/GeckoConsole( 1025): Content JS WARN at app://wappush.gaiamobile.org/shared/js/l10n.js:79 in consoleWarn: [l10n] #wap-push-message is undefined.
E/GeckoConsole( 1025): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:242 in onSuccess: displayWapPushMessage: got: 1390565170029
E/GeckoConsole( 1025): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:243 in onSuccess: displayWapPushMessage: got notifications: 1
E/GeckoConsole( 1025): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:245 in onSuccess: displayWapPushMessage: notifications: 0
I/Gecko   ( 1025): -*- NotificationStorage.js: DELETE: {5b07a3c5-2bbe-42e1-8b92-8f31b13abfe7}
I/Gecko   (  837): -*- NotificationDB component: Received message:Notification:Delete
I/Gecko   (  837): -*- NotificationDB component: Queueing task: delete
I/Gecko   (  837): -*- NotificationDB component: Queue status: delete => this.runningTask=false
I/Gecko   (  837): -*- NotificationDB component: Task, deleting
I/Gecko   (  837): -*- NotificationDB component: save: IN
I/Gecko   (  837): -*- NotificationDB component: save: will OS.File.writeAtomic()
I/Gecko   (  837): OS Controller Posting message {"fun":"writeAtomic","args":[{"string":"/data/b2g/mozilla/xqyuk9ts.default/notificationstore.json"},{"ptr":"1144308624"},{"bytes":321}],"id":1}
I/Gecko   (  837): -*- NotificationDB component: save: promise executed: [object Object]
I/GeckoDump(  837): XXX FIXME : Got a mozContentEvent: desktop-notification-close
I/Gecko   (  837): -*- NotificationDB component: save: promise onSuccess: [object Object]
I/Gecko   (  837): -*- NotificationDB component: save: promise onSuccess: JSON={}
I/Gecko   (  837): -*- NotificationDB component: Finishing task: delete
I/Gecko   (  837): -*- NotificationDB component: Will call callback on task: function
I/Gecko   (  837): -*- NotificationDB component: receiveMessage: returnMessage: sending Notification:Delete:Return:OK
I/Gecko   (  837): -*- NotificationDB component: Callback on task called: delete
I/Gecko   (  837): -*- NotificationDB component: this.runNextTask() called: delete

Comment 4

[:gerard-majax]

From comment 1, the first notification is tagged with '1390565062666'. From comment 2, the second one is tagged with '1390565170029'. We can see in comment 3 that the click triggers the WapPush application to display the latest notification, which is tagged '1390565170029'. Notification is correct retrieved and deleted, but it looks like the WapPush message has been lost.

Comment 5

[:gerard-majax]

What I'm observing might be a dupe of bug 962974.

Comment 6

[:gerard-majax]

Updated STR: the bug reproduces as long as you send two wappush messages. If you try to open the first one, it's okay, the second one will always get you the 'message expired' message.

In this second cse, ParsedMessage.load(timestamp) is called with the correct timestamp, but it returns 'null' as a message.

Comment 7

[Gabriele Svelto [:gsvelto] (PTO)]

This is really a dup of bug 942080. The two messages have an identical 'href' field (you need to decode the PDU to see it), this means that the second message is considered an update of the first and replaces it. We should remove the notification from the first message but before the new notification API landed we couldn't so we just marked the notification as expired. This can be confusing obviously as it might lead an user to think there's two or more pending messages when there's really just one.