1671488 - Intermittent Windows Webrender docshell/test/browser/browser_tab_replace_while_loading.js | Uncaught exception received from previously timed out test

Status: RESOLVED INCOMPLETE

(Core :: DOM: Navigation, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=318759305&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WlNs5-iOQoiS-wmTfshHBQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-10-15T19:06:13.611Z] 19:06:13 INFO - TEST-START | docshell/test/browser/browser_tab_replace_while_loading.js
[task 2020-10-15T19:06:58.626Z] 19:06:58 INFO - TEST-INFO | started process screenshot
[task 2020-10-15T19:06:58.717Z] 19:06:58 INFO - TEST-INFO | screenshot: exit 0
[task 2020-10-15T19:06:58.718Z] 19:06:58 INFO - Buffered messages logged at 19:06:13
[task 2020-10-15T19:06:58.719Z] 19:06:58 INFO - Entering test bound test_window_open_about_blank
[task 2020-10-15T19:06:58.719Z] 19:06:58 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/docshell/test/browser/file_open_about_blank.html" line: 0}]
[task 2020-10-15T19:06:58.719Z] 19:06:58 INFO - Opening about:blank using a click
[task 2020-10-15T19:06:58.720Z] 19:06:58 INFO - Waiting for the second tab to be opened
[task 2020-10-15T19:06:58.720Z] 19:06:58 INFO - Detaching tab
[task 2020-10-15T19:06:58.720Z] 19:06:58 INFO - Buffered messages logged at 19:06:14
[task 2020-10-15T19:06:58.720Z] 19:06:58 INFO - Asserting document is visible
[task 2020-10-15T19:06:58.721Z] 19:06:58 INFO - TEST-PASS | docshell/test/browser/browser_tab_replace_while_loading.js | Document should be visible - "visible" == "visible" -
[task 2020-10-15T19:06:58.721Z] 19:06:58 INFO - Leaving test bound test_window_open_about_blank
[task 2020-10-15T19:06:58.721Z] 19:06:58 INFO - Entering test bound test_detach_loading_page
[task 2020-10-15T19:06:58.721Z] 19:06:58 INFO - Buffered messages finished
[task 2020-10-15T19:06:58.721Z] 19:06:58 INFO - TEST-UNEXPECTED-FAIL | docshell/test/browser/browser_tab_replace_while_loading.js | Test timed out -
[task 2020-10-15T19:06:58.721Z] 19:06:58 INFO - GECKO(6752) | MEMORY STAT | vsize 2104343MB | vsizeMaxContiguous 66302653MB | residentFast 346MB | heapAllocated 82MB
[task 2020-10-15T19:06:58.721Z] 19:06:58 INFO - TEST-OK | docshell/test/browser/browser_tab_replace_while_loading.js | took 45052ms
[task 2020-10-15T19:06:58.722Z] 19:06:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-10-15T19:06:58.722Z] 19:06:58 INFO - TEST-UNEXPECTED-FAIL | docshell/test/browser/browser_tab_replace_while_loading.js | Found a tab after previous test timed out: http://mochi.test:8888/browser/docshell/test/browser/file_slow_load.sjs -
[task 2020-10-15T19:06:58.722Z] 19:06:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-10-15T19:06:58.722Z] 19:06:58 INFO - TEST-UNEXPECTED-FAIL | docshell/test/browser/browser_tab_replace_while_loading.js | Found a tab after previous test timed out: about:blank -
[task 2020-10-15T19:06:58.722Z] 19:06:58 INFO - checking window state
[task 2020-10-15T19:06:58.727Z] 19:06:58 INFO - TEST-START | docshell/test/browser/browser_tab_touch_events.js
[task 2020-10-15T19:06:59.039Z] 19:06:59 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-10-15T19:06:59.039Z] 19:06:59 INFO - Buffered messages logged at 19:06:58
[task 2020-10-15T19:06:59.039Z] 19:06:59 INFO - Entering test bound
[task 2020-10-15T19:06:59.039Z] 19:06:59 INFO - Buffered messages finished
[task 2020-10-15T19:06:59.040Z] 19:06:59 INFO - TEST-UNEXPECTED-FAIL | docshell/test/browser/browser_tab_replace_while_loading.js | Uncaught exception received from previously timed out test - at chrome://mochitests/content/browser/docshell/test/browser/browser_tab_replace_while_loading.js:58 - ReferenceError: info is not defined
[task 2020-10-15T19:06:59.040Z] 19:06:59 INFO - Stack trace:
[task 2020-10-15T19:06:59.040Z] 19:06:59 INFO - test_detach_loading_page@chrome://mochitests/content/browser/docshell/test/browser/browser_tab_replace_while_loading.js:58:3
[task 2020-10-15T19:06:59.042Z] 19:06:59 INFO - TEST-PASS | docshell/test/browser/browser_tab_touch_events.js | touchEventsOverride flag should be initially set to NONE - 2 == 2 -
[task 2020-10-15T19:06:59.042Z] 19:06:59 INFO - TEST-PASS | docshell/test/browser/browser_tab_touch_events.js | touchEventsOverride flag should be changed to DISABLED - 0 == 0 -
[task 2020-10-15T19:06:59.042Z] 19:06:59 INFO - TEST-PASS | docshell/test/browser/browser_tab_touch_events.js | touchEventsOverride flag should be passed on to frames. - 0 == 0 -
[task 2020-10-15T19:06:59.052Z] 19:06:59 INFO - TEST-PASS | docshell/test/browser/browser_tab_touch_events.js | Newly created frames should use the new touchEventsOverride flag - 0 == 0 -
[task 2020-10-15T19:06:59.062Z] 19:06:59 INFO - TEST-PASS | docshell/test/browser/browser_tab_touch_events.js | New touchEventsOverride flag should persist across reloads - 0 == 0 -
[task 2020-10-15T19:06:59.071Z] 19:06:59 INFO - Leaving test bound
[task 2020-10-15T19:06:59.132Z] 19:06:59 INFO - GECKO(6752) | MEMORY STAT | vsize 2104338MB | vsizeMaxContiguous 66302653MB | residentFast 348MB | heapAllocated 84MB
[task 2020-10-15T19:06:59.132Z] 19:06:59 INFO - TEST-OK | docshell/test/browser/browser_tab_touch_events.js | took 398ms
[task 2020-10-15T19:06:59.137Z] 19:06:59 INFO - checking window state
[task 2020-10-15T19:06:59.147Z] 19:06:59 INFO - TEST-START | docshell/test/browser/browser_timelineMarkers-01.js

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Bisection points to bug 1669239.

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1669239

Comment 4

[Intermittent Failures Robot]

19 failures in 655 pushes (0.029 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 6
• autoland: 13

Platform breakdown:

• windows10-64-shippable-qr: 4
• windows10-64-qr: 11
• windows10-64-shippable: 2
• windows10-64: 1
• windows7-32: 1

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

Comment 5

[Intermittent Failures Robot]

57 failures in 3694 pushes (0.015 failures/push) were associated with this bug in the last 7 days.

This is the #21 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: 41
• mozilla-central: 11
• try: 5

Platform breakdown:

• windows10-64-qr: 35
• windows10-64-shippable-qr: 8
• windows10-64-shippable: 6
• windows10-64: 5
• windows7-32: 1
• windows7-32-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1671488&startday=2020-10-12&endday=2020-10-18&tree=all

Comment 6

[Sean Feng [:sefeng]]

I think the bug here is that when the scheduled tick that happens in the content process, it's possible that the top-level widget is already detached at here, so no paint happens. And because of the loss of this paint, MozLayerTreeReady isn't going to be dispatched, so the test timeouts.

Comment 7

[Sean Feng [:sefeng]]

Jim, you seem to know these code well, Can I get your opinions about this bug?

Comment 8

[Intermittent Failures Robot]

25 failures in 4230 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 16
• mozilla-central: 8
• try: 1

Platform breakdown:

• windows10-64: 4
• windows10-64-shippable-qr: 5
• windows10-64-qr: 10
• windows7-32-shippable: 1
• windows10-64-shippable: 3
• windows7-32: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1671488&startday=2020-10-19&endday=2020-10-25&tree=all

Comment 9

[Pascal Chevrel:pascalc]

Emilio, would you have an opinion on this bug? Thanks

Comment 10

[Emilio Cobos Álvarez (:emilio)]

(In reply to Sean Feng [:sefeng] from comment #6)

I think the bug here is that when the scheduled tick that happens in the content process, it's possible that the top-level widget is already detached at here, so no paint happens. And because of the loss of this paint, MozLayerTreeReady isn't going to be dispatched, so the test timeouts.

Why does MozLayerTreeReady not firing cause the test to timeout Sean? I'm confused. But if MozLayerTreeReady is an expectation from the call to RecvRenderLayers even if we detach the tab, that seems like a bug that could cause tab spinners.

Comment 11

[Sean Feng [:sefeng]]

It timeouts because this call never returns https://searchfox.org/mozilla-central/rev/a147181ece866c1ecd176ac49f112785f960aac0/docshell/test/browser/browser_tab_replace_while_loading.js#52-55 because AsyncTabSwitcher doesn't think the tab switch has finished.

I don't get the second part. I don't see where we detach the tab....

Comment 12

[Sean Feng [:sefeng]]

Oh, I think I get what you meant. I guess my intuition was we needed to somehow force a paint to be able tofire MozLayerTreeReady? However, I am not sure when the detach should/would happen, so I am not sure if this is a bug.

The code worked before because we always painted inside the Invalidate method, so the detach call there didn't really matter.

I am not sure if you know this, but I think I should check what the detach call means here. I wouldn't expect it detached the test tab...

Comment 13

[Emilio Cobos Álvarez (:emilio)]

Well, the test is moving tabs around in two windows / detaching a tab into a different window.

If the expectation from the tab switcher code is that Invalidate() / assigning renderLayers / etc always creates a MozLayerTreeReady notification, then we either need to fix the tab switcher code to not do that, or to guarantee that that happens, right?

I'm looking into some related code as part of bug 1635914 but I suspect it's going to be different enough that you could probably get to this faster than me... Do you have the cycles for this Sean?

Comment 14

[Sean Feng [:sefeng]]

Yeah, I agree that is something we want to fix, and I do have cycles :)

What do you think of the next step that should be here?

Intuitively, I'd prefer guaranteeing MozLayerTreeReady to happen because that is the original behaviour. And changing the tab switcher code feels going to be a lot of works, as I probably need to use another event to let the tab switcher aware that it's ready to do the UI change. Although, I could look into the tab switcher code to see if I can fix it for sure.

Just getting your opinions before I blindly start looking into it, Emilio :)

Comment 15

[Emilio Cobos Álvarez (:emilio)]

Intuitively, I'd prefer guaranteeing MozLayerTreeReady to happen because that is the original behaviour.

I agree this is the less risky/complicated approach... It'd probably be a bit of a lie though (the tab switcher would get a LayerTreeReady, but we haven't really painted!). But yeah, worth a try.

Comment 16

[Intermittent Failures Robot]

9 failures in 4275 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• mozilla-central: 6

Platform breakdown:

• macosx1014-64: 1
• windows10-64-shippable-qr: 4
• windows10-64-qr: 2
• windows10-64-shippable: 1
• windows10-64-ccov-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1671488&startday=2020-10-26&endday=2020-11-01&tree=all

Comment 17

[Sean Feng [:sefeng]]

Attachment: Bug 1671488 - Reschedule the scheduled flush at where we attach the PuppetWidget to a different DocumentViewer r=emilio

In PuppetWidget::Invalidate, we could schedule a flush for the next
Tick. This scheduled flush is important to fire events like
MozLayerTreeReady.

However, one possible case is that the PuppetWidget got reattached to
a different DocumentViewer before the scheduled flush run. For instance,
it was originally attached to the content viewer for about:blank, and
then got reattached to the final url's content viewer. The issue is that
when the next Tick run, it couldn't do the paints because it didn't have
the widget (as it got attached to somewhere else).

This patch reschedules the flush at where we attach the PuppetWidget to
a different DocumentViewer if the scheduled flush hasn't run yet.

Comment 18

[Intermittent Failures Robot]

7 failures in 4128 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3
• autoland: 1
• try: 1
• mozilla-beta: 2

Platform breakdown:

• windows10-64-shippable-qr: 1
• windows10-64-shippable: 4
• windows10-64-qr: 1
• windows7-32-shippable: 1

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

Comment 19

[BugBot [:suhaib / :marco/ :calixte]]

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:sefeng, could you have a look please?
For more information, please visit auto_nag documentation.

Comment 20

[Ryan VanderMeulen [:RyanVM]]

This appears to have gone away in early November. Do we know why? :)

Comment 21

[Sean Feng [:sefeng]]

Not exactly.

I guess that means something has magically happened around paint scheduling. The failure was at a low volume and quite sensitive to how paints were scheduled. Perhaps I don't need to land the patch then :)

Comment 22

[Sean Feng [:sefeng]]

So the last occurrence for the failure was at 2020-11-03. I guess I am not going to do any work now and I'll just leave the patch there and hopefully we don't need to land it.

Comment 23

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.