1348639 - Intermittent browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.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

Status: RESOLVED FIXED

(WebExtensions :: Untriaged, defect)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

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

[task 2017-03-18T22:11:13.094788Z] 22:11:13     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.js | test result correct - 
[task 2017-03-18T22:11:13.100754Z] 22:11:13     INFO - Buffered messages logged at 22:11:02
[task 2017-03-18T22:11:13.105361Z] 22:11:13     INFO - Console message: Warning: attempting to write 4322 bytes to preference extensions.bootstrappedAddons. 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.
[task 2017-03-18T22:11:13.114373Z] 22:11:13     INFO - Console message: Warning: attempting to write 6081 bytes to preference extensions.webextensions.uuids. 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.
[task 2017-03-18T22:11:13.117958Z] 22:11:13     INFO - Leaving test bound test_options_with_browser_style_set_to_false
[task 2017-03-18T22:11:13.136785Z] 22:11:13     INFO - Console message: [JavaScript Error: "Called getURLForExtension on unmapped extension 4e772a5e9da395b748c4c65bac3a6c6f7c243d73@temporary-addon" {file: "resource://gre/modules/ExtensionManagement.jsm" line: 125}]
[task 2017-03-18T22:11:13.139915Z] 22:11:13     INFO - getURLForExtension@resource://gre/modules/ExtensionManagement.jsm:125:5
[task 2017-03-18T22:11:13.142241Z] 22:11:13     INFO - get optionsURL@resource://gre/modules/addons/XPIProvider.jsm:7296:20
[task 2017-03-18T22:11:13.144363Z] 22:11:13     INFO - get optionsType@resource://gre/modules/addons/XPIProvider.jsm:7317:26
[task 2017-03-18T22:11:13.146438Z] 22:11:13     INFO - hasInlineOptions@chrome://mozapps/content/extensions/extensions.js:1614:3
[task 2017-03-18T22:11:13.148152Z] 22:11:13     INFO - hide@chrome://mozapps/content/extensions/extensions.js:3310:11
[task 2017-03-18T22:11:13.150600Z] 22:11:13     INFO - shutdown@chrome://mozapps/content/extensions/extensions.js:786:7
[task 2017-03-18T22:11:13.152661Z] 22:11:13     INFO - shutdown@chrome://mozapps/content/extensions/extensions.js:285:3
[task 2017-03-18T22:11:13.157138Z] 22:11:13     INFO - _endRemoveTab@chrome://browser/content/tabbrowser.xml:2842:13
[task 2017-03-18T22:11:13.162663Z] 22:11:13     INFO - removeTab@chrome://browser/content/tabbrowser.xml:2593:15
[task 2017-03-18T22:11:13.165364Z] 22:11:13     INFO - removeTab/<@resource://testing-common/BrowserTestUtils.jsm:839:9
[task 2017-03-18T22:11:13.167974Z] 22:11:13     INFO - removeTab@resource://testing-common/BrowserTestUtils.jsm:829:12
[task 2017-03-18T22:11:13.171545Z] 22:11:13     INFO - testOptionsBrowserStyle@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.js:57:9
[task 2017-03-18T22:11:13.177308Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-18T22:11:13.180088Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.183828Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.186503Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.189012Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.191787Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.194721Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.198492Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.201141Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.203873Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.207965Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.210287Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.212839Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.217138Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.220122Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.221975Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.224286Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.226923Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.229368Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.231723Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.236417Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.239699Z] 22:11:13     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-18T22:11:13.245420Z] 22:11:13     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-18T22:11:13.252470Z] 22:11:13     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-18T22:11:13.255639Z] 22:11:13     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-18T22:11:13.259923Z] 22:11:13     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-18T22:11:13.262952Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:324:15
[task 2017-03-18T22:11:13.266509Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.269656Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.272696Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.277137Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.283836Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.287085Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.291100Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.294425Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.300100Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.303167Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.307371Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.311857Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.318183Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.323300Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.326366Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.329485Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.333879Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.338147Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.344997Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.349425Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.355044Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.358718Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.362595Z] 22:11:13     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-18T22:11:13.368182Z] 22:11:13     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-18T22:11:13.374341Z] 22:11:13     INFO - 
[task 2017-03-18T22:11:13.379088Z] 22:11:13     INFO - Console message: [JavaScript Error: "Called getURLForExtension on unmapped extension 4e772a5e9da395b748c4c65bac3a6c6f7c243d73@temporary-addon" {file: "resource://gre/modules/ExtensionManagement.jsm" line: 125}]
[task 2017-03-18T22:11:13.383809Z] 22:11:13     INFO - getURLForExtension@resource://gre/modules/ExtensionManagement.jsm:125:5
[task 2017-03-18T22:11:13.387954Z] 22:11:13     INFO - get optionsURL@resource://gre/modules/addons/XPIProvider.jsm:7296:20
[task 2017-03-18T22:11:13.392355Z] 22:11:13     INFO - get optionsType@resource://gre/modules/addons/XPIProvider.jsm:7317:26
[task 2017-03-18T22:11:13.395127Z] 22:11:13     INFO - hasInlineOptions@chrome://mozapps/content/extensions/extensions.js:1615:1
[task 2017-03-18T22:11:13.397596Z] 22:11:13     INFO - hide@chrome://mozapps/content/extensions/extensions.js:3310:11
[task 2017-03-18T22:11:13.402740Z] 22:11:13     INFO - shutdown@chrome://mozapps/content/extensions/extensions.js:786:7
[task 2017-03-18T22:11:13.405330Z] 22:11:13     INFO - shutdown@chrome://mozapps/content/extensions/extensions.js:285:3
[task 2017-03-18T22:11:13.408094Z] 22:11:13     INFO - _endRemoveTab@chrome://browser/content/tabbrowser.xml:2842:13
[task 2017-03-18T22:11:13.410766Z] 22:11:13     INFO - removeTab@chrome://browser/content/tabbrowser.xml:2593:15
[task 2017-03-18T22:11:13.413512Z] 22:11:13     INFO - removeTab/<@resource://testing-common/BrowserTestUtils.jsm:839:9
[task 2017-03-18T22:11:13.417951Z] 22:11:13     INFO - removeTab@resource://testing-common/BrowserTestUtils.jsm:829:12
[task 2017-03-18T22:11:13.422395Z] 22:11:13     INFO - testOptionsBrowserStyle@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.js:57:9
[task 2017-03-18T22:11:13.431545Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-18T22:11:13.439564Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.447290Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.454789Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.462997Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.468755Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.474177Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.480527Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.486194Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.492793Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.495881Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.499164Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.502370Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.505604Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.513677Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.516908Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.522687Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.527581Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.530847Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.533869Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.538091Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.542863Z] 22:11:13     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-18T22:11:13.546325Z] 22:11:13     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-18T22:11:13.550232Z] 22:11:13     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-18T22:11:13.554674Z] 22:11:13     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-18T22:11:13.560879Z] 22:11:13     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-18T22:11:13.563760Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:324:15
[task 2017-03-18T22:11:13.566911Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.570239Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.572666Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.578520Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.581721Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.585091Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.588124Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.592922Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.597752Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.602284Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.605431Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.608612Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.614747Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.623126Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.631416Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.639285Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.648536Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.652276Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.658059Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.664648Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.669986Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.677437Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.681292Z] 22:11:13     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-18T22:11:13.688641Z] 22:11:13     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-18T22:11:13.691937Z] 22:11:13     INFO - 
[task 2017-03-18T22:11:13.698086Z] 22:11:13     INFO - Console message: [JavaScript Error: "Called getURLForExtension on unmapped extension 4e772a5e9da395b748c4c65bac3a6c6f7c243d73@temporary-addon" {file: "resource://gre/modules/ExtensionManagement.jsm" line: 125}]
[task 2017-03-18T22:11:13.701624Z] 22:11:13     INFO - getURLForExtension@resource://gre/modules/ExtensionManagement.jsm:125:5
[task 2017-03-18T22:11:13.705214Z] 22:11:13     INFO - get optionsURL@resource://gre/modules/addons/XPIProvider.jsm:7296:20
[task 2017-03-18T22:11:13.710097Z] 22:11:13     INFO - get optionsType@resource://gre/modules/addons/XPIProvider.jsm:7317:26
[task 2017-03-18T22:11:13.713365Z] 22:11:13     INFO - hasInlineOptions@chrome://mozapps/content/extensions/extensions.js:1616:1
[task 2017-03-18T22:11:13.716646Z] 22:11:13     INFO - hide@chrome://mozapps/content/extensions/extensions.js:3310:11
[task 2017-03-18T22:11:13.721766Z] 22:11:13     INFO - shutdown@chrome://mozapps/content/extensions/extensions.js:786:7
[task 2017-03-18T22:11:13.726149Z] 22:11:13     INFO - shutdown@chrome://mozapps/content/extensions/extensions.js:285:3
[task 2017-03-18T22:11:13.729376Z] 22:11:13     INFO - _endRemoveTab@chrome://browser/content/tabbrowser.xml:2842:13
[task 2017-03-18T22:11:13.735209Z] 22:11:13     INFO - removeTab@chrome://browser/content/tabbrowser.xml:2593:15
[task 2017-03-18T22:11:13.737786Z] 22:11:13     INFO - removeTab/<@resource://testing-common/BrowserTestUtils.jsm:839:9
[task 2017-03-18T22:11:13.740668Z] 22:11:13     INFO - removeTab@resource://testing-common/BrowserTestUtils.jsm:829:12
[task 2017-03-18T22:11:13.744648Z] 22:11:13     INFO - testOptionsBrowserStyle@chrome://mochitests/content/browser/browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.js:57:9
[task 2017-03-18T22:11:13.749322Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-03-18T22:11:13.753694Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.755951Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.758322Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.762576Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.764922Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.767296Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.770689Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.774349Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.777165Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.779591Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.783715Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.786112Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.789795Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.792188Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.794641Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.800074Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.808393Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.818347Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.821954Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.826744Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.834707Z] 22:11:13     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-18T22:11:13.842361Z] 22:11:13     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-18T22:11:13.847579Z] 22:11:13     INFO - Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
[task 2017-03-18T22:11:13.850911Z] 22:11:13     INFO - schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
[task 2017-03-18T22:11:13.855716Z] 22:11:13     INFO - completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:707:7
[task 2017-03-18T22:11:13.862666Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:324:15
[task 2017-03-18T22:11:13.866533Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.870608Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.875460Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.878316Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.882057Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.886571Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.892567Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.895841Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.901153Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.904469Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.907648Z] 22:11:13     INFO - promise callback*TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:396:7
[task 2017-03-18T22:11:13.910619Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.914100Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.916893Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.921367Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.924242Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.926594Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.929029Z] 22:11:13     INFO - TaskImpl@resource://gre/modules/Task.jsm:277:3
[task 2017-03-18T22:11:13.931448Z] 22:11:13     INFO - asyncFunction@resource://gre/modules/Task.jsm:252:14
[task 2017-03-18T22:11:13.934688Z] 22:11:13     INFO - Task_spawn@resource://gre/modules/Task.jsm:166:12
[task 2017-03-18T22:11:13.937291Z] 22:11:13     INFO - TaskImpl_handleResultValue@resource://gre/modules/Task.jsm:389:16
[task 2017-03-18T22:11:13.940358Z] 22:11:13     INFO - TaskImpl_run@resource://gre/modules/Task.jsm:327:15
[task 2017-03-18T22:11:13.943027Z] 22:11:13     INFO - process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
[task 2017-03-18T22:11:13.946112Z] 22:11:13     INFO - walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
[task 2017-03-18T22:11:13.948949Z] 22:11:13     INFO - 
[task 2017-03-18T22:11:13.952977Z] 22:11:13     INFO - Buffered messages finished
[task 2017-03-18T22:11:13.956076Z] 22:11:13     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.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. - 

Followed by many more extension tests timing out.

Comment 1

[Shane Caraveo (:mixedpuppy)]

A month without further intermittent reports attached after the first, closing.

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Hit again: https://treeherder.mozilla.org/logviewer.html#?job_id=95421145&repo=mozilla-inbound
Please close bugs which lack recent occurrences with WORKSFORME, not INVALID.

Comment 3

[Intermittent Failures Robot]

14 failures in 770 pushes (0.018 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 10
* mozilla-central: 2
* autoland: 2

Platform breakdown:
* linux32: 14

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1348639&startday=2017-05-01&endday=2017-05-07&tree=all

Comment 4

[Intermittent Failures Robot]

14 failures in 777 pushes (0.018 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 6
* autoland: 5
* mozilla-central: 3

Platform breakdown:
* linux32: 14

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

Comment 5

[Intermittent Failures Robot]

21 failures in 157 pushes (0.134 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* mozilla-inbound: 7
* autoland: 6
* mozilla-central: 3
* try: 2
* graphics: 2
* oak: 1

Platform breakdown:
* linux32: 21

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

Comment 6

[Geoff Brown [:gbrown] (pto Mar 24)]

Test durations for browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.js on mozilla-central,mozilla-inbound,autoland between 2017-05-19 and 2017-05-26
linux32-nightly/opt-chunked:     6.05 s (4.44 s - 8.15 s over 13 runs)
linux32-nightly/opt-e10s:        6.99 s (5.48 s - 8.15 s over 6 runs)
linux32/debug-chunked:          74.26 s (44.46 s - 93.86 s over 325 runs)
linux32/debug-e10s:             81.76 s (71.79 s - 93.86 s over 158 runs)
linux32/opt-chunked:             7.14 s (4.84 s - 15.20 s over 611 runs)
linux32/opt-e10s:                7.96 s (6.37 s - 15.20 s over 304 runs)
linux64-ccov/opt-chunked:       30.68 s (27.16 s - 37.15 s over 6 runs)
linux64-ccov/opt-e10s:          28.74 s (28.74 s - 28.74 s over 1 runs)
linux64-jsdcov/opt:             10.71 s (10.11 s - 11.24 s over 5 runs)
linux64-nightly/opt-chunked:     6.31 s (4.36 s - 10.08 s over 11 runs)
linux64-nightly/opt-e10s:        7.07 s (5.31 s - 10.08 s over 6 runs)
linux64/asan-chunked:           16.32 s (9.84 s - 28.04 s over 352 runs)
linux64/asan-e10s:              18.16 s (14.24 s - 28.04 s over 179 runs)
linux64/debug-chunked:          47.16 s (31.30 s - 69.04 s over 691 runs)
linux64/debug-e10s:             53.43 s (40.50 s - 69.04 s over 178 runs)
linux64/opt-chunked:             6.57 s (4.22 s - 13.46 s over 518 runs)
linux64/opt-e10s:                7.68 s (5.53 s - 11.37 s over 175 runs)
linux64/pgo-chunked:             5.87 s (3.63 s - 11.85 s over 536 runs)
linux64/pgo-e10s:                7.18 s (5.22 s - 11.85 s over 180 runs)
macosx64/debug-e10s:            18.61 s (8.65 s - 45.99 s over 516 runs)
macosx64/opt-e10s:               4.42 s (2.87 s - 6.21 s over 511 runs)
macosx64/opt:                    2.73 s (2.03 s - 4.71 s over 524 runs)
win32/debug-e10s:               15.97 s (10.65 s - 21.03 s over 177 runs)
win32/debug:                    13.35 s (9.90 s - 17.71 s over 189 runs)
win32/opt-e10s:                  4.76 s (3.56 s - 6.79 s over 326 runs)
win32/opt:                       3.70 s (3.06 s - 5.13 s over 202 runs)
win32/pgo-e10s:                  3.71 s (3.14 s - 5.57 s over 116 runs)
win32/pgo:                       3.27 s (2.76 s - 4.46 s over 112 runs)
win64/debug-e10s:               15.48 s (9.95 s - 20.92 s over 181 runs)
win64/debug:                    12.13 s (8.77 s - 16.70 s over 178 runs)
win64/opt-e10s:                  4.76 s (3.84 s - 13.74 s over 183 runs)
win64/opt:                       4.03 s (3.34 s - 8.41 s over 188 runs)
win64/pgo-e10s:                  4.16 s (3.46 s - 8.50 s over 108 runs)
win64/pgo:                       3.61 s (2.93 s - 12.89 s over 110 runs)

Comment 7

[Geoff Brown [:gbrown] (pto Mar 24)]

Attachment: requestLongerTimeout

This test is intermittently running for longer than 90 seconds on linux32-debug. Let's increase the timeout for a quick fix.

Comment 8

[Matthew Wein [:mattw]]

Comment on attachment 8871810 [details] [diff] [review]
requestLongerTimeout

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

Sounds good to me. Could you also move extension.unload() before BrowserTestUtils.removeTab(tab) to get rid of the "Called getURLForExtension on unmapped extension" error? I'm not sure if that will fix the intermittent, but it would be nice to fix that error either way.

+mixedpuppy as additional reviewer for stamp of approval.

Comment 9

[Geoff Brown [:gbrown] (pto Mar 24)]

(In reply to Matthew Wein [:mattw] from comment #8)
> Could you also move extension.unload() before
> BrowserTestUtils.removeTab(tab) to get rid of the "Called getURLForExtension
> on unmapped extension" error? I'm not sure if that will fix the
> intermittent, but it would be nice to fix that error either way.

It's already in that order:

https://hg.mozilla.org/mozilla-central/file/f7adbf457ee20eeffde72694e0d17d73616e3cfd/browser/components/extensions/test/browser/browser_ext_optionsPage_browser_style.js#l55

Should it be 

  await BrowserTestUtils.removeTab(tab);

  await extension.unload();

?

Comment 10

[Matthew Wein [:mattw]]

(In reply to Geoff Brown [:gbrown] from comment #9)
> (In reply to Matthew Wein [:mattw] from comment #8)
> > Could you also move extension.unload() before
> > BrowserTestUtils.removeTab(tab) to get rid of the "Called getURLForExtension
> > on unmapped extension" error? I'm not sure if that will fix the
> > intermittent, but it would be nice to fix that error either way.
> 
> It's already in that order:
> 
> https://hg.mozilla.org/mozilla-central/file/
> f7adbf457ee20eeffde72694e0d17d73616e3cfd/browser/components/extensions/test/
> browser/browser_ext_optionsPage_browser_style.js#l55
> 
> Should it be 
> 
>   await BrowserTestUtils.removeTab(tab);
> 
>   await extension.unload();
> 
> ?

Yes, sorry, I got that backwards.

Comment 11

[Intermittent Failures Robot]

46 failures in 891 pushes (0.052 failures/push) were associated with this bug in the last 7 days. 

This is the #29 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: 14
* mozilla-inbound: 13
* mozilla-central: 9
* try: 6
* graphics: 3
* oak: 1

Platform breakdown:
* linux32: 44
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1348639&startday=2017-05-22&endday=2017-05-28&tree=all

Comment 12

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

gbrown, I see you uploaded a patch which has r+, should we land this?

Comment 13

[Geoff Brown [:gbrown] (pto Mar 24)]

Thanks for the reminder!

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3eccf32d5a83
requestLongerTimeout for test browser_ext_optionsPage_browser_style.js; r=mattw,mixedpuppy

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/3eccf32d5a83

Comment 16

[Intermittent Failures Robot]

14 failures in 820 pushes (0.017 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 4
* autoland: 4
* mozilla-central: 3
* graphics: 2
* try: 1

Platform breakdown:
* linux32: 14

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