1357635 - Intermittent toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Test timed out.

Status: RESOLVED INCOMPLETE

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

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

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

Comment 1

[Intermittent Failures Robot]

35 failures in 131 pushes (0.267 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 22
* mozilla-inbound: 12
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api15: 35

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1357635&startday=2017-06-15&endday=2017-06-15&tree=all

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

this started on the 14th and is failing often, I have done some retriggers to help identify the root cause here:
https://treeherder.mozilla.org/#/jobs?repo=autoland&filter-searchStr=mochitest-48&tochange=4ded3c833e14550922fdf6ceb9ca8b541e22325e&fromchange=f2e62c744c62c91b394095885a64f7905bc9b9c4&selectedJob=107131348

this is all on android debug, here is a recent log:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=107832116&lineNumber=2112

and a clip from that log:
task 2017-06-16T23:06:46.360427Z] 23:06:46     INFO -  36 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.360519Z] 23:06:46     INFO -  Buffered messages logged at 23:02:14
[task 2017-06-16T23:06:46.360581Z] 23:06:46     INFO -  37 INFO SpawnTask.js | Leaving test test_invalid_FindProxyForURL_type
[task 2017-06-16T23:06:46.360643Z] 23:06:46     INFO -  38 INFO SpawnTask.js | Entering test test_invalid_FindProxyForURL_return_types
[task 2017-06-16T23:06:46.360691Z] 23:06:46     INFO -  Buffered messages logged at 23:02:15
[task 2017-06-16T23:06:46.360734Z] 23:06:46     INFO -  39 INFO Extension loaded
[task 2017-06-16T23:06:46.360780Z] 23:06:46     INFO -  Buffered messages logged at 23:02:29
[task 2017-06-16T23:06:46.360852Z] 23:06:46     INFO -  40 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.360902Z] 23:06:46     INFO -  Buffered messages logged at 23:02:42
[task 2017-06-16T23:06:46.360943Z] 23:06:46     INFO -  41 INFO Extension loaded
[task 2017-06-16T23:06:46.360986Z] 23:06:46     INFO -  Buffered messages logged at 23:03:10
[task 2017-06-16T23:06:46.361058Z] 23:06:46     INFO -  42 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.361105Z] 23:06:46     INFO -  Buffered messages logged at 23:03:15
[task 2017-06-16T23:06:46.361151Z] 23:06:46     INFO -  43 INFO Extension loaded
[task 2017-06-16T23:06:46.361196Z] 23:06:46     INFO -  Buffered messages logged at 23:03:30
[task 2017-06-16T23:06:46.361267Z] 23:06:46     INFO -  44 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.361314Z] 23:06:46     INFO -  Buffered messages logged at 23:03:35
[task 2017-06-16T23:06:46.361359Z] 23:06:46     INFO -  45 INFO Extension loaded
[task 2017-06-16T23:06:46.361405Z] 23:06:46     INFO -  Buffered messages logged at 23:03:58
[task 2017-06-16T23:06:46.361480Z] 23:06:46     INFO -  46 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.361526Z] 23:06:46     INFO -  Buffered messages logged at 23:04:02
[task 2017-06-16T23:06:46.361568Z] 23:06:46     INFO -  47 INFO Extension loaded
[task 2017-06-16T23:06:46.361744Z] 23:06:46     INFO -  Buffered messages logged at 23:04:17
[task 2017-06-16T23:06:46.362232Z] 23:06:46     INFO -  48 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.362646Z] 23:06:46     INFO -  Buffered messages logged at 23:04:22
[task 2017-06-16T23:06:46.363057Z] 23:06:46     INFO -  49 INFO Extension loaded
[task 2017-06-16T23:06:46.363459Z] 23:06:46     INFO -  Buffered messages logged at 23:04:36
[task 2017-06-16T23:06:46.363943Z] 23:06:46     INFO -  50 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.364377Z] 23:06:46     INFO -  Buffered messages logged at 23:04:41
[task 2017-06-16T23:06:46.364771Z] 23:06:46     INFO -  51 INFO Extension loaded
[task 2017-06-16T23:06:46.365170Z] 23:06:46     INFO -  Buffered messages logged at 23:05:14
[task 2017-06-16T23:06:46.365644Z] 23:06:46     INFO -  52 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.366054Z] 23:06:46     INFO -  Buffered messages logged at 23:05:19
[task 2017-06-16T23:06:46.366449Z] 23:06:46     INFO -  53 INFO Extension loaded
[task 2017-06-16T23:06:46.366855Z] 23:06:46     INFO -  Buffered messages logged at 23:05:42
[task 2017-06-16T23:06:46.367321Z] 23:06:46     INFO -  54 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.367870Z] 23:06:46     INFO -  Buffered messages logged at 23:05:47
[task 2017-06-16T23:06:46.368273Z] 23:06:46     INFO -  55 INFO Extension loaded
[task 2017-06-16T23:06:46.368712Z] 23:06:46     INFO -  Buffered messages logged at 23:06:03
[task 2017-06-16T23:06:46.369093Z] 23:06:46     INFO -  56 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.369414Z] 23:06:46     INFO -  Buffered messages logged at 23:06:08
[task 2017-06-16T23:06:46.369827Z] 23:06:46     INFO -  57 INFO SpawnTask.js | Leaving test test_invalid_FindProxyForURL_return_types
[task 2017-06-16T23:06:46.370196Z] 23:06:46     INFO -  58 INFO SpawnTask.js | Entering test test_runtime_error_in_FindProxyForURL
[task 2017-06-16T23:06:46.370422Z] 23:06:46     INFO -  59 INFO Extension loaded
[task 2017-06-16T23:06:46.370676Z] 23:06:46     INFO -  Buffered messages logged at 23:06:32
[task 2017-06-16T23:06:46.370985Z] 23:06:46     INFO -  60 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Correct error message received
[task 2017-06-16T23:06:46.371272Z] 23:06:46     INFO -  61 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Error should include file name
[task 2017-06-16T23:06:46.371556Z] 23:06:46     INFO -  62 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Error should include line number
[task 2017-06-16T23:06:46.371845Z] 23:06:46     INFO -  63 INFO TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Error should include stack trace
[task 2017-06-16T23:06:46.372071Z] 23:06:46     INFO -  Buffered messages finished
[task 2017-06-16T23:06:46.372388Z] 23:06:46     INFO -  64 INFO TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Test timed out.
[task 2017-06-16T23:06:46.372692Z] 23:06:46     INFO -      reportError@SimpleTest/TestRunner.js:121:7
[task 2017-06-16T23:06:46.372967Z] 23:06:46     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
[task 2017-06-16T23:06:46.373278Z] 23:06:46     INFO -  65 INFO TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | Extension not fully unloaded at test shutdown
[task 2017-06-16T23:06:46.373524Z] 23:06:46     INFO -      ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:112:7
[task 2017-06-16T23:06:46.373798Z] 23:06:46     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1224:19
[task 2017-06-16T23:06:46.374065Z] 23:06:46     INFO -      SimpleTest.finish@SimpleTest/SimpleTest.js:1237:5
[task 2017-06-16T23:06:46.374312Z] 23:06:46     INFO -      killTest@SimpleTest/TestRunner.js:130:7
[task 2017-06-16T23:06:46.374565Z] 23:06:46     INFO -      delayedKillTest@SimpleTest/TestRunner.js:157:47
[task 2017-06-16T23:06:46.374827Z] 23:06:46     INFO -  66 INFO SpawnTask.js | Leaving test test_runtime_error_in_FindProxyForURL
[task 2017-06-16T23:06:46.375086Z] 23:06:46     INFO -  67 ERROR [SimpleTest.finish()] this test already called finish!
[task 2017-06-16T23:06:46.375384Z] 23:06:46     INFO -  68 INFO TEST-UNEXPECTED-ERROR | toolkit/components/extensions/test/mochitest/test_ext_proxy.html | called finish() multiple times
[task 2017-06-16T23:06:46.375606Z] 23:06:46     INFO -  TEST-INFO took 321266ms
[task 2017-06-16T23:06:46.375884Z] 23:06:46     INFO -  69 INFO TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_proxy.html
[task 2

I am not sure if we are timing out or if this is a longer running test?  As this happens on debug, it could just be a long running test.  I see some data about average runtime:
android-4-3-armv7-api15/debug-chunked: 186.16 s (118.37 s - 317.89 s over 488 runs)

this indicates that this is probably normally running much less than the max time.


:andym, can you get someone from the webextensions team to look into this failure?

Comment 3

[Intermittent Failures Robot]

54 failures in 814 pushes (0.066 failures/push) were associated with this bug in the last 7 days. 

This is the #36 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: 32
* mozilla-inbound: 20
* try: 1
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api15: 54

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1357635&startday=2017-06-12&endday=2017-06-18&tree=all

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

the retriggers show bug 1355198 as the root cause

:mattw, can you take a look at this and get this resolved this week?

Comment 5

[Intermittent Failures Robot]

16 failures in 151 pushes (0.106 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 8
* mozilla-inbound: 5
* try: 3

Platform breakdown:
* android-4-3-armv7-api15: 16

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1357635&startday=2017-06-19&endday=2017-06-19&tree=all

Comment 6

[Intermittent Failures Robot]

15 failures in 173 pushes (0.087 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 8
* mozilla-inbound: 6
* mozilla-central: 1

Platform breakdown:
* android-4-3-armv7-api15: 15

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1357635&startday=2017-06-20&endday=2017-06-20&tree=all

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

pinging to follow up here, we have 15+ failures/day showing up on android and have identified a root cause- what are the next steps here?

Comment 8

[Intermittent Failures Robot]

64 failures in 892 pushes (0.072 failures/push) were associated with this bug in the last 7 days. 

This is the #30 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: 30
* mozilla-inbound: 24
* try: 5
* mozilla-central: 5

Platform breakdown:
* android-4-3-armv7-api15: 64

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1357635&startday=2017-06-19&endday=2017-06-25&tree=all

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: disable test for android/debug

Comment 10

[Geoff Brown [:gbrown]]

Comment on attachment 8881218 [details] [diff] [review]
disable test for android/debug

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

::: toolkit/components/extensions/test/mochitest/mochitest-common.ini
@@ +80,5 @@
>  skip-if = os == 'android' # Android support Bug 1336194
>  [test_ext_notifications.html]
>  [test_ext_permission_xhr.html]
>  [test_ext_proxy.html]
> +skip-if = os == 'andorid' && debug # Bug 1357635

oops - s/andorid/android/ !!

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fefa3d2a3d40
Intermittent toolkit/components/extensions/test/mochitest/test_ext_proxy.html. temporarily disable on android/debug. r=gbrown

Comment 12

[Carsten Book [:Tomcat]]

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

Comment 13

[Intermittent Failures Robot]

6 failures in 718 pushes (0.008 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 6

Platform breakdown:
* android-4-3-armv7-api15: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1357635&startday=2017-06-26&endday=2017-07-02&tree=all

Comment 14

[Bob Silverberg [:bsilverberg]]

This test was converted to an xpcshell test via [1], so this bug is no longer valid. Closing it and changing the whiteboard tag to [stockwell unknown].

[1] https://hg.mozilla.org/mozilla-central/rev/f3342ea446a5