Closed Bug 970879 Opened 6 years ago Closed 6 years ago

Intermittent wappush/test/unit/wappush_test.js | WAP Push automatic closing of the application the app is closed after displaying a notification | expected close to be called once but was called 0 times

Categories

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

x86_64
Linux
defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: RyanVM, Assigned: gsvelto)

Details

(Keywords: intermittent-failure)

Attachments

(2 files, 1 obsolete file)

https://tbpl.mozilla.org/php/getParsedLog.php?id=34461403&tree=B2g-Inbound

b2g_ubuntu64_vm b2g-inbound opt test gaia-unit on 2014-02-10 18:59:15 PST for push 932bf66bc441
slave: tst-linux64-spot-320

19:11:28     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js |
19:11:28     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | WAP Push
19:11:28     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | init
19:11:28     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push init the message handlers are bound
19:11:28     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | init
19:11:28     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | unsupported message
19:11:28     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push unsupported message unsupported messages are discarded
19:11:28     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | unsupported message
19:11:28     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | receiving and displaying a message
19:11:28     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a message the notification is sent
19:11:28     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a message Notification.get() called with correct tag
19:11:28     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a message the display is populated with the message contents
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a message Notification is closed
19:11:29     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | receiving and displaying a message
19:11:29     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | receiving and displaying a CP message
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a CP message the notification is sent
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a CP message Notification.get() called with correct tag
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a CP message the display is populated with the NETWPIN message contents
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a CP message the display is populated with the USERPIN message contents
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push receiving and displaying a CP message Notification is closed
19:11:29     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | receiving and displaying a CP message
19:11:29     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | handling out-of-order reception of messages
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push handling out-of-order reception of messages the old message is expired
19:11:29     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push handling out-of-order reception of messages an outdated message does not replace a newer one
19:11:30     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push handling out-of-order reception of messages the current message is displayed
19:11:30     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | handling out-of-order reception of messages
19:11:30     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | handling expired messages
19:11:30     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push handling expired messages the message was not stored in the database
19:11:30     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | handling expired messages
19:11:30     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | handling actions
19:11:30     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push handling actions action=signal-none does not send a notification
19:11:30     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | handling actions
19:11:30     INFO -  gaia-unit-tests TEST-START | wappush/test/unit/wappush_test.js | automatic closing of the application
19:11:30     INFO -  gaia-unit-tests TEST-UNEXPECTED-FAIL | wappush/test/unit/wappush_test.js | WAP Push automatic closing of the application the app is closed after displaying a notification | expected close to be called once but was called 0 times
19:11:30     INFO -  gaia-unit-tests INFO       | stack trace:
19:11:30     INFO -      Error: expected close to be called once but was called 0 times
19:11:30     INFO -          at fail (http://wappush.gaiamobile.org:8080/common/vendor/sinon/sinon.js:4137)
19:11:30     INFO -          at failAssertion (http://wappush.gaiamobile.org:8080/common/vendor/sinon/sinon.js:4098)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/common/vendor/sinon/sinon.js:4121)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/test/unit/wappush_test.js:523)
19:11:30     INFO -          at wrapper (http://wappush.gaiamobile.org:8080/common/test/mocha_generators.js:62)
19:11:30     INFO -          at run (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3709)
19:11:30     INFO -          at runTest (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:4081)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:4127)
19:11:30     INFO -          at next (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:4007)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:4016)
19:11:30     INFO -          at next (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3964)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3979)
19:11:30     INFO -          at done (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3700)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3712)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/common/test/mocha_generators.js:46)
19:11:30     INFO -          at wpm_settingsLockSuccess (http://wappush.gaiamobile.org:8080/js/wappush.js:64)
19:11:30     INFO -          at (anonymous) (http://wappush.gaiamobile.org:8080/shared/test/unit/mocks/mock_navigator_moz_settings.js:74)
19:11:30     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push automatic closing of the application the app is not closed if it is visible
19:11:30     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push automatic closing of the application the app is closed only after processing all messages
19:11:30     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push automatic closing of the application prevent the app from closing if it becomes visible
19:11:30     INFO -  gaia-unit-tests TEST-PASS  | wappush/test/unit/wappush_test.js | WAP Push automatic closing of the application the app is closed when hidden
19:11:30     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | automatic closing of the application
19:11:31     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js | WAP Push
19:11:31     INFO -  gaia-unit-tests TEST-END   | wappush/test/unit/wappush_test.js |
19:11:31     INFO -  gaia-unit-tests INFO       | suite results (pass/fail): 20/1
Component: Gaia::TestAgent → Gaia::Wappush
This is quite weird, I've never seen this happen locally as that test uses mocked timers & a mocked |document.hidden| property so it should be fully deterministic:

https://github.com/mozilla-b2g/gaia/blob/72707888e08ccf5bc5f2180e04d8d2a6dfac70ce/apps/wappush/test/unit/wappush_test.js#L517

It does depend on the shared mozSettings mock (which appears in the backtrace) and it seems that there was a change there recently:

https://github.com/mozilla-b2g/gaia/commit/82d99defb293c44fab46be06e1cb4842f1c064c8

Which I see you promptly reverted here:

https://github.com/mozilla-b2g/gaia/commit/92d8a3f2de9f0b6310ddb478bcc58015c3c1057a
OS: Linux → Gonk (Firefox OS)
Hardware: x86_64 → ARM
Gabriele, note that this is marked as intermittent.

I have a possible explanation:
* we're using the fake timers only at this location
* therefore, previous tests do not use the fake timers, and use the timeout

Therefore, is it possible that other tests are running so slow that they interfere with this one, possibly setting the "_closeTimeout" var ?

I'd avise to set up the fake timers in the main setup.
FWIW, this was filed on x86_64::Linux because it's happening on a desktop B2G build. We don't run Gaia unit tests on the emulator yet.
We don't either. I usually file unit tests issue with "x86" or "x86_64". Not that it's that useful though.
(In reply to Julien Wajsberg [:julienw] from comment #3)
> I have a possible explanation:
> * we're using the fake timers only at this location
> * therefore, previous tests do not use the fake timers, and use the timeout
> 
> Therefore, is it possible that other tests are running so slow that they
> interfere with this one, possibly setting the "_closeTimeout" var ?
> 
> I'd avise to set up the fake timers in the main setup.

That shouldn't happen, in the previous tests the timeout shouldn't start at all. It starts only if |document.hidden| is true which should never be the case. That being said we might want to control that too to ensure that |document.hidden| is always false except for the tests where we want it to be true.
OS: Gonk (Firefox OS) → Linux
Hardware: ARM → x86_64
I may be onto something: we're creating the event-listener for the |visibilitychange| event with .bind(), this prevents the event-listener logic from dropping duplicate entries when calling multiple times WapPushManager.init(). This means that one |visibilitychange| listener is added per test and one of those might go off at the wrong time clearing the timer and triggering the problem. I'm preparing a patch to fix this issue.
Assignee: nobody → gsvelto
Status: NEW → ASSIGNED
ahah I saw today a similar issue in Messages ;)
I've refactored the WapPushManager to work like other objects in the app, by the nature of the change this prevents redundant listeners from accumulating during tests as we don't need to .bind() them to the |this| pointer. The code is also cleaner overall.

I've also increased control over the |document.hidden| field to make testing more robust. During testing I can now see that the close timeout is issued only when we're testing it and never in other situations.

I've also took the liberty of removing the remaining jshint issues.
Attachment #8374357 - Flags: feedback?(felash)
Comment on attachment 8374357 [details] [diff] [review]
[PATCH] Prevent redundant listeners from being registered during testing

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

I need a pull request to run all tests ;)
Attachment #8374357 - Flags: feedback?(felash) → feedback+
Right, sorry, it was late yesterday night and I forgot the PR.
Attachment #8374357 - Flags: review?(felash)
Comment on attachment 8374357 [details] [diff] [review]
[PATCH] Prevent redundant listeners from being registered during testing

I'm gonna trust the unit tests here ;)

r=me with the little construct change
Attachment #8374357 - Flags: review?(felash) → review+
Updated patch with the comment in GitHub addressed, carrying over the r+ flag. I've updated to PR too and I'm waiting for the Travis run to turn green:

https://travis-ci.org/mozilla-b2g/gaia/builds/18739818

I've also gave this a spin in the emulator with real WAP Push messages to verify that I hadn't accidentally messed up something.
Attachment #8374357 - Attachment is obsolete: true
Attachment #8374883 - Flags: review+
Merged in gaia/master a403bdf3cf2a09b5ed0ed5aee362d8b7b31810b3

Travis unit-tests-in-firefox run was red and it remained so when I re-run it. All errors seemed to be related to the system, clock and communications apps and are happening across other PRs too so they should be unrelated.

Ryan how should we treat the status of this bug? I cannot be sure that my patch fixes the problem as I couldn't reproduce it locally, shall we leave this open for a week or two and then close it if we don't see any further intermittent failures?
Flags: needinfo?(ryanvm)
sgtm
Flags: needinfo?(ryanvm)
I'd rather do the opposite but maybe it's my contradictory mood ;)

Adding to the whiteboard so that it's clear
Whiteboard: [closeme 02/27]
This hasn't bothered us anymore fortunately, closing.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Whiteboard: [closeme 02/27]
You need to log in before you can comment on or make changes to this bug.