Closed Bug 1420610 Opened 5 years ago Closed 5 years ago

Intermittent browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js | Test timed out -

Categories

(Firefox :: Security, defect, P5)

Product:
Firefox
Component:
Security
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 59
Tracking Flags:
Tracking Status
firefox59 --- fixed

People

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

References

Details

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

Attachments

(1 file, 4 obsolete files)

Bug1420610-12-13-17C.patch
4.41 KB, patch
Gijs
: review+
Details | Diff | Splinter Review 
In the last 7 days there were 37 failures. 
:Wennie Can you please take a look at this?
Flags: needinfo?(wleung)
Whiteboard: [stockwell needswork]
here is a recent log:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=148633836&lineNumber=3321

and a screenshot:
https://public-artifacts.taskcluster.net/MCPI9b7zRCmHuCQYQ4EtpA/0/public/test_info//mozilla-test-fail-screenshot_wfp1m1.png

here is data from the log:
[task 2017-11-29T23:58:37.519Z] 23:58:37     INFO - TEST-INFO | started process screentopng
[task 2017-11-29T23:58:37.990Z] 23:58:37     INFO - TEST-INFO | screentopng: exit 0
[task 2017-11-29T23:58:37.992Z] 23:58:37     INFO - Buffered messages logged at 23:57:07
[task 2017-11-29T23:58:37.992Z] 23:58:37     INFO - Entering test bound 
[task 2017-11-29T23:58:37.992Z] 23:58:37     INFO - Buffered messages logged at 23:57:10
[task 2017-11-29T23:58:37.994Z] 23:58:37     INFO - TEST-PASS | browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js | Tab shouldn't have usercontextid attribute - true == true - 
[task 2017-11-29T23:58:37.994Z] 23:58:37     INFO - Buffered messages finished
[task 2017-11-29T23:58:37.995Z] 23:58:37     INFO - TEST-UNEXPECTED-FAIL | browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js | Test timed out - 
[task 2017-11-29T23:58:37.999Z] 23:58:37     INFO - GECKO(1128) | MEMORY STAT | vsize 2722MB | residentFast 305MB | heapAllocated 93MB
[task 2017-11-29T23:58:37.999Z] 23:58:37     INFO - TEST-OK | browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js | took 90134ms
[task 2017-11-29T23:58:37.999Z] 23:58:37     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-11-29T23:58:38.003Z] 23:58:38     INFO - TEST-UNEXPECTED-FAIL | browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js | Found a tab after previous test timed out: http://example.com/ - 
[task 2017-11-29T23:58:38.005Z] 23:58:38     INFO - Not taking screenshot here: see the one that was previously logged
[task 2017-11-29T23:58:38.006Z] 23:58:38     INFO - TEST-UNEXPECTED-FAIL | browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js | Found a tab after previous test timed out: about:blank - 
[task 2017-11-29T23:58:38.009Z] 23:58:38     INFO - GECKO(1128) | ++DOCSHELL 0x7faf4c105000 == 2 [pid = 1181] [id = {b988508a-871e-440f-a628-424958f645a6}]
[task 2017-11-29T23:58:38.010Z] 23:58:38     INFO - GECKO(1128) | ++DOMWINDOW == 3 (0x7faf58285660) [pid = 1181] [serial = 80] [outer = (nil)]
[task 2017-11-29T23:58:38.011Z] 23:58:38     INFO - checking window state
Hi Tanvi, please take a look at this. thanks!
Flags: needinfo?(wleung) → needinfo?(tanvi)
Looks like the tests are failing on: await BrowserTestUtils.browserLoaded(tab2.linkedBrowser);

I can see the timeouts in different places on different logs, some for line 35 and some for line 80 both are preceded by that code.

The fix might simply be making a variable for that promise and awaiting it at the same position.
Attached patch Bug1420610-12-11-17.patch (obsolete) — — Splinter Review 
Jonathan, is this what you had in mind?

I can't reproduce the timeout locally.  I will push to try once I have access again, with and without this patch.  In the meantime, would it help to push this to see if it reduces or eliminates the timeouts?
Attachment #8936316 - Flags: feedback?(jkt)
Sorry I wasn't clear, I meant use the variable earlier if possible.

I think if possible:
let browserLoadedPromise = BrowserTestUtils.browserLoaded(tab2.linkedBrowser);

Should go before:
let tab2 = await newTabPromise;

Or even earlier perhaps just after newTabPromise gets defined?

My thinking is that linux is starting the load after the tab is dropped and at the point this browserLoadedPromise is defined the load has already started.

Perhaps try and retrigger that one test in try a tonne of times to see if you can get it to fail?
(In reply to Jonathan Kingston [:jkt] from comment #19)
> Sorry I wasn't clear, I meant use the variable earlier if possible.
> 
> I think if possible:
> let browserLoadedPromise =
> BrowserTestUtils.browserLoaded(tab2.linkedBrowser);
> 
> Should go before:
> let tab2 = await newTabPromise;
> 
> Or even earlier perhaps just after newTabPromise gets defined?
> 
But we can't define browserLoadedPromise until tab2 is defined.  So we can't declare it before let tab2 = await newTabPromise.

I wonder if we even need to await this promise in the first two tests (line 35 and 80) since the tab is newly created with the right usercontextid.  We can keep it in the third test (around line 137) where the tab already exists but is being navigated.

> My thinking is that linux is starting the load after the tab is dropped and
> at the point this browserLoadedPromise is defined the load has already
> started.
> 
> Perhaps try and retrigger that one test in try a tonne of times to see if
> you can get it to fail?
Attached patch Bug1420610-12-12-17.patch (obsolete) — — Splinter Review 
Not really sure if I can do this, but giving it a shot.  Removed the promise in the first two tests and pushed to try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=d31b53f90f6ba0afbf4ad756df76925a4ac5b70c&selectedJob=151340393
Attachment #8936316 - Attachment is obsolete: true
Attachment #8936316 - Flags: feedback?(jkt)
Attachment #8936480 - Flags: feedback?(jkt)
thank for working on this :tanvi, I look forward to this landing soon!
Attached patch Bug1420610-12-13-17.patch (obsolete) — — Splinter Review 
Define promise earlier.

Push to try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=1f513bc4ec9e02dd1013df2acf1aaaae6687f972
Attachment #8936480 - Attachment is obsolete: true
Attachment #8936480 - Flags: feedback?(jkt)
Attachment #8936667 - Flags: feedback?(jkt)
Comment on attachment 8936667 [details] [diff] [review]
Bug1420610-12-13-17.patch

This looks like what I was mentioning, would be worth checking with Gijs too and try :).

Thanks!
Attachment #8936667 - Flags: feedback?(jkt) → feedback+
Attachment #8936667 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8936667 [details] [diff] [review]
Bug1420610-12-13-17.patch

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

Asserts are synchronous and don't influence this load, so this won't fix the issue.

I expect the fix here requires something along the lines of this change:

https://hg.mozilla.org/mozilla-central/rev/976f45726ed5#l4.12

or, higher up in that cset, https://hg.mozilla.org/mozilla-central/rev/976f45726ed5#l1.12 - perhaps we can/should wait for the new tab to have loaded completely before asserting anything (ie make the load promise part of the new tab promise which we await right before the respective asserts ?
Attachment #8936667 - Flags: review?(gijskruitbosch+bugs) → review-
Attached patch Bug1420610-12-13-17B.patch (obsolete) — — Splinter Review 
Like this?

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0565880a3ec28f347a0318c50dbbaebc0fdb8723
Attachment #8936667 - Attachment is obsolete: true
Attachment #8936696 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8936696 [details] [diff] [review]
Bug1420610-12-13-17B.patch

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

r=me to just rm the browserLoadedPromises, see below.

::: browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js
@@ +38,5 @@
>  
>    await awaitDrop;
>  
>    let tab2 = await newTabPromise;
> +  await browserLoadedPromise;

Yes, but in this case, we don't use the promises separately, so I think you could just define newTabPromise as: `BrowserTestUtils.waitForNewTab(gBrowser, "http://test1.example.com/", true)` (where the 3rd arg means we wait for that url to load - see definition in https://dxr.mozilla.org/mozilla-central/rev/93b37aa497c48a6e28a9463eeb753b2ce3964f42/testing/mochitest/BrowserTestUtils/BrowserTestUtils.jsm#406 ).

Then you could only `await newTabPromise`, and just not check `browserLoadedPromise`.

@@ +67,5 @@
>  
>    let awaitDrop = BrowserTestUtils.waitForEvent(gBrowser.tabContainer, "drop");
> +
> +  let browserLoadedPromise;
> +  let newTabPromise = new Promise(resolve => {

Same here.

@@ +133,5 @@
>    await awaitDrop;
>    Assert.equal(tab2.getAttribute("usercontextid"), 2);
>  
> +  let browserLoadedPromise = BrowserTestUtils.browserLoaded(tab2.linkedBrowser);
> +  await browserLoadedPromise;

This looks like it's just a leftover hunk/change? :-)
Attachment #8936696 - Flags: review?(gijskruitbosch+bugs) → review+
Comment on attachment 8936716 [details] [diff] [review]
Bug1420610-12-13-17C.patch

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

LGTM, thanks!
Attachment #8936716 - Flags: review?(gijskruitbosch+bugs) → review+
Assignee: nobody → tanvi
Status: NEW → ASSIGNED
Flags: needinfo?(tanvi)
Keywords: checkin-needed
Comment on attachment 8936716 [details] [diff] [review]
Bug1420610-12-13-17C.patch

Put checkin-needed on the whiteboard instead of the patch.  Correcting.
Attachment #8936716 - Flags: checkin+
Keywords: checkin-needed
Comment on attachment 8936716 [details] [diff] [review]
Bug1420610-12-13-17C.patch

Nevermind, that doesn't look right.
Attachment #8936716 - Flags: checkin+
Keywords: checkin-needed
Marking affected to see if that helps this show up for merges/checkin
status-firefox59: --- → affected
Pushed by archaeopteryx@coole-files.de:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e3d4a5930118
Check if url loaded within newTabPromise to resolve timeouts. r=gijs
Keywords: checkin-needed
Thanks Liz!
https://hg.mozilla.org/mozilla-central/rev/e3d4a5930118
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox59: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 59
Duplicate of this bug: 1425991
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:other]
You need to log in before you can comment on or make changes to this bug.