Open Bug 1292134 Opened 8 years ago Updated 7 months ago

Intermittent pointerevent_touch-action-span-test_touch-manual.html | touch-action attribute test in element: assert_not_equals: span scroll x offset should not be 0 in the end of the test got disallowed value 0

Categories

(Core :: DOM: Events, defect, P3)

defect

Tracking

()

REOPENED
mozilla57
Tracking Status
firefox56 --- fixed
firefox57 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, leave-open, Whiteboard: [stockwell disabled])

Attachments

(2 files)

Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Summary: Intermittent /tests/dom/events/test/pointerevents/pointerevent_touch-action-span-test_touch-manual.html | touch-action attribute test in element: assert_not_equals: span scroll x offset should not be 0 in the end of the test got disallowed value 0 → Intermittent pointerevent_touch-action-span-test_touch-manual.html | touch-action attribute test in element: assert_not_equals: span scroll x offset should not be 0 in the end of the test got disallowed value 0
this intermittent is a lot more frequent in the last week, it looks to be around June 11th when it started, primarily on debug and e10s.

here is a recent linux64-debug log:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=107880648

and here is some of the text surrounding the failure:
[task 2017-06-17T07:38:45.438580Z] 07:38:45     INFO - GECKO(1887) | TEST-PASS | /tests/dom/events/test/pointerevents/pointerevent_touch-action-pan-y-css_touch-manual.html | touch-action: pan-y: Elided 2 passes or known failures.
[task 2017-06-17T07:38:46.742643Z] 07:38:46     INFO - GECKO(1887) | --DOMWINDOW == 13 (0x7f67a4c0e000) [pid = 1932] [serial = 242] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/events/test/pointerevents/pointerevent_touch-action-pan-x-css_touch-manual.html]
[task 2017-06-17T07:38:46.747672Z] 07:38:46     INFO - GECKO(1887) | --DOMWINDOW == 12 (0x7f67a34ae800) [pid = 1932] [serial = 245] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/events/test/pointerevents/pointerevent_touch-action-pan-x-pan-y-pan-y_touch-manual.html]
[task 2017-06-17T07:38:47.996021Z] 07:38:47     INFO - GECKO(1887) | JavaScript error: resource:///modules/E10SUtils.jsm, line 127: TypeError: aURI is null
[task 2017-06-17T07:38:47.999123Z] 07:38:47     INFO - GECKO(1887) | ++DOCSHELL 0x7f67a3961800 == 5 [pid = 1932] [id = {f8b0cacf-8f5d-4877-8e42-2fdf2e2053a7}]
[task 2017-06-17T07:38:48.001335Z] 07:38:48     INFO - GECKO(1887) | ++DOMWINDOW == 13 (0x7f67a396d000) [pid = 1932] [serial = 254] [outer = (nil)]
[task 2017-06-17T07:38:48.032279Z] 07:38:48     INFO - GECKO(1887) | [Parent 1887] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser.
[task 2017-06-17T07:38:48.034229Z] 07:38:48     INFO - GECKO(1887) | : file /home/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 794
[task 2017-06-17T07:38:48.282099Z] 07:38:48     INFO - GECKO(1887) | ++DOMWINDOW == 14 (0x7f67a4c15000) [pid = 1932] [serial = 255] [outer = 0x7f67a396d000]
[task 2017-06-17T07:38:48.439315Z] 07:38:48     INFO - GECKO(1887) | ++DOMWINDOW == 15 (0x7f67a5d8e000) [pid = 1932] [serial = 256] [outer = 0x7f67a396d000]
[task 2017-06-17T07:38:50.149576Z] 07:38:50     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:38:50.412909Z] 07:38:50     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:38:51.672354Z] 07:38:51     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:38:52.807973Z] 07:38:52     INFO - GECKO(1887) | --DOCSHELL 0x7f67a34af000 == 4 [pid = 1932] [id = {0c37cd7a-a6a0-4f18-94a6-83e29e5d30c4}]
[task 2017-06-17T07:38:52.945020Z] 07:38:52     INFO - GECKO(1887) | --DOCSHELL 0x7f67a34ad800 == 3 [pid = 1932] [id = {7bf28864-d054-41ca-a1ff-64d81594df9c}]
[task 2017-06-17T07:38:52.962645Z] 07:38:52     INFO - GECKO(1887) | --DOMWINDOW == 14 (0x7f67a3965800) [pid = 1932] [serial = 247] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:38:52.964329Z] 07:38:52     INFO - GECKO(1887) | --DOMWINDOW == 13 (0x7f67a395b800) [pid = 1932] [serial = 249] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:38:52.967434Z] 07:38:52     INFO - GECKO(1887) | --DOMWINDOW == 12 (0x7f67a5e02800) [pid = 1932] [serial = 244] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:38:53.809428Z] 07:38:53     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:38:54.047634Z] 07:38:54     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:38:54.090087Z] 07:38:54     INFO - GECKO(1887) | --DOMWINDOW == 11 (0x7f67a34b1800) [pid = 1932] [serial = 248] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/events/test/pointerevents/pointerevent_touch-action-pan-x-pan-y_touch-manual.html]
[task 2017-06-17T07:38:54.111028Z] 07:38:54     INFO - GECKO(1887) | TEST-PASS | /tests/dom/events/test/pointerevents/pointerevent_touch-action-span-test_touch-manual.html | Span touch-action test: Elided 1 passes or known failures.
[task 2017-06-17T07:38:54.116080Z] 07:38:54    ERROR - GECKO(1887) | TEST-UNEXPECTED-FAIL | /tests/dom/events/test/pointerevents/pointerevent_touch-action-span-test_touch-manual.html | touch-action attribute test in element: assert_not_equals: span scroll y offset should not be 0 in the end of the test got disallowed value 0
[task 2017-06-17T07:38:54.134371Z] 07:38:54     INFO - GECKO(1887) | TEST-PASS | /tests/dom/events/test/pointerevents/pointerevent_touch-action-span-test_touch-manual.html | Span touch-action test: Elided 1 passes or known failures.
[task 2017-06-17T07:38:56.611616Z] 07:38:56     INFO - GECKO(1887) | JavaScript error: resource:///modules/E10SUtils.jsm, line 127: TypeError: aURI is null
[task 2017-06-17T07:38:56.614226Z] 07:38:56     INFO - GECKO(1887) | ++DOCSHELL 0x7f67a3950800 == 4 [pid = 1932] [id = {96957d55-47ac-40be-8409-c68a0f8674b3}]
[task 2017-06-17T07:38:56.619219Z] 07:38:56     INFO - GECKO(1887) | ++DOMWINDOW == 12 (0x7f67a3951800) [pid = 1932] [serial = 257] [outer = (nil)]
[task 2017-06-17T07:38:56.662586Z] 07:38:56     INFO - GECKO(1887) | [Parent 1887] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser.
[task 2017-06-17T07:38:56.664752Z] 07:38:56     INFO - GECKO(1887) | : file /home/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 794
[task 2017-06-17T07:38:56.901658Z] 07:38:56     INFO - GECKO(1887) | ++DOMWINDOW == 13 (0x7f67a4c0e800) [pid = 1932] [serial = 258] [outer = 0x7f67a3951800]
[task 2017-06-17T07:38:57.107388Z] 07:38:57     INFO - GECKO(1887) | ++DOMWINDOW == 14 (0x7f67a4c1d000) [pid = 1932] [serial = 259] [outer = 0x7f67a3951800]
[task 2017-06-17T07:38:58.459730Z] 07:38:58     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:38:58.952648Z] 07:38:58     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:38:59.359995Z] 07:38:59     INFO - GECKO(1887) | --DOCSHELL 0x7f67a3961800 == 3 [pid = 1932] [id = {f8b0cacf-8f5d-4877-8e42-2fdf2e2053a7}]
[task 2017-06-17T07:38:59.362101Z] 07:38:59     INFO - GECKO(1887) | --DOMWINDOW == 13 (0x7f67a3963000) [pid = 1932] [serial = 250] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:38:59.363486Z] 07:38:59     INFO - GECKO(1887) | --DOMWINDOW == 12 (0x7f67a3957800) [pid = 1932] [serial = 252] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:38:59.364871Z] 07:38:59     INFO - GECKO(1887) | --DOMWINDOW == 11 (0x7f67a4c15000) [pid = 1932] [serial = 255] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:39:01.251112Z] 07:39:01     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:01.287597Z] 07:39:01     INFO - GECKO(1887) | --DOMWINDOW == 10 (0x7f67a34b2000) [pid = 1932] [serial = 251] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/events/test/pointerevents/pointerevent_touch-action-pan-y-css_touch-manual.html]
[task 2017-06-17T07:39:03.401817Z] 07:39:03     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:03.486372Z] 07:39:03     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:03.523014Z] 07:39:03     INFO - GECKO(1887) | TEST-PASS | /tests/dom/events/test/pointerevents/pointerevent_touch-action-svg-test_touch-manual.html | SVG test: Elided 3 passes or known failures.
[task 2017-06-17T07:39:05.015355Z] 07:39:05     INFO - GECKO(1887) | --DOMWINDOW == 9 (0x7f67a4c0e800) [pid = 1932] [serial = 258] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:39:05.018325Z] 07:39:05     INFO - GECKO(1887) | --DOMWINDOW == 8 (0x7f67a3960800) [pid = 1932] [serial = 253] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:39:05.903569Z] 07:39:05     INFO - GECKO(1887) | JavaScript error: resource:///modules/E10SUtils.jsm, line 127: TypeError: aURI is null
[task 2017-06-17T07:39:05.907417Z] 07:39:05     INFO - GECKO(1887) | ++DOCSHELL 0x7f67a34a9000 == 4 [pid = 1932] [id = {885a66d4-7361-4e94-bf08-6fa0ba12c8f9}]
[task 2017-06-17T07:39:05.909529Z] 07:39:05     INFO - GECKO(1887) | ++DOMWINDOW == 9 (0x7f67a34aa000) [pid = 1932] [serial = 260] [outer = (nil)]
[task 2017-06-17T07:39:05.946661Z] 07:39:05     INFO - GECKO(1887) | [Parent 1887] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser.
[task 2017-06-17T07:39:05.948758Z] 07:39:05     INFO - GECKO(1887) | : file /home/worker/workspace/build/src/dom/base/nsFrameLoader.cpp, line 794
[task 2017-06-17T07:39:06.176387Z] 07:39:06     INFO - GECKO(1887) | ++DOMWINDOW == 10 (0x7f67a34bd000) [pid = 1932] [serial = 261] [outer = 0x7f67a34aa000]
[task 2017-06-17T07:39:06.339842Z] 07:39:06     INFO - GECKO(1887) | ++DOMWINDOW == 11 (0x7f67a3955000) [pid = 1932] [serial = 262] [outer = 0x7f67a34aa000]
[task 2017-06-17T07:39:08.493247Z] 07:39:08     INFO - GECKO(1887) | --DOMWINDOW == 10 (0x7f67a396d000) [pid = 1932] [serial = 254] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/events/test/pointerevents/pointerevent_touch-action-span-test_touch-manual.html]
[task 2017-06-17T07:39:09.799345Z] 07:39:09     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:10.085251Z] 07:39:10     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:12.357356Z] 07:39:12     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:14.225086Z] 07:39:14     INFO - GECKO(1887) | --DOCSHELL 0x7f67a3950800 == 3 [pid = 1932] [id = {96957d55-47ac-40be-8409-c68a0f8674b3}]
[task 2017-06-17T07:39:14.227188Z] 07:39:14     INFO - GECKO(1887) | --DOMWINDOW == 9 (0x7f67a5d8e000) [pid = 1932] [serial = 256] [outer = (nil)] [url = about:blank]
[task 2017-06-17T07:39:14.503411Z] 07:39:14     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:14.600051Z] 07:39:14     INFO - GECKO(1887) | Flushed APZ repaints, waiting for callback...
[task 2017-06-17T07:39:14.641752Z] 07:39:14     INFO - GECKO(1887) | TEST-PASS | /tests/dom/events/test/pointerevents/pointerevent_touch-action-table-test_touch-manual.html | Table touch-action test: Elided 3 passes or known failures.
[task 2017-06-17T07:39:15.673292Z] 07:39:15     INFO - GECKO(1887) | --DOMWINDOW == 8 (0x7f67a3951800) [pid = 1932] [serial = 257] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/events/test/pointerevents/pointerevent_touch-action-svg-test_touch-manual.html]
[task 2017-06-17T07:39:16.775247Z] 07:39:16     INFO - GECKO(1887) | MEMORY STAT | vsize 1793MB | residentFast 104MB | heapAllocated 24MB
[task 2017-06-17T07:39:17.017998Z] 07:39:17     INFO - TEST-OK | dom/events/test/pointerevents/test_touch_action.html | took 103953ms


I will keep an eye on this and make sure that it remains high or reduce the priority if this reduces in frequency.

:overholt, can you get someone from the dom:events team to look at this in the next 2 weeks?
Flags: needinfo?(overholt)
Whiteboard: [stockwell needswork]
Stone may know what's up here.
Flags: needinfo?(overholt) → needinfo?(sshih)
Didn't find something useful in the logs for identifying the cause. Have to do some tests.
Whiteboard: [stockwell needswork] → [stockwell unknown]
Priority: P3 → --
Whiteboard: [stockwell unknown] → [stockwell needswork:DOM]
this has gone back and forth in frequency- I think due to the lower volume of pushes in the last 2 weeks- do let me know if there is more data that would be helpful in tracking this down.
Whiteboard: [stockwell needswork:DOM] → [stockwell needswork:owner]
3 of the last 4 weeks this has been a high frequency failure, :stone, do you have plans to work on this soon, or should we disable this test?
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #37)
> 3 of the last 4 weeks this has been a high frequency failure, :stone, do you
> have plans to work on this soon, or should we disable this test?

I'm trying to figure out what's going on. I might disable it if still can't find something cause it in these days.
Flags: needinfo?(sshih)
Priority: -- → P2
Can't reproduce it in local with rr. Reproduced it on try server [1] and it looks like touchScrollDown doesn't work when this test failed.

Normally we got the following sequence
  Test case resets target's scrollLeft to 0
  Dispatch scroll event (target's scrollLeft = 0)
  Test case synthesize drag
  Dispatch scroll event (target's scrollLeft != 0)

When the problem happened
  Test case resets target's scrollLeft to 0
  Test case synthesize drag
  Dispatch scroll event (target's scrollLeft = 0)

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=2f1088c2f81cd69cbf02fcb3547d17ef0459c564&selectedJob=125717938

Hi Kats
Any thoughts?
Flags: needinfo?(bugmail)
Thanks for the try pushes and logging! I looked at the log and I suspect what's happening is that there is a collision between the setTimeout in the test and APZ doing the touchScrollDown. That is, one of the "objectScroller set left to 0" lines before [1] takes some time to propagate that scroll position update to APZ. But in the meantime we dispatch the touch input to APZ. If the scroll position update arrives at APZ after the input events, it will cancel the effect of the input block because JS scrolling takes priority over user scrolling in this scenario. I think what we need to do is delay the input a little more so that we are guaranteed to send it after the scroll position update has been received.

I think if you copy the line at [2] and paste it again just before [3] that should probably fix it.

[1] https://treeherder.mozilla.org/logviewer.html#?job_id=125717938&repo=try&lineNumber=9301
[2] http://searchfox.org/mozilla-central/rev/5696c3e525fc8222674eed6a562f5fcbe804c4c7/dom/events/test/pointerevents/touch_action_helpers.js#162
[3] http://searchfox.org/mozilla-central/rev/5696c3e525fc8222674eed6a562f5fcbe804c4c7/dom/events/test/pointerevents/touch_action_helpers.js#164
Flags: needinfo?(bugmail)
great progress here!
waitForApzFlushedRepaints before touchScrollDown can decrease the possibility but still can reproduce it.
https://treeherder.mozilla.org/#/jobs?repo=try&author=sshih@mozilla.com&selectedJob=126319755

It seems the problem is not reproducible when using longer timeout
https://treeherder.mozilla.org/#/jobs?repo=try&revision=00df494e1e10ff47784d4562d3ec4119146bb60a

Try to explicitly wait for the scroll event which is triggered by reset scrollLeft and check if this is still reproducible.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b4b3d6de8cbd5f84c6a61df129ee5fc230a3bb87
Assignee: nobody → sshih
(In reply to Ming-Chou Shih [:stone] from comment #44)
> Created attachment 8902145 [details] [diff] [review]
> Revise touch-action related test cases to wait for the scroll event to avoid
> resetting scrollLeft break the following scroll behaviors.

It seems bug 1347322 and bug 1347689 are caused by the same problem. This patch includes the fix for them. According to [1], they are no longer reproducible.
[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=9d4a51cf1a3add0f2b43b15bb97105908d95f110
Attachment #8902145 - Flags: review?(bugmail)
Comment on attachment 8902145 [details] [diff] [review]
Revise touch-action related test cases to wait for the scroll event to avoid resetting scrollLeft break the following scroll behaviors.

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

This seems reasonable also, thanks!
Attachment #8902145 - Flags: review?(bugmail) → review+
Pushed by sshih@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b85516a5f3bd
Revise touch-action related test cases to wait for the scroll event to avoid resetting scrollLeft break the following scroll behaviors. r=kats.
https://hg.mozilla.org/mozilla-central/rev/b85516a5f3bd
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
https://hg.mozilla.org/releases/mozilla-beta/rev/87d6a25221a7
Whiteboard: [stockwell needswork:owner] → [stockwell fixed]
Whiteboard: [stockwell fixed] → [stockwell fixed:timing]
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
The intermittent failure is a timing issue that the test using a timer to reset the variable isFirstPart to false and expect no scroll events are dispatched after that. That assumption is sometimes broken [1]. I think the better solution is to revise the test case.

I'd like to disable it temporarily and revise the test case later.

[1] https://treeherder.mozilla.org/#/jobs?repo=try&author=sshih@mozilla.com&fromchange=80e346ab039f2c7728e5985064c2ef3d51402693&selectedJob=128208587
Attachment #8908464 - Flags: review?(bugmail)
Comment on attachment 8908464 [details] [diff] [review]
Disable pointerevent_touch-action-span-test_touch-manual

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

Either mark this bug leave-open, or file a new bug to track fixing it and put the bug number in the comment in test_touch_action.html
Attachment #8908464 - Flags: review?(bugmail) → review+
Keywords: leave-open
Pushed by sshih@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6af67f8caff4
Disable pointerevent_touch-action-span-test_touch-manual because of intermittent failures. r=kats.
Whiteboard: [stockwell needswork:owner] → [stockwell disabled]
Priority: -- → P2
No failures happened in the past two weeks.
Status: REOPENED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → FIXED
hmmm. The test is disabled. Need to submit some tries to make sure it's fixed.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---

The bug assignee didn't login in Bugzilla in the last 7 months and this bug has priority 'P2'.
:hsinyi, could you have a look please?
For more information, please visit auto_nag documentation.

Assignee: stone123456 → nobody
Flags: needinfo?(htsai)
Severity: normal → --
Flags: needinfo?(htsai)
Priority: P2 → P3
Severity: -- → S3
You need to log in before you can comment on or make changes to this bug.