1647474 - Intermittent layout/forms/test/test_bug564115.html | The page's scroll offset should not have been changed - got 9, expected 5000

Status: RESOLVED FIXED

(Core :: Layout: Form Controls, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-06-22T20:20:00.549Z] 20:20:00 INFO - TEST-START | layout/forms/test/test_bug564115.html
[task 2020-06-22T20:20:00.778Z] 20:20:00 INFO - GECKO(4651) | [GLX] window 20003b has VisualID 0x41
[task 2020-06-22T20:20:00.785Z] 20:20:00 INFO - GECKO(4651) | [GPU 4689, Renderer] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp, line 623
[task 2020-06-22T20:20:00.787Z] 20:20:00 INFO - GECKO(4651) | [GPU 4689, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/checkouts/gecko/gfx/gl/GLContext.cpp, line 958
[task 2020-06-22T20:20:00.787Z] 20:20:00 INFO - GECKO(4651) | [GPU 4689, Renderer] WARNING: robustness marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp, line 623
[task 2020-06-22T20:20:00.814Z] 20:20:00 INFO - GECKO(4651) | [Parent 4651, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4281
[task 2020-06-22T20:20:01.300Z] 20:20:01 INFO - GECKO(4651) | [2020-06-22T20:20:01Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aClipTileRect", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 4, found at -1
[task 2020-06-22T20:20:01.940Z] 20:20:01 INFO - GECKO(4651) | [2020-06-22T20:20:01Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aClipTileRect", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 4, found at -1
[task 2020-06-22T20:20:02.021Z] 20:20:02 INFO - GECKO(4651) | [2020-06-22T20:20:02Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aClipLocalPos", count: 2, kind: F32 } is not found in the shader cs_clip_box_shadow. Expected at 3, found at -1
[task 2020-06-22T20:20:02.023Z] 20:20:02 INFO - GECKO(4651) | [2020-06-22T20:20:02Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aClipTileRect", count: 4, kind: F32 } is not found in the shader cs_clip_box_shadow. Expected at 4, found at -1
[task 2020-06-22T20:20:02.905Z] 20:20:02 INFO - GECKO(4651) | [2020-06-22T20:20:02Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aUvRect1", count: 4, kind: F32 } is not found in the shader composite. Expected at 6, found at -1
[task 2020-06-22T20:20:02.905Z] 20:20:02 INFO - GECKO(4651) | [2020-06-22T20:20:02Z WARN webrender::device::gl] Attribute VertexAttribute { name: "aUvRect2", count: 4, kind: F32 } is not found in the shader composite. Expected at 7, found at -1
[task 2020-06-22T20:20:03.614Z] 20:20:03 INFO - TEST-INFO | started process screentopng
[task 2020-06-22T20:20:04.078Z] 20:20:04 INFO - TEST-INFO | screentopng: exit 0
[task 2020-06-22T20:20:04.079Z] 20:20:04 INFO - Buffered messages logged at 20:20:01
[task 2020-06-22T20:20:04.080Z] 20:20:04 INFO - must wait for load
[task 2020-06-22T20:20:04.081Z] 20:20:04 INFO - must wait for focus
[task 2020-06-22T20:20:04.082Z] 20:20:04 INFO - TEST-PASS | layout/forms/test/test_bug564115.html | Page should be scrolled correctly
[task 2020-06-22T20:20:04.083Z] 20:20:04 INFO - must wait for focus
[task 2020-06-22T20:20:04.083Z] 20:20:04 INFO - Buffered messages logged at 20:20:03
[task 2020-06-22T20:20:04.084Z] 20:20:04 INFO - must wait for focus
[task 2020-06-22T20:20:04.085Z] 20:20:04 INFO - Buffered messages finished
[task 2020-06-22T20:20:04.086Z] 20:20:04 INFO - TEST-UNEXPECTED-FAIL | layout/forms/test/test_bug564115.html | The page's scroll offset should not have been changed - got 9, expected 5000
[task 2020-06-22T20:20:04.087Z] 20:20:04 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:383:14
[task 2020-06-22T20:20:04.088Z] 20:20:04 INFO - @layout/forms/test/test_bug564115.html:39:17
[task 2020-06-22T20:20:04.088Z] 20:20:04 INFO - focusedOrLoaded/<@SimpleTest/SimpleTest.js:918:23
[task 2020-06-22T20:20:04.089Z] 20:20:04 INFO - GECKO(4651) | MEMORY STAT | vsize 2574MB | residentFast 170MB | heapAllocated 19MB
[task 2020-06-22T20:20:04.092Z] 20:20:04 INFO - GECKO(4651) | [Child 4893, Main Thread] WARNING: SendNotifyIMEFocus got rejected.: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp, line 784
[task 2020-06-22T20:20:04.093Z] 20:20:04 INFO - GECKO(4651) | [GPU 4689, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp, line 370

Comment 1

[Intermittent Failures Robot]

21 failures in 1020 pushes (0.021 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 17
• try: 2
• mozilla-central: 2

Platform breakdown:

• linux1804-64-qr: 14
• linux1804-64-tsan: 1
• linux1804-64-shippable-qr: 6

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

Comment 2

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

This looks WR-specific. Please triage this frequent failure.

Comment 3

[Kartikaya Gupta (email:[e-mail])]

There's also one instance on a tsan non-qr build, so it might be a general race condition that just happens to trigger more with QR builds. Looking at the test I'm not sure offhand why it would fail like this except if somehow putting focus on the input field is causing a scroll-to-input that ends up putting the scroll position at y=9, and that scroll-to-input clobbers any other attempts at scrolling.

At any rate it might be a bug in the code so I'll take a closer look.

Comment 4

[Kartikaya Gupta (email:[e-mail])]

Indeed, there is some sort of scroll-into-view thing going on:

 0:59.14 GECKO(31286) #01: mozilla::PresShell::ScrollFrameRectIntoView(nsIFrame*, nsRect const&, mozilla::ScrollAxis, mozilla::ScrollAxis, mozilla::ScrollFlags) (/home/kats/zspace/gecko-fire/layout/generic/nsIFrame.h:5402)
 0:59.14 GECKO(31286) #02: mozilla::dom::Selection::ScrollIntoView(short, mozilla::ScrollAxis, mozilla::ScrollAxis, int) (/home/kats/zspace/gecko-fire/dom/base/Selection.cpp:2979)
 0:59.14 GECKO(31286) #03: mozilla::dom::Selection::ScrollSelectionIntoViewEvent::Run() (/home/kats/zspace/gecko-fire/dom/base/Selection.cpp:2885)
 0:59.15 GECKO(31286) #04: nsRefreshDriver::Tick(mozilla::layers::BaseTransactionId<mozilla::VsyncIdType>, mozilla::TimeStamp) (/home/kats/zspace/gecko-fire/obj-host-debugopt/dist/include/mozilla/ArrayIterator.h:85)

Comment 5

[Kartikaya Gupta (email:[e-mail])]

Oh. Looks like emilio touched this code recently, around when this started.

Comment 6

[Kartikaya Gupta (email:[e-mail])]

As far as I can tell the double-rAF seems insufficient sometimes? I sometimes see the ScrollIntoView happening after the scrollTo(5000) and that obviously then causes problems. I haven't been able to catch the problem in rr so chasing it down is a bit harder than I'd like.

Comment 7

[Emilio Cobos Álvarez (:emilio)]

Hmm, it ought to be sufficient, we run early refresh runners (the ScrollSelectionIntoViewEvent) before frame request callbacks...

https://searchfox.org/mozilla-central/rev/a87a1c3b543475276e6d57a7a80cb02f3e42b6ed/layout/base/nsRefreshDriver.cpp#1938-1942,2019

Comment 8

[Emilio Cobos Álvarez (:emilio)]

If you don't have the cycles to dig into this I can take this Kats, just let me know.

Comment 9

[Kartikaya Gupta (email:[e-mail])]

Yes please. If it turns out to be some weird scroll synchronization problem then feel free to throw it back to me.

Comment 10

[Emilio Cobos Álvarez (:emilio)]

I don't think it will be.

Comment 11

[Intermittent Failures Robot]

21 failures in 1046 pushes (0.02 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 5
• autoland: 11
• mozilla-central: 5

Platform breakdown:

• linux1804-64-qr: 18
• linux1804-64-shippable-qr: 3

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

Comment 12

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

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

Comment 13

[Emilio Cobos Álvarez (:emilio)]

Attachment: Bug 1647474 - Wait for frame callbacks on the right window. r=kats

Quite obvious in hindsight :(

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d6deac041d1a
Wait for frame callbacks on the right window. r=kats

Comment 15

[Atila Butkovits]

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

Comment 16

[Intermittent Failures Robot]

15 failures in 1151 pushes (0.013 failures/push) were associated with this bug yesterday.

Repository breakdown:

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

Platform breakdown:

• linux1804-64-qr: 11
• linux1804-64-shippable-qr: 4

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

Comment 17

[Intermittent Failures Robot]

63 failures in 5252 pushes (0.012 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: 39
• mozilla-central: 16
• try: 8

Platform breakdown:

• linux1804-64-qr: 48
• linux1804-64-shippable-qr: 14
• linux1804-64-tsan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1647474&startday=2020-06-22&endday=2020-06-28&tree=all