Closed Bug 996976 Opened 12 years ago Closed 12 years ago

Intermittent system/test/unit/icc_test.js | STK (icc) > launchStkCommand: STK_CMD_GET_INPUT | Error: expected false to equal true | "after each" hook | this.sinon is null

Categories

(Firefox OS Graveyard :: RIL, defect)

Product:
Firefox OS Graveyard
Component:
RIL
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(tracking-b2g:backlog, b2g-v2.0 fixed)

Status:
RESOLVED FIXED
Milestone:
2.0 S1 (9may)
Project Flags:
tracking-b2g backlog
Tracking Flags:
Tracking Status
b2g-v2.0 --- fixed

People

(Reporter: RyanVM, Assigned: frsela)

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled])

Attachments

(1 file)

Patch to fix STK unit tests & TBPL errors
46 bytes, text/x-github-pull-request
vingtetun
: review+
Details | Review
+++ This bug was initially created as a clone of Bug #995687 +++ https://tbpl.mozilla.org/php/getParsedLog.php?id=37878950&tree=Mozilla-Inbound b2g_ubuntu64_vm mozilla-inbound opt test gaia-unit on 2014-04-15 14:23:08 PDT for push f1660c847ca2 slave: tst-linux64-spot-923 15:59:30 INFO - gaia-unit-tests TEST-START | system/test/unit/icc_test.js | 15:59:30 INFO - gaia-unit-tests TEST-START | system/test/unit/icc_test.js | STK (icc) > 15:59:31 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > getIcc 15:59:32 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > getIccInfo 15:59:33 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > clearMenuCache 15:59:34 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > responseSTKCommand 15:59:34 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > terminateResponse 15:59:35 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > backResponse 15:59:36 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > calculateDurationInMS 15:59:37 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > hideViews 15:59:37 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > Sending incomplete message (empty object) 15:59:38 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > Sending incomplete message (null) 15:59:39 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > Sending incomplete message (without iccId) 15:59:40 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > Sending incomplete message (without command) 15:59:40 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > Sending incomplete message (without command.typeOfCommand) 15:59:41 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > Sending incomplete message (without command.options) 15:59:43 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > UI: Input (timeout 1sec) 15:59:44 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > UI: Input (contents) 15:59:45 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > UI: Input (checkInputLengthValid) 15:59:46 INFO - break hereJavaScript error: http://system.gaiamobile.org:8080/common/test/helper.js?time=1397602770571, line 33: expected false to equal true 15:59:46 INFO - gaia-unit-tests TEST-PASS | system/test/unit/icc_test.js | STK (icc) > launchStkCommand: STK_CMD_GET_INPUT 15:59:46 INFO - gaia-unit-tests TEST-UNEXPECTED-FAIL | system/test/unit/icc_test.js | STK (icc) > launchStkCommand: STK_CMD_GET_INPUT | Error: expected false to equal true (http://system.gaiamobile.org:8080/common/test/helper.js?time=1397602770571:33) 15:59:46 INFO - gaia-unit-tests INFO | stack trace: 15:59:46 INFO - Error: Error: expected false to equal true (http://system.gaiamobile.org:8080/common/test/helper.js?time=1397602770571:33) 15:59:46 INFO - at onerror (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:4959:7) 15:59:46 INFO - gaia-unit-tests TEST-UNEXPECTED-FAIL | system/test/unit/icc_test.js | "after each" hook | this.sinon is null 15:59:46 INFO - gaia-unit-tests INFO | stack trace: 15:59:46 INFO - TypeError: this.sinon is null 15:59:46 INFO - at (anonymous) (http://system.gaiamobile.org:8080/common/test/sinon_helper.js:8:5) 15:59:46 INFO - at wrapper (http://system.gaiamobile.org:8080/common/test/mocha_generators.js:62:13) 15:59:46 INFO - at run (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3709:7) 15:59:46 INFO - at next (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3973:5) 15:59:46 INFO - at (anonymous) (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3984:5) 15:59:46 INFO - at (anonymous) (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:4932:28) 15:59:46 INFO - gaia-unit-tests INFO | suite results (pass/fail): 18/2 15:59:46 INFO - gaia-unit-tests TEST-END | system/test/unit/permission_manager_test.js | STK (icc) >
ni? for frsela for the test is added by frsela.
Flags: needinfo?(frsela)
blocking-b2g: --- → backlog
This sounds like a gaia-ui-test issue, not obvious to RIL...
I couldn't reproduce it on my box but I think this bug is caused by a race condition while teardown the test, so launching a unit test over the visibilitychange event will remove the event and a new useful test is added ;) Can you check if this patch fix also the build?
Attachment #8409662 - Flags: feedback?(ryanvm)
Flags: needinfo?(frsela) → needinfo?(ryanvm)
Attachment #8409662 - Flags: feedback?(ryanvm)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #5) > https://wiki.mozilla.org/ReleaseEngineering/TryServer#Using_a_custom_Gaia Yes, I know, but I'm having problems accesing the test repo. I asked for a password reset and now a SSH key change with a new one (https://bugzilla.mozilla.org/show_bug.cgi?id=999359) Meanwhile, I'll test with a colleage computer. Is not a way to run the same as TBPL in localhost? Thank you
TBPL is just a dashboard for displaying the results of the various builds/tests we run in automation, so that's not really what you want to be worrying about here. MDN has documentation for how to run Gaia unit tests locally: https://developer.mozilla.org/en-US/Firefox_OS/Platform/Automated_testing/Gaia_unit_tests
With the proposed patch, TBPL passed without errors in gaia: https://tbpl.mozilla.org/?tree=Try&rev=2ff9a0d06671
Attachment #8409662 - Flags: review?(vyang)
Comment on attachment 8409662 [details] [review] Patch to fix STK unit tests & TBPL errors Hi Fernando, I'd like to help, but I know little about Gaia UI test framework. I don't think I'm qualified to review this, especially it looks like a racing condition in the way you write this test script rather than some technical problems of STK implementation. From commit history I see Vivien is the last reviewer, maybe he would be a better person for this. Thank you.
Attachment #8409662 - Flags: review?(vyang) → review?(21)
Comment on attachment 8409662 [details] [review] Patch to fix STK unit tests & TBPL errors Can you explain how the proposed patch solve the TBPL issue ? Please re-ask r? with the explanation, this is not obvious from the patch :)
Attachment #8409662 - Flags: review?(21)
May be possible that bug 873397 has caused this. Just a guess.
Maybe not, the first comment here is a day before that patch landed.
(In reply to Vivien Nicolas (:vingtetun) (:21) (NOT reading bugmails, needinfo? please) from comment #12) > Comment on attachment 8409662 [details] [review] > On visibilitychange event the test tried to access a destroyed mock > > Can you explain how the proposed patch solve the TBPL issue ? Please re-ask > r? with the explanation, this is not obvious from the patch :) Hi Vivien, Running the tests on Travis and in localhost works without any fail. TBPL is failing (I suppose a race condition) Doing too many tests I saw that on teardown, after the icc mocked object is dropped from the test suite, the visibilitychange event is fired and the callback called (https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/icc_worker.js#L272) This callback uses the icc object which is null after the test so some errors are displayed in the console (no in the test since it finished Ok) The proposed patch tests this event so the event is fired when icc exists. The event callback also removes itself (https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/icc_worker.js#L274) so no more problems after the test finish. Using this patch, the TBPL finished in green for Gaia tests: https://bugzilla.mozilla.org/show_bug.cgi?id=996976#c9
Flags: needinfo?(21)
(In reply to Fernando R. Sela (no CC, needinfo please) [:frsela] from comment #29) > (In reply to Vivien Nicolas (:vingtetun) (:21) (NOT reading bugmails, > needinfo? please) from comment #12) > > Comment on attachment 8409662 [details] [review] > > On visibilitychange event the test tried to access a destroyed mock > > > > Can you explain how the proposed patch solve the TBPL issue ? Please re-ask > > r? with the explanation, this is not obvious from the patch :) > > Hi Vivien, > > Running the tests on Travis and in localhost works without any fail. TBPL is > failing (I suppose a race condition) > > Doing too many tests I saw that on teardown, after the icc mocked object is > dropped from the test suite, the visibilitychange event is fired and the > callback called > (https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/icc_worker. > js#L272) > > This callback uses the icc object which is null after the test so some > errors are displayed in the console (no in the test since it finished Ok) > > The proposed patch tests this event so the event is fired when icc exists. > The event callback also removes itself > (https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/icc_worker. > js#L274) so no more problems after the test finish. > > Using this patch, the TBPL finished in green for Gaia tests: > https://bugzilla.mozilla.org/show_bug.cgi?id=996976#c9 What I don't understand in the test, is why do you set remove the visibilitychange handler instead of hacking around by having it still fires, but does nothing because you resetted window.icc.onresponse. Seems to me that the visibilitychange handler should not be here anymore and the bug will go away ?
Flags: needinfo?(21)
(In reply to Vivien Nicolas (:vingtetun) (:21) (NOT reading bugmails, needinfo? please) from comment #30) > > What I don't understand in the test, is why do you set remove the > visibilitychange handler instead of hacking around by having it still fires, > but does nothing because you resetted window.icc.onresponse. > The remove handler is not in the test. It's into the main code of STK (once time is used it's removed - It has been inherithed from the previous code in settings) https://github.com/mozilla-b2g/gaia/commit/6c337c3c30a50c20c1be71f4db1d26f6879fc296 This event was added in 1.2 version Without this test added, the console throws a JavaScript error because icc is null inside the visibility change event. > Seems to me that the visibilitychange handler should not be here anymore and > the bug will go away ? The STK spec force us to answer something to the SIM card, if the user doesn't do it we'll do it, so we can answer when the visibility changes since it's ignoring the message. Anyway this question shall be answered by product team if we really need this message.
Can we please disable this test if the fix isn't going to land soon? This is currently one of the top intermittent failures across all platforms.
Assignee: nobody → frsela
Flags: needinfo?(frsela)
Hey Fernando, there are several issues in your test: * first biggest issue: your last test using assertions in a setTimeout, but your test function is not asynchronous (no "done" used as parameter). That means that mocha does not wait for the setTimeout before moving forward to the next test, which means that the setTimeout (with its assertions!) runs sometime later. Sometimes you might be lucky if the iframe is destroyed already. * other issues: you should remove the use of setTimeout in favor of sinon's fake timers. Please look [1] to see how awesome it is. Remember that we have a sinon sandbox in `this.sinon` so you can simply use `this.sinon.useFakeTimers();` in a setp and `this.sinon.clock.tick(500)` in tests, and you should be able to test everything in a synchronous way. [1] http://sinonjs.org/docs/#clock Hope this helps, don't hesitate to ping me or someone else on IRC in case you need help !
Disabled until all issues in comment 66 are resolved and this passes on TBPL. https://github.com/mozilla-b2g/gaia/commit/db3bcec51a361daddb7d3d4ba4d8a2a664b7b6aa
I guess we want leave-open so this doesn't get resolved automatically?
Keywords: leave-open
Meh, that only really matters on the Gecko side.
Whiteboard: [test disabled]
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #58) > Can we please disable this test if the fix isn't going to land soon? This is > currently one of the top intermittent failures across all platforms. Sorry, I had been in bank holidays. I was checking it now and it was disabled by Kevin in commit db3bcec5: https://github.com/mozilla-b2g/gaia/commit/db3bcec5
Flags: needinfo?(frsela)
(In reply to Julien Wajsberg [:julienw] (away until 5th May) from comment #66) > Hey Fernando, there are several issues in your test: > > * first biggest issue: your last test using assertions in a setTimeout, but > your test function is not asynchronous (no "done" used as parameter). That > means that mocha does not wait for the setTimeout before moving forward to > the next test, which means that the setTimeout (with its assertions!) runs > sometime later. Sometimes you might be lucky if the iframe is destroyed > already. > Ups ... I forgot it ... OMG, thanks for the review. I'll fix it just now :p > * other issues: you should remove the use of setTimeout in favor of sinon's > fake timers. Please look [1] to see how awesome it is. Remember that we have > a sinon sandbox in `this.sinon` so you can simply use > `this.sinon.useFakeTimers();` in a setp and `this.sinon.clock.tick(500)` in > tests, and you should be able to test everything in a synchronous way. > > [1] http://sinonjs.org/docs/#clock > I'll check this too, thanks > Hope this helps, don't hesitate to ping me or someone else on IRC in case > you need help !
Comment on attachment 8409662 [details] [review] Patch to fix STK unit tests & TBPL errors Based on julienw comments, I fixed the bug. First commit which solves the async error: https://github.com/frsela/gaia/commit/9771d317ba6e19dc8f782155108172a7ac25ea64 and the TBPL result: https://tbpl.mozilla.org/?tree=Try&rev=68e6640f61ca Then a second commit which removes timeouts in favor of sinon: https://github.com/frsela/gaia/commit/3671e7c10f82e8cc1253e8c0b9cda21e680cd071 with the correspondent TBPL result: https://tbpl.mozilla.org/?tree=Try&rev=7f444529841f If you agree on both proposals I'll squash and land it. Thanks in advance
Attachment #8409662 - Flags: review?(21)
Travis seems to fail: 1) [system-test/unit/icc_test.js] STK (icc) > getIccInfo: Error: timeout of 10000ms exceeded at (anonymous) (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3680:9) maybe you miss some ticks ? :)
(In reply to Julien Wajsberg [:julienw] (away until 5th May) from comment #74) > Travis seems to fail: > > 1) [system-test/unit/icc_test.js] STK (icc) > getIccInfo: > > Error: timeout of 10000ms exceeded > > at (anonymous) > (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3680:9) > > maybe you miss some ticks ? :) Re-runned with successful result. Probably a race condition ... I'll fix this too
Attachment #8409662 - Attachment description: On visibilitychange event the test tried to access a destroyed mock → Patch to fix STK unit tests & TBPL errors
(In reply to Fernando R. Sela (no CC, needinfo please) [:frsela] from comment #75) > (In reply to Julien Wajsberg [:julienw] (away until 5th May) from comment > #74) > > Travis seems to fail: > > > > 1) [system-test/unit/icc_test.js] STK (icc) > getIccInfo: > > > > Error: timeout of 10000ms exceeded > > > > at (anonymous) > > (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3680:9) > > > > maybe you miss some ticks ? :) > > Re-runned with successful result. > > Probably a race condition ... I'll fix this too The issue was testing the function https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/icc.js#L66 Which uses XHR on loading the JS file to get some required settings. Since this XHR is used on loading, I can't use sinon.fakeXhrRequest since in suiteSetup is not defined yet and in setup() is too late. After some testings, the file is allways loaded under 200msecs (between 50 and 150 aprox) so I increased the grace period to 200ms
Comment on attachment 8409662 [details] [review] Patch to fix STK unit tests & TBPL errors Can't you just add a callback method to getIccInfo: function icc_getIccInfo(callback) and use that instead of setTimeout ? 200ms will be racy as well depending on the load on the test machine.
Usually using setTimeout(..., value) is evil is value is != 0.
(In reply to Vivien Nicolas (:vingtetun) (:21) (NOT reading bugmails, needinfo? please) from comment #78) > Usually using setTimeout(..., value) is evil is value is != 0. I see ... what do you suggest to test this if it's using XHR on load and I can't use sinon on suiteSetup ... Or remove this test ... WDYT?
Flags: needinfo?(21)
(In reply to Fernando R. Sela (no CC, needinfo please) [:frsela] from comment #76) > (In reply to Fernando R. Sela (no CC, needinfo please) [:frsela] from > comment #75) > > (In reply to Julien Wajsberg [:julienw] (away until 5th May) from comment > > #74) > > > Travis seems to fail: > > > > > > 1) [system-test/unit/icc_test.js] STK (icc) > getIccInfo: > > > > > > Error: timeout of 10000ms exceeded > > > > > > at (anonymous) > > > (http://system.gaiamobile.org:8080/common/vendor/mocha/mocha.js:3680:9) > > > > > > maybe you miss some ticks ? :) > > > > Re-runned with successful result. > > > > Probably a race condition ... I'll fix this too > > The issue was testing the function > https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/icc.js#L66 > > Which uses XHR on loading the JS file to get some required settings. > Since this XHR is used on loading, I can't use sinon.fakeXhrRequest since in > suiteSetup is not defined yet and in setup() is too late. why is setup too late? Can't you run "init" in setup ? > > After some testings, the file is allways loaded under 200msecs (between 50 > and 150 aprox) so I increased the grace period to 200ms This is not a good idea :) I mean, really.
(In reply to Julien Wajsberg [:julienw] (away until 5th May) from comment #80) > > why is setup too late? Can't you run "init" in setup ? > Sorry, I didn't explained it well. I fixed it: https://github.com/frsela/gaia/commit/5538e61c6b81d2c37471acac5d0f1d1866f27b1c So no more timers in tests :)
Comment on attachment 8409662 [details] [review] Patch to fix STK unit tests & TBPL errors No more setTimeout ? r+! :)
Attachment #8409662 - Flags: review?(21) → review+
Flags: needinfo?(21)
(In reply to Vivien Nicolas (:vingtetun) (:21) (NOT reading bugmails, needinfo? please) from comment #82) > Comment on attachment 8409662 [details] [review] > Patch to fix STK unit tests & TBPL errors > > No more setTimeout ? r+! :) Thank you Vivien. I'll rebase and squash the patch in order to land it ;) Regards
Landed: https://github.com/mozilla-b2g/gaia/commit/8b0bc981df46b52079151df717d0969d35cd84e5
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
status-b2g-v2.0: --- → fixed
Target Milestone: --- → 2.0 S1 (9may)
blocking-b2g: backlog → ---
tracking-b2g: --- → backlog
Removing leave-open keyword from resolved bugs, per :sylvestre.
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: