1532435 - Intermittent TEST-UNEXPECTED-TIMEOUT | runjunit.py | Timed out after 2400 seconds

Status: RESOLVED FIXED

(GeckoView :: General, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: apavel [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=231709799&repo=autoland

https://queue.taskcluster.net/v1/task/XzFNwaJITVqITV_3M6IexA/runs/0/artifacts/public/logs/live_backing.log

[task 2019-03-04T20:09:32.664Z] 20:09:32 INFO - TEST-START | org.mozilla.geckoview.test.TextInputDelegateTest.inputConnection[#input]
[task 2019-03-04T20:17:17.665Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-03-04T20:17:17.665Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=62
[task 2019-03-04T20:17:17.665Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.TextInputDelegateTest
[task 2019-03-04T20:17:17.666Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=.
[task 2019-03-04T20:17:17.666Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=66
[task 2019-03-04T20:17:17.666Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=inputConnection[#input]
[task 2019-03-04T20:17:17.666Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 0
[task 2019-03-04T20:17:17.666Z] 20:17:17 INFO - TEST-PASS | org.mozilla.geckoview.test.TextInputDelegateTest.inputConnection[#input] | took 465003ms
[task 2019-03-04T20:17:17.766Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2019-03-04T20:17:17.767Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=63
[task 2019-03-04T20:17:17.767Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.TextInputDelegateTest
[task 2019-03-04T20:17:17.767Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2019-03-04T20:17:17.767Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=66
[task 2019-03-04T20:17:17.768Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=inputConnection[#textarea]
[task 2019-03-04T20:17:17.769Z] 20:17:17 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2019-03-04T20:17:17.769Z] 20:17:17 INFO - TEST-START | org.mozilla.geckoview.test.TextInputDelegateTest.inputConnection[#textarea]
[task 2019-03-04T20:20:51.603Z] 20:20:51 WARNING - TEST-UNEXPECTED-TIMEOUT | runjunit.py | Timed out after 2400 seconds
[task 2019-03-04T20:20:51.603Z] 20:20:51 INFO - Passed: 56
[task 2019-03-04T20:20:51.604Z] 20:20:51 INFO - Failed: 0
[task 2019-03-04T20:20:51.604Z] 20:20:51 INFO - Todo: 6
[task 2019-03-04T20:20:51.604Z] 20:20:51 INFO - SUITE-END | took 2400s
[task 2019-03-04T20:20:53.024Z] 20:20:53 INFO - Stopping web server
[task 2019-03-04T20:20:53.032Z] 20:20:53 INFO - Stopping web socket server
[task 2019-03-04T20:20:53.051Z] 20:20:53 INFO - Stopping ssltunnel
[task 2019-03-04T20:20:56.876Z] 20:20:56 INFO - Return code: 0
[task 2019-03-04T20:20:56.877Z] 20:20:56 INFO - TinderboxPrint: geckoview-junit<br/>56/0
[task 2019-03-04T20:20:56.877Z] 20:20:56 INFO - ##### geckoview-junit log ends
[task 2019-03-04T20:20:56.877Z] 20:20:56 WARNING - # TBPL WARNING #
[task 2019-03-04T20:20:56.877Z] 20:20:56 WARNING - setting return code to 1
[task 2019-03-04T20:20:56.877Z] 20:20:56 WARNING - The geckoview-junit suite: geckoview-junit ran with return status: WARNING

Comment 1

[Cristina Coroiu [:ccoroiu]]

Retriggered on this range:
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=android%2C4.3%2Capi16%2B%2Cdebug%2Ctest-android-em-4.3-arm7-api-16%2Fdebug-geckoview-junit-e10s-5%2C%28gv-junit5%29&tochange=a9bb4a23d4072a2735b50b577f9668728af06d30&fromchange=9adad198b9b4b54b5813cf8a367ab0db41c36635&selectedJob=231709799

Robert, can you please take a look?

Comment 2

[Robert Strong (they/them - no direct email)]

The code change that landed in bug 1510276 was for the Windows installer. So, there is no way this code runs on Android or for that matter junit.

Comment 3

[Andreea Pavel [:apavel]]

This is from 1482231, Geoff can you please take a look?

There are 23 total failures in the last 7 days on android-em-4-3-armv7-api16 opt and debug.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=232414336&repo=autoland&lineNumber=1912

[task 2019-03-07T13:36:02.181Z] 13:36:02 INFO - TEST-START | org.mozilla.geckoview.test.GeckoSessionTestRuleTest.waitForPageStops_withSpecificSessions
[task 2019-03-07T14:12:59.299Z] 14:12:59 WARNING - TEST-UNEXPECTED-TIMEOUT | runjunit.py | Timed out after 2400 seconds
[task 2019-03-07T14:12:59.299Z] 14:12:59 INFO - Passed: 33
[task 2019-03-07T14:12:59.300Z] 14:12:59 INFO - Failed: 0
[task 2019-03-07T14:12:59.300Z] 14:12:59 INFO - Todo: 1
[task 2019-03-07T14:12:59.300Z] 14:12:59 INFO - SUITE-END | took 2400s
[task 2019-03-07T14:17:59.382Z] 14:17:59 INFO - Traceback (most recent call last):
[task 2019-03-07T14:17:59.382Z] 14:17:59 INFO - File "/builds/worker/workspace/build/tests/mochitest/runjunit.py", line 444, in run_test_harness
[task 2019-03-07T14:17:59.384Z] 14:17:59 INFO - result = runner.run_tests(options.test_filters)
[task 2019-03-07T14:17:59.384Z] 14:17:59 INFO - File "/builds/worker/workspace/build/tests/mochitest/runjunit.py", line 275, in run_tests
[task 2019-03-07T14:17:59.384Z] 14:17:59 INFO - if self.check_for_crashes():
[task 2019-03-07T14:17:59.385Z] 14:17:59 INFO - File "/builds/worker/workspace/build/tests/mochitest/runjunit.py", line 291, in check_for_crashes
[task 2019-03-07T14:17:59.385Z] 14:17:59 INFO - logcat = self.device.get_logcat()
[task 2019-03-07T14:17:59.385Z] 14:17:59 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 1569, in get_logcat
[task 2019-03-07T14:17:59.385Z] 14:17:59 INFO - lines = self.command_output(cmds, timeout=timeout).splitlines()
[task 2019-03-07T14:17:59.385Z] 14:17:59 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 1094, in command_output
[task 2019-03-07T14:17:59.385Z] 14:17:59 INFO - timeout=timeout)
[task 2019-03-07T14:17:59.386Z] 14:17:59 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 306, in command_output
[task 2019-03-07T14:17:59.386Z] 14:17:59 CRITICAL - raise ADBTimeoutError("%s" % adb_process)
[task 2019-03-07T14:17:59.386Z] 14:17:59 CRITICAL - ADBTimeoutError: args: adb-5554 wait-for-device logcat -v time -d dalvikvm:I ConnectivityService:S WifiMonitor:S WifiStateTracker:S wpa_supplicant:S NetworkStateTracker:S EmulatedCamera_Camera:S EmulatedCamera_Device:S EmulatedCamera_FakeCamera:S EmulatedCamera_FakeDevice:S EmulatedCamera_CallbackNotifier:S GnssLocationProvider:S Hyphenator:S BatteryStats:S, exitcode: None, stdout:
[task 2019-03-07T14:17:59.386Z] 14:17:59 INFO - runjunit.py | Received unexpected exception while running tests
[task 2019-03-07T14:17:59.386Z] 14:17:59 INFO - Stopping web server
[task 2019-03-07T14:17:59.396Z] 14:17:59 INFO - Stopping web socket server
[task 2019-03-07T14:17:59.416Z] 14:17:59 INFO - Stopping ssltunnel
[task 2019-03-07T14:22:59.480Z] 14:22:59 INFO - Traceback (most recent call last):
[task 2019-03-07T14:22:59.480Z] 14:22:59 INFO - File "/builds/worker/workspace/build/tests/mochitest/runjunit.py", line 128, in cleanup
[task 2019-03-07T14:22:59.480Z] 14:22:59 INFO - self.device.stop_application(self.options.app)
[task 2019-03-07T14:22:59.480Z] 14:22:59 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 3163, in stop_application
[task 2019-03-07T14:22:59.480Z] 14:22:59 INFO - timeout=timeout, root=root)
[task 2019-03-07T14:22:59.480Z] 14:22:59 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/mozdevice/adb.py", line 1471, in shell_output
[task 2019-03-07T14:22:59.480Z] 14:22:59 CRITICAL - raise ADBTimeoutError("%s" % adb_process)
[task 2019-03-07T14:22:59.481Z] 14:22:59 CRITICAL - ADBTimeoutError: args: adb-5554 wait-for-device shell am force-stop org.mozilla.geckoview.test; echo adb_returncode=$?, exitcode: None, stdout:
[task 2019-03-07T14:22:59.481Z] 14:22:59 INFO - Caught and ignored an exception during cleanup
[task 2019-03-07T14:22:59.497Z] 14:22:59 ERROR - Return code: 1
[task 2019-03-07T14:22:59.498Z] 14:22:59 INFO - TinderboxPrint: geckoview-junit<br/>33/0
[task 2019-03-07T14:22:59.498Z] 14:22:59 INFO - ##### geckoview-junit log ends
[task 2019-03-07T14:22:59.498Z] 14:22:59 CRITICAL - # TBPL RETRY #
[task 2019-03-07T14:22:59.498Z] 14:22:59 WARNING - setting return code to 4
[task 2019-03-07T14:22:59.498Z] 14:22:59 CRITICAL - The geckoview-junit suite: geckoview-junit ran with return status: RETRY
[task 2019-03-07T14:22:59.498Z] 14:22:59 INFO - Running post-action listener: _package_coverage_data
[task 2019-03-07T14:22:59.499Z] 14:22:59 INFO - Running post-action listener: _resource_record_post_action
[task 2019-03-07T14:22:59.499Z] 14:22:59 INFO - Running post-action listener: process_java_coverage_data
[task 2019-03-07T14:22:59.499Z] 14:22:59 INFO - Running post-action listener: stop_device
[task 2019-03-07T14:27:59.545Z] 14:27:59 INFO - failed to pull /data/anr: ADBTimeoutError args: /builds/worker/workspace/build/android-sdk-linux/platform-tools/adb-5554 wait-for-device shell test -d /data/anr; echo adb_returncode=$?, exitcode: None, stdout:
[taskcluster:error] Task timeout after 3600 seconds. Force killing container.

Comment 4

[Geoff Brown [:gbrown]]

Bug 1531611 probably transformed some retries-on-adb-timeout into failures reported here. Bug 1533445 should change those back to retries going forward. In this case that's not ideal, because it looks like the adb timeout might be caused by something happening in the test. I'll try to collect better logs from the anticipated retries.

Comment 5

[Jan Henning [:JanH]]

I think the timeouts happen simply if the actual tests (i.e. roughly the bits between SUITE-START and SUITE-END in the live logs) take more than 2400 s, because I'm running into this with https://treeherder.mozilla.org/#/jobs?repo=try&revision=4c33414bc4cf8ee894e15c773337da2754309be3, where word-wrapping adds several minutes to a test that happened to display loads of binary data as text and therefore takes debug-geckoview-junit-e10s-5 firmly into permafailing territory.

So the question is whether that behaviour (direct timeout even if a chunk is happily running, but the JUnit tests themselves simply take longer than 40 minutes) is intentional?

Although at the same time maybe we should have more chunks for debug builds in any case anyway, though.

Comment 6

[Intermittent Failures Robot]

59 failures in 2818 pushes (0.021 failures/push) were associated with this bug in the last 7 days.

This is the #27 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 43
• mozilla-inbound: 10
• mozilla-central: 6

Platform breakdown:

• android-em-4-3-armv7-api16: 55
• android-em-4-3-armv7-api16-ccov: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1532435&startday=2019-03-04&endday=2019-03-10&tree=all

Comment 7

[Geoff Brown [:gbrown]]

(In reply to Jan Henning [:JanH] from comment #5)

So the question is whether that behaviour (direct timeout even if a chunk is happily running, but the JUnit tests themselves simply take longer than 40 minutes) is intentional?

Yes, it is intentional. If a test harness does not time out on its own and eventually exceeds the task max-run-time, the task is killed and no artifacts are collected, which makes it really difficult to debug. geckoview-junit max-run-time is 60 minutes and includes some setup before the test harness runs, so I think 40 minutes is appropriate (Perhaps could be increased 5 or 10 minutes).

Although at the same time maybe we should have more chunks for debug builds in any case anyway, though.

We added more chunks earlier this month, and chunks other than debug gv-5 seem to be doing okay, so I am reluctant to increase the chunks again.

Comment 8

[Geoff Brown [:gbrown]]

Android 4.3/debug geckoview-junit-5 contains some long-running tests, like

TEST-PASS | org.mozilla.geckoview.test.TextInputDelegateTest.inputConnection[#input] | took 386263ms
TEST-PASS | org.mozilla.geckoview.test.TextInputDelegateTest.inputConnection[#textarea] | took 386855ms

I wonder if something is going wrong there.

Comment 9

[Intermittent Failures Robot]

16 failures in 519 pushes (0.031 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 6
• mozilla-central: 5
• mozilla-inbound: 5

Platform breakdown:

• android-em-4-3-armv7-api16: 13
• android-em-4-3-armv7-api16-ccov: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1532435&startday=2019-03-11&endday=2019-03-11&tree=all

Comment 10

[Geoff Brown [:gbrown]]

Attachment: Bug 1532435 - Skip junit inputConnection test on debug only, to save lots of time; r=snorp

Disabling inputConnection on debug saves about 15 minutes of time, which helps
us avoid the timeouts seen in this bug. It continues running on opt, where it
runs much faster.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c2beaac71305
Skip junit inputConnection test on debug only, to save lots of time; r=snorp

Comment 12

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/c2beaac71305

Comment 13

[Intermittent Failures Robot]

32 failures in 2771 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 12
• mozilla-central: 11
• mozilla-inbound: 9

Platform breakdown:

• android-em-4-3-armv7-api16: 27
• android-em-4-3-armv7-api16-ccov: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1532435&startday=2019-03-11&endday=2019-03-17&tree=all