837448 - Intermittent test_emulator_loopback.js | ScriptTimeoutException: timed out

Status: RESOLVED FIXED

(Core :: DOM: Device Interfaces, defect)

Description

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=19391589&tree=Mozilla-Inbound
b2g_ics_armv7a_gecko_emulator mozilla-inbound opt test marionette-webapi on 2013-02-02 17:33:22 PST for push b2f1089d6cd4
slave: talos-r3-fed-044

17:41:51    ERROR -  Traceback (most recent call last):
17:41:51     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette_test.py", line 213, in runTest
17:41:51     INFO -      results = self.marionette.execute_js_script(js, args, special_powers=True)
17:41:51     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 478, in execute_js_script
17:41:51     INFO -      scriptTimeout=script_timeout)
17:41:51     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 249, in _send_message
17:41:51     INFO -      self._handle_error(response)
17:41:51     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 298, in _handle_error
17:41:51    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
17:41:51    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
17:41:51     INFO -  ----------------------------------------------------------------------
17:41:51     INFO -  Ran 1 test in 11.076s
17:41:51    ERROR -  FAILED (errors=1)

Comment 1

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

Somehow the test script failed in the forth test case -- sending a long UCS2 encoded string.

Comment 2

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

Enable RIL debug messages and trying https://tbpl.mozilla.org/?tree=Try&rev=d3c0ba2a0ae4

Comment 3

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

Seems can't be easily reproduced :S

Comment 4

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=19641123&tree=Firefox
b2g_ics_armv7a_gecko_emulator mozilla-central opt test marionette-webapi on 2013-02-11 12:33:33
slave: talos-r3-fed-012

12:42:13    ERROR -  Traceback (most recent call last):
12:42:13    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
12:42:13    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
12:42:13    ERROR -  FAILED (errors=1)
12:44:59    ERROR - Return code: 10

Comment 5

[Jonathan Griffin (:jgriffin)]

Logs no longer available, and hasn't recurred in over 2 months, so I'm closing.

Comment 6

[Andrew Halberstadt [:ahal]]

Saw this on Cedar with the new full emulator builds:
https://tbpl.mozilla.org/php/getParsedLog.php?id=24673269&tree=Cedar

Comment 7

[Andrew Halberstadt [:ahal]]

Note the above failure is perma-orange on the Cedar branch while running on the Ubuntu VM pool. We need to either fix or disable it before we can move the Mn tests over to those slaves on m-i/m-c.

Comment 8

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=24736528&tree=Mozilla-Inbound
b2g_emulator mozilla-inbound opt test marionette-webapi on 2013-06-28 21:18:24
revision: dc039d7f5e00
slave: talos-r3-fed-101

21:27:01    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
21:27:01    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
21:33:21    ERROR - Return code: 10

Comment 9

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=24770992&tree=Mozilla-Inbound
b2g_emulator mozilla-inbound opt test marionette-webapi on 2013-06-30 20:51:02
revision: 23f0ca9de75f
slave: talos-r3-fed-026

20:59:23    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
20:59:23    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
21:05:37    ERROR - Return code: 10

Comment 10

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=25070737&tree=Mozilla-Inbound
b2g_emulator mozilla-inbound opt test marionette-webapi on 2013-07-09 08:37:20
revision: e37887500089
slave: talos-r3-fed-085

08:51:17    ERROR -      raise TimeoutException(message='socket.timeout', status=ErrorCodes.TIMEOUT, stacktrace=None)
08:51:17    ERROR -  TEST-UNEXPECTED-FAIL | test_simpletest_pass.js | TimeoutException: socket.timeout
08:54:40    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
08:54:40    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
09:01:00    ERROR - Return code: 10

Comment 11

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=25169698&tree=Birch
b2g_emulator birch opt test marionette-webapi on 2013-07-11 05:48:56
revision: 727dbc1b23d0
slave: talos-r3-fed-064

05:57:07    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
05:57:07    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
06:04:06    ERROR - Return code: 1
06:04:13    ERROR - Marionette exited with return code 1: harness failures
06:04:13    ERROR - # TBPL FAILURE #

Comment 12

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=25169698&tree=Birch
b2g_emulator birch opt test marionette-webapi on 2013-07-11 05:48:56
revision: 727dbc1b23d0
slave: talos-r3-fed-064

05:57:07    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
05:57:07    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
06:04:06    ERROR - Return code: 1
06:04:13    ERROR - Marionette exited with return code 1: harness failures
06:04:13    ERROR - # TBPL FAILURE #

Comment 13

[Andrew Halberstadt [:ahal]]

Given that this is peram-orange on the ubuntu VM pool and green on the fedora pool, it's most likely a timing issue. Vicamo, any chance you can look into it or pass it along? Thanks!

Comment 14

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

Don't know how to bind VMs from a specific pool.  Drop ownership.

Comment 15

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

Weird! I seem to be able to reproduce it with JB gonk.

Comment 16

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

Attachment: qemu-jb-x86_test-emulator-loopback.txt

Comment 17

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

(In reply to Vicamo Yang [:vicamo][:vyang] from comment #16)
> Created attachment 775621 [details]
> qemu-jb-x86_test-emulator-loopback.txt

Somehow in line 52, emulator returned "AT+CMGS=87" instead of expected "AT+CMGS=149", and then in line 55, we got a new transaction with wrong parameters.

Comment 18

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

(In reply to Vicamo Yang [:vicamo][:vyang] from comment #17)
> (In reply to Vicamo Yang [:vicamo][:vyang] from comment #16)
> > Created attachment 775621 [details]
> > qemu-jb-x86_test-emulator-loopback.txt
> 
> Somehow in line 52, emulator returned "AT+CMGS=87" instead of expected
> "AT+CMGS=149",

It's correct.  That's the length of followed SMS TEXT.

> and then in line 55, we got a new transaction with wrong parameters.

https://github.com/mozilla-b2g/platform_external_qemu/blob/master/telephony/sms.c#L476
In function |sms_address_eq()|, we should have following code instead:

  return ( !memcmp( addr1->data, addr2->data, (addr1->len + 1) / 2) );

because |addr1->len| is the number of digits, and SMS-ADDRESS packs two digits into one octet.  So sometimes the garbage data at the end fail the comparison, which in turn fails |sms_receiver_find_p()|, and then results in a new fragment created with wrong parameter.

Comment 19

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

Attachment: Github PR for platform/external/qemu

Comment 20

[Legacy TBPL/Treeherder Robot]

msucan
https://tbpl.mozilla.org/php/getParsedLog.php?id=25289443&tree=Try
b2g_emulator try opt test marionette-webapi on 2013-07-15 10:47:03
revision: d9024f1bcd70
slave: talos-r3-fed-022

10:48:02    ERROR - Return code: 1
10:48:03    ERROR - Return code: 1
10:55:16    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
10:55:16    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
11:01:42    ERROR - Return code: 10

Comment 21

[Legacy TBPL/Treeherder Robot]

edmorley#testing
https://tbpl.mozilla.org/php/getParsedLog.php?id=25275939&tree=Cedar
b2g_emulator_vm cedar opt test marionette-webapi on 2013-07-14 19:22:28
revision: 77f8a03fc62e
slave: tst-linux64-ec2-408

19:32:01    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
19:32:01    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | ScriptTimeoutException: timed out
19:35:30    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
19:35:30    ERROR -  TEST-UNEXPECTED-FAIL | test_strict_7bit_encoding.js | ScriptTimeoutException: timed out
19:40:23    ERROR - Return code: 10

Comment 22

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Comment on attachment 775687 [details]
Github PR for platform/external/qemu

Thank you!!!

Comment 23

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

Merged on GitHub https://github.com/mozilla-b2g/platform_external_qemu/commit/8986e5942cb42e79c021b3317c6a82e726296ba2 .

@Andrew, could you help confirm this and update emulator HEAD?

Comment 24

[Andrew Halberstadt [:ahal]]

(In reply to Vicamo Yang [:vicamo][:vyang] from comment #23)
> Merged on GitHub
> https://github.com/mozilla-b2g/platform_external_qemu/commit/
> 8986e5942cb42e79c021b3317c6a82e726296ba2 .
> 
> @Andrew, could you help confirm this and update emulator HEAD?

The emulator builds no longer need to be updated, they pull in the latest gonk/gaia/etc on their own and do a full stack build. So this should get picked up whenever the change gets mirrored over to the releng hg mirrors.

Thanks for the fix!

Comment 25

[Andrew Halberstadt [:ahal]]

This has gone green on Cedar, resolving

Comment 26

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=25890222&tree=Mozilla-Inbound
b2g_emulator mozilla-inbound opt test marionette-webapi on 2013-07-29 18:41:06
revision: 770b97caaaba
slave: talos-r3-fed-028

18:51:33    ERROR -      raise TimeoutException(message='socket.timeout', status=ErrorCodes.TIMEOUT, stacktrace=None)
18:51:33    ERROR -  TEST-UNEXPECTED-FAIL | test_emulator_loopback.js | TimeoutException: socket.timeout
18:56:54    ERROR - Return code: 2560
18:57:03    ERROR - Marionette exited with return code 2560: harness failures
18:57:03    ERROR - # TBPL FAILURE #