Open Bug 1850660 Opened 9 months ago Updated 12 days ago

Intermittent gfx/layers/apz/test/mochitest/test_group_double_tap_zoom.html | single tracking bug

Categories

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

Product:
Core
Component:
Panning and Zooming
Type:
defect

Tracking

()

Status:
REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, intermittent-testcase)

Attachments

(3 files, 1 obsolete file)

a screen shot on a failure run
359.56 KB, image/png
Details
another screen shot on a failure run on the revision I commented in comment 14
391.75 KB, image/png
Details
A screen shot on a different test failure run
226.35 KB, image/png
Details

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

[task 2023-08-30T02:44:09.622Z] 02:44:09     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_double_tap_zoom.html | helper_doubletap_zoom_small.html?touchpad | only implemented on mac. implement sendNativeTouchpadDoubleTap for this platform, see bug 1696802 for how it was done on macOS 
[task 2023-08-30T02:44:09.622Z] 02:44:09     INFO - Buffered messages finished
[task 2023-08-30T02:44:09.622Z] 02:44:09     INFO - TEST-UNEXPECTED-TIMEOUT | gfx/layers/apz/test/mochitest/test_group_double_tap_zoom.html | application timed out after 370 seconds with no output
[task 2023-08-30T02:44:09.622Z] 02:44:09     INFO - TEST-INFO took 383636ms
[task 2023-08-30T02:44:09.623Z] 02:44:09     INFO - Buffered messages finished
[task 2023-08-30T02:44:09.623Z] 02:44:09  WARNING - Force-terminating active process(es).
[task 2023-08-30T02:44:09.623Z] 02:44:09     INFO - Determining child pids from psutil...
[task 2023-08-30T02:44:09.623Z] 02:44:09     INFO - [7355, 7357, 7358, 7360, 7387, 7396, 7397]
[task 2023-08-30T02:44:09.624Z] 02:44:09     INFO - ==> process 7354 launched child process 7355
[task 2023-08-30T02:44:09.624Z] 02:44:09     INFO - ==> process 7354 launched child process 7356
[task 2023-08-30T02:44:09.624Z] 02:44:09     INFO - ==> process 7354 launched child process 7357
[task 2023-08-30T02:44:09.624Z] 02:44:09     INFO - ==> process 7354 launched child process 7358
[task 2023-08-30T02:44:09.625Z] 02:44:09     INFO - ==> process 7354 launched child process 7359
[task 2023-08-30T02:44:09.625Z] 02:44:09     INFO - ==> process 7354 launched child process 7360
[task 2023-08-30T02:44:09.625Z] 02:44:09     INFO - ==> process 7354 launched child process 7361
[task 2023-08-30T02:44:09.626Z] 02:44:09     INFO - ==> process 7354 launched child process 7362
[task 2023-08-30T02:44:09.626Z] 02:44:09     INFO - ==> process 7354 launched child process 7377
[task 2023-08-30T02:44:09.626Z] 02:44:09     INFO - ==> process 7354 launched child process 7386
[task 2023-08-30T02:44:09.626Z] 02:44:09     INFO - ==> process 7354 launched child process 7387
[task 2023-08-30T02:44:09.627Z] 02:44:09     INFO - ==> process 7354 launched child process 7396
[task 2023-08-30T02:44:09.627Z] 02:44:09     INFO - ==> process 7354 launched child process 7397
[task 2023-08-30T02:44:09.627Z] 02:44:09     INFO - Found child pids: {7360, 7361, 7362, 7396, 7397, 7387, 7377, 7386, 7355, 7356, 7357, 7358, 7359}
[task 2023-08-30T02:44:09.627Z] 02:44:09     INFO - Failed to get child procs
[task 2023-08-30T02:44:09.628Z] 02:44:09     INFO - Killing process: 7360
[task 2023-08-30T02:44:09.628Z] 02:44:09     INFO - TEST-INFO | started process screencapture
[task 2023-08-30T02:44:09.716Z] 02:44:09     INFO - TEST-INFO | screencapture: exit 0
[task 2023-08-30T02:44:09.716Z] 02:44:09     INFO - Killing process: 7361
[task 2023-08-30T02:44:09.716Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.716Z] 02:44:09     INFO - Can't trigger Breakpad, process no longer exists
[task 2023-08-30T02:44:09.717Z] 02:44:09     INFO - Killing process: 7362
[task 2023-08-30T02:44:09.717Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.717Z] 02:44:09     INFO - Can't trigger Breakpad, process no longer exists
[task 2023-08-30T02:44:09.718Z] 02:44:09     INFO - Killing process: 7396
[task 2023-08-30T02:44:09.718Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.718Z] 02:44:09     INFO - Killing process: 7397
[task 2023-08-30T02:44:09.718Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.719Z] 02:44:09     INFO - Killing process: 7387
[task 2023-08-30T02:44:09.719Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.719Z] 02:44:09     INFO - Killing process: 7377
[task 2023-08-30T02:44:09.720Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.720Z] 02:44:09     INFO - Can't trigger Breakpad, process no longer exists
[task 2023-08-30T02:44:09.720Z] 02:44:09     INFO - Killing process: 7386
[task 2023-08-30T02:44:09.720Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.721Z] 02:44:09     INFO - Can't trigger Breakpad, process no longer exists
[task 2023-08-30T02:44:09.721Z] 02:44:09     INFO - Killing process: 7355
[task 2023-08-30T02:44:09.721Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.721Z] 02:44:09     INFO - Killing process: 7356
[task 2023-08-30T02:44:09.722Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.722Z] 02:44:09     INFO - Can't trigger Breakpad, process no longer exists
[task 2023-08-30T02:44:09.722Z] 02:44:09     INFO - Killing process: 7357
[task 2023-08-30T02:44:09.722Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.723Z] 02:44:09     INFO - Killing process: 7358
[task 2023-08-30T02:44:09.723Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.723Z] 02:44:09     INFO - Killing process: 7359
[task 2023-08-30T02:44:09.724Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:09.724Z] 02:44:09     INFO - Can't trigger Breakpad, process no longer exists
[task 2023-08-30T02:44:09.724Z] 02:44:09     INFO - Killing process: 7354
[task 2023-08-30T02:44:09.724Z] 02:44:09     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-08-30T02:44:10.108Z] 02:44:10     INFO - psutil found pid 7354 dead
[task 2023-08-30T03:00:50.240Z] 03:00:50     INFO - Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_169335311989996/build/venv/bin/python', '-u', '/opt/worker/tasks/task_169335311989996/build/tests/mochitest/runtests.py', 'browser/components/extensions/test/mochitest/mochitest.ini', 'browser/components/resistfingerprinting/test/mochitest/mochitest.ini', 'dom/animation/test/mochitest.ini', 'dom/base/test/fullscreen/mochitest.ini', 'dom/bindings/test/mochitest.ini', 'dom/canvas/test/crossorigin/mochitest.ini', 'dom/console/tests/mochitest.ini', 'dom/credentialmanagement/tests/mochitest/mochitest.ini', 'dom/events/test/mochitest.ini', 'dom/file/tests/mochitest.ini', 'dom/html/test/forms/without_selectionchange/mochitest.ini', 'dom/localstorage/test/mochitest.ini', 'dom/midi/tests/mochitest.ini', 'dom/promise/tests/mochitest.ini', 'dom/security/sanitizer/tests/mochitest/mochitest.ini', 'dom/security/test/general/mochitest.ini', 'dom/security/test/sri/mochitest.ini', 'dom/tests/mochitest/ajax/jquery/mochitest.ini', 'dom/tests/mochitest/dom-level2-core/mochitest.ini', 'dom/tests/mochitest/dom-level2-html/mochitest.ini', 'dom/tests/mochitest/localstorage/mochitest.ini', 'dom/websocket/tests/mochitest.ini', 'dom/xslt/tests/mochitest/mochitest.ini', 'editor/libeditor/tests/mochitest.ini', 'gfx/layers/apz/test/mochitest/mochitest.ini', 'intl/uconv/tests/mochitest.ini', 'js/xpconnect/tests/mochitest/hasinstance/mochitest.ini', 'layout/inspector/tests/mochitest.ini', 'layout/tables/test/mochitest.ini', 'modules/libjar/test/mochitest/mochitest.ini', 'toolkit/components/find/test/mochitest/mochitest.ini', 'toolkit/content/tests/mochitest/mochitest.ini', 'toolkit/xre/test/mochitest.ini', '--setpref=layout.css.stylo-threads=4', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--appname=/opt/worker/tasks/task_169335311989996/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=/opt/worker/tasks/task_169335311989996/build/symbols', '--certificate-path=tests/certs', '--quiet', '--log-errorsummary=/opt/worker/tasks/task_169335311989996/build/blobber_upload_dir/mochitest-plain_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/opt/worker/tasks/task_169335311989996/build', '--log-raw=-', '--chunk-by-dir=4']
[taskcluster:error] Aborting task...
[taskcluster:warn 2023-08-30T03:41:56.022Z] no such process
[taskcluster 2023-08-30T03:41:56.022Z] === Task Finished ===

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

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

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=441786820&repo=mozilla-central

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Attachment #9383779 - Attachment is obsolete: true

The failure rate here seems to have spiked in the last couple of days.

The failures are all timeouts on Mac. I had a look at a few of the logs and in each case, the last log message before the timeout is from helper_doubletap_zoom_textarea.html.

I noticed that will call sendNativeTouchTap but it doesn't pass an observer, not sure if that could be why.

The helper_doubletap_zoom_textarea.html timedout failures seem to have started from this change (bug 1889463), but it's frontend changes.

I have no idea how it affected the test case.

I tried to run test_group_double_tap_zoom.html with --run-until-failure locally on my Macbook, but I haven't seen any failures.

(In reply to Timothy Nikkel (:tnikkel) from comment #13)

I noticed that will call sendNativeTouchTap but it doesn't pass an observer, not sure if that could be why.

Awaiting the observer callback doesn't help there. I also tried a larger offset where the double-tap happens (which was inspired by this change), it doesn't help either.

See Also: → 1893742

I filed bug 1893742 to temporarily disable the offending subtest.

See Also: → 1894132

(In reply to Botond Ballo [:botond] from comment #19)

I filed bug 1893742 to temporarily disable the offending subtest.

Unfortunately, the high failure rate is persisting. This time, it seems to be the touchpad variant of helper_doubletap_zoom_textarea.html which is timing out.

Here is a screenshot on a failure run, oddly the textarea is out of the viewport, thus I guess tapping on the textarea element did nothing.

In this screenshot, the textarea element is also out of the viewport, and oddly the mouse cursor is the one as if it's hovering over the textarea element. :/

Okay, now I have a hypothesis where the test in question, helper_doubletap_zoom_textarea.html fails.

Attaching screen short is a failure run that a different test, helper_doubletap_zoom_touch_action_manipulation.html failed. As you can see the screen size is 1920x1080. On the other hands both screen shot's sizes in comment 23 and comment 24 are 3840 x 2160. So my hypothesis is that helper_doubletap_zoom_textarea.html fails on 3840 x 2160.

(In reply to Hiroyuki Ikezoe (:hiro) from comment #23)

Created attachment 9400620 [details]
a screen shot on a failure run

Here is a screenshot on a failure run, oddly the textarea is out of the viewport, thus I guess tapping on the textarea element did nothing.

I briefly looked into this when it first spiked (but I didn't find anything worth reporting), and from my memory having the textarea out of view is fine because I believe the screenshot is after we double tapped to zoom in, and then the next step of the test was to double tap and have it zoom out, but that zoom out part is failing for some reason.

Interesting that we are getting test machines which very different resolutions!

Maybe Joel knows why the screen resolution would differ.

(In reply to Timothy Nikkel (:tnikkel) from comment #26)

(In reply to Hiroyuki Ikezoe (:hiro) from comment #23)

Created attachment 9400620 [details]
a screen shot on a failure run

Here is a screenshot on a failure run, oddly the textarea is out of the viewport, thus I guess tapping on the textarea element did nothing.

I briefly looked into this when it first spiked (but I didn't find anything worth reporting), and from my memory having the textarea out of view is fine because I believe the screenshot is after we double tapped to zoom in, and then the next step of the test was to double tap and have it zoom out, but that zoom out part is failing for some reason.

A problem here in this case is that if the textarea (which is the target element of doubleTapOn) is out of the viewport, the calculated tapping point on the element in the screen coordinates will be out of the screen.

Depends on: 1896016
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: