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

Status: RESOLVED FIXED

(Firefox :: Security, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: shindli [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/O2moCnpESfyLU3p_EfU9jg/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

4 failures in 744 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

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

Platform breakdown:
* linux32: 2
* linux64-stylo-disabled: 1
* linux32-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1420610&startday=2017-11-20&endday=2017-11-26&tree=all

Comment 2

[Intermittent Failures Robot]

21 failures in 137 pushes (0.153 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 14
* autoland: 6
* mozilla-central: 1

Platform breakdown:
* linux64: 7
* linux32-stylo-disabled: 7
* linux32: 5
* linux64-stylo-disabled: 1
* linux64-ccov: 1

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

Comment 3

[Cristian Brindusan [:cbrindusan]]

In the last 7 days there were 37 failures. 
:Wennie Can you please take a look at this?

Comment 4

[Intermittent Failures Robot]

16 failures in 155 pushes (0.103 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 8
* autoland: 6
* mozilla-central: 2

Platform breakdown:
* linux64-stylo-disabled: 5
* linux64: 5
* linux32: 5
* linux32-stylo-disabled: 1

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

Comment 5

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

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

Comment 6

[Intermittent Failures Robot]

24 failures in 154 pushes (0.156 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 14
* mozilla-inbound: 5
* try: 3
* mozilla-central: 2

Platform breakdown:
* linux64-stylo-disabled: 14
* linux64: 4
* linux32-stylo-disabled: 4
* linux32: 2

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

Comment 7

[Intermittent Failures Robot]

15 failures in 105 pushes (0.143 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 6
* autoland: 6
* try: 2
* mozilla-central: 1

Platform breakdown:
* linux64-stylo-disabled: 8
* linux32: 4
* linux64: 2
* linux32-stylo-disabled: 1

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

Comment 8

[Intermittent Failures Robot]

119 failures in 792 pushes (0.15 failures/push) were associated with this bug in the last 7 days. 

This is the #3 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 51
* mozilla-inbound: 46
* mozilla-central: 16
* try: 6

Platform breakdown:
* linux64-stylo-disabled: 41
* linux64: 33
* linux32-stylo-disabled: 22
* linux32: 22
* linux64-ccov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1420610&startday=2017-11-27&endday=2017-12-03&tree=all

Comment 9

[Wennie]

Hi Tanvi, please take a look at this. thanks!

Comment 10

[Intermittent Failures Robot]

17 failures in 178 pushes (0.096 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 8
* autoland: 6
* try: 2
* mozilla-central: 1

Platform breakdown:
* linux32: 5
* linux64-stylo-disabled: 4
* linux64: 4
* linux32-stylo-disabled: 3
* linux64-ccov: 1

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

Comment 11

[Tanvi Vyas[:tanvi]]

Link to test:
https://searchfox.org/mozilla-central/source/browser/components/contextualidentity/test/browser/browser_usercontextid_tabdrop.js

Written as part of bug https://bugzilla.mozilla.org/show_bug.cgi?id=1237077.  No changes to the test itself recently.

Comment 12

[Jonathan Kingston [:jkt] he/him]

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.

Comment 13

[Intermittent Failures Robot]

17 failures in 157 pushes (0.108 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 5
* mozilla-central: 5
* autoland: 5
* try: 2

Platform breakdown:
* linux64: 10
* linux64-stylo-disabled: 2
* linux32-stylo-disabled: 2
* linux32: 2
* linux64-ccov: 1

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

Comment 14

[Intermittent Failures Robot]

19 failures in 164 pushes (0.116 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 9
* mozilla-inbound: 7
* mozilla-central: 3

Platform breakdown:
* linux64: 7
* linux32: 5
* linux64-stylo-disabled: 3
* linux32-stylo-disabled: 3
* linux64-ccov: 1

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

Comment 15

[Intermittent Failures Robot]

8 failures in 55 pushes (0.145 failures/push) were associated with this bug yesterday.    

** This test has failed more than 200 times in the last 30 days. It should be disabled until it can be fixed. ** 

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

Platform breakdown:
* linux64-stylo-disabled: 4
* linux64-ccov: 1
* linux64: 1
* linux32-stylo-disabled: 1
* linux32: 1

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

Comment 16

[Intermittent Failures Robot]

103 failures in 889 pushes (0.116 failures/push) were associated with this bug in the last 7 days. 

This is the #10 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* mozilla-inbound: 41
* autoland: 40
* mozilla-central: 17
* try: 5

Platform breakdown:
* linux64: 36
* linux64-stylo-disabled: 25
* linux32: 23
* linux32-stylo-disabled: 15
* linux64-ccov: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1420610&startday=2017-12-04&endday=2017-12-10&tree=all

Comment 17

[Tanvi Vyas[:tanvi]]

Attachment: Bug1420610-12-11-17.patch

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?

Comment 18

[Tanvi Vyas[:tanvi]]

With patch - https://treeherder.mozilla.org/#/jobs?repo=try&revision=ea5cc9745e0222123c0565bc885f30abaad8d4a2

Without patch - https://treeherder.mozilla.org/#/jobs?repo=try&revision=1570d9fafee5f60597857488598b232f2c9a853c

Comment 19

[Jonathan Kingston [:jkt] he/him]

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?

Comment 20

[Tanvi Vyas[:tanvi]]

(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?

Comment 21

[Tanvi Vyas[:tanvi]]

Attachment: Bug1420610-12-12-17.patch

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

Comment 22

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

thank for working on this :tanvi, I look forward to this landing soon!

Comment 23

[Tanvi Vyas[:tanvi]]

Attachment: Bug1420610-12-13-17.patch

Define promise earlier.

Push to try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=1f513bc4ec9e02dd1013df2acf1aaaae6687f972

Comment 24

[Jonathan Kingston [:jkt] he/him]

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!

Comment 25

[:Gijs (he/him)]

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 ?

Comment 26

[Tanvi Vyas[:tanvi]]

Attachment: Bug1420610-12-13-17B.patch

Like this?

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0565880a3ec28f347a0318c50dbbaebc0fdb8723

Comment 27

[:Gijs (he/him)]

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? :-)

Comment 28

[Tanvi Vyas[:tanvi]]

Attachment: Bug1420610-12-13-17C.patch

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

Comment 29

[Intermittent Failures Robot]

15 failures in 92 pushes (0.163 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 8
* mozilla-inbound: 6
* mozilla-central: 1

Platform breakdown:
* linux64-stylo-disabled: 8
* linux32-stylo-disabled: 4
* linux32: 3

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

Comment 30

[:Gijs (he/him)]

Comment on attachment 8936716 [details] [diff] [review]
Bug1420610-12-13-17C.patch

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

LGTM, thanks!

Comment 31

[Intermittent Failures Robot]

63 failures in 423 pushes (0.149 failures/push) were associated with this bug in the last 7 days. 

This is the #9 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: 28
* mozilla-inbound: 21
* mozilla-central: 10
* try: 4

Platform breakdown:
* linux64-stylo-disabled: 20
* linux64: 16
* linux32-stylo-disabled: 16
* linux32: 11

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1420610&startday=2017-12-11&endday=2017-12-17&tree=all

Comment 32

[Tanvi Vyas[:tanvi]]

Comment on attachment 8936716 [details] [diff] [review]
Bug1420610-12-13-17C.patch

Put checkin-needed on the whiteboard instead of the patch.  Correcting.

Comment 33

[Tanvi Vyas[:tanvi]]

Comment on attachment 8936716 [details] [diff] [review]
Bug1420610-12-13-17C.patch

Nevermind, that doesn't look right.

Comment 34

[Liz Henry (:lizzard) (relman/hg->git project)]

Marking affected to see if that helps this show up for merges/checkin

Comment 35

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e3d4a5930118
Check if url loaded within newTabPromise to resolve timeouts. r=gijs

Comment 36

[Tanvi Vyas[:tanvi]]

Thanks Liz!

Comment 37

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/e3d4a5930118

Comment 39

[Intermittent Failures Robot]

11 failures in 590 pushes (0.019 failures/push) were associated with this bug in the last 7 days.    

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

Platform breakdown:
* linux32-stylo-disabled: 4
* linux32: 4
* linux64: 2
* linux64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1420610&startday=2017-12-18&endday=2017-12-24&tree=all