Closed Bug 1385882 Opened 8 years ago Closed 5 years ago

Intermittent browser/base/content/test/pageActions/browser_page_action_menu.js | Test timed out - | Found a tab after previous test timed out: http://example.com/browser_page_action_menu -

Categories

(Firefox :: Toolbars and Customization, defect, P5)

Product:
Firefox
Component:
Toolbars and Customization
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 58
Tracking Flags:
Tracking Status
firefox57 --- fixed
firefox58 --- fixed
firefox77 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

Attachments

(2 files)

Bug 1385882 - Intermittent browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out.
59 bytes, text/x-review-board-request
Gijs
: review+
Details
Bug 1519226 - Wait for the bookmarked status to finish updating before starting test; r?Gijs
47 bytes, text/x-phabricator-request
Details | Review
Filed by: archaeopteryx [at] coole-files.de https://treeherder.mozilla.org/logviewer.html#?job_id=119549158&repo=autoland https://queue.taskcluster.net/v1/task/Xk5fR_LVQ_iRTCUtdEKR-g/runs/0/artifacts/public/test_info//browser-chrome-chunked_errorsummary.log [task 2017-07-31T12:13:03.697902Z] 12:13:03 INFO - TEST-START | browser/base/content/test/urlbar/browser_page_action_menu.js [task 2017-07-31T12:13:48.964915Z] 12:13:48 INFO - TEST-INFO | started process screentopng [task 2017-07-31T12:13:50.063984Z] 12:13:50 INFO - TEST-INFO | screentopng: exit 0 [task 2017-07-31T12:13:50.066655Z] 12:13:50 INFO - Buffered messages logged at 12:13:03 [task 2017-07-31T12:13:50.068685Z] 12:13:50 INFO - Global property added while loading resource://testing-common/sinon-2.3.2.js: sinon [task 2017-07-31T12:13:50.070677Z] 12:13:50 INFO - Entering test bound bookmark [task 2017-07-31T12:13:50.074310Z] 12:13:50 INFO - Buffered messages logged at 12:13:04 [task 2017-07-31T12:13:50.076480Z] 12:13:50 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_page_action_menu.js | "Bookmark This Page" == "Bookmark This Page" - [task 2017-07-31T12:13:50.082861Z] 12:13:50 INFO - TEST-PASS | browser/base/content/test/urlbar/browser_page_action_menu.js | true == true - [task 2017-07-31T12:13:50.086203Z] 12:13:50 INFO - Buffered messages finished [task 2017-07-31T12:13:50.088712Z] 12:13:50 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out - [task 2017-07-31T12:13:50.095014Z] 12:13:50 INFO - GECKO(1511) | MEMORY STAT | vsize 2282MB | residentFast 291MB | heapAllocated 132MB [task 2017-07-31T12:13:50.097304Z] 12:13:50 INFO - TEST-OK | browser/base/content/test/urlbar/browser_page_action_menu.js | took 45300ms [task 2017-07-31T12:13:50.101759Z] 12:13:50 INFO - Not taking screenshot here: see the one that was previously logged [task 2017-07-31T12:13:50.105329Z] 12:13:50 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/urlbar/browser_page_action_menu.js | Found a tab after previous test timed out: http://example.com/browser_page_action_menu - [task 2017-07-31T12:13:50.107297Z] 12:13:50 INFO - checking window state
with ::mak on holiday, let me see if :sfoster might have an idea of who would work on location bar and help get this resolved. So far we have 50+ failures annotated for this
Flags: needinfo?(sfoster)
Whiteboard: [stockwell needswork]
See Also: → 1384464
This started around when the test was updated by bug 1374477, so let's check in with :adw instead.
Blocks: 1374477
Flags: needinfo?(sfoster) → needinfo?(adw)
This looks basically the same as bug 1384464: both are timeouts. But I don't know why they're logged differently. Can we mark one as a duplicate of the other?
Flags: needinfo?(adw)
Marking one as a dup wouldn't be terrible, but it might cause some confusion and/or additional work for sheriffs: The next time the test fails with the message for the dup'd bug, that bug may be reopened, or a new bug filed to report the failure against.
Whiteboard: [stockwell needswork] → [stockwell unknown]
Bug 1384464 is fixed, so this might be fixed too, but looking at the logs here again, I think maybe this is timing out in a different way from bug 1384464. It's timing out near the start of the test, after it's checked the bookmark menu item's label and starred state, which means it's timing out clicking the bookmark menu item, waiting for the edit-bookmark panel to open, or waiting for the page action menu to open. Out of those three possibilities, I'd guess that the first is most likely since it's similar to the reason bug 1384464 timed out. If that's the case, then promisePageActionPanelOpen should wait until at least one of its children has non-zero bounds, the way that promisePageActionViewShown now does, or it should do something else similar to make sure that children are visible and clickable.
I'll try what comment 12 says.
Assignee: nobody → adw
Status: NEW → ASSIGNED
There were no failures on multiple runs on try, so I'll ask for review on this. I did hit bug 1396263 though. I'll fix that too.
Attachment #8914444 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8914444 [details] Bug 1385882 - Intermittent browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out. https://reviewboard.mozilla.org/r/185760/#review190994 LGTM, thanks for figuring this out!
Attachment #8914444 - Flags: review?(gijskruitbosch+bugs) → review+
Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/01b425a64b97 Intermittent browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out. r=Gijs
https://hg.mozilla.org/mozilla-central/rev/01b425a64b97
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox58: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 58
Hi Drew, there are at least 2 occurrences after this got merged to central. Can you take a look, please? https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1385882
Flags: needinfo?(adw)
Looks like there are two kinds of failures. (1) https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=134917460&lineNumber=2546 https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=134821116&lineNumber=2369 The last things logged: > INFO - promisePageActionViewChildrenVisible waiting for a child node to be visible > INFO - TEST-PASS | browser/base/content/test/urlbar/browser_page_action_menu.js | "Bookmark This Page" == "Bookmark This Page" - > INFO - TEST-PASS | browser/base/content/test/urlbar/browser_page_action_menu.js | true == true - "promisePageActionViewChildrenVisible waiting..." is the check that I added. BrowserTestUtils.waitForCondition did not log that it failed, so it must have succeeded, so the children must be visible. The next thing the test does is try to click one of those children and then wait for the popup to close. So that's still not happening. In another test, or maybe it was this one, I disabled the panel's open animation and that fixed it. I can try that here too. (2) https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=134847225&lineNumber=7372 https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=134779066&lineNumber=7241 https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=134754836&lineNumber=7228 The last thing logged: > INFO - Waiting for the Sent! notification panel to open This is new. I haven't seen the test fail here before.
Status: RESOLVED → REOPENED
Flags: needinfo?(adw)
Resolution: FIXED → ---
(In reply to Drew Willcoxon :adw from comment #24) > (2) > > https://treeherder.mozilla.org/logviewer. > html#?repo=autoland&job_id=134847225&lineNumber=7372 > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > inbound&job_id=134779066&lineNumber=7241 > https://treeherder.mozilla.org/logviewer. > html#?repo=autoland&job_id=134754836&lineNumber=7228 > > The last thing logged: > > > INFO - Waiting for the Sent! notification panel to open > > This is new. I haven't seen the test fail here before. Ah, I just noticed this stack before the timeout: > INFO - GECKO(2482) | console.error: > INFO - GECKO(2482) | Could not send tab to device > INFO - GECKO(2482) | Message: Error: Unknown remote client ID: '0'. > INFO - GECKO(2482) | Stack: > INFO - GECKO(2482) |> _sendCommandToClient@resource://services-sync/engines/clients.js:607:13 > INFO - GECKO(2482) | async*sendCommand@resource://services-sync/engines/clients.js:786:13 > INFO - GECKO(2482) | async*sendURIToClientForDisplay@resource://services-sync/engines/clients.js:816:11 > INFO - GECKO(2482) | async*sendTabToDevice@chrome://browser/content/browser-sync.js:293:5 > INFO - GECKO(2482) | _appendSendTabDeviceList/onTargetDeviceCommand/<@chrome://browser/content/browser-sync.js:342:35 > INFO - GECKO(2482) | onTargetDeviceCommand@chrome://browser/content/browser-sync.js:342:7 > INFO - GECKO(2482) | doApply@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:148:10 > INFO - GECKO(2482) | apply@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:213:30 > INFO - GECKO(2482) | synthesizeMouseAtPoint@chrome://mochikit/content/tests/SimpleTest/EventUtils.js:425:7 > INFO - GECKO(2482) | synthesizeMouse@chrome://mochikit/content/tests/SimpleTest/EventUtils.js:356:10 > INFO - GECKO(2482) | synthesizeMouseAtCenter@chrome://mochikit/content/tests/SimpleTest/EventUtils.js:489:10 > INFO - GECKO(2482) | sendToDevice_inUrlbar/<@chrome://mochitests/content/browser/browser/base/content/test/urlbar/browser_page_action_menu.js:556:5 > INFO - GECKO(2482) | async*withNewTab@resource://testing-common/BrowserTestUtils.jsm:105:24 > INFO - GECKO(2482) | async*sendToDevice_inUrlbar@chrome://mochitests/content/browser/browser/base/content/test/urlbar/browser_page_action_menu.js:475:9 > ...
Hmm, looks like a red herring though. That error happens even on successful runs. And I can't see how it would prevent the notification from opening anyway. Which means we show the successful "Sent!" notification even on failure. :-/ So I'm stumped. One thing is that the popupshown event listener is added *after* the click that opens the notification. But promisePanelEvent handles that by checking panel.state first. Maybe that's broken?
Comment 24 describes the two types of timeouts. I don't know whether these changes will fix them but they're my best guesses. I meant for the mozreview to be a new commit, not a diff of the old one, sorry about that. Fix summary for each type of timeout: (1) Disable animations for the main panel. I poked around the panel code and found that popupshown isn't fired until transitionend is -- but only on non-Linux. That might explain why this is failing only on Linux. Of course, I don't know why Linux is special-cased, I'm sure there's a good reason. Not sure which of these is the relevant code, but they do the same thing looks like: https://dxr.mozilla.org/mozilla-central/source/layout/xul/nsXULPopupManager.cpp#1607 https://dxr.mozilla.org/mozilla-central/source/layout/xul/nsMenuPopupFrame.cpp#587 (2) My best guess is that the timeout that automatically closes the feedback panel happens before the panel's state becomes `shown`. Seems weird but maybe it's possible. So I added a way for the test to say, Don't close the panel until I tell you. The timeout is here for reference: https://dxr.mozilla.org/mozilla-central/rev/c97190c389c4cfef20fe55b4bacade95a36ae6ef/browser/base/content/browser-pageActions.js#750
Comment on attachment 8914444 [details] Bug 1385882 - Intermittent browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out. I still can't figure out how to re-request review. Please see the previous comment for a description of the new patch.
Attachment #8914444 - Flags: review+ → review?(gijskruitbosch+bugs)
(In reply to Drew Willcoxon :adw from comment #29) > I still can't figure out how to re-request review. Via mozreview I mean. https://treeherder.mozilla.org/#/jobs?repo=try&revision=217278f618e2
Comment on attachment 8914444 [details] Bug 1385882 - Intermittent browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out. https://reviewboard.mozilla.org/r/185760/#review191896 This patch is easy to follow, so rs=me on the patch. I haven't checked myself if it helps... I hope it does? :-) ::: browser/base/content/test/urlbar/browser_page_action_menu.js:559 (Diff revision 2) > + BrowserPageActionFeedback._panelHidePromise = > + new Promise(r => resolveFeedbackHidePromise = r); FWIW, you can use `PromiseUtils.defer();` to make this a tiny bit more ergonomic: ```js let feedbackHideDeferred = PromiseUtils.defer(); BrowserPageActionFeedback._panelHidePromise = feedbackHideDeferred.promise; ... feedbackHideDeferred.resolve(); ``` not really important though.
Attachment #8914444 - Flags: review?(gijskruitbosch+bugs) → review+
Ah thanks.
I just noticed on that try push that the "TV" test on Linux is orange because the test left `UIState` on the window. Never seen that before. So I just pushed a mozreview commit that cleans it up. I'll push to try one more time to make sure that did it before landing.
Thanks for working on this Drew (I was pinged in comment #1) (In reply to Drew Willcoxon :adw from comment #28) > (1) Disable animations for the main panel. I poked around the panel code > and found that popupshown isn't fired until transitionend is -- but only on > non-Linux. That might explain why this is failing only on Linux. Of > course, I don't know why Linux is special-cased, I'm sure there's a good > reason. Some of the window managers on Linux dont have the opacity support we need to animate these popups, and as we don't have a good way to detect these capabilities, we have to disable the animations across the board for linux (GTK). It means that hiding a popup can be a synchronous affair. We want to disable these animations during testing eventually (see my failed attempt to do so on bug 1380065) so test code should be able to handle either case. I'm a bit suspicious of that setTimeout. We've seen time and again that setTimeout isn't synchronized with anything much. In bug 1388183 it was suggested to rAF in the callback before touching the DOM. I don't know for sure how applicable that advice is here, but its something to consider. > (2) My best guess is that the timeout that automatically closes the feedback > panel happens before the panel's state becomes `shown`. Seems weird but > maybe it's possible. So I added a way for the test to say, Don't close the > panel until I tell you. Yeah that seems plausible.
(In reply to Sam Foster [:sfoster] from comment #37) > I'm a bit suspicious of that setTimeout. We've seen time and again that > setTimeout isn't synchronized with anything much. In bug 1388183 it was > suggested to rAF in the callback before touching the DOM. I don't know for > sure how applicable that advice is here, but its something to consider. Thanks Sam. Your comment dislodged something in my brain: the right way to fix this is to start the timeout only after popupshown has fired. To not have the timeout race the popupshown in the first place. There were tons of vague "unknown test url" errors on that last try push. No idea what that's about. I'll try to see what's going on before landing this. Also, now I'm seeing an error locally about `UIState` not being defined when it's accessed by browser-sync.js. Guess I'll remove the `delete window.UIState` that I added earlier today. I didn't change anything about UIState at all, so I don't really know wtf is going on in general here.
OK, the "unknown test url" errors were due to the same `delete window.UIState` problem. Another try push. If the "TV" tests again complain about leaving UIState on the window... https://treeherder.mozilla.org/#/jobs?repo=try&revision=28999a986088
eslint fix, sigh.
Try looks OK, so I autolanded this, but the tree is closed right now.
Pushed by dwillcoxon@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/5b9c57e69925 Intermittent browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out. r=Gijs
https://hg.mozilla.org/mozilla-central/rev/5b9c57e69925
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
Hi Drew, this still occurs, e.g. https://treeherder.mozilla.org/logviewer.html#?job_id=135496316&repo=autoland Do you want a new bug for potential remaining work or this one reopened?
Flags: needinfo?(adw)
Let's just keep this open until we really get it. I figured the previous commit wasn't a sure thing.
Status: RESOLVED → REOPENED
Flags: needinfo?(adw)
Resolution: FIXED → ---
I haven't seen any failures here since October 7th, I believe this is fixed
Summary: Intermittent browser/base/content/test/urlbar/browser_page_action_menu.js | Test timed out - | Found a tab after previous test timed out: http://example.com/browser_page_action_menu - → Intermittent browser/base/content/test/pageActions/browser_page_action_menu.js | Test timed out - | Found a tab after previous test timed out: http://example.com/browser_page_action_menu -

Page action bugs live in Toolbars and Customization, moving there

Component: Address Bar → Toolbars and Customization

Edgar, looks like fixing bug 1615732 made this intermittent spike, and caused test-verify tests to fail on Linux ( https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=296572866&revision=d8726d18021eecb2e7f6768823672635a37012b9 ). Can you take a look?

Assignee: adw → nobody
Flags: needinfo?(echen)
Regressed by: 1615732
Keywords: regression

(In reply to :Gijs (he/him) from comment #88)

Edgar, looks like fixing bug 1615732 made this intermittent spike, and caused test-verify tests to fail on Linux ( https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=296572866&revision=d8726d18021eecb2e7f6768823672635a37012b9 ). Can you take a look?

The recent spike is from the new added test in bug 1615732, https://searchfox.org/mozilla-central/rev/97cb0a90bd053de87cd1ab7646d5565809166bb1/browser/base/content/test/pageActions/browser_page_action_menu.js#59-84.

It run into the same situation as https://bugzilla.mozilla.org/show_bug.cgi?id=1519226#c24, the synthesized mouse action is ignored because of Bookmark status is not yet finishing updating, https://searchfox.org/mozilla-central/rev/97cb0a90bd053de87cd1ab7646d5565809166bb1/browser/base/content/browser-places.js#1813.

Assignee: nobody → echen
Flags: needinfo?(echen)

The Bookmark page button ignores activation if there is pending update. Thus,
the test must wait for the update to be finished before synthesizing mouse
actions.

Pushed by apavel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/04ef9640c589 Wait for the bookmarked status to finish updating before starting test; r=Gijs CLOSED TREE DONTBUILD

https://hg.mozilla.org/mozilla-central/rev/04ef9640c589

Status: REOPENED → RESOLVED
Closed: 7 years ago → 5 years ago
status-firefox77: --- → fixed
Resolution: --- → FIXED
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: