Closed
Bug 1754681
Opened 3 years ago
Closed 3 years ago
Intermittent [Tier 2] raptor-browsertime Error: Browsertime failed to run | raptor-browsertime Critical: Failed waiting on page https://imgur.com/gallery/m5tYJL6 to finished loading, timed out after 300000 ms NoSuchWindowError: Browsing context has been d
Categories
(Testing :: Raptor, defect, P5)
Testing
Raptor
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=367347616&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/MvhbvCGKRLmSIztqG1VCQg/runs/0/artifacts/public/logs/live_backing.log
[task 2022-02-10T06:14:06.794Z] 06:14:06 INFO - raptor-browsertime Info: Testing url https://imgur.com/gallery/m5tYJL6 iteration 11
[task 2022-02-10T06:14:06.797Z] 06:14:06 INFO - raptor-browsertime Info: Start firefox window recorder.
[task 2022-02-10T06:14:14.797Z] 06:14:14 INFO - raptor-browsertime Info: Stop firefox window recorder.
[task 2022-02-10T06:14:39.017Z] 06:14:39 INFO - raptor-browsertime Info: Navigating to secondary url:https://imgur.com/gallery/L13Ci
[task 2022-02-10T06:14:39.017Z] 06:14:39 INFO - raptor-browsertime Info: Navigating to url https://imgur.com/gallery/L13Ci iteration 11
[task 2022-02-10T06:14:49.086Z] 06:14:49 INFO - raptor-browsertime Info: Navigating to primary url:https://imgur.com/gallery/m5tYJL6
[task 2022-02-10T06:14:49.086Z] 06:14:49 INFO - raptor-browsertime Info: Cycle 1, waiting for 1000 ms
[task 2022-02-10T06:14:50.087Z] 06:14:50 INFO - raptor-browsertime Info: Cycle 1, starting the measure
[task 2022-02-10T06:14:50.087Z] 06:14:50 INFO - raptor-browsertime Info: Testing url https://imgur.com/gallery/m5tYJL6 iteration 11
[task 2022-02-10T06:14:50.088Z] 06:14:50 INFO - raptor-browsertime Info: Start firefox window recorder.
[task 2022-02-10T06:14:57.025Z] 06:14:57 INFO - raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6 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 2022-02-10T06:14:57.028Z] 06:14:57 INFO - raptor-browsertime Info: Stop firefox window recorder.
[taskcluster 2022-02-10T06:15:15.367Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/MvhbvCGKRLmSIztqG1VCQg/0/on/mdc1/t-linux64-ms-233/until/1644474915.35
[task 2022-02-10T06:15:21.057Z] 06:15:21 INFO - raptor-browsertime Info: Browsertime pageload ended.
[task 2022-02-10T06:15:23.354Z] 06:15:23 INFO - raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6 TTFB: 26ms DOMContentLoaded: 515ms firstPaint: 268ms FCP: 769ms Load: 1.46s
[task 2022-02-10T06:15:23.355Z] 06:15:23 INFO - raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6?browsertime_run=2 TTFB: -1ms DOMContentLoaded: 336ms firstPaint: 90ms FCP: 506ms Load: 551ms
[task 2022-02-10T06:15:23.356Z] 06:15:23 INFO - raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2022-02-10T06:15:25.411Z] 06:15:25 INFO - raptor-browsertime Info: Starting a browsertime pageload
[task 2022-02-10T06:15:25.411Z] 06:15:25 INFO - raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2022-02-10T06:15:26.413Z] 06:15:26 INFO - raptor-browsertime Info: Navigating to about:blank, count: 0
[task 2022-02-10T06:15:26.414Z] 06:15:26 INFO - raptor-browsertime Info: Navigating to url about:blank iteration 12
[task 2022-02-10T06:15:31.460Z] 06:15:31 INFO - raptor-browsertime Info: Navigating to primary url:https://imgur.com/gallery/m5tYJL6
[task 2022-02-10T06:15:31.461Z] 06:15:31 INFO - raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2022-02-10T06:15:32.462Z] 06:15:32 INFO - raptor-browsertime Info: Cycle 0, starting the measure
[task 2022-02-10T06:15:32.462Z] 06:15:32 INFO - raptor-browsertime Info: Testing url https://imgur.com/gallery/m5tYJL6 iteration 12
[task 2022-02-10T06:15:32.465Z] 06:15:32 INFO - raptor-browsertime Info: Start firefox window recorder.
[task 2022-02-10T06:17:27.384Z] 06:17:27 ERROR - raptor-browsertime Error: Browsertime failed to run
[task 2022-02-10T06:17:27.402Z] 06:17:27 INFO - raptor-browsertime Info: at Object.throwDecodedError (/home/cltbld/tasks/task_164447269439265/fetches/browsertime/node_modules/selenium-webdriver/lib/error.js:539:15)
[task 2022-02-10T06:17:27.402Z] 06:17:27 INFO - raptor-browsertime Info: at parseHttpResponse (/home/cltbld/tasks/task_164447269439265/fetches/browsertime/node_modules/selenium-webdriver/lib/http.js:647:13)
[task 2022-02-10T06:17:27.402Z] 06:17:27 INFO - raptor-browsertime Info: at Executor.execute (/home/cltbld/tasks/task_164447269439265/fetches/browsertime/node_modules/selenium-webdriver/lib/http.js:573:28)
[task 2022-02-10T06:17:27.402Z] 06:17:27 INFO - raptor-browsertime Info: at processTicksAndRejections (internal/process/task_queues.js:97:5)
[task 2022-02-10T06:17:27.402Z] 06:17:27 INFO - raptor-browsertime Info: at async Driver.execute (/home/cltbld/tasks/task_164447269439265/fetches/browsertime/node_modules/selenium-webdriver/lib/webdriver.js:735:17)
[task 2022-02-10T06:17:27.403Z] 06:17:27 INFO - raptor-browsertime Info: URL failed to load, trying 5 more time(s): Failed waiting on page https://imgur.com/gallery/m5tYJL6 to finished loading, timed out after 300000 ms
[task 2022-02-10T06:17:27.403Z] 06:17:27 CRITICAL - raptor-browsertime Critical: Failed waiting on page https://imgur.com/gallery/m5tYJL6 to finished loading, timed out after 300000 ms NoSuchWindowError: Browsing context has been discarded
[task 2022-02-10T06:17:27.403Z] 06:17:27 INFO - raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2022-02-10T06:17:27.403Z] 06:17:27 INFO - raptor-mitmproxy Info: Mitmproxy stop!!
[task 2022-02-10T06:17:27.403Z] 06:17:27 INFO - raptor-mitmproxy Info: Turning off the browser proxy
[task 2022-02-10T06:17:27.403Z] 06:17:27 INFO - raptor-mitmproxy Info: writing: /home/cltbld/tasks/task_164447269439265/build/application/firefox/distribution/policies.json
[task 2022-02-10T06:17:27.404Z] 06:17:27 INFO - raptor-perftest Info: Removing temporary directory: /tmp/tmpr7ydmhuv
[task 2022-02-10T06:17:27.413Z] 06:17:27 ERROR - Traceback (most recent call last):
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - File "/home/cltbld/tasks/task_164447269439265/build/tests/raptor/raptor/raptor.py", line 215, in <module>
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - main()
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - File "/home/cltbld/tasks/task_164447269439265/build/tests/raptor/raptor/raptor.py", line 161, in main
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - File "/home/cltbld/tasks/task_164447269439265/build/tests/raptor/raptor/perftest.py", line 450, in run_tests
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - File "/home/cltbld/tasks/task_164447269439265/build/tests/raptor/raptor/browsertime/base.py", line 555, in run_test
[task 2022-02-10T06:17:27.414Z] 06:17:27 INFO - raise Exception(self.browsertime_failure)
[task 2022-02-10T06:17:27.415Z] 06:17:27 INFO - Exception: Failed waiting on page https://imgur.com/gallery/m5tYJL6 to finished loading, timed out after 300000 ms NoSuchWindowError: Browsing context has been discarded
[task 2022-02-10T06:17:27.475Z] 06:17:27 ERROR - Return code: 1
[task 2022-02-10T06:17:27.475Z] 06:17:27 WARNING - setting return code to 1
[task 2022-02-10T06:17:27.475Z] 06:17:27 INFO - Copying Raptor results to upload dir:
[task 2022-02-10T06:17:27.475Z] 06:17:27 INFO - /home/cltbld/tasks/task_164447269439265/build/blobber_upload_dir/perfherder-data.json
[task 2022-02-10T06:17:27.475Z] 06:17:27 INFO - Copying raptor results from /home/cltbld/tasks/task_164447269439265/build/raptor.json to /home/cltbld/tasks/task_164447269439265/build/blobber_upload_dir/perfherder-data.json
[task 2022-02-10T06:17:27.475Z] 06:17:27 CRITICAL - Error copying results /home/cltbld/tasks/task_164447269439265/build/raptor.json to upload dir /home/cltbld/tasks/task_164447269439265/build/blobber_upload_dir/perfherder-data.json
[task 2022-02-10T06:17:27.476Z] 06:17:27 INFO - [Errno 2] No such file or directory: '/home/cltbld/tasks/task_164447269439265/build/raptor.json'
[task 2022-02-10T06:17:27.476Z] 06:17:27 INFO - Running post-action listener: _package_coverage_data
[task 2022-02-10T06:17:27.476Z] 06:17:27 INFO - Running post-action listener: _resource_record_post_action
[task 2022-02-10T06:17:27.476Z] 06:17:27 INFO - Running post-action listener: process_java_coverage_data
[task 2022-02-10T06:17:27.476Z] 06:17:27 INFO - Running post-action listener: stop_device
[task 2022-02-10T06:17:27.476Z] 06:17:27 INFO - [mozharness: 2022-02-10 06:17:27.476940Z] Finished run-tests step (success)
[task 2022-02-10T06:17:27.477Z] 06:17:27 INFO - Running post-run listener: _resource_record_post_run
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - Total resource usage - Wall time: 1115s; CPU: 17%; Read bytes: 181275291648; Write bytes: 19394039808; Read time: 2597996; Write time: 4244840
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: CPU usage<br/>16.7%
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: I/O read bytes / time<br/>181,275,291,648 / 2,597,996
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: I/O write bytes / time<br/>19,394,039,808 / 4,244,840
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: CPU idle<br/>6,971.7 (78.4%)
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: CPU iowait<br/>428.8 (4.8%)
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: CPU system<br/>302.4 (3.4%)
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: CPU user<br/>1,096.4 (12.3%)
[task 2022-02-10T06:17:27.578Z] 06:17:27 INFO - TinderboxPrint: Swap in / out<br/>0 / 1,027,600,384
[task 2022-02-10T06:17:27.579Z] 06:17:27 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 2022-02-10T06:17:27.579Z] 06:17:27 INFO - install - Wall time: 9s; CPU: 13%; Read bytes: 65536; Write bytes: 1657896960; Read time: 128; Write time: 13052
[task 2022-02-10T06:17:27.589Z] 06:17:27 INFO - run-tests - Wall time: 1107s; CPU: 17%; Read bytes: 181273808896; Write bytes: 17732071424; Read time: 2597860; Write time: 4231716
[task 2022-02-10T06:17:27.790Z] 06:17:27 WARNING - returning nonzero exit status 1
[taskcluster 2022-02-10T06:17:27.821Z] Exit Code: 1
[taskcluster 2022-02-10T06:17:27.821Z] User Time: 19m3.111002s
[taskcluster 2022-02-10T06:17:27.821Z] Kernel Time: 3m1.604697s
[taskcluster 2022-02-10T06:17:27.821Z] Wall Time: 19m8.890264088s
[taskcluster 2022-02-10T06:17:27.821Z] Result: FAILED
[taskcluster 2022-02-10T06:17:27.821Z] === Task Finished ===
[taskcluster 2022-02-10T06:17:27.821Z] Task Duration: 19m8.894064232s
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 4•3 years ago
|
||
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
You need to log in
before you can comment on or make changes to this bug.
Description
•