1737915 - Intermittent [tier 2] raptor-browsertime Error: Browsertime failed to run | raptor-browsertime Critical: JavascriptError: JavaScriptError: Document was unloaded

Status: RESOLVED INCOMPLETE

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-10-26T22:25:24.951Z] 22:25:24     INFO -  raptor-browsertime Info: Cycle 1, starting the measure
[task 2021-10-26T22:25:24.952Z] 22:25:24     INFO -  raptor-browsertime Info: Testing url https://www.buzzfeed.com/ iteration 23
[task 2021-10-26T22:25:24.952Z] 22:25:24     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2021-10-26T22:25:33.182Z] 22:25:33     INFO -  raptor-browsertime Info: https://www.buzzfeed.com/ has been tested before within the same run, it will get an extra query parameter named browsertime_run. Make sure to use alias to keep track of the URLs
[task 2021-10-26T22:25:33.183Z] 22:25:33     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2021-10-26T22:25:34.540Z] 22:25:34    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2021-10-26T22:25:34.543Z] 22:25:34    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2021-10-26T22:25:34.547Z] 22:25:34 CRITICAL -  raptor-browsertime Critical: JavascriptError: JavaScriptError: Document was unloaded
[task 2021-10-26T22:25:34.548Z] 22:25:34     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2021-10-26T22:25:34.548Z] 22:25:34     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2021-10-26T22:25:34.548Z] 22:25:34     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 997
[task 2021-10-26T22:25:35.101Z] 22:25:35     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2021-10-26T22:25:35.101Z] 22:25:35     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2021-10-26T22:25:35.101Z] 22:25:35     INFO -  raptor-mitmproxy Info: writing: /Users/cltbld/tasks/task_1635285880/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
[task 2021-10-26T22:25:35.102Z] 22:25:35     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/ns/8_v12r_52yb3x70z2n37lrbh000017/T/tmp0_rd3vo9
[task 2021-10-26T22:25:35.129Z] 22:25:35     INFO -  Could not terminate process: 999
[task 2021-10-26T22:25:35.129Z] 22:25:35     INFO -  Exception in thread ProcessReader:
[task 2021-10-26T22:25:35.130Z] 22:25:35    ERROR -  Traceback (most recent call last):
[task 2021-10-26T22:25:35.130Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 223, in send_sig
[task 2021-10-26T22:25:35.130Z] 22:25:35     INFO -      os.killpg(pid, sig)
[task 2021-10-26T22:25:35.130Z] 22:25:35     INFO -  PermissionError: [Errno 1] Operation not permitted
[task 2021-10-26T22:25:35.131Z] 22:25:35     INFO -  During handling of the above exception, another exception occurred:
[task 2021-10-26T22:25:35.131Z] 22:25:35    ERROR -  Traceback (most recent call last):
[task 2021-10-26T22:25:35.132Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 233, in send_sig
[task 2021-10-26T22:25:35.132Z] 22:25:35     INFO -      os.waitpid(-pid, 0)
[task 2021-10-26T22:25:35.132Z] 22:25:35     INFO -  ChildProcessError: [Errno 10] No child processes
[task 2021-10-26T22:25:35.132Z] 22:25:35     INFO -  During handling of the above exception, another exception occurred:
[task 2021-10-26T22:25:35.133Z] 22:25:35    ERROR -  Traceback (most recent call last):
[task 2021-10-26T22:25:35.133Z] 22:25:35     INFO -    File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 926, in _bootstrap_inner
[task 2021-10-26T22:25:35.133Z] 22:25:35     INFO -      self.run()
[task 2021-10-26T22:25:35.134Z] 22:25:35     INFO -    File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/threading.py", line 870, in run
[task 2021-10-26T22:25:35.134Z] 22:25:35     INFO -      self._target(*self._args, **self._kwargs)
[task 2021-10-26T22:25:35.134Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 1230, in _read
[task 2021-10-26T22:25:35.134Z] 22:25:35     INFO -      callback(line.rstrip())
[task 2021-10-26T22:25:35.135Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 1136, in __call__
[task 2021-10-26T22:25:35.135Z] 22:25:35     INFO -      e(*args, **kwargs)
[task 2021-10-26T22:25:35.135Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/tests/raptor/raptor/browsertime/base.py", line 522, in _line_handler
[task 2021-10-26T22:25:35.136Z] 22:25:35     INFO -      proc.kill()
[task 2021-10-26T22:25:35.136Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 975, in kill
[task 2021-10-26T22:25:35.136Z] 22:25:35     INFO -      self.proc.kill(sig=sig, timeout=timeout)
[task 2021-10-26T22:25:35.137Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 251, in kill
[task 2021-10-26T22:25:35.137Z] 22:25:35     INFO -      send_sig(signal.SIGTERM)
[task 2021-10-26T22:25:35.137Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 235, in send_sig
[task 2021-10-26T22:25:35.137Z] 22:25:35     INFO -      return send_sig(sig, retries + 1)
[task 2021-10-26T22:25:35.138Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/venv/lib/python3.7/site-packages/mozprocess/processhandler.py", line 223, in send_sig
[task 2021-10-26T22:25:35.138Z] 22:25:35     INFO -      os.killpg(pid, sig)
[task 2021-10-26T22:25:35.138Z] 22:25:35     INFO -  PermissionError: [Errno 1] Operation not permitted
[task 2021-10-26T22:25:35.138Z] 22:25:35    ERROR -  Traceback (most recent call last):
[task 2021-10-26T22:25:35.139Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/tests/raptor/raptor/raptor.py", line 213, in <module>
[task 2021-10-26T22:25:35.139Z] 22:25:35     INFO -      main()
[task 2021-10-26T22:25:35.139Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/tests/raptor/raptor/raptor.py", line 159, in main
[task 2021-10-26T22:25:35.139Z] 22:25:35     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2021-10-26T22:25:35.140Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/tests/raptor/raptor/perftest.py", line 457, in run_tests
[task 2021-10-26T22:25:35.140Z] 22:25:35     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2021-10-26T22:25:35.140Z] 22:25:35     INFO -    File "/Users/cltbld/tasks/task_1635285880/build/tests/raptor/raptor/browsertime/base.py", line 567, in run_test
[task 2021-10-26T22:25:35.141Z] 22:25:35     INFO -      raise Exception(self.browsertime_failure)
[task 2021-10-26T22:25:35.141Z] 22:25:35     INFO -  Exception: JavascriptError: JavaScriptError: Document was unloaded
[task 2021-10-26T22:25:35.295Z] 22:25:35    ERROR - Return code: 1
[task 2021-10-26T22:25:35.295Z] 22:25:35  WARNING - setting return code to 1
[task 2021-10-26T22:25:35.295Z] 22:25:35     INFO - Copying Raptor results to upload dir:
[task 2021-10-26T22:25:35.295Z] 22:25:35     INFO - /Users/cltbld/tasks/task_1635285880/build/blobber_upload_dir/perfherder-data.json
[task 2021-10-26T22:25:35.296Z] 22:25:35     INFO - Copying raptor results from /Users/cltbld/tasks/task_1635285880/build/raptor.json to /Users/cltbld/tasks/task_1635285880/build/blobber_upload_dir/perfherder-data.json
[task 2021-10-26T22:25:35.296Z] 22:25:35 CRITICAL - Error copying results /Users/cltbld/tasks/task_1635285880/build/raptor.json to upload dir /Users/cltbld/tasks/task_1635285880/build/blobber_upload_dir/perfherder-data.json
[task 2021-10-26T22:25:35.296Z] 22:25:35     INFO - [Errno 2] No such file or directory: '/Users/cltbld/tasks/task_1635285880/build/raptor.json'
[task 2021-10-26T22:25:35.297Z] 22:25:35     INFO - Running post-action listener: _package_coverage_data
[task 2021-10-26T22:25:35.297Z] 22:25:35     INFO - Running post-action listener: _resource_record_post_action
[task 2021-10-26T22:25:35.297Z] 22:25:35     INFO - Running post-action listener: process_java_coverage_data
[task 2021-10-26T22:25:35.297Z] 22:25:35     INFO - Running post-action listener: stop_device
[task 2021-10-26T22:25:35.298Z] 22:25:35     INFO - [mozharness: 2021-10-26 22:25:35.297920Z] Finished run-tests step (success)
[task 2021-10-26T22:25:35.298Z] 22:25:35     INFO - Running post-run listener: _resource_record_post_run
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - Total resource usage - Wall time: 1199s; CPU: 18%; Read bytes: 439316480; Write bytes: 4939900416; Read time: 8303; Write time: 29721
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - TinderboxPrint: CPU usage<br/>18.0%
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - TinderboxPrint: I/O read bytes / time<br/>439,316,480 / 8,303
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - TinderboxPrint: I/O write bytes / time<br/>4,939,900,416 / 29,721
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - TinderboxPrint: CPU idle<br/>3,582.5 (74.7%)
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - TinderboxPrint: CPU system<br/>316.7 (6.6%)
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - TinderboxPrint: CPU user<br/>896.5 (18.7%)
[task 2021-10-26T22:25:35.470Z] 22:25:35     INFO - TinderboxPrint: Swap in / out<br/>672,247,808 / 0
[task 2021-10-26T22:25:35.471Z] 22:25:35     INFO - install-chromium-distribution - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-10-26T22:25:35.472Z] 22:25:35     INFO - install - Wall time: 31s; CPU: 38%; Read bytes: 433600000; Write bytes: 421670912; Read time: 27569; Write time: 936
[task 2021-10-26T22:25:35.479Z] 22:25:35     INFO - run-tests - Wall time: 1168s; CPU: 17%; Read bytes: 424411136; Write bytes: 4499031552; Read time: 7706; Write time: 28704
[task 2021-10-26T22:25:35.634Z] 22:25:35  WARNING - returning nonzero exit status 1
[taskcluster 2021-10-26T22:25:35.678Z]    Exit Code: 1
[taskcluster 2021-10-26T22:25:35.678Z]    User Time: 13m40.29011s
[taskcluster 2021-10-26T22:25:35.678Z]  Kernel Time: 3m30.5207s
[taskcluster 2021-10-26T22:25:35.678Z]    Wall Time: 20m48.492711454s
[taskcluster 2021-10-26T22:25:35.678Z]       Result: FAILED

Comment 1

[Intermittent Failures Robot]

2 failures in 2845 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• macosx1014-64-shippable-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1737915&startday=2021-10-25&endday=2021-10-31&tree=all

Comment 2

[BugBot [:suhaib / :marco]]

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

Comment 3

[Treeherder Bug Filer]

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

Comment 4

[Intermittent Failures Robot]

12 failures in 3165 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 9
• mozilla-central: 3

Platform and build breakdown:

• macosx1015-64-shippable-qr: 12
  • opt: 12

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1737915&startday=2022-01-31&endday=2022-02-06&tree=all

Comment 5

[BugBot [:suhaib / :marco]]

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

Comment 6

[Treeherder Bug Filer]

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

Comment 7

[Intermittent Failures Robot]

2 failures in 3312 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

• linux1804-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1737915&startday=2022-06-27&endday=2022-07-03&tree=all

Comment 8

[BugBot [:suhaib / :marco]]

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