1528456 - Intermittent dom/ipc/tests/browser_domainPolicy.js | Test timed out -

Status: RESOLVED FIXED

(Core :: DOM: Content Processes, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=228803701&repo=autoland

https://queue.taskcluster.net/v1/task/Bbgv8C-PSpuIi5o20KhpGQ/runs/1/artifacts/public/logs/live_backing.log

[task 2019-02-16T07:07:36.276Z] 07:07:36 INFO - TEST-PASS | dom/ipc/tests/browser_domainPolicy.js | Checking script-enabled for root (https://sub1.test1.example.com/browser/dom/ipc/tests/file_disableScript.html) -
[task 2019-02-16T07:07:36.278Z] 07:07:36 INFO - Creating child process first, activating domainPolicy after
[task 2019-02-16T07:07:36.283Z] 07:07:36 INFO - Buffered messages logged at 07:06:54
[task 2019-02-16T07:07:36.285Z] 07:07:36 INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://mochi.test:8888/browser/dom/ipc/tests/file_domainPolicy_base.html" line: 0}]
[task 2019-02-16T07:07:36.287Z] 07:07:36 INFO - Buffered messages finished
[task 2019-02-16T07:07:36.289Z] 07:07:36 INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_domainPolicy.js | Test timed out -
[task 2019-02-16T07:07:36.291Z] 07:07:36 INFO - GECKO(9225) | MEMORY STAT | vsize 650MB | residentFast 268MB | heapAllocated 77MB
[task 2019-02-16T07:07:36.293Z] 07:07:36 INFO - TEST-OK | dom/ipc/tests/browser_domainPolicy.js | took 45035ms
[task 2019-02-16T07:07:36.295Z] 07:07:36 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-02-16T07:07:36.299Z] 07:07:36 INFO - TEST-UNEXPECTED-FAIL | dom/ipc/tests/browser_domainPolicy.js | Found a tab after previous test timed out: http://mochi.test:8888/browser/dom/ipc/tests/file_domainPolicy_base.html -

Comment 1

[Narcis Beleuzu [:NarcisB]]

::dao , this fail started from your push on autoland and it`s pretty intermittent.
Could you please take a look?

Comment 2

[Intermittent Failures Robot]

19 failures in 121 pushes (0.157 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16
• mozilla-central: 3

Platform breakdown:

• osx-10-10: 8
• linux32: 4
• windows10-64: 1
• linux64: 5
• macosx64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528456&startday=2019-02-16&endday=2019-02-16&tree=all

Comment 3

[Dão Gottwald [:dao]]

(In reply to Narcis Beleuzu [:NarcisB] from comment #1)

::dao , this fail started from your push on autoland and it`s pretty intermittent.
Could you please take a look?

It's ntim's patch so I think you'd want to ask him. However, that patch only affects the Library window UI (where users can manage their browsing history and bookmarks), and only on Linux. It doesn't look like it could cause this failure.

Comment 4

[Andreea Pavel [:apavel]]

Tim can you take a look at this?

It has 29 total failures in ~3 days on linux32, linux64, osx and win.

Comment 5

[Dão Gottwald [:dao]]

(In reply to Andreea Pavel [:apavel] from comment #4)

Tim can you take a look at this?

It has 29 total failures in ~3 days on linux32, linux64, osx and win.

Like I said this is very unlikely to be caused by Tim's patch.

Comment 6

[Intermittent Failures Robot]

36 failures in 2832 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

This is the #49 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: 19
• oak: 1
• mozilla-inbound: 2
• try: 6
• mozilla-central: 8

Platform breakdown:

• linux64: 9
• macosx64-nightly: 1
• linux32: 9
• linux64-ccov: 1
• windows10-64: 1
• linux32-nightly: 1
• linux32-devedition: 1
• osx-10-10: 13

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528456&startday=2019-02-11&endday=2019-02-17&tree=all

Comment 7

[Tim Nguyen :ntim]

As Dão says, my patch only touched the library window, so it seems to be completely unrelated to the failure.

I see that treeherder didn’t run the affected test suite on :bz’s previous push: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=367ca1e168537c05f091c766e11b2c8338621cba

So that could have been that patch that caused the failure (and it would seem more likely).

I’ve triggered bc1 on bz’s push.

Comment 8

[Tim Nguyen :ntim]

Ni? Boris who might know about this.

Comment 9

[Cosmin Sabou [:CosminS]]

This indeed looks that has started with Boris's push, around 70 green jobs before that: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2Copt%2Cmochitests%2Cwith%2Ce10s%2Ctest-linux32%2Fopt-mochitest-browser-chrome-e10s-1%2Cm-e10s%28bc1%29&tochange=e034cf8eb6f2ca8806264817cb2f909060cbfba8&fromchange=27280189b6faf5b8353e39f2f429ccc853f2d851&selectedJob=229021160

Comment 10

[Intermittent Failures Robot]

56 failures in 328 pushes (0.171 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-inbound: 13
• try: 7
• autoland: 32
• mozilla-central: 4

Platform breakdown:

• linux64: 17
• osx-10-10: 23
• macosx64-nightly: 2
• macosx64-devedition: 1
• linux32: 13

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528456&startday=2019-02-18&endday=2019-02-18&tree=all

Comment 11

[Boris Zbarsky [:bzbarsky]]

Is this only happening on 32-bit opt Linux?

Comment 12

[Boris Zbarsky [:bzbarsky]]

This test is one of a very small number of places we listen for "DOMDocElementInserted" events, so that seems like a pretty plausible connection...

Comment 13

[Cristina Coroiu [:ccoroiu]]

:bz this is frequently failing on:

• linux32 opt and debug
• linux64 pgo, opt and debug
• osx-10-10 opt and debug

https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-02-13&endday=2019-02-20&tree=trunk&bug=1528456

Comment 14

[Boris Zbarsky [:bzbarsky]]

For what it's worth, I've confirmed on try that not doing nsDocElementCreatedNotificationRunner for non-initial about:blank makes the timeouts go away. Still trying to understand what the test is doing enough to figure out where the race is, and/or reproduce the timeout under rr.

Comment 15

[Intermittent Failures Robot]

82 failures in 501 pushes (0.164 failures/push) were associated with this bug yesterday.

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

Repository breakdown:

• mozilla-inbound: 20
• mozilla-central: 2
• autoland: 50
• try: 10

Platform breakdown:

• linux64-pgo-qr: 1
• osx-10-10: 29
• macosx64-devedition: 2
• windows10-64: 1
• linux32: 20
• macosx64-nightly: 2
• linux64: 27

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528456&startday=2019-02-19&endday=2019-02-19&tree=all

Comment 16

[Andreea Pavel [:apavel]]

(In reply to Boris Zbarsky [:bzbarsky, bz on IRC] from comment #14)

For what it's worth, I've confirmed on try that not doing nsDocElementCreatedNotificationRunner for non-initial about:blank makes the timeouts go away. Still trying to understand what the test is doing enough to figure out where the race is, and/or reproduce the timeout under rr.

Thanks for looking Boris. Let us know if this needs to be disabled if you find no other solution.
Removing the stockwell tag until then.

Comment 17

[Boris Zbarsky [:bzbarsky]]

Attachment: Bug 1528456. Fix browser_domainPolicy.js to not be racy. r=gijs

The old complicated code here was working around a fundamental race in the
test. The test was trying to do the following:

1. Open a new tab. This sends an IPC message to do that and to start loading
   about:blank in the tab.

2. Add a "load" listener. This sends an IPC message to add the listener.

3. Start loading the URL we really want to load. This sends an IPC message to
   start the load.

There are two races here: the message from step 2 can be received before or
after the about:blank load is done, and the message from step 3 can be received
before or after the about:blank load is done. If step 2 wins the race (we add
the listener before the about:blank load is done) but step 3 loses the race
(new load starts only after the about:blank load is done), then we would get a
load event for the about:blank, not for the url we care about.

The test worked around this by having step 2 add a listener for the
"DOMDocElementInserted" event, which about:blank did not fire. Then when that
happened (indicating that the load from step 3 is now in progress), it added a
"load" listener. This fixed the race.

Bug 1528146 fixed about:blank to also fire "DOMDocElementInserted", so the test
became racy again. Now if the "DOMDocElementInserted" listener got added
after the about:blank load had fired that event (which is what usually
happened), then the test passed. But if the IPC message from step 2 to add the
"DOMDocElementInserted" listener won the race against the about:blank load
firing "DOMDocElementInserted", then we added the "load" listener too early and
got the "load" event for the about:blank, not the document we cared about.

The fix is to just use the (now) existing openNewForegroundTab function which
lets us pass in a url, then wait until that URL is loaded, instead of trying to
reinvent that wheel.

There is an additional ride-along change to make openNewForegroundTab always
create a new process in this test, which is the original intent of the test but
wasn't necessarily guaranteed by the old code.

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/febefd80b125
Fix browser_domainPolicy.js to not be racy.  r=Gijs

Comment 19

[Intermittent Failures Robot]

42 failures in 425 pushes (0.099 failures/push) were associated with this bug yesterday.

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

Repository breakdown:

• autoland: 27
• mozilla-inbound: 8
• mozilla-central: 2
• try: 5

Platform breakdown:

• macosx64-nightly: 2
• osx-10-10: 19
• linux64-devedition: 2
• linux32-devedition: 1
• linux32: 5
• macosx64-devedition: 1
• linux64: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528456&startday=2019-02-20&endday=2019-02-20&tree=all

Comment 20

[Oana Pop-Rus]

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

Comment 21

[Intermittent Failures Robot]

194 failures in 2602 pushes (0.075 failures/push) were associated with this bug in the last 7 days.

This is the #5 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: 114
• mozilla-central: 12
• mozilla-inbound: 46
• try: 22

Platform breakdown:

• linux64: 60
• osx-10-10: 78
• linux32: 41
• macosx64-nightly: 6
• macosx64-devedition: 4
• windows10-64: 1
• linux64-pgo-qr: 1
• linux64-devedition: 2
• linux32-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1528456&startday=2019-02-18&endday=2019-02-24&tree=all