851658 - Intermittent B2G emulator Marionette test_proximity_change.js | MarionetteException: Emulator callback still pending when finish() called

Status: RESOLVED FIXED

(Core :: DOM: Device Interfaces, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

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

b2g_ics_armv7a_gecko_emulator_vm mozilla-inbound opt test marionette-webapi on 2013-03-15 12:32:25 PDT for push cc590755a7dc
slave: tst-linux64-ec2-363

12:45:29     INFO -  TEST-START test_proximity_change.js
12:45:32     INFO -  /builds/slave/test/build/tests/marionette/tests/dom/system/tests/marionette/test_proximity_change.js, runTest (marionette_test.MarionetteJSTestCase) ... ERROR
12:45:32     INFO -  ======================================================================
12:45:32     INFO -  ERROR: /builds/slave/test/build/tests/marionette/tests/dom/system/tests/marionette/test_proximity_change.js, runTest (marionette_test.MarionetteJSTestCase)
12:45:32     INFO -  ----------------------------------------------------------------------
12:45:32     INFO -  Traceback (most recent call last):
12:45:32     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 212, in runTest
12:45:32     INFO -      results = self.marionette.execute_js_script(js, args, special_powers=True)
12:45:32     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 513, in execute_js_script
12:45:32     INFO -      scriptTimeout=script_timeout)
12:45:32     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 284, in _send_message
12:45:32     INFO -      self._handle_error(response)
12:45:32     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 341, in _handle_error
12:45:32     INFO -      raise MarionetteException(message=message, status=status, stacktrace=stacktrace)
12:45:32     INFO -  TEST-UNEXPECTED-FAIL | test_proximity_change.js | MarionetteException: Emulator callback still pending when finish() called
12:45:32     INFO -  START LOG:
12:45:32     INFO -  INFO TEST-START: /builds/slave/test/build/tests/marionette/tests/dom/system/tests/marionette/test_proximity_change.js Fri Mar 15 2013 08:45:14 GMT-1100 (SST)
12:45:32     INFO -  INFO Enabling 'deviceproximity' event listener. Fri Mar 15 2013 08:45:15 GMT-1100 (SST)
12:45:32     INFO -  INFO Waiting for device proximity event. Fri Mar 15 2013 08:45:15 GMT-1100 (SST)
12:45:32     INFO -  INFO Received 'deviceproximity' event via listener (value:1 min:0 max:1). Fri Mar 15 2013 08:45:15 GMT-1100 (SST)
12:45:32     INFO -  INFO Sending emulator command to fake proximity change (7:3:15). Fri Mar 15 2013 08:45:15 GMT-1100 (SST)
12:45:32     INFO -  INFO Emulator callback. Fri Mar 15 2013 08:45:15 GMT-1100 (SST)
12:45:32     INFO -  INFO Received 'deviceproximity' event via listener (value:7 min:0 max:1). Fri Mar 15 2013 08:45:16 GMT-1100 (SST)
12:45:32     INFO -  INFO Received 'ondeviceproximity' event via handler (value:7 min:0 max:1). Fri Mar 15 2013 08:45:16 GMT-1100 (SST)
12:45:32     INFO -  INFO Sending emulator command to restore proximity (1:0:0). Fri Mar 15 2013 08:45:16 GMT-1100 (SST)
12:45:32     INFO -  INFO Received 'deviceproximity' event via listener (value:7 min:0 max:1). Fri Mar 15 2013 08:45:17 GMT-1100 (SST)
12:45:32     INFO -  INFO Received 'ondeviceproximity' event via handler (value:7 min:0 max:1). Fri Mar 15 2013 08:45:17 GMT-1100 (SST)
12:45:32     INFO -  INFO Sending emulator command to restore proximity (1:0:0). Fri Mar 15 2013 08:45:17 GMT-1100 (SST)
12:45:32     INFO -  END LOG:
12:45:32     INFO -  ----------------------------------------------------------------------
12:45:32     INFO -  Ran 1 test in 2.640s
12:45:32  WARNING -  FAILED (errors=1)

Comment 1

[Jonathan Griffin (:jgriffin)]

Rob, looking at this log, it looks like sometimes we can end up calling restoreProximity() recursively, which causes this error: 

12:45:45     INFO -  I/Gecko   (  267): 1363376717047	Marionette	INFO	sendToClient: {"emulator_cmd":"sensor set proximity 1:0:0","id":754}, -1, {b97ccb20-32a7-4159-943f-06056ef24ef0}
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE LOG: INFO: Received 'deviceproximity' event via listener (value:7 min:0 max:1).
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE TEST RESULT:TEST-PASS | test_proximity_change.js | value - 7 should equal 7
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE TEST RESULT:TEST-PASS | test_proximity_change.js | min - 0 should equal 0
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE TEST RESULT:TEST-PASS | test_proximity_change.js | max - 1 should equal 1
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE LOG: INFO: Received 'ondeviceproximity' event via handler (value:7 min:0 max:1).
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE TEST RESULT:TEST-PASS | test_proximity_change.js | value - 7 should equal 7
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE TEST RESULT:TEST-PASS | test_proximity_change.js | min - 0 should equal 0
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE TEST RESULT:TEST-PASS | test_proximity_change.js | max - 1 should equal 1
12:45:45     INFO -  I/Gecko   (  267): MARIONETTE LOG: INFO: Sending emulator command to restore proximity (1:0:0).
12:45:45     INFO -  I/Gecko   (  267): 1363376717107	Marionette	INFO	sendToClient: {"emulator_cmd":"sensor set proximity 1:0:0","id":755}, -1, {b97ccb20-32a7-4159-943f-06056ef24ef0}

Comment 2

[Robert Wood [:rwood]]

Ok I'll have a look, thanks Jonathan

Comment 3

[Robert Wood [:rwood]]

Attachment: Fix intermittent failure

Comment 4

[Jonathan Griffin (:jgriffin)]

Comment on attachment 735137 [details] [diff] [review]
Fix intermittent failure

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

Cool, I think that will do the trick.

Comment 5

[Robert Wood [:rwood]]

Pushed to try:

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

Comment 6

[Robert Wood [:rwood]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2d46d1476514

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/2d46d1476514

Comment 8

[Robert Wood [:rwood]]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/0f04a689798e

Comment 9

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=22904443&tree=Mozilla-B2g18
b2g_ics_armv7a_gecko_emulator mozilla-b2g18 opt test marionette-webapi on 2013-05-13 07:36:58
slave: talos-r3-fed-095

07:58:06    ERROR -      raise TimeoutException(message='socket.timeout', status=ErrorCodes.TIMEOUT, stacktrace=None)
07:58:06    ERROR -  TEST-UNEXPECTED-FAIL | test_proximity_init.js | TimeoutException: socket.timeout
07:58:08     INFO -  TEST-UNEXPECTED-FAIL | test_proximity_change.js | MarionetteException: Emulator callback still pending when finish() called
07:58:10    ERROR - Return code: 10

Comment 10

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=23203509&tree=Mozilla-Inbound
b2g_ics_armv7a_gecko_emulator_vm mozilla-inbound opt test marionette-webapi on 2013-05-21 06:30:37
slave: tst-linux64-ec2-070

06:56:14    ERROR -      raise TimeoutException(message='socket.timeout', status=ErrorCodes.TIMEOUT, stacktrace=None)
06:56:14    ERROR -  TEST-UNEXPECTED-FAIL | test_proximity_init.js | TimeoutException: socket.timeout
06:56:16     INFO -  TEST-UNEXPECTED-FAIL | test_proximity_change.js | MarionetteException: Emulator callback still pending when finish() called
06:56:17    ERROR - Return code: 10