Closed Bug 816246 Opened 7 years ago Closed 7 years ago

Add a 'timeout' kwarg to execute_* in marionette

Categories

(Testing :: Marionette, defect)

x86
All
defect
Not set

Tracking

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

RESOLVED FIXED
mozilla21
Tracking Status
firefox21 --- fixed
b2g18 --- fixed
b2g18-v1.0.0 --- wontfix
b2g18-v1.0.1 --- fixed

People

(Reporter: mdas, Assigned: mdas)

References

Details

Attachments

(1 file, 2 obsolete files)

This will be for internal use only. It will let us set the script timeout for that particular execute script call, without changing the timeout set by 'set_script_timeout'. It will be for one-shot use.
Attached patch patch v1.0 (obsolete) — Splinter Review
This adds the 'timeout' kwarg and backend support for it. oh, and a test.
Attachment #687903 - Flags: review?(jgriffin)
Comment on attachment 687903 [details] [diff] [review]
patch v1.0

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

lgtm

::: testing/marionette/client/marionette/tests/unit/test_execute_async_script.py
@@ +19,5 @@
>      def test_execute_async_timeout(self):
>          self.assertRaises(ScriptTimeoutException, self.marionette.execute_async_script, "var x = 1;")
>  
> +    def test_execute_async_unique_timeout(self):
> +        self.assertEqual(1, self.marionette.execute_async_script("setTimeout(function() {marionetteScriptFinished(1);}, 2000);", script_timeout=5000))

Should we explicitly call set_script_timeout() here to set the general timeout to 1000, or some other value that we know should make this test work?
Attachment #687903 - Flags: review?(jgriffin) → review+
> Should we explicitly call set_script_timeout() here to set the general
> timeout to 1000, or some other value that we know should make this test work?

Yup, it's already being set explicity to 1000 in TestExecuteAsyncContent's setUp function, which TestExecuteAsyncChrome also uses.
(In reply to Malini Das [:mdas] from comment #4)
> > Should we explicitly call set_script_timeout() here to set the general
> > timeout to 1000, or some other value that we know should make this test work?
> 
> Yup, it's already being set explicity to 1000 in TestExecuteAsyncContent's
> setUp function, which TestExecuteAsyncChrome also uses.

Oh cool, thanks!
Attached patch unbitrotted patch (obsolete) — Splinter Review
Attachment #687903 - Attachment is obsolete: true
Attachment #688349 - Flags: review+
landed in m-i: https://hg.mozilla.org/integration/mozilla-inbound/rev/4a0c471957b7
Whiteboard: [automation-needed-in-beta][automation-needed-in-aurora][leave-open]
(In reply to Ryan VanderMeulen from comment #9)
> https://hg.mozilla.org/mozilla-central/rev/4a0c471957b7

This was just backed out inbound for Mn failures; I don't think it should be uplifted to m-c.  See comment #8.
Good call, sorry for missing that beforehand.
https://hg.mozilla.org/mozilla-central/rev/1942b4d64dc8
Flags: in-testsuite+
cant reproduce crash locally. I have pushed to try https://tbpl.mozilla.org/?tree=Try&rev=98411497c3ef for it
Try run for 98411497c3ef is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=98411497c3ef
Results (out of 2 total builds):
    success: 1
    warnings: 1
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/dburns@mozilla.com-98411497c3ef
This appears to be the cause of B2G Marionette bustage again.

I've requested a few retriggers to fill in the gaps due to coalescing, but I'm sure it's this bug.

For results, see:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&jobname=marionette-webapi&fromchange=5e0647093cd7&tochange=bf86988e2420

Anyway it's getting pretty late, so I've just had to close the tree for now as the retriggers are pending & may not start any time soon.
pushed again to try https://tbpl.mozilla.org/?tree=Try&rev=18131c4d179a

After this it might be a case of getting a slave from releng to see what the differences are between local, try and inbound
(In reply to David Burns :automatedtester from comment #18)
> pushed again to try https://tbpl.mozilla.org/?tree=Try&rev=18131c4d179a
> 
> After this it might be a case of getting a slave from releng to see what the
> differences are between local, try and inbound

One big difference is that TBPL uses an older copy of the emulator, and installs a new copy of gecko into it.  We could try updating the emulator to see if that helps with this problem.
Looking at this, its a case of the an Marionette getting out of sync.

The test is failing during a setUp 

04:13:55     INFO -  ======================================================================
04:13:55     INFO -  ERROR: test_execute_async_unload (test_execute_async_script.TestExecuteAsyncContent)
04:13:55     INFO -  ----------------------------------------------------------------------
04:13:55    ERROR -  Traceback (most recent call last):
04:13:55     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py", line 11, in setUp
04:13:55     INFO -      self.marionette.set_script_timeout(1000)
04:13:55     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 321, in set_script_timeout
04:13:55     INFO -      response = self._send_message('setScriptTimeout', 'ok', value=timeout)
04:13:55     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 211, in _send_message
04:13:55     INFO -      self._handle_error(response)
04:13:55     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 269, in _handle_error
04:13:55     INFO -      raise MarionetteException(message=response, status=500)
04:13:55     INFO -  TEST-UNEXPECTED-FAIL | test_execute_async_script.py TestExecuteAsyncContent.test_execute_async_unload | MarionetteException: {u'from': u'conn91.marionette1', u'value': 1}
04:13:55     INFO -  ----------------------------------------------------------------------
output of logcat for test before and after

04:14:34     INFO -  I/Gecko   (  288): 1354968813157	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968813324	Marionette	DEBUG	Got request: setTestName, data: {"to":"conn90.marionette1","session":"6-b2g","type":"setTestName","value":"test_execute_async_script.py TestExecuteAsyncContent.test_execute_async_unique_timeout"}, id: {46c581ed-55fc-4dd0-937d-83e8a178a517}
04:14:34     INFO -  I/Gecko   (  288): 1354968813328	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","ok":true}, {46c581ed-55fc-4dd0-937d-83e8a178a517}, {46c581ed-55fc-4dd0-937d-83e8a178a517}
04:14:34     INFO -  I/Gecko   (  288): 1354968813343	Marionette	DEBUG	Got request: execute, data: {"to":"conn90.marionette1","specialPowers":false,"session":"6-b2g","scriptTimeout":null,"newSandbox":true,"args":[],"type":"executeScript","value":"log('TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unique_timeout')"}, id: {b8038f7a-d86f-4c3b-8ebf-f05ac9f167d4}
04:14:34     INFO -  I/Gecko   (  288): MARIONETTE LOG: INFO: TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unique_timeout
04:14:34     INFO -  I/Gecko   (  288): 1354968813435	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","value":null}, {b8038f7a-d86f-4c3b-8ebf-f05ac9f167d4}, {b8038f7a-d86f-4c3b-8ebf-f05ac9f167d4}
04:14:34     INFO -  I/Gecko   (  288): 1354968813450	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","ok":true}, {556eb96f-cfff-42ff-8113-828fccd49fa1}, {556eb96f-cfff-42ff-8113-828fccd49fa1}
04:14:34     INFO -  I/Gecko   (  288): 1354968815588	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","value":1}, undefined, {0519e0c8-ba09-487c-a456-b1d9db02b600}
04:14:34     INFO -  I/Gecko   (  288): 1354968815589	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968816899	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","error":{"message":"timed out","status":28,"stacktrace":null}}, undefined, {7e3c0a59-5d34-4a10-be33-53350f15b751}
04:14:34     INFO -  I/Gecko   (  288): 1354968816900	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968816917	Marionette	DEBUG	Got request: setContext, data: {"to":"conn90.marionette1","session":"6-b2g","type":"setContext","value":"content"}, id: {5cc3428b-f5ed-449b-87ac-95cdc8793b17}
04:14:34     INFO -  I/Gecko   (  288): 1354968816919	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","ok":true}, {5cc3428b-f5ed-449b-87ac-95cdc8793b17}, {5cc3428b-f5ed-449b-87ac-95cdc8793b17}
04:14:34     INFO -  I/Gecko   (  288): 1354968816959	Marionette	DEBUG	Got request: execute, data: {"to":"conn90.marionette1","specialPowers":false,"session":"6-b2g","scriptTimeout":null,"newSandbox":true,"args":[],"type":"executeScript","value":"log('TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unique_timeout')"}, id: {577c1dfb-a1be-4a54-b1dd-4c732123d9a2}
04:14:34     INFO -  I/Gecko   (  288): MARIONETTE LOG: INFO: TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unique_timeout
04:14:34     INFO -  I/Gecko   (  288): 1354968817070	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","value":null}, {577c1dfb-a1be-4a54-b1dd-4c732123d9a2}, {577c1dfb-a1be-4a54-b1dd-4c732123d9a2}
04:14:34     INFO -  I/Gecko   (  288): 1354968817083	Marionette	DEBUG	Got request: setTestName, data: {"to":"conn90.marionette1","session":"6-b2g","type":"setTestName","value":null}, id: {71d09fff-6a66-406f-bf55-ea398ede8845}
04:14:34     INFO -  I/Gecko   (  288): 1354968817087	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","ok":true}, {71d09fff-6a66-406f-bf55-ea398ede8845}, {71d09fff-6a66-406f-bf55-ea398ede8845}
04:14:34     INFO -  I/Gecko   (  288): 1354968817125	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","value":[["INFO","TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unique_timeout","Sat Dec 08 2012 12:13:33 GMT+0000 (GMT)"],["INFO","TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unique_timeout","Sat Dec 08 2012 12:13:37 GMT+0000 (GMT)"]]}, {b474dc2d-d2b1-47cc-b6c4-d1b1db65aa1f}, {b474dc2d-d2b1-47cc-b6c4-d1b1db65aa1f}
04:14:34     INFO -  I/Gecko   (  288): 1354968817204	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","value":{}}, {e524487a-4a5f-44bd-8080-5a9bcf89f5aa}, {e524487a-4a5f-44bd-8080-5a9bcf89f5aa}
04:14:34     INFO -  I/Gecko   (  288): 1354968817219	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","ok":true}, {c47a9513-18a3-45bf-8771-72f1fc0c2b82}, {c47a9513-18a3-45bf-8771-72f1fc0c2b82}
04:14:34     INFO -  I/Gecko   (  288): 1354968817274	Marionette	INFO	sendToClient: {"from":"conn90.marionette1","ok":true}, {8cafac3a-6c5a-4f0c-bcfe-c19ff17c5f4e}, {8cafac3a-6c5a-4f0c-bcfe-c19ff17c5f4e}
04:14:34     INFO -  E/GeckoConsole(  288): [JavaScript Error: "[Exception... "Component returned failure code: 0x80470002 (NS_BASE_STREAM_CLOSED) [nsIOutputStream.write]"  nsresult: "0x80470002 (NS_BASE_STREAM_CLOSED)"  location: "JS frame :: chrome://global/content/devtools/dbg-transport.js :: DT_onOutputStreamReady :: line 94"  data: no]" {file: "chrome://global/content/devtools/dbg-transport.js" line: 94}]
04:14:34     INFO -  I/Gecko   (  288): 1354968817352	Marionette	INFO	could not load listener into content for page: chrome://browser/content/shell.xul
04:14:34     INFO -  I/Gecko   (  288): 1354968817374	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","value":"6-b2g"}, undefined, {103868cf-e43c-4af3-83f7-eadd5e1f08ac}
04:14:34     INFO -  I/Gecko   (  288): 1354968817376	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968817549	Marionette	DEBUG	Got request: setTestName, data: {"to":"conn91.marionette1","session":"6-b2g","type":"setTestName","value":"test_execute_async_script.py TestExecuteAsyncContent.test_execute_async_unload"}, id: {c02edde7-ce84-4df2-ac90-630c8eb5db13}
04:14:34     INFO -  I/Gecko   (  288): 1354968817553	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {c02edde7-ce84-4df2-ac90-630c8eb5db13}, {c02edde7-ce84-4df2-ac90-630c8eb5db13}
04:14:34     INFO -  I/Gecko   (  288): 1354968817566	Marionette	DEBUG	Got request: execute, data: {"to":"conn91.marionette1","specialPowers":false,"session":"6-b2g","scriptTimeout":null,"newSandbox":true,"args":[],"type":"executeScript","value":"log('TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unload')"}, id: {79389beb-30d1-4d7a-b4a2-402865914ca9}
04:14:34     INFO -  I/Gecko   (  288): MARIONETTE LOG: INFO: TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unload
04:14:34     INFO -  I/Gecko   (  288): 1354968817629	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","value":null}, {79389beb-30d1-4d7a-b4a2-402865914ca9}, {79389beb-30d1-4d7a-b4a2-402865914ca9}
04:14:34     INFO -  I/Gecko   (  288): 1354968817701	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","value":1}, undefined, null
04:14:34     INFO -  I/Gecko   (  288): 1354968817702	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968817709	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {2542cbef-84ad-4809-8c95-604db8cd18ec}, {2542cbef-84ad-4809-8c95-604db8cd18ec}
04:14:34     INFO -  I/Gecko   (  288): 1354968817745	Marionette	DEBUG	Got request: setTestName, data: {"to":"conn91.marionette1","session":"6-b2g","type":"setTestName","value":"test_execute_async_script.py TestExecuteAsyncContent.test_execute_js_exception"}, id: {649e4ced-78b1-4eee-956c-9f80179fede3}
04:14:34     INFO -  I/Gecko   (  288): 1354968817748	Marionette	DEBUG	Got request: execute, data: {"to":"conn91.marionette1","specialPowers":false,"session":"6-b2g","scriptTimeout":null,"newSandbox":true,"args":[],"type":"executeScript","value":"log('TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_js_exception')"}, id: {05aa2d57-f954-4b86-ac05-4770cd38ede4}
04:14:34     INFO -  I/Gecko   (  288): MARIONETTE LOG: INFO: TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_js_exception
04:14:34     INFO -  I/Gecko   (  288): 1354968817814	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {649e4ced-78b1-4eee-956c-9f80179fede3}, {05aa2d57-f954-4b86-ac05-4770cd38ede4}
04:14:34     INFO -  I/Gecko   (  288): 1354968817817	Marionette	WARN	ignoring out-of-sync response
04:14:34     INFO -  I/Gecko   (  288): 1354968817822	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {649e4ced-78b1-4eee-956c-9f80179fede3}, {05aa2d57-f954-4b86-ac05-4770cd38ede4}
04:14:34     INFO -  I/Gecko   (  288): 1354968817826	Marionette	WARN	ignoring out-of-sync response
04:14:34     INFO -  I/Gecko   (  288): 1354968817872	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","value":null}, {05aa2d57-f954-4b86-ac05-4770cd38ede4}, {05aa2d57-f954-4b86-ac05-4770cd38ede4}
04:14:34     INFO -  I/Gecko   (  288): 1354968817884	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {0d7e0df4-5782-4de8-a84a-e77a20568a23}, {0d7e0df4-5782-4de8-a84a-e77a20568a23}
04:14:34     INFO -  I/Gecko   (  288): 1354968818036	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","error":{"message":"ReferenceError: foo is not defined","status":17,"stacktrace":null}}, undefined, {474fc2ae-1b14-43a1-8ec2-d9a6852431b8}
04:14:34     INFO -  I/Gecko   (  288): 1354968818037	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968818053	Marionette	DEBUG	Got request: setContext, data: {"to":"conn91.marionette1","session":"6-b2g","type":"setContext","value":"content"}, id: {9859fe9d-9816-4170-8894-d1074468bf5f}
04:14:34     INFO -  I/Gecko   (  288): 1354968818055	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {9859fe9d-9816-4170-8894-d1074468bf5f}, {9859fe9d-9816-4170-8894-d1074468bf5f}
04:14:34     INFO -  I/Gecko   (  288): 1354968818094	Marionette	DEBUG	Got request: execute, data: {"to":"conn91.marionette1","specialPowers":false,"session":"6-b2g","scriptTimeout":null,"newSandbox":true,"args":[],"type":"executeScript","value":"log('TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_js_exception')"}, id: {50471356-4f50-49b9-a034-f04a654dbc04}
04:14:34     INFO -  I/Gecko   (  288): MARIONETTE LOG: INFO: TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_js_exception
04:14:34     INFO -  I/Gecko   (  288): 1354968818190	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","value":null}, {50471356-4f50-49b9-a034-f04a654dbc04}, {50471356-4f50-49b9-a034-f04a654dbc04}
04:14:34     INFO -  I/Gecko   (  288): 1354968818203	Marionette	DEBUG	Got request: setTestName, data: {"to":"conn91.marionette1","session":"6-b2g","type":"setTestName","value":null}, id: {74075d4d-7177-4c53-ac8a-c5b5aa86954e}
04:14:34     INFO -  I/Gecko   (  288): 1354968818206	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {74075d4d-7177-4c53-ac8a-c5b5aa86954e}, {74075d4d-7177-4c53-ac8a-c5b5aa86954e}
04:14:34     INFO -  I/Gecko   (  288): 1354968818244	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","value":[["INFO","TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_async_unload","Sat Dec 08 2012 12:13:37 GMT+0000 (GMT)"],["INFO","TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_js_exception","Sat Dec 08 2012 12:13:37 GMT+0000 (GMT)"],["INFO","TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_js_exception","Sat Dec 08 2012 12:13:38 GMT+0000 (GMT)"]]}, {d35e17d4-41c0-4f0b-a6e8-fb91814e31e3}, {d35e17d4-41c0-4f0b-a6e8-fb91814e31e3}
04:14:34     INFO -  I/Gecko   (  288): 1354968818429	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","value":{}}, {1f0321dd-3a3a-4a51-bbb0-5e11f9118bf2}, {1f0321dd-3a3a-4a51-bbb0-5e11f9118bf2}
04:14:34     INFO -  I/Gecko   (  288): 1354968818444	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {a5195ca6-ed75-4119-80fe-4bfaedc55be0}, {a5195ca6-ed75-4119-80fe-4bfaedc55be0}
04:14:34     INFO -  I/Gecko   (  288): 1354968818499	Marionette	INFO	sendToClient: {"from":"conn91.marionette1","ok":true}, {3dceb032-5ac4-438d-bbfb-79616408c3af}, {3dceb032-5ac4-438d-bbfb-79616408c3af}
04:14:34     INFO -  E/GeckoConsole(  288): [JavaScript Error: "[Exception... "Component returned failure code: 0x80470002 (NS_BASE_STREAM_CLOSED) [nsIOutputStream.write]"  nsresult: "0x80470002 (NS_BASE_STREAM_CLOSED)"  location: "JS frame :: chrome://global/content/devtools/dbg-transport.js :: DT_onOutputStreamReady :: line 94"  data: no]" {file: "chrome://global/content/devtools/dbg-transport.js" line: 94}]
04:14:34     INFO -  I/Gecko   (  288): 1354968818578	Marionette	INFO	could not load listener into content for page: chrome://browser/content/shell.xul
04:14:34     INFO -  I/Gecko   (  288): 1354968818605	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","value":"6-b2g"}, undefined, {2d870e3f-00a2-4c62-8090-bfef1b84200f}
04:14:34     INFO -  I/Gecko   (  288): 1354968818606	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968818634	Marionette	DEBUG	Got request: setTestName, data: {"to":"conn92.marionette1","session":"6-b2g","type":"setTestName","value":"test_execute_async_script.py TestExecuteAsyncContent.test_execute_no_return"}, id: {6e5309a9-23b9-488e-ae3d-70af5c0dd7d9}
04:14:34     INFO -  I/Gecko   (  288): 1354968818637	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","ok":true}, {6e5309a9-23b9-488e-ae3d-70af5c0dd7d9}, {6e5309a9-23b9-488e-ae3d-70af5c0dd7d9}
04:14:34     INFO -  I/Gecko   (  288): 1354968818678	Marionette	DEBUG	Got request: execute, data: {"to":"conn92.marionette1","specialPowers":false,"session":"6-b2g","scriptTimeout":null,"newSandbox":true,"args":[],"type":"executeScript","value":"log('TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_no_return')"}, id: {d39241e2-8d19-4e7d-abde-56febaa10249}
04:14:34     INFO -  I/Gecko   (  288): MARIONETTE LOG: INFO: TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_no_return
04:14:34     INFO -  I/Gecko   (  288): 1354968818740	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","value":null}, {d39241e2-8d19-4e7d-abde-56febaa10249}, {d39241e2-8d19-4e7d-abde-56febaa10249}
04:14:34     INFO -  I/Gecko   (  288): 1354968818756	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","ok":true}, {718fbcf8-3ddc-4f24-9239-50462ac99349}, {718fbcf8-3ddc-4f24-9239-50462ac99349}
04:14:34     INFO -  I/Gecko   (  288): 1354968818856	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","value":null}, undefined, {0e4f45e2-8a8f-4fc6-b1bd-16bd62248074}
04:14:34     INFO -  I/Gecko   (  288): 1354968818858	Marionette	WARN	got a response with no command_id
04:14:34     INFO -  I/Gecko   (  288): 1354968818873	Marionette	DEBUG	Got request: setContext, data: {"to":"conn92.marionette1","session":"6-b2g","type":"setContext","value":"content"}, id: {aca940bc-ff98-4ce2-9759-2161937248aa}
04:14:34     INFO -  I/Gecko   (  288): 1354968818875	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","ok":true}, {aca940bc-ff98-4ce2-9759-2161937248aa}, {aca940bc-ff98-4ce2-9759-2161937248aa}
04:14:34     INFO -  I/Gecko   (  288): 1354968818917	Marionette	DEBUG	Got request: execute, data: {"to":"conn92.marionette1","specialPowers":false,"session":"6-b2g","scriptTimeout":null,"newSandbox":true,"args":[],"type":"executeScript","value":"log('TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_no_return')"}, id: {0f136685-2a9e-4356-9deb-7f7d68ed4aa3}
04:14:34     INFO -  I/Gecko   (  288): MARIONETTE LOG: INFO: TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_no_return
04:14:34     INFO -  I/Gecko   (  288): 1354968818980	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","value":null}, {0f136685-2a9e-4356-9deb-7f7d68ed4aa3}, {0f136685-2a9e-4356-9deb-7f7d68ed4aa3}
04:14:34     INFO -  I/Gecko   (  288): 1354968818994	Marionette	DEBUG	Got request: setTestName, data: {"to":"conn92.marionette1","session":"6-b2g","type":"setTestName","value":null}, id: {3ed639a2-7f68-467c-87da-1cb6fe570d14}
04:14:34     INFO -  I/Gecko   (  288): 1354968818997	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","ok":true}, {3ed639a2-7f68-467c-87da-1cb6fe570d14}, {3ed639a2-7f68-467c-87da-1cb6fe570d14}
04:14:34     INFO -  I/Gecko   (  288): 1354968819035	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","value":[["INFO","TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_no_return","Sat Dec 08 2012 12:13:38 GMT+0000 (GMT)"],["INFO","TEST-END: /home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py:test_execute_no_return","Sat Dec 08 2012 12:13:38 GMT+0000 (GMT)"]]}, {a9fa06e9-580d-4d07-ae44-a0af46b3cf2d}, {a9fa06e9-580d-4d07-ae44-a0af46b3cf2d}
04:14:34     INFO -  I/Gecko   (  288): 1354968819089	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","value":{}}, {9cc51ee2-de14-472f-b903-330739c18242}, {9cc51ee2-de14-472f-b903-330739c18242}
04:14:34     INFO -  I/Gecko   (  288): 1354968819123	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","ok":true}, {e712b573-7c90-4012-85a6-3946359cdb52}, {e712b573-7c90-4012-85a6-3946359cdb52}
04:14:34     INFO -  I/Gecko   (  288): 1354968819176	Marionette	INFO	sendToClient: {"from":"conn92.marionette1","ok":true}, {376ce53d-a96e-4f12-b73a-93af18d58913}, {376ce53d-a96e-4f12-b73a-93af18d58913}
04:14:34     INFO -  E/GeckoConsole(  288): [JavaScript Error: "[Exception... "Component returned failure code: 0x80470002 (NS_BASE_STREAM_CLOSED) [nsIOutputStream.write]"  nsresult: "0x80470002 (NS_BASE_STREAM_CLOSED)"  location: "JS frame :: chrome://global/content/devtools/dbg-transport.js :: DT_onOutputStreamReady :: line 94"  data: no]" {file: "chrome://global/content/devtools/dbg-transport.js" line: 94}]
04:14:34     INFO -  I/Gecko   (  288): 1354968819253	Marionette	INFO	could not load listener into content for page: chrome://browser/content/shell.xul
04:14:34     INFO -  I/Gecko   (  288): 1354968819275	Marionette	INFO	sendToClient: {"from":"conn93.marionette1","value":"6-b2g"}, undefined, {c3f5623d-eb3d-4d54-978f-a708c9f192bd}
(In reply to David Burns :automatedtester from comment #20)
> Looking at this, its a case of the an Marionette getting out of sync.
> 
> The test is failing during a setUp 
> 
> 04:13:55     INFO - 
> ======================================================================
> 04:13:55     INFO -  ERROR: test_execute_async_unload
> (test_execute_async_script.TestExecuteAsyncContent)
> 04:13:55     INFO - 
> ----------------------------------------------------------------------
> 04:13:55    ERROR -  Traceback (most recent call last):
> 04:13:55     INFO -    File
> "/home/cltbld/talos-slave/test/build/tests/marionette/tests/testing/
> marionette/client/marionette/tests/unit/test_execute_async_script.py", line
> 11, in setUp
> 04:13:55     INFO -      self.marionette.set_script_timeout(1000)
> 04:13:55     INFO -    File
> "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.
> py", line 321, in set_script_timeout
> 04:13:55     INFO -      response = self._send_message('setScriptTimeout',
> 'ok', value=timeout)
> 04:13:55     INFO -    File
> "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.
> py", line 211, in _send_message
> 04:13:55     INFO -      self._handle_error(response)
> 04:13:55     INFO -    File
> "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.
> py", line 269, in _handle_error
> 04:13:55     INFO -      raise MarionetteException(message=response,
> status=500)
> 04:13:55     INFO -  TEST-UNEXPECTED-FAIL | test_execute_async_script.py
> TestExecuteAsyncContent.test_execute_async_unload | MarionetteException:
> {u'from': u'conn91.marionette1', u'value': 1}
> 04:13:55     INFO - 
> ----------------------------------------------------------------------

The irony of this test failing on B2G is that it is set to ignore http://mxr.mozilla.org/mozilla-central/source/testing/marionette/client/marionette/tests/unit/test_execute_async_script.py#29
retrying after the emulator has been updated: 
https://tbpl.mozilla.org/?tree=Try&rev=3d54ac9d97e5
Try run for 3d54ac9d97e5 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=3d54ac9d97e5
Results (out of 5 total builds):
    success: 3
    warnings: 2
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/mdas@mozilla.com-3d54ac9d97e5
So, I've downloaded the emulator used by tbpl and updated it with the relevant changes in gecko, but I can't reproduce these errors on my linux machine. The errors, shown here: https://tbpl.mozilla.org/php/getParsedLog.php?id=18218860&tree=Try&full=1, appear to be out of sync errors, but they show up consistently under try.

Aki, do you know if it is possible to get access to a test machine used in try, so I can see what's different in the environment?
Flags: needinfo?(aki)
(In reply to Malini Das [:mdas] from comment #25)
> So, I've downloaded the emulator used by tbpl and updated it with the
> relevant changes in gecko, but I can't reproduce these errors on my linux
> machine. The errors, shown here:
> https://tbpl.mozilla.org/php/getParsedLog.php?id=18218860&tree=Try&full=1,
> appear to be out of sync errors, but they show up consistently under try.
> 
> Aki, do you know if it is possible to get access to a test machine used in
> try, so I can see what's different in the environment?

Yes.  I filed bug 829659 for this.
Flags: needinfo?(aki)
So I had a feeling it would pass after a while and the gonk tool-chain was updated, and it seems to be the case: 
https://tbpl.mozilla.org/?tree=Try&rev=27f7044cdad6

I'm going to run the full marionette&marionette-webapi tests here:
https://tbpl.mozilla.org/?tree=Try&rev=5a7619c61220 and see what happens. I'm running a modified patch now, so I'll update the patch here.
Attached file unbitrotted patch v2.0
carrying r+ forward. I removed the skip_if_b2g stuff for test_execute_async_unload since it can be successfully run in b2g. I also changed some of the return values from marionetteScriptFinished to be unique, so if we ever see out of sync return values, we at least know where they were thrown from.
Attachment #688349 - Attachment is obsolete: true
Attachment #706713 - Flags: review+
Whiteboard: [automation-needed-in-beta][automation-needed-in-aurora][leave-open] → [leave-open]
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Whiteboard: [leave-open]
Target Milestone: --- → mozilla21
You need to log in before you can comment on or make changes to this bug.