782338 - [B2G] Intermittent test_mobile_voice_state.js | Emulator callback still pending when finish() called

Status: RESOLVED FIXED

(Core :: DOM: Device Interfaces, defect)

Description

[Jonathan Griffin (:jgriffin)]

On the B2G CI, test_mobile_voice_state.js sometimes fails with the error:

test_mobile_voice_state.js
TEST-UNEXPECTED-FAIL | Traceback (most recent call last):
File "/data/jenkins/workspace/webapi-marionette-test/testing/marionette/client/marionette/marionette_test.py", line 176, in runTest
results = self.marionette.execute_js_script(js, args, special_powers=True)
File "/data/jenkins/workspace/webapi-marionette-test/testing/marionette/client/marionette/marionette.py", line 369, in execute_js_script
specialPowers=special_powers)
File "/data/jenkins/workspace/webapi-marionette-test/testing/marionette/client/marionette/marionette.py", line 171, in _send_message
self._handle_error(response)
File "/data/jenkins/workspace/webapi-marionette-test/testing/marionette/client/marionette/marionette.py", line 228, in _handle_error
raise MarionetteException(message=message, status=status, stacktrace=stacktrace)
MarionetteException: Emulator callback still pending when finish() called

Seems like a possible timing issue.

Comment 1

[Vicamo Yang [:vicamo][:vyang]]

Attachment: V1

Comment 2

[Marshall Culpepper [:marshall_law]]

Comment on attachment 651984 [details] [diff] [review]
V1

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

r+ since this will probably work -- but it feels a bit like a hack. See comments below.

::: dom/network/tests/marionette/test_mobile_voice_state.js
@@ +110,5 @@
>  function cleanUp() {
>    SpecialPowers.clearUserPref(WHITELIST_PREF);
> +
> +  // For 'Emulator callback still pending when finish() called'
> +  setTimeout(finish, 1000);

It would be better if we provided runEmulatorCmd a callback, and wait for that callback before moving on to the next test function (or in this case, cleanUp()). I currently do this in my voicemail tests here:

https://mxr.mozilla.org/mozilla-central/source/dom/telephony/test/marionette/test_voicemail_statuschanged.js#12

Comment 3

[Philipp von Weitershausen [:philikon]]

Comment on attachment 651984 [details] [diff] [review]
V1

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

::: dom/network/tests/marionette/test_mobile_voice_state.js
@@ +110,5 @@
>  function cleanUp() {
>    SpecialPowers.clearUserPref(WHITELIST_PREF);
> +
> +  // For 'Emulator callback still pending when finish() called'
> +  setTimeout(finish, 1000);

I agree with Marshall. I suggest something like this:

  let emulatorCmdPending = false;
  function setEmulatorVoiceState(state) {
    emulatorCmdPending = true;
    runEmulatorCmd("gsm voice " + state, function (result) {
      emulatorCmdPending = false;
      is(result[0], "OK");
    });
  }

and then do a tighter wait loop, e.g.:

  function cleanUp() {
    if (emulatorCmdPending) {
      setTimeout(cleanUp, 100);
      return;
    }
    SpecialPowers.clearUserPref(WHITELIST_PREF);
    finish();
  }

Comment 4

[Vicamo Yang [:vicamo][:vyang]]

Attachment: V2

* rebase to include changes made in bug 780558
* address review comment #2 and #3. Thank you both ;)

Comment 5

[Marshall Culpepper [:marshall_law]]

Comment on attachment 652652 [details] [diff] [review]
V2

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

Looks good

Comment 6

[Vicamo Yang [:vicamo][:vyang]]

Attachment: V3

rebase only

Comment 7

[Vicamo Yang [:vicamo][:vyang]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/785cd1cb9446

Comment 8

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/785cd1cb9446

Comment 9

[Legacy TBPL/Treeherder Robot]

paul
https://tbpl.mozilla.org/php/getParsedLog.php?id=18019426&tree=Fx-Team
b2g_ics_armv7a_gecko_emulator fx-team opt test marionette-webapi on 2012-12-17 08:23:37
slave: talos-r3-fed-051

08:35:07    ERROR -  Traceback (most recent call last):
08:35:07     INFO -  TEST-UNEXPECTED-FAIL | test_filter_unread.js | EOFError: telnet connection closed
08:35:07    ERROR -  FAILED (errors=1)
08:35:07    ERROR -  Traceback (most recent call last):
08:35:07     INFO -  TEST-UNEXPECTED-FAIL | test_number_of_messages.js | error: [Errno 111] Connection refused
08:35:07    ERROR -  FAILED (errors=1)
08:35:07    ERROR -  Traceback (most recent call last):
08:35:07     INFO -  TEST-UNEXPECTED-FAIL | test_mark_msg_read.js | error: [Errno 111] Connection refused
08:35:07    ERROR -  FAILED (errors=1)
08:35:07    ERROR -  Traceback (most recent call last):
08:35:07     INFO -  TEST-UNEXPECTED-FAIL | test_mark_msg_read_error.js | error: [Errno 111] Connection refused
08:35:07    ERROR -  FAILED (errors=1)
08:35:07    ERROR -  Traceback (most recent call last):
08:35:07     INFO -  TEST-UNEXPECTED-FAIL | test_bug814761.js | error: [Errno 111] Connection refused
08:35:07    ERROR -  FAILED (errors=1)
08:35:07    ERROR -  Traceback (most recent call last):
08:35:07     INFO -  TEST-UNEXPECTED-FAIL | test_mobile_voice_state.js | error: [Errno 111] Connection refused
08:35:07    ERROR -  FAILED (errors=1)
08:35:07    ERROR -  Traceback (most recent call last):
08:35:07     INFO -  TEST-UNEXPECTED-FAIL | test_mobile_iccinfo.js | error: [Errno 111] Connection refused
Only displaying first 20 of 100+ failures -
.