Closed Bug 1768867 Opened 3 years ago Closed 2 months ago

Intermittent raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 60000 / 120000 / 144000 ms

Categories

(Testing :: Raptor, defect, P5)

defect

Tracking

(firefox-esr91 unaffected, firefox100 unaffected, firefox101 unaffected, firefox102 wontfix)

RESOLVED INCOMPLETE
Tracking Status
firefox-esr91 --- unaffected
firefox100 --- unaffected
firefox101 --- unaffected
firefox102 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

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


[task 2022-05-11T13:23:06.493Z] 13:23:06     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-05-11T13:24:29.721Z] 13:24:29     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2022-05-11T13:26:53.763Z] 13:26:53    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2022-05-11T13:26:53.785Z] 13:26:53 CRITICAL -  raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 144000 ms
[task 2022-05-11T13:26:53.786Z] 13:26:53     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/6_/2fr28cdd7y77jbw9wg779c0r000014/T/tmpmhlf7qmh
[task 2022-05-11T13:26:53.802Z] 13:26:53    ERROR -  Traceback (most recent call last):
[task 2022-05-11T13:26:53.802Z] 13:26:53     INFO -    File "/opt/worker/tasks/task_165227504541766/build/tests/raptor/raptor/raptor.py", line 215, in <module>
[task 2022-05-11T13:26:53.802Z] 13:26:53     INFO -      main()
[task 2022-05-11T13:26:53.803Z] 13:26:53     INFO -    File "/opt/worker/tasks/task_165227504541766/build/tests/raptor/raptor/raptor.py", line 161, in main
[task 2022-05-11T13:26:53.803Z] 13:26:53     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-05-11T13:26:53.803Z] 13:26:53     INFO -    File "/opt/worker/tasks/task_165227504541766/build/tests/raptor/raptor/perftest.py", line 457, in run_tests
[task 2022-05-11T13:26:53.803Z] 13:26:53     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-05-11T13:26:53.804Z] 13:26:53     INFO -    File "/opt/worker/tasks/task_165227504541766/build/tests/raptor/raptor/browsertime/base.py", line 601, in run_test
[task 2022-05-11T13:26:53.804Z] 13:26:53     INFO -      raise Exception(self.browsertime_failure)
[task 2022-05-11T13:26:53.804Z] 13:26:53     INFO -  Exception: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 144000 ms
[task 2022-05-11T13:26:54.014Z] 13:26:54    ERROR - Return code: 1
[task 2022-05-11T13:26:54.014Z] 13:26:54  WARNING - setting return code to 1
[task 2022-05-11T13:26:54.015Z] 13:26:54     INFO - Copying Raptor results to upload dir:
[task 2022-05-11T13:26:54.015Z] 13:26:54     INFO - /opt/worker/tasks/task_165227504541766/build/blobber_upload_dir/perfherder-data.json
[task 2022-05-11T13:26:54.015Z] 13:26:54     INFO - Copying raptor results from /opt/worker/tasks/task_165227504541766/build/raptor.json to /opt/worker/tasks/task_165227504541766/build/blobber_upload_dir/perfherder-data.json
[task 2022-05-11T13:26:54.016Z] 13:26:54 CRITICAL - Error copying results /opt/worker/tasks/task_165227504541766/build/raptor.json to upload dir /opt/worker/tasks/task_165227504541766/build/blobber_upload_dir/perfherder-data.json
[task 2022-05-11T13:26:54.016Z] 13:26:54     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_165227504541766/build/raptor.json'

Set release status flags based on info from the regressing bug 1767797

:barret, it looks like the Window Recorder is having a lot of issues stopping on this test on the mac platform. Would you be able to look into it? If not, could you redirect the needinfo?

Flags: needinfo?(gmierz2) → needinfo?(brennie)

In the worst case, I can try using ffmpeg for recording but it's preferred to continue using the firefox window recorder.

I don't know why this is failing. I tried disabling/enabling the composition recorder directly on the latest macOS nightly (ie running windowUtils.setCompositionRecording(true|false) from the browser console) directly and the recorder itself seems to be working.

This is the script that is running in browserTime. Maybe you could add logging here to see whats up, e.g.

      const cb = arguments[arguments.length-1];
      Promise.resolve(
        windowUtils.setCompositionRecording(${enable})
      )
        .catch(e => console.log("*** e = " + e)
        .then(() => cb());

Flags: needinfo?(brennie)

Thanks :barret, I've made a try run with those changes to see what we find: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ecdb4d391f8958208272af97600666380bf77f2e

Something else that is interesting is that this is only happening on non-fission tests.

Has Regression Range: --- → yes

:barret, would you have any thoughts on what else we could try? The try run from yesterday didn't produce an error message: https://treeherder.mozilla.org/jobs?repo=try&tier=1%2C2%2C3&revision=ecdb4d391f8958208272af97600666380bf77f2e&selectedTaskRun=ReFcdudGQUWfgqYEm4Aqnw.0

It's timing out while it's trying to stop the recorder without an error being thrown. I could increase the timeout but 2.5 minutes already feels quite high.

Flags: needinfo?(brennie)

I just tried enabling & disabling the composition recorder on the latest nightly with fission disabled and it worked, so I don't have any concrete ideas as to what is going on. Next steps would be to add some logging into Firefox to see whats going on.

The call path is as follows:

Flags: needinfo?(brennie)

Ok, I wonder if there's any value in keeping this test running with fission disabled. :davehunt, what do you think?

Flags: needinfo?(dave.hunt)
Summary: High frequency raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 144000 ms → High frequency raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 60000 / 120000 / 144000 ms

(In reply to Greg Mierzwinski [:sparky] from comment #11)

Ok, I wonder if there's any value in keeping this test running with fission disabled. :davehunt, what do you think?

If it's only failing in non-Fission then I don't see a good reason to keep it running. If we're still running other tests with Fission disabled then perhaps those should be disabled too? :jmaher do you see a reason to keep non-Fission tests around?

Flags: needinfo?(dave.hunt) → needinfo?(jmaher)

we only ship fission by default; users can hack their prefs to disable fission, but for all desktop fission is and has been the default config. Android is different, fission still has a roadmap to walk down- but we run all our unit/perf tests on android in no-fission.

I vote for turning off the no-fission version of the tests on desktop.

Flags: needinfo?(jmaher)
See Also: → 1708940
See Also: → 1769482
Summary: High frequency raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 60000 / 120000 / 144000 ms → Intermittent raptor-browsertime Critical: Couldn't execute async script named toggle composition recorder error:ScriptTimeoutError: Timed out after 60000 / 120000 / 144000 ms
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Duplicate of this bug: 1801841
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago7 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 7 months ago4 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 months ago2 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.