Closed Bug 1743775 Opened 3 years ago Closed 6 months ago

Intermittent /tests/dom/animation/test/mozilla/test_restyles.html logged result after SimpleTest.finish(): undefined

Categories

(Core :: DOM: Animation, defect, P5)

Product:
Core
Component:
DOM: Animation
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
128 Branch
Tracking Flags:
Tracking Status
firefox128 --- fixed

People

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

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

mozilla-test-fail-screenshot_avtdbmih.png
397.69 KB, image/png
Details
Bug 1743775 - Check the VSync rate first and bail out if it's not applicable without adding a bunch of add_task calls. r?boris
48 bytes, text/x-phabricator-request
Details | Review

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

 INFO - TEST-START | dom/animation/test/mozilla/test_restyles.html
[task 2021-12-01T08:53:06.679Z] 08:53:06     INFO - GECKO(3528) | MEMORY STAT | vsize 19405637MB | vsizeMaxContiguous 68497838MB | residentFast 541MB
[task 2021-12-01T08:53:06.779Z] 08:53:06     INFO - TEST-OK | dom/animation/test/mozilla/test_restyles.html | took 1255ms
[task 2021-12-01T08:53:06.867Z] 08:53:06    ERROR - TEST-UNEXPECTED-FAIL | /tests/dom/animation/test/mozilla/test_restyles.html logged result after SimpleTest.finish(): undefined
[task 2021-12-01T08:53:06.904Z] 08:53:06     INFO - TEST-START | dom/animation/test/mozilla/test_restyling_xhr_doc.html

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

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

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=384124250&repo=autoland

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

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

Status: REOPENED → RESOLVED
Closed: 3 years ago → 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=391540590&repo=autoland

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

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=405081263&repo=autoland

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

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE

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

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

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 1 year ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=428048281&repo=autoland

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

Looking at the last few failures here, it looks like they happen after we hit this early-finish() call:
https://searchfox.org/mozilla-central/rev/54c9b4896fdc1e858cd4942f306d877f1f3d195e/dom/animation/test/mozilla/file_restyles.html#148-150

if (vsyncRate > 40 - 5) {
  ok(true, `the vsync rate ${vsyncRate} on this machine is too slow to run this test`);
  SimpleTest.finish();

And indeed, it looks like there's nothing stopping the test logic from proceeding to do more tests after we call finish() there. We make a bunch of calls to add_task up-front, the first of which has this early-finish(), and the subsequent ones have additional ok(...) tests; and when we call finish(), there's nothing stopping us from proceeding with those later tasks that have already been queued up.

I think the right fix here is to prevent ourselves from calling add_tasks for those later tasks, if we happen to take the early finish(). I'm not sure if that's doable with add_task (e.g. if you can make add_task operations conditional on earlier add_task work), but if you can, that's probably the thing to do here.

Alternately, we could set some flag in our early-finish() logic, and then locally-redefine ok/is/etc. to check that flag before performing any actual comparison. But that's probably unnecessary hacky/complex.

(side note: the logs say logged result after SimpleTest.finish(): undefined -- the undefined is there just because that's the description/message for the ok() comparison. Most of the ok() expressions in this test don't include a description/message as the second arg, so it's implicitly undefined, which makes for this kind-of clumsy output when the ok-comparison's result has to be printed due to failure or being logged after finish(); but aside from the confusion, it's ~harmless that it's undefined.)

Something interesting seems to have happened around comment 55 where this got much more frequent, particularly on macosx1015-64-*qr which is responsible for 90% of the failure volume here (>80% percent of the failures in the most recent 3 bugzilla comments).

This could potentially be flagged as skipped on macOS if needed, but really we should just fix (or improve) the test, if we can.

hiro, maybe you could take a look here? It looks like you've touched this test before, at least. :) See my notes in comment 43 about what seemed broken at that point.

Flags: needinfo?(hikezoe.birchill)

BTW, the reason I'm thinking we should escalate this a bit & try to get it fixed or mitigated soon is the following from comment 61:

61 failures in 3995 pushes (0.015 failures/push) were associated with this bug in the last 7 days.
This is the #21 most frequent failure this week.
** This failure happened more than 30 times this week! Resolving this bug is a high priority. **
** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

(just noting since that's not-otherwise-obvious, since the intermittent failure bot comments are auto-collapsed.)

I highly suspect the failure happens on 4K resolution mac.

Attaching file is a screenshot on a failure run, note that the screenshot did capture a different test failure since the SimpleTest.finish(): undefined seems to happen after running the test in question so that our capturing machinery isn't triggered I guess.

Anyway, the SimpleTest.finish() is probably this one, it looks to me that we should do the bailing out code outside of add_task and it should also do outside of waitForAllPaints() there. What we probably need to do is that checking the Vsync rate first, then if it's applicable we call waitForAllPaints() and add_task calls.

I will try it tomorrow.

Flags: needinfo?(hikezoe.birchill)

A try run with the change I commented in comment 64 is pretty much green. https://treeherder.mozilla.org/jobs?repo=try&revision=635468e3af07747f7dc9aac9b8c3d857643de808

Depends on: 1852884

SimpleTest.finish() inside an add_task call will cause
"logged result after SimpleTest.finish(): undefined" error.

Assignee: nobody → hikezoe.birchill
No longer depends on: 1852884
Pushed by hikezoe.birchill@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/311fed649f82 Check the VSync rate first and bail out if it's not applicable without adding a bunch of add_task calls. r=boris

https://hg.mozilla.org/mozilla-central/rev/311fed649f82

Status: REOPENED → RESOLVED
Closed: 1 year ago → 6 months ago
status-firefox128: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 128 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: