Closed Bug 1381305 Opened 7 years ago Closed 6 years ago

Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Test timed out -

Categories

(WebExtensions :: Untriaged, defect)

defect
Not set
normal

Tracking

(firefox-esr60 fixed, firefox62 fixed, firefox63 fixed)

RESOLVED FIXED
Tracking Status
firefox-esr60 --- fixed
firefox62 --- fixed
firefox63 --- fixed

People

(Reporter: aryx, Assigned: robwu)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:1454627])

Attachments

(1 file, 1 obsolete file)

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

17:49:12     INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js
17:49:12     INFO - GECKO(14434) | 1500166152639	addons.webextension.{495fc80f-1ebd-1e4a-a034-8231d6f4a948}	WARN	Please specify whether you want browser_style or not in your browser_action options.
17:49:12     INFO - GECKO(14434) | 1500166152649	addons.webextension.{495fc80f-1ebd-1e4a-a034-8231d6f4a948}	WARN	Please specify whether you want browser_style or not in your page_action options.
17:49:57     INFO - TEST-INFO | started process screencapture
17:49:57     INFO - TEST-INFO | screencapture: exit 0
17:49:57     INFO - Buffered messages logged at 17:49:12
17:49:57     INFO - Entering test bound testSources
17:49:57     INFO - Extension loaded
17:49:57     INFO - Console message: Warning: attempting to write 17340 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.
17:49:57     INFO - Console message: 1500166152639	addons.webextension.{495fc80f-1ebd-1e4a-a034-8231d6f4a948}	WARN	Please specify whether you want browser_style or not in your browser_action options.
17:49:57     INFO - Console message: 1500166152649	addons.webextension.{495fc80f-1ebd-1e4a-a034-8231d6f4a948}	WARN	Please specify whether you want browser_style or not in your page_action options.
17:49:57     INFO - Buffered messages finished
17:49:57     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Test timed out - 
17:49:57     INFO - Not taking screenshot here: see the one that was previously logged
17:49:57     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | no tasks awaiting on messages - Got ["request"], expected []
17:49:57     INFO - Stack trace:
17:49:57     INFO -     chrome://mochikit/content/browser-test.js:test_is:967
17:49:57     INFO -     chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:31
17:49:57     INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:390
17:49:57     INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:858:9
17:49:57     INFO -     setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:820:9
17:49:57     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:670:7
17:49:57     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
17:49:57     INFO - Not taking screenshot here: see the one that was previously logged
17:49:57     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Extension left running at test shutdown - 
17:49:57     INFO - Stack trace:
17:49:57     INFO -     chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
17:49:57     INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:390
17:49:57     INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:858:9
17:49:57     INFO -     setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:820:9
17:49:57     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:670:7
17:49:57     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
Priority: -- → P5
Over the last 7 days there are 45 failures present on this bug. Most of these happen on Linux, Linux x64, OS X 10.10, Windows 7, windows10-64.

Here is the most recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=173652778&lineNumber=4169

Here is a relevant part of that log: 

[task 2018-04-14T02:44:51.550Z] 02:44:51     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Test timed out - 
[task 2018-04-14T02:44:51.551Z] 02:44:51     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-04-14T02:44:51.552Z] 02:44:51     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | no tasks awaiting on messages - Got ["request"], expected []
[task 2018-04-14T02:44:51.553Z] 02:44:51     INFO - Stack trace:
[task 2018-04-14T02:44:51.554Z] 02:44:51     INFO -     chrome://mochikit/content/browser-test.js:test_is:1280
[task 2018-04-14T02:44:51.555Z] 02:44:51     INFO -     chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:31
[task 2018-04-14T02:44:51.556Z] 02:44:51     INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:675
[task 2018-04-14T02:44:51.556Z] 02:44:51     INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1171:9
[task 2018-04-14T02:44:51.557Z] 02:44:51     INFO -     setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1133:9
[task 2018-04-14T02:44:51.560Z] 02:44:51     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:967:9
[task 2018-04-14T02:44:51.560Z] 02:44:51     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-04-14T02:44:51.562Z] 02:44:51     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-04-14T02:44:51.563Z] 02:44:51     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Extension left running at test shutdown - 
[task 2018-04-14T02:44:51.564Z] 02:44:51     INFO - Stack trace:
[task 2018-04-14T02:44:51.565Z] 02:44:51     INFO -     chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
[task 2018-04-14T02:44:51.566Z] 02:44:51     INFO -     chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:675
[task 2018-04-14T02:44:51.568Z] 02:44:51     INFO -     timeoutFn@chrome://mochikit/content/browser-test.js:1171:9
[task 2018-04-14T02:44:51.569Z] 02:44:51     INFO -     setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1133:9
[task 2018-04-14T02:44:51.571Z] 02:44:51     INFO -     Tester.prototype.nextTest</<@chrome://mochikit/content/browser-test.js:967:9
[task 2018-04-14T02:44:51.572Z] 02:44:51     INFO -     SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-04-14T02:44:51.573Z] 02:44:51     INFO - Console message: Warning: attempting to write 25970 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 2018-04-14T02:44:51.575Z] 02:44:51     INFO - GECKO(3073) | MEMORY STAT | vsize 3373MB | residentFast 418MB | heapAllocated 126MB
[task 2018-04-14T02:44:51.592Z] 02:44:51     INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | took 45197ms
[task 2018-04-14T02:44:51.595Z] 02:44:51     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-04-14T02:44:51.599Z] 02:44:51     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Found a tab after previous test timed out: about:addons -
Flags: needinfo?(ddurst)
Attached patch bug1381305.patch (obsolete) — Splinter Review
I've created a patch to disable this test on linux because is failing on asan, opt and pgo.
Attachment #8969976 - Flags: review?(gbrown)
Comment on attachment 8969976 [details] [diff] [review]
bug1381305.patch

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

Sorry, but this won't work: There can only be one skip-if per test.

May I suggest:

skip-if = debug || (os == 'linux') # Bug 1381305 - timeout
Attachment #8969976 - Flags: review?(gbrown) → review-
Attachment #8969976 - Attachment is obsolete: true
Attachment #8970466 - Flags: review?(jmaher)
Comment on attachment 8970466 [details] [diff] [review]
Disabled test on linux

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

thanks
Attachment #8970466 - Flags: review?(jmaher) → review+
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Pushed by shindli@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e6e599de11b5
disable browser_ext_user_events.js for frequent failures on Linux. r=jmaher
Keywords: checkin-needed
There are 31 failures in the last 7 days.
Mostly on windows10-64 (28 failures) and 3 on osx-10-10

As I can see, the fail started ~11months ago but with low frequency.
The occurrences started to increase after the below push:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=107214f8a65dac49aa506f5411bf81d9ae6376c2&selectedJob=173005799

Kris, can you please take a look?
Flags: needinfo?(kmaglione+bmo)
Product: Toolkit → WebExtensions
This bug has failed 33 times in the last 7 days, on Windows 7, Windows 10, OSX 10 affecting asan, pgo, opt build types. 
Link to a recent log:https://treeherder.mozilla.org/logviewer.html#?job_id=184302592&repo=autoland&lineNumber=3002
Part of that log:18:02:13     INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js
18:02:58     INFO - TEST-INFO | started process screencapture
18:02:58     INFO - TEST-INFO | screencapture: exit 0
18:02:58     INFO - Buffered messages logged at 18:02:13
18:02:58     INFO - Entering test bound testSources
18:02:58     INFO - Extension loaded
18:02:58     INFO - Console message: Warning: attempting to write 26225 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.
18:02:58     INFO - Console message: Warning: attempting to write 5675 bytes to preference browser.pageActions.persistedActions. 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.
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | addon-webext-permissions notification shown - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | notification panel open - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | request() did not throw when called from page action click - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | request() succeeded when called from page action click - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Expect widget not to be overflowed - 
18:02:58     INFO - Buffered messages logged at 18:02:14
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | addon-webext-permissions notification shown - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | notification panel open - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | request() did not throw when called from browser action click - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | request() succeeded when called from browser action click - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Found context menu item - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | addon-webext-permissions notification shown - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | notification panel open - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | request() did not throw when called from context menu click - 
18:02:58     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | request() succeeded when called from context menu click - 
18:02:58     INFO - Buffered messages finished
18:02:58     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Test timed out - 
18:02:58     INFO - Not taking screenshot here: see the one that was previously logged
18:02:58     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | no tasks awaiting on messages - Got ["request"], expected []
18:02:58     INFO - Stack trace:
18:02:58     INFO - chrome://mochikit/content/browser-test.js:test_is:1300
18:02:58     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:31
18:02:58     INFO - chrome://mochikit/content/browser-test.js:nextTest:699
18:02:58     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1195
18:02:58     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1157
18:02:58     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:991
18:02:58     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
18:02:58     INFO - Not taking screenshot here: see the one that was previously logged
18:02:58     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Extension left running at test shutdown - 
18:02:58     INFO - Stack trace:
18:02:58     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
18:02:58     INFO - chrome://mochikit/content/browser-test.js:nextTest:699
18:02:58     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1195
18:02:58     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1157
18:02:58     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:991
18:02:58     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
18:02:58     INFO - Console message: Warning: attempting to write 26127 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.
18:02:58     INFO - GECKO(921) | MEMORY STAT | vsize 5741MB | residentFast 835MB | heapAllocated 131MB
18:02:58     INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | took 45109ms
18:02:58     INFO - Not taking screenshot here: see the one that was previously logged
18:02:58     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_user_events.js | Found a tab after previous test timed out: about:addons - 
18:02:58     INFO - checking window state
18:02:58     INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_frameId0.js
18:02:59     INFO - GECKO(921) | MEMORY STAT | vsize 5724MB | residentFast 818MB | heapAllocated 133MB
18:02:59     INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_frameId0.js | took 341ms
18:02:59     INFO - checking window state
18:02:59     INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_getFrames.js
18:02:59     INFO - GECKO(921) | MEMORY STAT | vsize 5730MB | residentFast 825MB | heapAllocated 136MB
18:02:59     INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_getFrames.js | took 416ms
18:02:59     INFO - checking window state

ddurst:, maglione do you guys have any updates on this bug?
We have 30 failures in the last 7 days.
For the failure pattern see Comment 21
:ddurst, can you please take a look into this?
Sorry, please see comment 42 for failure pattern
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]
I found a cause and will fix this in bug 1454627 (because in that bug I add a new test that extends this test file).
Assignee: nobody → rob
Status: NEW → ASSIGNED
Depends on: 1454627
Flags: needinfo?(kmaglione+bmo)
Flags: needinfo?(ddurst)
This failure has not occurred since the patches for bug 1454627 landed. The only failure that coincides with the date happened on the beta tree, where the patches were not included.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Keywords: leave-open
Resolution: --- → FIXED
Whiteboard: [stockwell disabled][stockwell needswork:owner] → [stockwell disabled]

I'm updating the whiteboard field, as this test has been re-enabled since https://hg.mozilla.org/mozilla-central/rev/64e2944b635b (part of Bug 1454627), and it doesn't seem that any new intermittent failures have been collected for this bugzilla issue in the last few months.

Whiteboard: [stockwell disabled] → [stockwell fixed:1454627]
You need to log in before you can comment on or make changes to this bug.