Closed Bug 1548111 Opened 6 years ago Closed 5 years ago

Intermittent browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Test timed out -

Categories

(Firefox :: Address Bar, defect, P5)

Product:
Firefox
Component:
Address Bar
Type:
defect
Points:
3

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 69
Iteration:
69.4 - Jun 24 - Jul 7
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- fixed
firefox68 --- wontfix
firefox69 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: adw)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file, 1 obsolete file)

Bug 1548111 - Fix intermittent failure in browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js by ignoring spurious resize events.
47 bytes, text/x-phabricator-request
RyanVM
: approval-mozilla-esr68+
Details | Review

Filed by: dvarga [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=243711004&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/DaDCwHh6QMOpJqoeRUBCog/runs/0/artifacts/public/logs/live_backing.log

18:57:41     INFO - Running step 6 - check swapBrowsersAndCloseOther preserves registered switch-to-tab result
18:57:41     INFO - Searching open pages.
18:57:41     INFO - Console message: [JavaScript Error: "Given tab is not restoring." {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 5130}]
18:57:41     INFO - _resetLocalTabRestoringState@resource:///modules/sessionstore/SessionStore.jsm:5130:10
18:57:41     INFO - receiveMessage@resource:///modules/sessionstore/SessionStore.jsm:989:30
18:57:41     INFO - MessageListener.receiveMessage*onLoad/<@resource:///modules/sessionstore/SessionStore.jsm:1103:10
18:57:41     INFO - onLoad@resource:///modules/sessionstore/SessionStore.jsm:1101:14
18:57:41     INFO - onBeforeBrowserWindowShown@resource:///modules/sessionstore/SessionStore.jsm:1282:10
18:57:41     INFO - ssi_observe@resource:///modules/sessionstore/SessionStore.jsm:770:14
18:57:41     INFO - onLoad@chrome://browser/content/browser.js:1513:18
18:57:41     INFO - EventHandlerNonNull*@chrome://browser/content/browser.xul:104:39
18:57:41     INFO - 
18:57:41     INFO - Buffered messages logged at 18:56:56
18:57:41     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
18:57:41     INFO - Buffered messages finished
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Test timed out - 
18:57:41     INFO - GECKO(1059) | MEMORY STAT | vsize 5659MB | residentFast 483MB | heapAllocated 132MB
18:57:41     INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | took 90078ms
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: about:mozilla - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: data:text/html,<body><iframe src=""></iframe></body> - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 - 
18:57:41     INFO - Not taking screenshot here: see the one that was previously logged
18:57:41     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 - 
18:57:41     INFO - checking window state
18:57:41     INFO - TEST-START | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar_perwindowpb.js
18:58:26     INFO - Not taking screenshot here: see the one that was previously logged
18:58:26     INFO - Buffered messages logged at 18:57:41
18:58:26     INFO - Entering test bound 
18:58:26     INFO - Console message: OpenGL compositor Initialized Succesfully.
18:58:26     INFO - Version: 2.1 INTEL-10.6.33

Getting that

 Given tab is not restoring. SessionStore.jsm:5174
    _resetLocalTabRestoringState resource:///modules/sessionstore/SessionStore.jsm:5174
    receiveMessage resource:///modules/sessionstore/SessionStore.jsm:1027

in firefox-hg r476702+.c909c105f914+-1

(In reply to howaboutsynergy from comment #3)

Getting that

 Given tab is not restoring. SessionStore.jsm:5174
    _resetLocalTabRestoringState resource:///modules/sessionstore/SessionStore.jsm:5174
    receiveMessage resource:///modules/sessionstore/SessionStore.jsm:1027

If you're seeing this outside of running the test that's failing here, please file a new bug under Firefox/Session Restore and provide actual details on what you're doing when you see it. Be prepared to also provide some profile information.

Cool, thanks!

Be prepared to also provide some profile information.

What is profile information though? as in profiler, or something else ?

See Also: → 1552410

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

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

9:42:36 INFO - TEST-START | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js
19:44:07 INFO - TEST-INFO | started process screenshot
19:44:07 INFO - TEST-INFO | screenshot: exit 0
19:44:07 INFO - <snipped 18 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
19:44:07 INFO - Buffered messages logged at 19:42:37
19:44:07 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch6 was found in autocomplete, was expected - true == true -
19:44:07 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have a tab switch result - 1 == 1 -

19:44:07 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 was found in autocomplete, was expected - true == true -
19:44:07 INFO - Leaving test bound step_5
19:44:07 INFO - Entering test bound step_6
19:44:07 INFO - Running step 6 - check swapBrowsersAndCloseOther preserves registered switch-to-tab result
19:44:07 INFO - Searching open pages.
19:44:07 INFO - Console message: [JavaScript Error: "Given tab is not restoring." {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 5182}]
19:44:07 INFO - _resetLocalTabRestoringState@resource:///modules/sessionstore/SessionStore.jsm:5182:10
19:44:07 INFO - receiveMessage@resource:///modules/sessionstore/SessionStore.jsm:1035:30
19:44:07 INFO - MessageListener.receiveMessageonLoad/<@resource:///modules/sessionstore/SessionStore.jsm:1151:10
19:44:07 INFO - onLoad@resource:///modules/sessionstore/SessionStore.jsm:1149:14
19:44:07 INFO - onBeforeBrowserWindowShown@resource:///modules/sessionstore/SessionStore.jsm:1330:10
19:44:07 INFO - ssi_observe@resource:///modules/sessionstore/SessionStore.jsm:799:14
19:44:07 INFO - onLoad@chrome://browser/content/browser.js:1543:18
19:44:07 INFO - EventHandlerNonNull@chrome://browser/content/browser.xhtml:112:39
19:44:07 INFO -
19:44:07 INFO - Buffered messages logged at 19:43:22
19:44:07 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
19:44:07 INFO - Buffered messages finished
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Test timed out -
19:44:07 INFO - GECKO(4144) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 110: uncaught exception: Object
19:44:07 INFO - GECKO(4144) | MEMORY STAT | vsize 797MB | vsizeMaxContiguous 685MB | residentFast 224MB | heapAllocated 87MB
19:44:07 INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | took 90285ms
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: about:mozilla -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: data:text/html,<body><iframe src=""></iframe></body> -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
19:44:07 INFO - Not taking screenshot here: see the one that was previously logged
19:44:07 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
19:44:07 INFO - checking window state
19:44:07 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 110}]

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

There are 19 total failures in the last 3 days on macosx1014-64, macosx1014-64- shippable, windows10-64-shippable, windows7-32-shippable

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

12:29:16 INFO - TEST-START | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js
12:30:47 INFO - TEST-INFO | started process screencapture
12:30:47 INFO - TEST-INFO | screencapture: exit 0
12:30:47 INFO - <snipped 17 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
12:30:47 INFO - Buffered messages logged at 12:29:17
12:30:47 INFO - Search for https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch8 in open tabs.
12:30:47 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch8 was found in autocomplete, was expected - true == true -
12:30:47 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Should have a tab switch result - 1 == 1 -

12:30:47 INFO - TEST-PASS | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 was found in autocomplete, was expected - true == true -
12:30:47 INFO - Leaving test bound step_5
12:30:47 INFO - Entering test bound step_6
12:30:47 INFO - Running step 6 - check swapBrowsersAndCloseOther preserves registered switch-to-tab result
12:30:47 INFO - Searching open pages.
12:30:47 INFO - Console message: [JavaScript Error: "Given tab is not restoring." {file: "resource:///modules/sessionstore/SessionStore.jsm" line: 5182}]
12:30:47 INFO - _resetLocalTabRestoringState@resource:///modules/sessionstore/SessionStore.jsm:5182:10
12:30:47 INFO - receiveMessage@resource:///modules/sessionstore/SessionStore.jsm:1035:30
12:30:47 INFO - MessageListener.receiveMessageonLoad/<@resource:///modules/sessionstore/SessionStore.jsm:1151:10
12:30:47 INFO - onLoad@resource:///modules/sessionstore/SessionStore.jsm:1149:14
12:30:47 INFO - onBeforeBrowserWindowShown@resource:///modules/sessionstore/SessionStore.jsm:1330:10
12:30:47 INFO - ssi_observe@resource:///modules/sessionstore/SessionStore.jsm:799:14
12:30:47 INFO - onLoad@chrome://browser/content/browser.js:1543:18
12:30:47 INFO - EventHandlerNonNull@chrome://browser/content/browser.xhtml:114:39
12:30:47 INFO -
12:30:47 INFO - Buffered messages logged at 12:30:02
12:30:47 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
12:30:47 INFO - Buffered messages finished
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Test timed out -
12:30:47 INFO - GECKO(2766) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 110: uncaught exception: Object
12:30:47 INFO - GECKO(2766) | MEMORY STAT | vsize 7637MB | residentFast 362MB | heapAllocated 96MB
12:30:47 INFO - TEST-OK | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | took 90313ms
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: about:mozilla -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: data:text/html,<body><iframe src=""></iframe></body> -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
12:30:47 INFO - Not taking screenshot here: see the one that was previously logged
12:30:47 INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js | Found a tab after previous test timed out: https://example.com/browser/browser/components/urlbar/tests/browser/dummy_page.html#tabmatch16 -
12:30:47 INFO - checking window state
12:30:47 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 110}]

Drew can you take a look? this showed up when bug 1552410landed

Flags: needinfo?(adw)
Regressed by: 1552410
Assignee: nobody → adw
Status: REOPENED → ASSIGNED
Flags: needinfo?(adw)

It looks like the same resize problem from bug 1552410 comment 12.

Iteration: --- → 69.4 - Jun 24 - Jul 7
Points: --- → 3
Blocks: 1562416

Different approach, bail out of _on_resize if the window width didn't actually change:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=442628a48a649ade02b2ab1e58b1fc5bf5653306

Pushed by mak77@bonardo.net: https://hg.mozilla.org/integration/autoland/rev/89a995281a36 Fix intermittent failure in browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js by ignoring spurious resize events. r=mak
Attachment #9075469 - Attachment is obsolete: true

https://hg.mozilla.org/mozilla-central/rev/89a995281a36

Status: ASSIGNED → RESOLVED
Closed: 5 years ago → 5 years ago
status-firefox69: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 69

Please nominate this for ESR68 approval if you feel it's safe to do so.

status-firefox68: --- → wontfix
status-firefox-esr60: --- → unaffected
status-firefox-esr68: --- → affected
Flags: needinfo?(adw)

Comment on attachment 9075870 [details]
Bug 1548111 - Fix intermittent failure in browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js by ignoring spurious resize events.

ESR Uplift Approval Request

  • If this is not a sec:{high,crit} bug, please state case for ESR consideration: Fixes an intermittent test
  • User impact if declined: Basically no user impact if declined. The patch is designed to fix a failing test. It's unlikely that many users would actually hit the conditions caused by the test. Even if they did, the only thing that would happen is that their urlbar popup would close unexpectedly.
  • Fix Landed on Version: 69
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): Small patch, little to no effect on actual users.
  • String or UUID changes made by this patch: None
Flags: needinfo?(adw)
Attachment #9075870 - Flags: approval-mozilla-esr68?

Comment on attachment 9075870 [details]
Bug 1548111 - Fix intermittent failure in browser/components/urlbar/tests/browser/browser_tabMatchesInAwesomebar.js by ignoring spurious resize events.

Small reliability improvement for CI. Approved for 68.1esr.

Attachment #9075870 - Flags: approval-mozilla-esr68? → approval-mozilla-esr68+
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: