Closed Bug 1569744 Opened 5 years ago Closed 5 years ago

Intermittent gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected async key scrolling after test - got false, expected true

Categories

(Core :: Panning and Zooming, defect, P5)

Product:
Core
Component:
Panning and Zooming
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla71
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- wontfix
firefox67 --- wontfix
firefox68 --- wontfix
firefox69 --- wontfix
firefox70 --- wontfix
firefox71 --- fixed

People

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

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1569744 - Ensure that lock is held even with smooth scrolling disabled.
47 bytes, text/x-phabricator-request
Details | Review

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=258841980&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/FjYliIqRSw6OQGDTfDmILA/runs/0/artifacts/public/logs/live_backing.log

[task 2019-07-29T18:28:47.495Z] 18:28:47 INFO - GECKO(1928) | [Parent 1928, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-29T18:28:47.544Z] 18:28:47 INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_group_hittest.html | took 6995ms
[task 2019-07-29T18:28:47.587Z] 18:28:47 INFO - GECKO(1928) | ++DOMWINDOW == 48 (0x11c6c6000) [pid = 1930] [serial = 77] [outer = 0x1197453e0]
[task 2019-07-29T18:28:47.688Z] 18:28:47 INFO - TEST-START | gfx/layers/apz/test/mochitest/test_group_keyboard.html
[task 2019-07-29T18:28:47.688Z] 18:28:47 INFO - GECKO(1928) | ++DOMWINDOW == 49 (0x11c915c00) [pid = 1930] [serial = 78] [outer = 0x1197453e0]
[task 2019-07-29T18:28:47.710Z] 18:28:47 INFO - GECKO(1928) | ++DOCSHELL 0x111f1b000 == 9 [pid = 1930] [id = {ce36549e-8b0b-2d48-9997-f130ca564c65}]
[task 2019-07-29T18:28:47.710Z] 18:28:47 INFO - GECKO(1928) | ++DOMWINDOW == 50 (0x1197e23e0) [pid = 1930] [serial = 79] [outer = 0x0]
[task 2019-07-29T18:28:47.726Z] 18:28:47 INFO - GECKO(1928) | [Child 1930, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-07-29T18:28:47.746Z] 18:28:47 INFO - GECKO(1928) | [Parent 1928, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-29T18:28:47.747Z] 18:28:47 INFO - GECKO(1928) | [Parent 1928, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-29T18:28:47.747Z] 18:28:47 INFO - GECKO(1928) | ++DOMWINDOW == 51 (0x11a99d000) [pid = 1930] [serial = 80] [outer = 0x1197e23e0]
<...>
[task 2019-07-29T18:28:48.577Z] 18:28:48 INFO - GECKO(1928) | helper_key_scroll.html | waiting for paint...
[task 2019-07-29T18:28:48.611Z] 18:28:48 INFO - GECKO(1928) | helper_key_scroll.html | got MozAfterPaint: 0,0,0,0
[task 2019-07-29T18:28:48.611Z] 18:28:48 INFO - GECKO(1928) | helper_key_scroll.html | Dispatching 1 onpaint listeners
[task 2019-07-29T18:28:48.611Z] 18:28:48 INFO - GECKO(1928) | helper_key_scroll.html | done...
[task 2019-07-29T18:28:48.612Z] 18:28:48 INFO - TEST-INFO | started process screencapture
[task 2019-07-29T18:28:48.773Z] 18:28:48 INFO - TEST-INFO | screencapture: exit 0
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - Buffered messages logged at 18:28:47
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | Starting subtest helper_key_scroll.html
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - Buffered messages logged at 18:28:48
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected no async key scrolling before test
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - Reached final scroll position of sync KEY_End scroll
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected no async key scrolling before KEY_Home dispatch
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - Reached final scroll position of async KEY_Home scroll
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected at least one paint in compositor test data
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - Buffered messages finished
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected async key scrolling after test - got false, expected true
[task 2019-07-29T18:28:48.778Z] 18:28:48 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
[task 2019-07-29T18:28:48.779Z] 18:28:48 INFO - spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:389:18
[task 2019-07-29T18:28:48.779Z] 18:28:48 INFO - waitForScrollTop/<@gfx/layers/apz/test/mochitest/helper_key_scroll.html:74:9
[task 2019-07-29T18:28:48.779Z] 18:28:48 INFO - setTimeout handlerpaintListener@SimpleTest/paint_listener.js:39:14
[task 2019-07-29T18:28:48.779Z] 18:28:48 INFO - EventListener.handleEvent@SimpleTest/paint_listener.js:42:10
[task 2019-07-29T18:28:48.779Z] 18:28:48 INFO - @SimpleTest/paint_listener.js:103:3
[task 2019-07-29T18:28:48.779Z] 18:28:48 INFO - GECKO(1928) | [Parent 1928, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-29T18:28:48.779Z] 18:28:48 INFO - GECKO(1928) | [Parent 1928, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RangeBoundary.h, line 79
[task 2019-07-29T18:28:48.780Z] 18:28:48 INFO - GECKO(1928) | MEMORY STAT | vsize 7338MB | residentFast 162MB | heapAllocated 23MB
[task 2019-07-29T18:28:48.780Z] 18:28:48 INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_group_keyboard.html | took 1087ms
[task 2019-07-29T18:28:48.780Z] 18:28:48 INFO - GECKO(1928) | ++DOMWINDOW == 32 (0x11214dc00) [pid = 1930] [serial = 82] [outer = 0x1197453e0]
[task 2019-07-29T18:28:48.788Z] 18:28:48 INFO - TEST-START | gfx/layers/apz/test/mochitest/test_group_mainthread.html
[task 2019-07-29T18:28:48.793Z] 18:28:48 INFO - [1925, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-07-29T18:28:48.793Z] 18:28:48 INFO - GECKO(1928) | ++DOMWINDOW == 33 (0x1121dfc00) [pid = 1930] [serial = 83] [outer = 0x1197453e0]
[task 2019-07-29T18:28:48.860Z] 18:28:48 INFO - GECKO(1928) | ++DOCSHELL 0x1121ad000 == 4 [pid = 1930] [id = {2fc76da6-07d1-0f43-9f15-f5d085b91b95}]

Removing "regression" keyword from APZ intermittents for reasons laid out in bug 1571054 comment 0.

Keywords: regression

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=269500186&repo=autoland&lineNumber=28822

task 2019-10-02T20:14:42.821Z] 20:14:42 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected at least one paint in compositor test data
[task 2019-10-02T20:14:42.821Z] 20:14:42 INFO - Buffered messages finished
[task 2019-10-02T20:14:42.830Z] 20:14:42 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | helper_key_scroll.html | expected async key scrolling after test - got false, expected true
[task 2019-10-02T20:14:42.830Z] 20:14:42 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:322:16
[task 2019-10-02T20:14:42.830Z] 20:14:42 INFO - spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:389:18
[task 2019-10-02T20:14:42.830Z] 20:14:42 INFO - waitForScrollTop/<@gfx/layers/apz/test/mochitest/helper_key_scroll.html:74:11
[task 2019-10-02T20:14:42.830Z] 20:14:42 INFO - setTimeout handlerpaintListener@SimpleTest/paint_listener.js:39:14
[task 2019-10-02T20:14:42.830Z] 20:14:42 INFO - EventListener.handleEvent@SimpleTest/paint_listener.js:42:10
[task 2019-10-02T20:14:42.830Z] 20:14:42 INFO - @SimpleTest/paint_listener.js:103:3
[task 2019-10-02T20:14:42.831Z] 20:14:42 INFO - GECKO(1930) | MEMORY STAT | vsize 7386MB | residentFast 199MB | heapAllocated 31MB

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

So I just got a somewhat scary intermittent failure on this test that pernosco managed to catch:

We reproduced the failure

Assertion failure: IsAcquired() && mOwningThread == PR_GetCurrentThread(), at /builds/worker/workspace/build/src/xpcom/threads/BlockingResourceBase.cpp:501

in gfx/layers/apz/test/mochitest/test_group_keyboard.html that may correspond to your recent failed test-linux64-qr/debug-mochitest-e10s-12 test job at https://treeherder.mozilla.org/#/jobs?repo=try&revision=2ab7f3a18f05995a5a2d16167b5e732acf15d569.

Go to https://pernos.co/debug/PCOfTc3h4gIzaeRmNiUaDg/index.html to debug it!
You can view the test harness output at https://s3.us-east-2.amazonaws.com/pernosco-logs/reproducer-mozilla-mozilla/EJnhq2STRtq7vz7RcgCCAA/ZuoTwOjQT2ifaccibsinyQ-16a53d88.log.gz

Seems we're failing the assertion there because Metrics() is accessed without locking. It should be reasonably straight-forward to fix.

Pushed by ealvarez@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7bb758a5b7a0
Ensure that lock is held even with smooth scrolling disabled. r=botond

https://hg.mozilla.org/mozilla-central/rev/7bb758a5b7a0

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
status-firefox71: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla71
Assignee: nobody → emilio

Is there a real-world impact from this bug which might cause us to want to consider uplifting this or can it ride Fx71 to release?

status-firefox67: --- → wontfix
status-firefox68: --- → wontfix
status-firefox69: --- → wontfix
status-firefox70: --- → affected
status-firefox-esr60: --- → unaffected
status-firefox-esr68: --- → affected
Flags: needinfo?(emilio)

301 Botond. It is a data race looks like, but in practice this code path is disabled by default...

Flags: needinfo?(emilio) → needinfo?(botond)

It's a fairly benign data race (by my reading, the worst thing that can happen is we'll scroll to a silly location) in a codepath that's disabled by default. Let's just let it ride the trains.

Flags: needinfo?(botond)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: