Open Bug 1918902 Opened 1 year ago Updated 1 day ago

Intermittent Linux shippable headless [tier 2] TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms. Animated image still doesn't look correct, after call #4703 to myPoll

Categories

(Core :: Graphics: ImageLib, defect, P5)

Product:
Core
Component:
Graphics: ImageLib
Type:
defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned, NeedInfo)

References

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [retriggered])

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

[task 2024-09-15T00:56:14.421Z] 00:56:14     INFO - TEST-PASS | image/test/mochitest/test_animSVGImage.html | The author of the test has indicated that flaky timeouts are expected.  Reason: Pre-existing timeouts when converting from mochitest-chrome 
[task 2024-09-15T00:56:14.422Z] 00:56:14     INFO - TEST-INFO | started process screentopng
[task 2024-09-15T00:56:14.616Z] 00:56:14     INFO - TEST-INFO | screentopng: exit 0
[task 2024-09-15T00:56:14.616Z] 00:56:14     INFO - Buffered messages logged at 00:54:14
[task 2024-09-15T00:56:14.617Z] 00:56:14     INFO - TEST-PASS | image/test/mochitest/test_animSVGImage.html | A valid string reason is expected 
[task 2024-09-15T00:56:14.617Z] 00:56:14     INFO - TEST-PASS | image/test/mochitest/test_animSVGImage.html | Reason cannot be empty 
[task 2024-09-15T00:56:14.617Z] 00:56:14     INFO - Buffered messages finished
[task 2024-09-15T00:56:14.618Z] 00:56:14     INFO - TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms.  Animated image still doesn't look correct, after call #4703 to myPoll 
[task 2024-09-15T00:56:14.618Z] 00:56:14     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:426:16
[task 2024-09-15T00:56:14.618Z] 00:56:14     INFO -     failTest@image/test/mochitest/test_animSVGImage.html:89:5
[task 2024-09-15T00:56:14.618Z] 00:56:14     INFO -     setTimeout handler*SimpleTest_setTimeoutShim@SimpleTest/SimpleTest.js:922:41
[task 2024-09-15T00:56:14.618Z] 00:56:14     INFO -     main@image/test/mochitest/test_animSVGImage.html:116:13
[task 2024-09-15T00:56:14.618Z] 00:56:14     INFO -     EventHandlerNonNull*@image/test/mochitest/test_animSVGImage.html:119:1
[task 2024-09-15T00:56:14.620Z] 00:56:14     INFO - GECKO(12795) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2024-09-15T00:56:14.621Z] 00:56:14     INFO - GECKO(12795) | MEMORY STAT | vsize 2731MB | residentFast 224MB | heapAllocated 66MB
[task 2024-09-15T00:56:14.621Z] 00:56:14     INFO - Buffered messages logged at 00:56:14
[task 2024-09-15T00:56:14.621Z] 00:56:14     INFO - TEST-PASS | image/test/mochitest/test_animSVGImage.html | myPoll called 
[task 2024-09-15T00:56:14.622Z] 00:56:14     INFO - Buffered messages finished
[task 2024-09-15T00:56:14.622Z] 00:56:14    ERROR - TEST-UNEXPECTED-FAIL | /tests/image/test/mochitest/test_animSVGImage.html logged result after SimpleTest.finish(): myPoll called
[task 2024-09-15T00:56:14.622Z] 00:56:14     INFO - TEST-OK | image/test/mochitest/test_animSVGImage.html | took 121087ms
[task 2024-09-15T00:56:14.622Z] 00:56:14     INFO - TEST-START | image/test/mochitest/test_animated_css_image.html

I think this might have the same issue as Bug 1918637, this bug has the same behavior on backfills as the mentioned one.
A part of the backfill range can be checked here. I stopped there because it seemed like it was going to fail no matter how deep I was going with the bakfills.

Hi @aryx! Can you please take a look at this to see if this might be the same root cause as Bug 1918637?
Thank you!

Flags: needinfo?(aryx.bugmail)
Whiteboard: [retriggered]

In the screenshot there is no Firefox window visible at all.

There is no UI visible because these failures are in headless mode. Should we skip it?

Flags: needinfo?(aryx.bugmail)
Summary: High frequency Linux [tier 2] TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms. Animated image still doesn't look correct, after call #4703 to myPoll → High frequency Linux shippable headless [tier 2] TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms. Animated image still doesn't look correct, after call #4703 to myPoll

Do we expect gifs to animate in headless mode? I think the answer might be "yes", assuming this test was running before in headless mode and passing.

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

Do we expect gifs to animate in headless mode? I think the answer might be "yes",

I think so, yeah. (The actual image is an animated SVG in this case, rather than a GIF; but, same answer regardless.)

FWIW it seems this test has some known preexisting failures on various platforms:
https://searchfox.org/mozilla-central/rev/c414b4538dd3c7e1dc674f7b66176e7c309afa95/image/test/mochitest/mochitest.toml#106-110

["test_animSVGImage.html"]
skip-if = [
  "os == 'android'",
  "os == 'win'",
  "os == 'mac' && os_version == '10.15'", # Bug 1370784, macosx due to bug 1549058

One of those annotations was added in long-ago-bug 1370784 which has a similar failure-mode as what we're seeing here:

test_animSVGImage.html | timing out after 120000ms.  Animated image still doesn't look correct, after call #3508 to myPoll

(exact call # doesn't matter; the point is that we've polled a ton waiting for the rendering to change, and we gave up checking)

I haven't dug in in detail, but as a shot-in-the-dark -- maybe we're somehow capturing our reference-screenshot before it's finished rendering, so the animated image never ends up looking "correct" because we're comparing it against a bad reference? Or something else that makes the screenshots fail to compare for uninteresting reasons.

Probably when we fail the test, we should log the snapshot-image data-URIs for the last testcase screenshot that we captured (which failed its comparison) and the reference snapshot that we compared it against, so that we can the investigate to see what that comparison was actually comparing.

If anyone has cycles to write that diagnostic patch, I'll gladly r+; otherwise I can try a crack at it myself later this week [hence: ni=me], but I don't have time to do so today.

Flags: needinfo?(dholbert)
Flags: needinfo?(dholbert)
See Also: → 1370784
Flags: needinfo?(dholbert)

I could be wrong, but I think there is an open phab revision about this test from many years ago that didn't quite get pushed across the finish line, that could be a starting point.

https://phabricator.services.mozilla.com/D12543 was what I was thinking of. Maybe not as helpful starting point as I thought.

Frequency seems to have dropped.

Summary: High frequency Linux shippable headless [tier 2] TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms. Animated image still doesn't look correct, after call #4703 to myPoll → Linux shippable headless [tier 2] TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms. Animated image still doesn't look correct, after call #4703 to myPoll

Because it was disabled in https://bugzilla.mozilla.org/show_bug.cgi?id=1776936#c117

Summary: Linux shippable headless [tier 2] TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms. Animated image still doesn't look correct, after call #4703 to myPoll → Intermittent Linux shippable headless [tier 2] TEST-UNEXPECTED-FAIL | image/test/mochitest/test_animSVGImage.html | timing out after 120000ms. Animated image still doesn't look correct, after call #4703 to myPoll

Ah, that bug is in a different component and not on my radar.

See Also: → 1776936
You need to log in before you can comment on or make changes to this bug.