962977 - Unable to remove WAP push/SMS message from notification bar unless pressing "clear all" button or reboot device.

Status: VERIFIED FIXED

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

Description

[Enpei]

Attachment: time stamp: 14:55, 1/23.

When screen timeout/suspend device while one WAP Push message is opened, the message will become expired bug stay on notification bar forever after resuming device. You need to reboot device to get rid of the expired message.

Comment 1

[Enpei]

* Build Number  
Buri
Gaia      a6f1bc96ac9e0a32022c75f0ee7771a2ab9050db
Gecko     http://hg.mozilla.org/mozilla-central/rev/b739b3354222
BuildID   20140122154850
Version   29.0a1

* Reproduce Steps
1. Send a WAP push SI message to DUT
2. Open the message, then press power key to suspend device.
3. Resume device.

* Expected Result
Message is opened.

* Actual Result
Message is not displayed on screen but it's still on notification bar. Once open it, it says it's expired. And then unable to remove it from notification bar even press "x" or home button. The only way is to reboot device.

* Occurrence rate
100%

Comment 2

[Enpei]

Attachment: VIDEO0018.mp4

Comment 3

[:gerard-majax]

It's strange: when we display the message, we retrieve the associated notifications and close them. Can you attach logcat ?

So if the notification is still there it means we did not called .close().

Comment 4

[Enpei]

Update the summary because I found that the real bug here is that there is no way to close WAP push(SI/SL) messages, nothing to do with suspend/resume device.

* Update reproduce Steps
1. Send a WAP push SI message to DUT
2. Open the message, then press "x" button on the left
3. Message will be closed but still can be reopened from notification bar.
4. Re-open the message
5. It says that message is expired.
Need to reboot or press clear all on notification tray.

Comment 5

[:gerard-majax]

WTF is this :(

01-23 14:53:41.919 I/Gecko   (  136): A coding exception was thrown in a Promise resolution callback.
01-23 14:53:41.919 I/Gecko   (  136): 
01-23 14:53:41.919 I/Gecko   (  136): Full message: TypeError: this.byTag[origin] is undefined
01-23 14:53:41.919 I/Gecko   (  136): See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
01-23 14:53:41.919 I/Gecko   (  136): Full stack: NotificationDB.taskSave@resource://gre/modules/NotificationDB.jsm:236
01-23 14:53:41.919 I/Gecko   (  136): NotificationDB.runNextTask/<@resource://gre/modules/NotificationDB.jsm:204
01-23 14:53:41.919 I/Gecko   (  136): onSuccess@resource://gre/modules/NotificationDB.jsm:61
01-23 14:53:41.919 I/Gecko   (  136): Handler.prototype.process@resource://gre/modules/Promise.jsm:767
01-23 14:53:41.919 I/Gecko   (  136): this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm:531

Comment 6

[Julien Wajsberg [:julienw]]

Promises catches exceptions, so the only meaningful message here is "TypeError: this.byTag[origin] is undefined". This is unfortunate we don't get the full stack with line numbers :(

Hopefully it should be reasonably easy to grep "this.byTag[origin]"

Comment 7

[:gerard-majax]

(In reply to Julien Wajsberg [:julienw] from comment #6)
> Promises catches exceptions, so the only meaningful message here is
> "TypeError: this.byTag[origin] is undefined". This is unfortunate we don't
> get the full stack with line numbers :(
> 
> Hopefully it should be reasonably easy to grep "this.byTag[origin]"

Yes, the fact is I already saw this issue previously and I thought it had been fixed since. I've looked at the code while in the train, I'm unsure why we get into this.

Comment 8

[:gerard-majax]

I think I just saw this in logcat after upgrading my Nexus S to master right now. And this was when starting the Messages app ... Not sure if this issue is really due to WapPush then.

Comment 9

[:gerard-majax]

Testing in the emulator, I get this:
E/GeckoConsole(  299): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:234 in wpm_displayWapPushMessage: displayWapPushMessage: IN: 1390469334049
I/Gecko   (  299): -*- NotificationStorage.js: GET: 1390469334049
I/Gecko   (   45): -*- NotificationDB component: Received message:Notification:GetAll
I/Gecko   (   45): -*- NotificationDB component: Queueing task: getall
E/GeckoConsole(  299): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:237 in wpm_loadSuccess: displayWapPushMessage: loaded: {"type":"text/vnd.wap.si","sender":"[phone]","timestamp":"1390469334049","href":"http://www.oreilly.com/","id":"http://www.oreilly.com/","text":"Check this website","action":"signal-medium"}
E/GeckoConsole(  299): Content JS DEBUG at app://wappush.gaiamobile.org/js/wappush.js:238 in wpm_loadSuccess: displayWapPushMessage: get: 1390469334049

So, getall is queued but never called ?

Comment 10

[Enpei]

(In reply to Alexandre LISSY :gerard-majax from comment #8)
> I think I just saw this in logcat after upgrading my Nexus S to master right
> now. And this was when starting the Messages app ... Not sure if this issue
> is really due to WapPush then.

You are right, SMS has the same problem as well. Update summary. And 1.3 has no such bug.

Works fine on
Gaia      744fb691c2b2a25a07c5d19fabf5748ae9aba4d9
Gecko     http://hg.mozilla.org/releases/mozilla-aurora/rev/71a8786c3815
BuildID   20140122004001
Version   28.0a2

Comment 11

[:gerard-majax]

I/Gecko   (  208): -*- NotificationStorage.js: PUT: {7b5b532c-f7bd-4a0e-af33-b97d253374c2}: [phone]
I/Gecko   (   45): -*- NotificationDB component: Received message:Notification:Save
I/Gecko   (   45): -*- NotificationDB component: Queueing task: save
I/Gecko   (   45): -*- NotificationDB component: Queue status: save => this.runningTask=false
I/Gecko   (   45): -*- NotificationDB component: Task, saving
I/Gecko   (   45): -*- NotificationDB component: Finishing task: save
I/Gecko   (  287): -*- NotificationStorage.js: GET: 1390470275862
I/Gecko   (   45): -*- NotificationDB component: Received message:Notification:GetAll
I/Gecko   (   45): -*- NotificationDB component: Queueing task: getall
I/Gecko   (   45): -*- NotificationDB component: Queue status: getall => this.runningTask=true

Comment 12

[:gerard-majax]

I am getting somehow blocked when calling message.target.sendAsyncMessage(). If I do comment this, then the notification correctly does get cleared in the emulator.

Comment 13

[:gerard-majax]

Sending a first WapPush PDU:
I/Gecko   (   45): -*- NotificationDB component: Task, saving
I/Gecko   (   45): -*- NotificationDB component: Task: notifications={}
I/Gecko   (   45): -*- NotificationDB component: Task: origin="app://wappush.gaiamobile.org/manifest.webapp"
I/Gecko   (   45): -*- NotificationDB component: Task: notifications[origin]=undefined
I/Gecko   (   45): -*- NotificationDB component: save: IN
I/Gecko   (   45): -*- NotificationDB component: save: will OS.File.writeAtomic()
I/Gecko   (   45): OS Controller Posting message {"fun":"writeAtomic","args":[{"string":"/data/b2g/mozilla/dfl5f29t.default/notificationstore.json"},{"ptr":"1167457968"},{"bytes":321}],"id":5}
I/Gecko   (   45): OS Controller Message posted
I/Gecko   (   45): -*- NotificationDB component: save: promise executed: [object Object]
I/Gecko   (   45): OS Controller Received message from worker {"id":4}
I/Gecko   (   45): OS Controller Received message from worker {"ok":321,"id":5}
I/Gecko   (   45): -*- NotificationDB component: save: promise onSuccess: [object Object]
I/Gecko   (   45): -*- NotificationDB component: save: promise onSuccess: JSON={}
I/Gecko   (   45): -*- NotificationDB component: Finishing task: save
I/Gecko   (   45): -*- NotificationDB component: Will call callback on task: function
I/Gecko   (   45): -*- NotificationDB component: Notification:Save: callback IN
I/Gecko   (   45): -*- NotificationDB component: Notification:Save: callback message={"target":{},"name":"Notification:Save","sync":false,"json":{"origin":"app://wappush.gaiamobile.org/manifest.webapp","notification":{"id":"{cebb8461-fb54-421c-a617-def9bb0b29f5}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390480621103","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}},"data":{"origin":"app://wappush.gaiamobile.org/manifest.webapp","notification":{"id":"{cebb8461-fb54-421c-a617-def9bb0b29f5}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390480621103","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}},"objects":{}}

Then, stopping and restarting B2G, sending a second WapPush:
I/Gecko   (  418): -*- NotificationStorage.js: PUT: {d260a75f-b0f0-485f-b47f-87b8d624c7c8}: [phone]
I/Gecko   (  308): -*- NotificationDB component: Received message:Notification:Save
I/Gecko   (  308): -*- NotificationDB component: Queueing task: save
I/Gecko   (  308): -*- NotificationDB component: Queue status: save => this.runningTask=false
I/Gecko   (  308): Task queue was not running, starting now...
I/Gecko   (  308): runNextTask: this.tasks.length=1
I/Gecko   (  308): OS Controller Posting message {"fun":"read","args":[{"string":"/data/b2g/mozilla/dfl5f29t.default/notificationstore.json"},null,{}],"id":1}
I/Gecko   (  308): OS Controller Message posted
I/Gecko   (  418): 
I/Gecko   (  418): ###!!! [Child][MessageChannel] Error: Channel closing: too late to send/recv, messages will be lost
I/Gecko   (  418): 
I/Gecko   (  308): OS Controller Received message from worker {"ok":{"buffer":{},"byteOffset":0,"byteLength":321},"id":1}
I/Gecko   (  308): -*- NotificationDB component: Task, saving
I/Gecko   (  308): -*- NotificationDB component: Task: notifications={"app://wappush.gaiamobile.org/manifest.webapp":{"{cebb8461-fb54-421c-a617-def9bb0b29f5}":{"id":"{cebb8461-fb54-421c-a617-def9bb0b29f5}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390480621103","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}}}
I/Gecko   (  308): -*- NotificationDB component: Task: origin="app://wappush.gaiamobile.org/manifest.webapp"
I/Gecko   (  308): -*- NotificationDB component: Task: notifications[origin]={"{cebb8461-fb54-421c-a617-def9bb0b29f5}":{"id":"{cebb8461-fb54-421c-a617-def9bb0b29f5}","title":"[phone]","dir":"auto","lang":"","body":"Check this website http://www.oreilly.com/","tag":"1390480621103","icon":"app://wappush.gaiamobile.org/style/icons/wappush.png"}}
I/Gecko   (  308): *************************
I/Gecko   (  308): A coding exception was thrown in a Promise resolution callback.
I/Gecko   (  308): 
I/Gecko   (  308): Full message: TypeError: this.byTag[origin] is undefined
I/Gecko   (  308): See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise
I/Gecko   (  308): Full stack: NotificationDB.taskSave@resource://gre/modules/NotificationDB.jsm:255
I/Gecko   (  308): NotificationDB.runNextTask/<@resource://gre/modules/NotificationDB.jsm:220
I/Gecko   (  308): onSuccess@resource://gre/modules/NotificationDB.jsm:61
I/Gecko   (  308): Handler.prototype.process@resource://gre/modules/Promise.jsm:767
I/Gecko   (  308): this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm:531
I/Gecko   (  308): 
I/Gecko   (  308): *************************

Comment 14

[:gerard-majax]

The way I understand the dump in previous comment is:
 - we store a notification
 - after rebooting b2g, we load the previous notifications
 - this.notifications[origin] exists, since we have previous notifications
 - but this.byTag[origin] has not been filled

Comment 15

[:gerard-majax]

My understanding of this bug is that Enpei first tested bug 962974, which populated one notification that did not got closed. Then starting a second WapPush on the same profile (maybe after a stop and start) and that would explain this second bug where we did not filled this.byTag[origin].

Enpei, could you confirm that you:
 - send a wappush message, ran into bug 962974
 - kept the profile, maybe reboot or stop/start b2g
 - second a second wappush message, and ran into the present bug

Thanks !

Comment 16

[:gerard-majax]

Turns out that sendAsyncMessage was throwing:
I/Gecko   (   45): -*- NotificationDB component: Notification:Save: sendAsyncMessage throw: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIMessageSender.sendAsyncMessage]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/NotificationDB.jsm :: NotificationDB.receiveMessage/< :: line 153"  data: no]

Comment 17

[:gerard-majax]

sendAsyncMessage throwing NS_ERROR_NOT_INITIALIZED probably comes from: http://hg.mozilla.org/mozilla-central/file/1a75d37e1e39/content/base/src/nsFrameMessageManager.cpp#l640

Comment 18

[Jason Smith [:jsmith]]

(In reply to Alexandre LISSY :gerard-majax from comment #15)
> My understanding of this bug is that Enpei first tested bug 962974, which
> populated one notification that did not got closed. Then starting a second
> WapPush on the same profile (maybe after a stop and start) and that would
> explain this second bug where we did not filled this.byTag[origin].
> 
> Enpei, could you confirm that you:
>  - send a wappush message, ran into bug 962974
>  - kept the profile, maybe reboot or stop/start b2g
>  - second a second wappush message, and ran into the present bug
> 
> Thanks !

Enpei - Can you additionally check if this reproduces on a 1/16/2014 build? That will help determine if this is caused by the new notification API work for WAP Push.

Comment 19

[:gerard-majax]

Michael, after discussing of this with Vivien, the behavior of message.target.sendAsyncMessage() seems to be consistent:
 - wappush wakes up, creates a new notification and nearly just after will close itself
 - meanwhile, notification code will call Put() method to save in the database
 - this triggers parent process code, in NotificationDB, that performs the save
 - when this parent process comes to the point of sending the Notification:Save:Return:OK message, the app has already been killed
 - hence we throw the NS_ERROR_NOT_INITIALIZED

Comment 20

[Michael Henretty [:mikehenrty][:mhenretty]]

(In reply to Alexandre LISSY :gerard-majax from comment #19)
>  - when this parent process comes to the point of sending the
> Notification:Save:Return:OK message, the app has already been killed
>  - hence we throw the NS_ERROR_NOT_INITIALIZED

This makes sense. We should put a try catch around any sendAsyncMessage, because it seems we cannot be guaranteed the app will still be alive when we finish our IO operations.


(In reply to Alexandre LISSY :gerard-majax from comment #14)
> The way I understand the dump in previous comment is:
>  - we store a notification
>  - after rebooting b2g, we load the previous notifications
>  - this.notifications[origin] exists, since we have previous notifications
>  - but this.byTag[origin] has not been filled

Yup, that's the case. We are not populating our byTag list upon reload. I will work on both these problems today.

Alexandre, is there any documentation on how to set up a WAP push testing environment? I'm afraid I don't know much about it, and I couldn't find much info. I could test in other ways, but would be nice to repro this actual bug.

Comment 21

[Michael Henretty [:mikehenrty][:mhenretty]]

(In reply to Jason Smith [:jsmith] from comment #18)
> Enpei - Can you additionally check if this reproduces on a 1/16/2014 build?
> That will help determine if this is caused by the new notification API work
> for WAP Push.

FWIW, the problems we've discussed above have always existed with notification storage.

Comment 23

[:gerard-majax]

(In reply to Michael Henretty [:mhenretty] from comment #20)
> Alexandre, is there any documentation on how to set up a WAP push testing
> environment? I'm afraid I don't know much about it, and I couldn't find much
> info. I could test in other ways, but would be nice to repro this actual bug.

I will suggest you what Gabriele documented to me. Use an emulator build, telnet localhost 5554 and dump a SMS PDU command (one line):
sms pdu 07911326040000F0400B911346610089F6000420806291731408350605040B8423F0010603AEAF8203056A0045C60D036F7265696C6C7900850103436865636B20746869732077656273697465000101

This will trigger the WapPush workflow. A bit painful, but 100% reproductibility.

Comment 24

[Jason Smith [:jsmith]]

(In reply to Michael Henretty [:mhenretty] from comment #21)
> (In reply to Jason Smith [:jsmith] from comment #18)
> > Enpei - Can you additionally check if this reproduces on a 1/16/2014 build?
> > That will help determine if this is caused by the new notification API work
> > for WAP Push.
> 
> FWIW, the problems we've discussed above have always existed with
> notification storage.

Would that imply that this would happen with the old mozNotification API as well then?

Comment 25

[Michael Henretty [:mikehenrty][:mhenretty]]

(In reply to Jason Smith [:jsmith] from comment #24)
> Would that imply that this would happen with the old mozNotification API as
> well then?

No, the notification storage service in question is exclusive to the new Web Notification API.

Comment 26

[Michael Henretty [:mikehenrty][:mhenretty]]

Attachment: Wrap sendAsyncMessage in try/catch

I believe this will fix it. Passes current mochitests. I am going to run Alexandre's steps in comment 23 against this as soon as I can get the emulator working.

Comment 27

[Enpei]

(In reply to Alexandre LISSY :gerard-majax from comment #15)
> My understanding of this bug is that Enpei first tested bug 962974, which
> populated one notification that did not got closed. Then starting a second
> WapPush on the same profile (maybe after a stop and start) and that would
> explain this second bug where we did not filled this.byTag[origin].
> 
> Enpei, could you confirm that you:
>  - send a wappush message, ran into bug 962974
>  - kept the profile, maybe reboot or stop/start b2g
>  - second a second wappush message, and ran into the present bug
> 
> Thanks !

Hi Alexandre,

I found that for SMS, message notification can be removed from notification bar only for the first time. That's when I flash build, send a SMS to device, open it, notification will be removed from notification bar. But after that, every SMS message notification will be kept on notification bar even I reboot device.

But for WAP push, it's 100% hit this bug, no first time pass case. And for CP, seriously I am not sure, because I did see the original bug 962974(it's been updated) twice that it will be removed from notification bar, just don't know how to reproduce it.

Yet this bug does not found on 0115 build, back to that point it only has bug 962974(I modified its summary, please check it first)
Gaia      255a56ac67e5b28f1fc78307969cc83391c9652f
Gecko     http://hg.mozilla.org/mozilla-central/rev/81bced59e8b3
BuildID   20140115041401
Version   29.0a1

Hope it's not toooo complicated so far...

Comment 28

[:gerard-majax]

(In reply to Michael Henretty [:mhenretty] from comment #26)
> Created attachment 8364667 [details] [diff] [review]
> Wrap sendAsyncMessage in try/catch
> 
> I believe this will fix it. Passes current mochitests. I am going to run
> Alexandre's steps in comment 23 against this as soon as I can get the
> emulator working.

Thanks, this is also the same kind of patcht that I was testing yesterday. I'll build an emulator with all those patches.

Comment 29

[:gerard-majax]

As far as I can say,your try/catch patch does the same correct job of fixing as what I previously tested on emulator and the GetAll request will not get blocked because we could not reset the running flag. Excellent!

Comment 30

[Michael Henretty [:mikehenrty][:mhenretty]]

Comment on attachment 8364667 [details] [diff] [review]
Wrap sendAsyncMessage in try/catch

Alexandre, care to take a look here as well?

https://tbpl.mozilla.org/?tree=Try&rev=504fbf02aea3

Comment 31

[Gregor Wagner [:gwagner]]

https://hg.mozilla.org/integration/b2g-inbound/rev/cf830f161937

Comment 32

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/cf830f161937

Comment 33

[Enpei]

Latest build still has the bug, is it uplifted?
Gaia      f382061fe95750d584a9078175c421a36892afc9
Gecko     http://hg.mozilla.org/mozilla-central/rev/3f1dd2a8e972
BuildID   20140126040203
Version   29.0a1

Comment 34

[Julien Wajsberg [:julienw]]

Maybe this build does not have the fix yet, can you try with the next build?

Comment 35

[Michael Henretty [:mikehenrty][:mhenretty]]

I just checked, and the build you have didn't contain the fix.

http://hg.mozilla.org/mozilla-central/file/3f1dd2a8e972/dom/src/notification/NotificationDB.jsm#l134

It should be in the next build.

Comment 36

[Enpei]

Latest build has no such problem now.

Gaia      3c5119507a985c59cfc264ed23821679b138486d
Gecko     605c25a204717675f3251c05cb99766eb3b75554
BuildID   20140128124203
Version   28.0a2

Comment 37

[Enpei]

Ignore last comment, here is the build I verified with.
Gaia      6586d2b8b43c6997be5cf5895bbdf3dd20490725
Gecko     http://hg.mozilla.org/mozilla-central/rev/ba31f271fbd0
BuildID   20140127160545
Version   29.0a1

Comment 38

[:gerard-majax]

This will cause us issues on 1.3 as well, nominating.

Comment 39

[Gregor Wagner [:gwagner]]

blocking a blocker

Comment 40

[Gregor Wagner [:gwagner]]

Comment on attachment 8364667 [details] [diff] [review]
Wrap sendAsyncMessage in try/catch

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #):
[User impact] if declined: Notficication won't work.
[Testing completed]:
[Risk to taking this patch] (and alternatives if risky): super low risk. wrapping try block around messagemanager functions. Has been on trunk for a long time.
[String changes made]:

Comment 41

[Michael Henretty [:mikehenrty][:mhenretty]]

uplifted to 1.3: https://github.com/mozilla-b2g/gaia/commit/932789749406a79c5630c27c724f1856bd3c3f10

Comment 42

[Gregor Wagner [:gwagner]]

https://hg.mozilla.org/releases/mozilla-b2g28_v1_3/rev/5c892a91add1