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

https://treeherder.mozilla.org/logviewer.html#?job_id=233431770&repo=try

https://queue.taskcluster.net/v1/task/DpSaE3YVSe-JP_y6DmXAZw/runs/0/artifacts/public/logs/live_backing.log

Test: mochitest-e10s-4

Context:
18:22:18 INFO - TEST-START | gfx/layers/apz/test/mochitest/test_group_touchevents.html
18:22:18 INFO - GECKO(6368) | Parent process: flushed APZ repaints, waiting for callback...
18:22:18 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:18 INFO - GECKO(6368) | Finished native drag, waiting for transform-end observer...
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:18 INFO - GECKO(6368) | Parent process: flushed APZ repaints, waiting for callback...
18:22:18 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:18 INFO - GECKO(6368) | Finished native drag, waiting for transform-end observer...
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=21
18:22:18 INFO - GECKO(6368) | InjectTouchInput failure. GetLastError=87
18:22:18 INFO - GECKO(6368) | Transform complete; flushing repaints...
18:22:18 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:18 INFO - Not taking screenshot here: see the one that was previously logged
18:22:18 INFO - Buffered messages logged at 18:22:18
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Check if TouchEvent is supported (it should be, the test harness forces it on everywhere)
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Starting subtest helper_basic_pan.html
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_basic_pan.html | check that the window scrolled
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_basic_pan.html | Got some layout viewport scroll events
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_basic_pan.html | Got no visual viewport scroll events
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_basic_pan.html | Got some mozvisualscroll events
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Starting subtest helper_div_pan.html
18:22:18 INFO - Buffered messages finished
18:22:18 INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_div_pan.html | check that the div scrolled - got 49, expected 50
18:22:18 INFO - SimpleTest.is@SimpleTest/SimpleTest.js:320:16
18:22:18 INFO - spawnTest/w.is@gfx/layers/apz/test/mochitest/apz_test_utils.js:281:45
18:22:18 INFO - checkScroll@gfx/layers/apz/test/mochitest/helper_div_pan.html:26:3
18:22:18 INFO - setTimeout handler*repaintDone@gfx/layers/apz/test/mochitest/apz_test_utils.js:147:7
18:22:18 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Starting subtest helper_iframe_pan.html
18:22:19 INFO - GECKO(6368) | Parent process: flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Finished native drag, waiting for transform-end observer...
18:22:19 INFO - GECKO(6368) | Transform complete; flushing repaints...
18:22:19 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | iframe scrolled 50px
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_iframe_pan.html | iframe scrolled at least 45 px
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_iframe_pan.html | iframe scrolled at most 50 px
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Starting subtest helper_tap.html
18:22:19 INFO - GECKO(6368) | Parent process: flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Finished synthesizing tap, waiting for button to be clicked...
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_tap.html | Clicked on button, yay! (at 13,22)
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Starting subtest helper_tap_fullzoom.html
18:22:19 INFO - GECKO(6368) | Parent process: flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Finished synthesizing tap, waiting for button to be clicked...
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_tap_fullzoom.html | Clicked on button, yay! (at 13,123)
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Starting subtest helper_scrollto_tap.html?true
18:22:19 INFO - GECKO(6368) | Parent process: flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:19 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_scrollto_tap.html?true | Document element didn't get painted
18:22:19 INFO - GECKO(6368) | Finished synthesizing tap, waiting for button to be clicked...
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_scrollto_tap.html?true | Clicked on button, yay! (at 13,52)
18:22:19 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | Starting subtest helper_scrollto_tap.html?false
18:22:20 INFO - GECKO(6368) | Parent process: flushed APZ repaints, waiting for callback...
18:22:20 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:20 INFO - GECKO(6368) | Flushed APZ repaints, waiting for callback...
18:22:20 INFO - GECKO(6368) | Finished synthesizing tap, waiting for button to be clicked...
18:22:20 INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_touchevents.html | helper_scrollto_tap.html?false | Clicked on button, yay! (at 13,52)
18:22:20 INFO - GECKO(6368) | MEMORY STAT | vsize 5644MB | vsizeMaxContiguous 74548783MB | residentFast 133MB | heapAllocated 18MB
18:22:20 INFO - TEST-OK | gfx/layers/apz/test/mochitest/test_group_touchevents.html | took 2122ms

As noted in the child bug 1537595, recent try pushes have seen this test produce expected outcome: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=e2ea6029e57f1ea4853cb193c132b6142a2bb743&selectedJob=235790132

Adding intermittent-failure keyword to this bug. Failure for this test to produce expected outcome occurs intermittently on windows10-aarch64.

:kartikaya - do you have bandwidth to look into this failure for windows10-aarch64, or know someone that may be able to assist? If it fails more consistently this test can be disabled for the time being, so it doesn't continuously show up in the test log.

I'm at a workweek at the moment but I can look into it next week. It looks like the taskcluster jobs are running on Lenovo Yoga machines in bitbar so I can try reproducing locally on the Yoga that I have.

I started setting up the Yoga to try and debug this. Of course, it's Windows so even just getting a m-c clone onto the thing is a nightmare. And apparently we're not yet at the point where we can build on arm64 so I'm not sure if it's even worth trying to debug locally. I might just do try pushes.

(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #6)

I started setting up the Yoga to try and debug this. Of course, it's Windows so even just getting a m-c clone onto the thing is a nightmare. And apparently we're not yet at the point where we can build on arm64 so I'm not sure if it's even worth trying to debug locally. I might just do try pushes.

I'm not sure if it will meet your needs, but it is possible to run artifact builds on the windows10-aarch64 hardware successfully. I have been able to run tests with it using the start-shell installed by Mozilla-Build 2.2.0, like ./mach mochitest.

For information on how to get an artifact build going, see https://www.gijsk.com/blog/2019/02/getting-firefox-artifact-builds-working-on-an-arm64-aarch64-windows-device/.

I will also be updating the wiki page at https://wiki.mozilla.org/CI_Automation/windows10_aarch64 due to some parts being out of date already.

Actually the log from the failed run might be enough to diagnose this. I see this:

InjectTouchInput failure. GetLastError=21

show up a bunch of times. Error code 21 is ERROR_NOT_READY, and the InjectTouchInput documentation says:

If a custom PerformanceCount resulted in the same .1 millisecond window from previous injection, the API will return an error (ERROR_NOT_READY) and will not inject the data.

So if this happens on the last touch event, presumably it will just scroll 49 pixels instead of 50. It's basically a timing problem.

Actually we're not setting dwTime or the PerformanceCount, so it's this section that's more relevant:

When neither dwTime or PerformanceCount values are specified, the InjectTouchInput allocates the timestamp based on the timing of the API call. If the calls are less than 0.1 millisecond apart, the API may return an error (ERROR_NOT_READY). The error will not invalidate the input immediately, but the injection application needs to retry the same frame again to ensure injection is successful.

So we can just loop and retry when we get this error condition.

https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=4c4b419e057a686f5d718d25ad91b0c29c1c833a

https://hg.mozilla.org/mozilla-central/rev/2df4f2b12f9a