Closed Bug 845625 Opened 9 years ago Closed 9 years ago

Intermittent B2G test_execute_async_script.py TestExecuteAsyncContent.test_execute_async_unload | MarionetteException: {u'from': u'conn40.marionette1', u'value': 3} and others

Categories

(Testing :: Marionette, defect)

Product:
Testing
Component:
Marionette
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox22 fixed, b2g18 fixed, b2g18-v1.0.0 wontfix, b2g18-v1.0.1 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla22
Tracking Flags:
Tracking Status
firefox22 --- fixed
b2g18 --- fixed
b2g18-v1.0.0 --- wontfix
b2g18-v1.0.1 --- fixed

People

(Reporter: ryanvm, Assigned: jgriffin)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 2 obsolete files)

Prevent tests from getting out of sync when an exception is thrown
1.89 KB, patch
mdas
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=20113890&tree=Mozilla-Inbound

b2g_ics_armv7a_gecko_emulator_vm mozilla-inbound opt test marionette-webapi on 2013-02-26 12:12:06 PST for push a38bbae7a53b
slave: tst-linux64-ec2-325

12:22:14     INFO -  test_execute_async_unload (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  test_execute_js_exception (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  test_execute_no_return (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  test_execute_permission (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  test_no_timeout (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  test_same_context (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  test_sandbox_reuse (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  test_script_finished (test_execute_async_script.TestExecuteAsyncContent) ... ERROR
12:22:15     INFO -  ======================================================================
12:22:15     INFO -  ERROR: test_execute_async_unload (test_execute_async_script.TestExecuteAsyncContent)
12:22:15     INFO -  ----------------------------------------------------------------------
12:22:15    ERROR -  Traceback (most recent call last):
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py", line 10, in setUp
12:22:15     INFO -      super(TestExecuteAsyncContent, self).setUp()
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 131, in setUp
12:22:15     INFO -      self.marionette.test_name = self.test_name
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 349, in test_name
12:22:15     INFO -      if self._send_message('setTestName', 'ok', value=test_name):
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 255, in _send_message
12:22:15     INFO -      self._handle_error(response)
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 313, in _handle_error
12:22:15     INFO -      raise MarionetteException(message=response, status=500)
12:22:15     INFO -  TEST-UNEXPECTED-FAIL | test_execute_async_script.py TestExecuteAsyncContent.test_execute_async_unload | MarionetteException: {u'from': u'conn40.marionette1', u'value': 3}
12:22:15     INFO -  ======================================================================
12:22:15     INFO -  ERROR: test_execute_js_exception (test_execute_async_script.TestExecuteAsyncContent)
12:22:15     INFO -  ----------------------------------------------------------------------
12:22:15    ERROR -  Traceback (most recent call last):
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py", line 10, in setUp
12:22:15     INFO -      super(TestExecuteAsyncContent, self).setUp()
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 133, in setUp
12:22:15     INFO -      (self.filepath.replace('\\', '\\\\'), self.methodName))
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 497, in execute_script
12:22:15     INFO -      scriptTimeout=script_timeout)
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 255, in _send_message
12:22:15     INFO -      self._handle_error(response)
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 313, in _handle_error
12:22:15     INFO -      raise MarionetteException(message=response, status=500)
12:22:15     INFO -  TEST-UNEXPECTED-FAIL | test_execute_async_script.py TestExecuteAsyncContent.test_execute_js_exception | MarionetteException: {u'ok': True, u'from': u'conn40.marionette1'}
12:22:15     INFO -  ======================================================================
12:22:15     INFO -  ERROR: test_execute_no_return (test_execute_async_script.TestExecuteAsyncContent)
12:22:15     INFO -  ----------------------------------------------------------------------
12:22:15    ERROR -  Traceback (most recent call last):
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py", line 10, in setUp
12:22:15     INFO -      super(TestExecuteAsyncContent, self).setUp()
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 131, in setUp
12:22:15     INFO -      self.marionette.test_name = self.test_name
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 349, in test_name
12:22:15     INFO -      if self._send_message('setTestName', 'ok', value=test_name):
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 255, in _send_message
12:22:15     INFO -      self._handle_error(response)
12:22:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 313, in _handle_error
12:22:15     INFO -      raise MarionetteException(message=response, status=500)

etc etc etc
It's tempting to think this is some side effect of bug 839675, but since this problem wasn't reported until Feb 26, bug 844942 seems like a more likely source, if the problem is internal to Marionette.
This is an out-of-sync problem; somehow the script return for this:

http://mxr.mozilla.org/mozilla-central/source/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py#24

is leaking into the next test.
I think this will solve this problem.  I'll push to try as soon as bug 847683 is resolved.
Assignee: nobody → jgriffin
(In reply to Jonathan Griffin (:jgriffin) from comment #36)
> Created attachment 720961 [details] [diff] [review]
> Prevent tests from getting out of sync when an exception is thrown
> 
> I think this will solve this problem.  I'll push to try as soon as bug
> 847683 is resolved.

Thank you for looking at this :-)
This was green on the try run except for test_simpletest_pass.js, which failed because it tries to assert on window.location.href.  I've removed that check, which really doesn't belong there anyway.
Attachment #721363 - Flags: review?(mdas)
Attachment #720961 - Attachment is obsolete: true
Comment on attachment 721363 [details] [diff] [review]
Prevent tests from getting out of sync when an exception is thrown

Nm, I'm getting my try runs mixed up, this try run for this isn't back yet.
Attachment #721363 - Flags: review?(mdas)
Attachment #721363 - Attachment is obsolete: true
Comment on attachment 721366 [details] [diff] [review]
Prevent tests from getting out of sync when an exception is thrown

try run is green.

This patch causes us to be a little more strict with command_id's than we were previously (actually, as strict as we can get).  There was one gap that out-of-sync messages could still pass through, and this plugs it.

It also fixes screenShot to set this.command_id, since previously it was benefiting from said gap unintentionally.
Attachment #721366 - Flags: review?(mdas)
Comment on attachment 721366 [details] [diff] [review]
Prevent tests from getting out of sync when an exception is thrown

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

great, I can't see any other holes with the new code

::: testing/marionette/marionette-actors.js
@@ +277,5 @@
> +        // A null value for this.command_id means we've already processed
> +        // a message for the previous value, and so the current message is a
> +        // duplicate.
> +        logger.warn("ignoring duplicate response for command_id " + command_id);
> +        return;        

there's some additional whitespace after the ;

@@ +1954,4 @@
>     * of the window will be taken.
>     */
>    screenShot: function MDA_saveScreenshot(aRequest) {
> +    this.command_id = this.getCommandId();

nice catch!
Attachment #721366 - Flags: review?(mdas) → review+
Thanks, I fixed the whitespace problem.

https://hg.mozilla.org/integration/mozilla-inbound/rev/a9533266197d
Target Milestone: --- → mozilla22
https://hg.mozilla.org/mozilla-central/rev/a9533266197d
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
(In reply to TinderboxPushlog Robot from comment #62)
> honzab.moz%firemni.cz
> https://tbpl.mozilla.org/php/getParsedLog.php?id=20436500&tree=Try
> b2g_ics_armv7a_gecko_emulator_vm try opt test marionette-webapi on
> 2013-03-07 14:57:18

This run was purposely based on older changes set (https://hg.mozilla.org/try/rev/216ec69cc531).
Blocks: 833764
You need to log in before you can comment on or make changes to this bug.