932209 - [WAP push] Fail to receive SI message any more if previous SI message has not been read.

Status: VERIFIED FIXED

(Firefox OS Graveyard :: RIL, defect)

Description

[Hubert Lu[:hlu] <[e-mail]>]

Attachment: logcat.txt

* Build Number                
Gaia:     2ef9bc3c7a6de228b63e6ba3613eb0c0dd639c59
Gecko:    http://hg.mozilla.org/releases/mozilla-aurora/rev/4a94d2ea9d37
BuildID   20131028004002
Version   26.0a2

* Reproduce Steps
1. Send more than 3 WAP Push messages from NowSMS with text, WAP URL and SI push type values filled and selected on the software.

* Expected Result
DUT could receive all of messages.

* Actual Result
DUT only could receive the first SI message.

* Occurrence rate
100%

Comment 1

[Gabriele Svelto [:gsvelto]]

I may have run into this problem before but I a little bit of extra information: can you reproduce the problem if you increase the time between each message? I.e. does the problem happens only if you send the messages together in rapid sequence or does it happen also if you let pass some time between the messages (say 20 seconds)?

Comment 2

[Hubert Lu[:hlu] <[e-mail]>]

DUT fails to receive SI message any more if previous SI message has not been read even the sending interval time between message is over 30 seconds. And we do the same testing for SL message, DUT does not have this bug.

Comment 3

[Preeti Raghunath(:Preeti)]

koi+ for SI type messages being sent inconsistently.

Comment 4

[bhavana bajaj [:bajaj]]

NI on ken Chang to help find an owner here .

Comment 5

[Ken Chang[:kenkai]]

Gabriele, can you please take this bug?

Comment 6

[Gabriele Svelto [:gsvelto]]

(In reply to Ken Chang from comment #5)
> Gabriele, can you please take this bug?

Yes, I'll try addressing it next week.

Comment 7

[Preeti Raghunath(:Preeti)]

Gabriele,

Have you had a chance to take this bug forward?

Please provide ETA for fix.

Comment 8

[Gabriele Svelto [:gsvelto]]

I'm currently working on it, I've set the ETA for sprint C5 as it should be ready by the end of the week.

Comment 9

[Gabriele Svelto [:gsvelto]]

Moving this to the next sprint as I've not managed to fix the problem yet.

Comment 10

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH] Do not automatically close the app if there are pending messages waiting to be processed

So after further analysis I figured out that the cause of this bug is that often more than one message is delivered at the same time to the WAP Push app. Due to the asynchronous nature of the app in those cases we would retrieve 2-3 messages from the system app but process only the first before closing. This would reliably make us lose 1-2 messages, sometimes more depending on the time of arrival.

This patch prevents closing the app if there's still pending messages. Note that it reduces the chance of losing a message but does not eliminate it. There's always the possibility of a narrow race condition were a message can be delivered after we've invoked the close() method and thus have no way of processing it and we will lose it anyway. This is fairly unlikely though so I think we'll rarely encounter it in practice.

Comment 11

[Gabriele Svelto [:gsvelto]]

Attachment: [PULL REQUEST] Do not automatically close the app if there are pending messages waiting to be processed

Comment 12

[Julien Wajsberg [:julienw]]

Comment on attachment 8338318 [details] [diff] [review]
[PATCH] Do not automatically close the app if there are pending messages waiting to be processed

Review of attachment 8338318 [details] [diff] [review]:
-----------------------------------------------------------------

As we saw together, adding tests should not be that difficult. I'd like that you try to test all cases where we're decrementing pendingMessages, if that's possible.

Please request review when you're ready!

::: apps/wappush/js/wappush.js
@@ +131,3 @@
>      var message = ParsedMessage.from(wapMessage, Date.now());
>  
>      if (!this.shouldDisplayMessage(message)) {

here you need to decrement the pendingMessages var too.

@@ +145,5 @@
>      message.save(
>        (function wpm_saveSuccess(status) {
>          if ((status === 'discarded') || (message.action === 'signal-none')) {
> +          this._pendingMessages--;
> +          this.close(/* background */ true);

you forgot "return" here

@@ +250,2 @@
>        window.setTimeout(window.close);
>      }

how about moving the pendingMessages decrement + the call to close in another function ? Maybe called "finish" ?

This function would:
* decrement pendingMessages
* if pendingMessages is 0 and document.hidden is true, call close.

Now, close could be a lot more simple and only call "window.setTimeout(window.close)".

It's especially necessary because other modules are calling it when the user presses the cross and we agreed that in that case we need to close even if there is pending messages left (which is very unlikely anyway, and hopefully Gecko is waiting that we don't have any pending event before closing the app.

Comment 13

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH v2] Do not automatically close the app if there are pending messages waiting to be processed

Updated patch with review comments addressed and unit tests added. Besides addressing all the issues highlighted in comment 12 I also modified the way the application is closed: this now always happens on a timer making the whole process slightly more complicated but also more robust as it now covers effectively the case where a message is received while the user is manually closing the app.

Effectively the new procedure schedules closing the app on a timer and then depending on the app state postpones the timer (if there are pending messages), cancels it (if the app became visible in the meantime) or actually closes the app.

Comment 14

[Julien Wajsberg [:julienw]]

Comment on attachment 8338988 [details] [diff] [review]
[PATCH v2] Do not automatically close the app if there are pending messages waiting to be processed

Review of attachment 8338988 [details] [diff] [review]:
-----------------------------------------------------------------

Small comments, especially around the delayed close implementation.

The beauty here is that your tests will probably still work once you'll change wappush.js :) (except that I ask you changes to the tests too, but you get the point).

We're nearly there!

Please add a commit on top of your existing commits in github, that new commit will contain only your follow-up changes. And ask me review again once you're ready :)

Thanks!

::: apps/wappush/js/wappush.js
@@ +253,3 @@
>     */
>    close: function wpm_close(background) {
> +    if ((background && !document.hidden) || (this._closeTimeout !== null)) {

`finish` is the only location that calls `close` with a `true` arg, therefore I'd move the `background` + `document.hidden` logic inside `finish` instead of having it here.

@@ +263,5 @@
> +     * and have not yet been processed. If some messages are pending we'll
> +     * reschedule the close until they've all been processed. */
> +    this._closeTimeout = window.setTimeout((function delayedClose() {
> +      if (background && !document.hidden) {
> +        // The app is visible, give up, it will be closed by the user eventually

I don't like this much.

How about calling `clearTimeout(this._closeTimeout); this._closeTimeout = null;` at the start of `onNotification` instead? Plus this would save this little edge case where the getSelf request has not been returned yet.

@@ +265,5 @@
> +    this._closeTimeout = window.setTimeout((function delayedClose() {
> +      if (background && !document.hidden) {
> +        // The app is visible, give up, it will be closed by the user eventually
> +        this._closeTimeout = null;
> +      } else if (this._pendingMessages > 0) {

Another possibility: at the start of `onWapPushReceived` just call `clearTimeout(this._closeTimeout) + nullify the variable`

@@ +266,5 @@
> +      if (background && !document.hidden) {
> +        // The app is visible, give up, it will be closed by the user eventually
> +        this._closeTimeout = null;
> +      } else if (this._pendingMessages > 0) {
> +        // There are pending messages, try again

(if you keep this) nit: better write this comment like this: "// pending messages were received since we set this timer"

@@ +271,5 @@
> +        this._closeTimeout = window.setTimeout(delayedClose.bind(this), 100);
> +      } else {
> +        // There's no more pending messages, close for real
> +        this._closeTimeout = null;
> +        window.close();

I think you just need this in the end :)

@@ +273,5 @@
> +        // There's no more pending messages, close for real
> +        this._closeTimeout = null;
> +        window.close();
> +      }
> +    }).bind(this), 100);

nit: I think you don't need to use the parens around the function, gjslint is not buggy for this construct

::: apps/wappush/test/unit/wappush_test.js
@@ +407,5 @@
> +    });
> +
> +    teardown(function() {
> +      delete document.hidden;
> +      this.clock.restore();

you don't need to call restore, this is done automatically by the test-agent helper, see https://github.com/mozilla-b2g/gaia/blob/master/test_apps/test-agent/common/test/sinon_helper.js for the magic.

@@ +413,5 @@
> +      MockNavigatormozSetMessageHandler.mTeardown();
> +    });
> +
> +    test('the app is closed after displaying a notification', function() {
> +      var closeSpy = this.sinon.spy(window, 'close');

you do this in all tests, you should move it to the setup.

also, you don't need to use a variable `closeSpy`, just use `window.close` wherever you used `closeSpy` instead, it's short enough that we don't need a shortcut var and it's more readable.

@@ +419,5 @@
> +
> +      MockNavigatormozSetMessageHandler.mTrigger('wappush-received', message);
> +      MockNavigatormozApps.mTriggerLastRequestSuccess();
> +      this.clock.tick(100);
> +      assert.isTrue(closeSpy.calledOnce);

nit: `sinon.assert.calledOnce(closeSpy)` is more expressive and gives better error messages in case of failures

@@ +420,5 @@
> +      MockNavigatormozSetMessageHandler.mTrigger('wappush-received', message);
> +      MockNavigatormozApps.mTriggerLastRequestSuccess();
> +      this.clock.tick(100);
> +      assert.isTrue(closeSpy.calledOnce);
> +      window.close.restore();

no need to restore, the helper does this for you (ditto in all the tests)

@@ +457,5 @@
> +      MockNavigatormozSetMessageHandler.mTrigger('wappush-received', message);
> +      MockNavigatormozApps.mTriggerLastRequestSuccess();
> +      MockNavigatormozSetMessageHandler.mTrigger('wappush-received', message);
> +      this.clock.tick(100);
> +      assert.isTrue(closeSpy.notCalled);

nit: you can remove this assert, the last one is enough

Comment 15

[Gabriele Svelto [:gsvelto]]

I'm almost done refining the patch, just a few notes on your comments though.

(In reply to Julien Wajsberg [:julienw] from comment #14)
> ::: apps/wappush/js/wappush.js
> @@ +253,3 @@
> >     */
> >    close: function wpm_close(background) {
> > +    if ((background && !document.hidden) || (this._closeTimeout !== null)) {
> 
> `finish` is the only location that calls `close` with a `true` arg,
> therefore I'd move the `background` + `document.hidden` logic inside
> `finish` instead of having it here.

We call close(/* background */ true) from onVisibilityChange() too which is why I didn't move the check in finish().

> @@ +263,5 @@
> > +     * and have not yet been processed. If some messages are pending we'll
> > +     * reschedule the close until they've all been processed. */
> > +    this._closeTimeout = window.setTimeout((function delayedClose() {
> > +      if (background && !document.hidden) {
> > +        // The app is visible, give up, it will be closed by the user eventually
> 
> I don't like this much.
> 
> How about calling `clearTimeout(this._closeTimeout); this._closeTimeout =
> null;` at the start of `onNotification` instead? Plus this would save this
> little edge case where the getSelf request has not been returned yet.

You mean in onVisibilityChanged()? I didn't want to spread the logic too much, the idea here is that if the conditions in which the timer started change the timer either re-schedules the close or cancels itself. Having all the code in the same place means that once the first message starts the close operation it will go on until all messages have been processed or until the application becomes visible. Once the application becomes visible we cancel the close procedure and resume it only if the user explicitly closes the application or it becomes hidden again (e.g. by pressing on the home button).

> @@ +265,5 @@
> > +    this._closeTimeout = window.setTimeout((function delayedClose() {
> > +      if (background && !document.hidden) {
> > +        // The app is visible, give up, it will be closed by the user eventually
> > +        this._closeTimeout = null;
> > +      } else if (this._pendingMessages > 0) {
> 
> Another possibility: at the start of `onWapPushReceived` just call
> `clearTimeout(this._closeTimeout) + nullify the variable`

That doesn't work in practice because due to the asynchronous nature of this code if more than one message is pending onWapPushReceived() is called multiple times in a row so starting with the second call the timer has not started yet there are more than one message in flight already.

> (if you keep this) nit: better write this comment like this: "// pending
> messages were received since we set this timer"

Yup.

> @@ +271,5 @@
> > +        this._closeTimeout = window.setTimeout(delayedClose.bind(this), 100);
> > +      } else {
> > +        // There's no more pending messages, close for real
> > +        this._closeTimeout = null;
> > +        window.close();
> 
> I think you just need this in the end :)

Yes, it's more readable that way.

> nit: I think you don't need to use the parens around the function, gjslint
> is not buggy for this construct

Thanks, it used to be buggy. I also applied all the changes you suggested to the tests.

Comment 16

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH v3] Do not automatically close the app if there are pending messages waiting to be processed

Updated patch, note that I've pushed the differences with the previous patch in a separate commit in the PR as you suggested. I've applied all the changes you requested to the unit-tests and some to the actual logic but I've also improved the comments there to clear up how the timer logic works and why it works that way.

Comment 17

[Julien Wajsberg [:julienw]]

(In reply to Gabriele Svelto [:gsvelto] from comment #15)
> I'm almost done refining the patch, just a few notes on your comments though.
> 
> (In reply to Julien Wajsberg [:julienw] from comment #14)
> > ::: apps/wappush/js/wappush.js
> > @@ +253,3 @@
> > >     */
> > >    close: function wpm_close(background) {
> > > +    if ((background && !document.hidden) || (this._closeTimeout !== null)) {
> > 
> > `finish` is the only location that calls `close` with a `true` arg,
> > therefore I'd move the `background` + `document.hidden` logic inside
> > `finish` instead of having it here.
> 
> We call close(/* background */ true) from onVisibilityChange() too which is
> why I didn't move the check in finish().

then I'd rather see this check in onVisibilityChange too. This is something we're used to in visibilityChange handlers so it feels right.

> 
> > @@ +263,5 @@
> > > +     * and have not yet been processed. If some messages are pending we'll
> > > +     * reschedule the close until they've all been processed. */
> > > +    this._closeTimeout = window.setTimeout((function delayedClose() {
> > > +      if (background && !document.hidden) {
> > > +        // The app is visible, give up, it will be closed by the user eventually
> > 
> > I don't like this much.
> > 
> > How about calling `clearTimeout(this._closeTimeout); this._closeTimeout =
> > null;` at the start of `onNotification` instead? Plus this would save this
> > little edge case where the getSelf request has not been returned yet.
> 
> You mean in onVisibilityChanged()?

I meant in onNotification ;) as soon as possible.

> I didn't want to spread the logic too
> much, the idea here is that if the conditions in which the timer started
> change the timer either re-schedules the close or cancels itself. Having all
> the code in the same place means that once the first message starts the
> close operation it will go on until all messages have been processed or
> until the application becomes visible. Once the application becomes visible
> we cancel the close procedure and resume it only if the user explicitly
> closes the application or it becomes hidden again (e.g. by pressing on the
> home button).

I still think this is more complicated and it makes your setTimeout callback difficult to read because we don't understand its behavior at the first glance.

But I won't block on this.

> 
> > @@ +265,5 @@
> > > +    this._closeTimeout = window.setTimeout((function delayedClose() {
> > > +      if (background && !document.hidden) {
> > > +        // The app is visible, give up, it will be closed by the user eventually
> > > +        this._closeTimeout = null;
> > > +      } else if (this._pendingMessages > 0) {
> > 
> > Another possibility: at the start of `onWapPushReceived` just call
> > `clearTimeout(this._closeTimeout) + nullify the variable`
> 
> That doesn't work in practice because due to the asynchronous nature of this
> code if more than one message is pending onWapPushReceived() is called
> multiple times in a row so starting with the second call the timer has not
> started yet there are more than one message in flight already.

Sorry, I don't get why this wouldn't work?
clearTimeout perfectly works with an invalid id as parameter.

> 
> > nit: I think you don't need to use the parens around the function, gjslint
> > is not buggy for this construct
> 
> Thanks, it used to be buggy. I also applied all the changes you suggested to
> the tests.

It was buggy only for this construct: "var xxx = function() { ... }.bind(this);" and it still is afaik.

Comment 18

[Julien Wajsberg [:julienw]]

Comment on attachment 8339696 [details] [diff] [review]
[PATCH v3] Do not automatically close the app if there are pending messages waiting to be processed

Review of attachment 8339696 [details] [diff] [review]:
-----------------------------------------------------------------

mmm it was not a format-patch-generated patch...

r=me with the "background" parameter removal, as said in the previous comment.

About the setTimeout, I still think this is a bad idea but I won't block on this.

Please merge on a green Travis.

Comment 19

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH v4] Do not automatically close the app if there are pending messages waiting to be processed r=julienw

Revised patch will all review comments addressed, carrying over the r+ flag. I've removed the |background| parameter from WapPushManager.close() and moved the clear-the-timer-when-becoming-visible logic into the visibility-change handler. Similar logic has been moved into WapPushManager.finish() to prevent closing the app while it's still visible. Travis run is here: http://is.gd/RcYFgc

Comment 20

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH v5] Do not automatically close the app if there are pending messages waiting to be processed r=julienw

Zut! I forgot the bit about canceling the close timer within onNotification(), this time it's fixed for good. Travis run is here: http://is.gd/6CISI8

v1.2 patch coming soon...

Comment 21

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH gaia/v1.2] Do not automatically close the app if there are pending messages waiting to be processed r=julienw

Patch adapted for v1.2. Only small changes were required to accommodate for the fact that v1.2 does not have the onClose() callback we use in master.

Comment 22

[Gabriele Svelto [:gsvelto]]

Travis is green except for an unrelated failure, pushed to:

- gaia/master da07dd3d80a1253bd6ed2c2e9653cd9a8b93d3e6
- gaia/v1.2   9db579112e7ffe17fbd1d12b444584987aeadf5f

Comment 23

[Enpei]

Verified on Buri.
Gaia      8d762f3376318fd6be390432db750ae4904c9ab6
Gecko     http://hg.mozilla.org/releases/mozilla-b2g26_v1_2/rev/758f3fb32dda
BuildID   20131204004003
Version   26.0