Open Bug 1437051 Opened 6 years ago Updated 1 year ago

Intermittent browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -

Categories

(Firefox :: Settings UI, defect, P5)

Product:
Firefox
Component:
Settings UI
Type:
defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned, NeedInfo)

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(1 file, 3 obsolete files)

Disable browser_extension_controlled.js on win ccov for frequent failures
770 bytes, patch
jmaher
: review+
Details | Diff | Splinter Review 
Filed by: ncsoregi [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=161297527&repo=mozilla-central

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

11:47:36     INFO -  502 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy pref is set to the expected value. -
11:47:36     INFO -  503 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | The connection settings description is as expected. -
11:47:36     INFO -  Buffered messages logged at 11:47:35
11:47:36     INFO -  504 INFO Console message: Warning: attempting to write 6770 bytes to preference network.proxy.autoconfig_url. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
11:47:36     INFO -  Buffered messages logged at 11:47:36
11:47:36     INFO -  505 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
11:47:36     INFO -  506 INFO Leaving test bound testExtensionControlledProxyConfig
11:47:36     INFO -  507 INFO Console message: [JavaScript Warning: "Loading failed for the <script> with source “moz-extension://05466cee-03d4-4fcb-af9b-9c9ab02ea307/%7B621139a0-8597-49e9-94a2-8b2786d9f0ef%7D.js”." {file: "moz-extension://05466cee-03d4-4fcb-af9b-9c9ab02ea307/_generated_background_page.html" line: 5}]
11:47:36     INFO -  Buffered messages finished
11:47:36    ERROR -  508 INFO TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
There are 30 failures on this bug during the last 7 days. There failures happen on Linux, Linux x64, linux32-stylo-disabled, windows10-64-ccov.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=163819992&lineNumber=12660

Here is a relevant part of that log: 

:46:09     INFO -  Buffered messages logged at 23:46:09
23:46:09     INFO -  684 INFO Leaving test bound testExtensionControlledProxyConfig
23:46:09     INFO -  685 INFO Console message: [JavaScript Warning: "Loading failed for the <script> with source “moz-extension://0a20bad6-4866-4f46-a392-ba2bf0c24ffa/%7Bbb4401c4-8bbd-4d61-868a-46b012c1a666%7D.js”." {file: "moz-extension://0a20bad6-4866-4f46-a392-ba2bf0c24ffa/_generated_background_page.html" line: 5}]
23:46:09     INFO -  Buffered messages finished
23:46:09    ERROR -  686 INFO TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
23:46:09     INFO -  GECKO(3752) | MEMORY STAT | vsize 2478MB | vsizeMaxContiguous 132693770MB | residentFast 538MB | heapAllocated 167MB
23:46:09     INFO -  687 INFO TEST-OK | browser/components/preferences/in-content/tests/browser_extension_controlled.js | took 90800ms
23:46:09     INFO -  GECKO(3752) | ++DOCSHELL 000001DF06303800 == 1 [pid = 6036] [id = {b4dee2f5-ed7e-4b42-b710-49b333113b78}]
23:46:09     INFO -  GECKO(3752) | ++DOMWINDOW == 1 (000001DF05C6D800) [pid = 6036] [serial = 93] [outer = 0000000000000000]
23:46:09     INFO -  GECKO(3752) | ++DOMWINDOW == 2 (000001DF0634BC00) [pid = 6036] [serial = 94] [outer = 000001DF05C6D800]
23:46:09     INFO -  688 INFO checking window state
Flags: needinfo?(jaws)
Whiteboard: [stockwell needswork]
Redirecting to Mark who wrote the test.
Flags: needinfo?(jaws) → needinfo?(mstriemer)
There have been 38 failures in the last week.
Summary: Permafailing browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.

Fails on windows10-64-ccov / debug, with 2 exceptions for linux64-ccov / opt and Linux / debug.

Here is a recent log file and a snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=165797384&lineNumber=11231

23:43:26     INFO -  446 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
23:43:26     INFO -  447 INFO Leaving test bound testExtensionControlledProxyConfig
23:43:26     INFO -  448 INFO Console message: [JavaScript Warning: "Loading failed for the <script> with source “moz-extension://26c1b0af-dd92-45d6-8962-6560fe27cd8d/%7Bf6b41509-3bcc-4c75-bd2f-5e6c2990d14a%7D.js”." {file: "moz-extension://26c1b0af-dd92-45d6-8962-6560fe27cd8d/_generated_background_page.html" line: 5}]
23:43:26     INFO -  Buffered messages finished
23:43:26    ERROR -  449 INFO TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
23:43:26     INFO -  GECKO(3776) | MEMORY STAT | vsize 2526MB | vsizeMaxContiguous 130983510MB | residentFast 578MB | heapAllocated 188MB
23:43:26     INFO -  450 INFO TEST-OK | browser/components/preferences/in-content/tests/browser_extension_controlled.js | took 96750ms
23:43:26     INFO -  GECKO(3776) | ++DOCSHELL 000001F86F857000 == 1 [pid = 5848] [id = {c0197908-0080-45e9-8d60-819961eba2e1}]
23:43:26     INFO -  GECKO(3776) | ++DOMWINDOW == 1 (000001F874AB9800) [pid = 5848] [serial = 47] [outer = 0000000000000000]
23:43:26     INFO -  GECKO(3776) | ++DOMWINDOW == 2
In the last 7 days, there have been 37 failures.
For failure pattern, please see comment 6

Recent log file:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=167324095&lineNumber=12935

:jaws, :mstriemer, do you have any updates here?
Summary: Permafailing browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - → Intermittent browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
Update: there are 28 failures in the last 7 days, all of them on windows10-64-ccov

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=190641308&repo=mozilla-central&lineNumber=9412

00:22:48     INFO -  467 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy controls are enabled. -
00:22:48     INFO -  468 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy controls are enabled. -
00:22:48     INFO -  469 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy controls are enabled. -
00:22:48     INFO -  470 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy controls are enabled. -
00:22:48     INFO -  471 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy controls are enabled. -
00:22:48     INFO -  472 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy panel closed. -
00:22:48     INFO -  Buffered messages logged at 00:22:44
00:22:48     INFO -  473 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy pref is set to the expected value. -
00:22:48     INFO -  474 INFO TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | The connection settings description is as expected. -
00:22:48     INFO -  Buffered messages logged at 00:22:47
00:22:48     INFO -  475 INFO Leaving test bound testExtensionControlledProxyConfig
00:22:48     INFO -  Buffered messages logged at 00:22:48
00:22:48     INFO -  476 INFO Console message: Warning: attempting to write 6753 bytes to preference network.proxy.autoconfig_url. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
00:22:48     INFO -  Buffered messages finished
00:22:48    ERROR -  477 INFO TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
00:22:48     INFO -  GECKO(6080) | MEMORY STAT | vsize 2375MB | vsizeMaxContiguous 131869512MB | residentFast 470MB | heapAllocated 132MB
00:22:48     INFO -  478 INFO TEST-OK | browser/components/preferences/in-content/tests/browser_extension_controlled.js | took 93032ms
00:22:48     INFO -  GECKO(6080) | ++DOCSHELL 000001CDD6F6B800 == 1 [pid = 6056] [id = {ecb587f6-af92-4aac-91cd-0be5b45cd4cd}]
00:22:48     INFO -  GECKO(6080) | ++DOMWINDOW == 1 (000001CDDD82BC00) [pid = 6056] [serial = 61] [outer = 0000000000000000]
00:22:48     INFO -  GECKO(6080) | ++DOMWINDOW == 2 (000001CDD6FE0C00) [pid = 6056] [serial = 62] [outer = 000001CDDD82BC00]
00:22:48     INFO -  479 INFO checking window state
 
Mark, are there any updates?
There's a warning right before the timeout which is making me think this is a bug in ExtensionPreferencesManager. It looks like it might be copying over the default values for all of the prefs in a set, including the autoconfig_url for proxies which I guess it fairly long.

I'll try to dig into this some more this week.
Assignee: nobody → mstriemer
Flags: needinfo?(mstriemer)
We are trying to build a tool to automatically classify intermittent failures, which would provide a starting point for fixing the bug, reducing the manual work for the developers.
We are collecting some feedback on the results, to see if they’re good enough and where we need to improve.
    
For this bug, the tool says that the intermittent failure is most likely a:
Test Timeout: This includes test failures in which a single test case or the whole test suite timed out. This might be due to an unresponsive or slow target system (e.g. either the system that executes the tests or the os itself), a test suite which has grown too large causing intermittent-timeouts or a timeout threshold for a process, thread, function call which was set too small/too large.


Once you’re done investigating and/or fixing the bug, could you tell me:
- Did the tool correctly recognize the type of intermittent failure?
- Did the information from the tool help your analysis, the bug fixing process, or anything in the process? (please also let us know how the tool was useful and/or what would improve the tool's usefulness for you)
Flags: needinfo?(mstriemer)
When an extension was disabled the preferences it had previously set would
be set back to their initial value. This is unnecessary though, as they
should be reset to the default instead.
Update:
There have been 38 failures in the last week.
All the failures occur on windows10-64-ccov with 1 exception for linux64-ccov.

Recent relevant log file and snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?job_id=195637147&repo=mozilla-central&lineNumber=13204

23:26:31     INFO - TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy panel closed. - 
23:26:31     INFO - TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | Proxy pref is set to the expected value. - 
23:26:31     INFO - TEST-PASS | browser/components/preferences/in-content/tests/browser_extension_controlled.js | The connection settings description is as expected. - 
23:26:31     INFO - Buffered messages logged at 23:26:31
23:26:31     INFO - Leaving test bound testExtensionControlledProxyConfig
23:26:31     INFO - Console message: Warning: attempting to write 6753 bytes to preference network.proxy.autoconfig_url. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
23:26:31     INFO - Buffered messages finished
23:26:31     INFO - TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
23:26:31     INFO - GECKO(5484) | MEMORY STAT | vsize 2405MB | vsizeMaxContiguous 131998949MB | residentFast 502MB | heapAllocated 163MB
23:26:31     INFO - TEST-OK | browser/components/preferences/in-content/tests/browser_extension_controlled.js | took 102493ms
Mark, in the patch you created i see there are some changes requested. Can you please take a look?
Flags: needinfo?(mstriemer)
Flags: needinfo?(mstriemer)
In the last 7 days there have been 30 occurrences on Windows 10 64 ccov Debug.

Test disabled on win10, 64 bits, ccov debug for frequent failures.

Attachment #9035210 - Flags: review?(jmaher)

Comment on attachment 9035210 [details] [diff] [review]
test disabed on ccov win10 64 debug

Review of attachment 9035210 [details] [diff] [review]:

::: browser/components/preferences/in-content/tests/browser.ini
@@ +54,4 @@

[browser_homepages_filter_aboutpreferences.js]
[browser_homepages_use_bookmark.js]
[browser_extension_controlled.js]
+skip-if = ccov || (os == 'win' && os_version == '10.0' && bits == 64 && debug) # Bug 1437051

this will skip on ccov for linux and osx, I think we only need:
skip-if = ccov && os == 'win'

Attachment #9035210 - Flags: review?(jmaher) → review-

(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #58)

Comment on attachment 9035210 [details] [diff] [review]
test disabed on ccov win10 64 debug

Review of attachment 9035210 [details] [diff] [review]:

::: browser/components/preferences/in-content/tests/browser.ini
@@ +54,4 @@

[browser_homepages_filter_aboutpreferences.js]
[browser_homepages_use_bookmark.js]
[browser_extension_controlled.js]
+skip-if = ccov || (os == 'win' && os_version == '10.0' && bits == 64 && debug) # Bug 1437051

this will skip on ccov for linux and osx, I think we only need:
skip-if = ccov && os == 'win'

Sorry, saw examples in searchfox this way and this fails only on win10, so I assumed this is the correct approach.

Comment on attachment 9035741 [details] [diff] [review]
Disable browser_extension_controlled.js on win ccov for frequent failures

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

thanks
Attachment #9035741 - Flags: review?(jmaher) → review+
Keywords: checkin-needed, leave-open
Whiteboard: [stockwell unknown] → [stockwell disabled]

Pushed by rmaries@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2cf71aa80108
disable browser_extension_controlled.js on win ccov for frequent failures. r=jmaher

Keywords: checkin-needed
Pushed by ccoroiu@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a452f7f04082
Follow-up for disable browser_extension_controlled.js on win ccov DONTBUILD r=me

There are 28 total failures on linux 32 & linux64-cov debug in the last 7 days.

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=241686279&repo=mozilla-central&lineNumber=10337

[task 2019-04-21T11:43:58.666Z] 11:43:58 INFO - TEST-START | browser/components/preferences/in-content/tests/browser_extension_controlled.js
[task 2019-04-21T11:45:57.627Z] 11:45:57 INFO - TEST-UNEXPECTED-FAIL | browser/components/preferences/in-content/tests/browser_extension_controlled.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
[task 2019-04-21T11:45:57.627Z] 11:45:57 INFO - GECKO(3292) | MEMORY STAT | vsize 3821MB | residentFast 918MB | heapAllocated 305MB
[task 2019-04-21T11:45:57.627Z] 11:45:57 INFO - TEST-OK | browser/components/preferences/in-content/tests/browser_extension_controlled.js | took 118417ms
[task 2019-04-21T11:45:57.629Z] 11:45:57 INFO - GECKO(3292) | ++DOCSHELL 0x7f34e07a7800 == 1 [pid = 3374] [id = {8d28e8bb-3204-44fb-bfb1-62c26cfc920b}]
[task 2019-04-21T11:45:57.629Z] 11:45:57 INFO - GECKO(3292) | ++DOMWINDOW == 1 (0x7f34e060dd40) [pid = 3374] [serial = 89] [outer = (nil)]
[task 2019-04-21T11:45:57.629Z] 11:45:57 INFO - GECKO(3292) | ++DOMWINDOW == 2 (0x7f34e0976000) [pid = 3374] [serial = 90] [outer = 0x7f34e060dd40]
[task 2019-04-21T11:45:57.630Z] 11:45:57 INFO - checking window state

Mark, are you still working on this?

Flags: needinfo?(mstriemer)
Flags: needinfo?(mstriemer)
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]
Attachment #9062813 - Attachment is obsolete: true
Whiteboard: [stockwell disabled][stockwell needswork:owner] → [stockwell disabled]
Assignee: mstriemer → nobody
Flags: needinfo?(mstriemer) → needinfo?(tomica)

The following patch is waiting for review from an inactive reviewer:

ID Title Author Reviewer Status
D3453 Bug 1437051 - Reset prefs instead of setting to initial value r?aswan mstriemer aswan: Resigned from review

:mstriemer, could you please find another reviewer or abandon the patch if it is no longer relevant?

For more information, please visit auto_nag documentation.

Flags: needinfo?(mstriemer)
Severity: normal → S3
Attachment #9001444 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: