Closed Bug 1597138 Opened 6 years ago Closed 4 years ago

Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-youtube-playback-<product>-live' timed out loading test page: waiting for pending metrics

Categories

(Testing :: Raptor, defect, P5)

Version 3
ARM
Android
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

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


task 2019-11-17T19:49:15.182Z] 19:49:12 INFO - adb shell_output: adb -s ZY322HQZLX wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:15.182Z] 19:49:13 INFO - raptor-main Info: removing reverse socket connections
[task 2019-11-17T19:49:15.182Z] 19:49:13 INFO - adb command_output: adb -s ZY322HQZLX wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - adb shell_bool: adb -s ZY322HQZLX wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - adb shell_output: adb -s ZY322HQZLX wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - adb shell_bool: adb -s ZY322HQZLX wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - adb command_output: adb -s ZY322HQZLX wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmpABO_iN/minidumps, timeout: None, timedout: None, exitcode: 0, output: /sdcard/raptor/profile/minidumps/: 0 files pulled.
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - raptor-main Info: removing webext /builds/task_1574016427/workspace/build/tests/raptor/raptor/../webext/raptor
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - perftest-results-handler Info: summarizing raptor test results
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - perftest-output Error: no raptor test results found for raptor-youtube-playback-geckoview-live
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - perftest-output Info: error: no raptor test results found, so no need to combine browser cycles
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - perftest-output Error: no summarized raptor results found for raptor-youtube-playback-geckoview-live
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - perftest-output Info: screen captures can be found locally at: /builds/task_1574016427/workspace/build/screenshots.html
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - perftest-results-handler Critical: PERFHERDER_DATA was seen 0 times, expected 1.
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - raptor-main Info: removing test folder for raptor: /sdcard/raptor
[task 2019-11-17T19:49:15.182Z] 19:49:14 INFO - adb shell_output: adb -s ZY322HQZLX wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:15.182Z] 19:49:15 INFO - adb shell_output: adb -s ZY322HQZLX wait-for-device shell rm -r /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - adb shell_output: adb -s ZY322HQZLX wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - adb shell_bool: adb -s ZY322HQZLX wait-for-device shell test -e /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 1, output:
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - raptor-control-server Info: shutting down control server
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - raptor-main Info: finished
[task 2019-11-17T19:49:35.812Z] 19:49:15 ERROR - raptor-main Critical: TEST-UNEXPECTED-FAIL: no raptor test results were found for raptor-youtube-playback-geckoview-live
[task 2019-11-17T19:49:35.812Z] 19:49:15 ERROR - Return code: 1
[task 2019-11-17T19:49:35.812Z] 19:49:15 WARNING - setting return code to 1
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Killing logcat pid 605.
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Copying Raptor results to upload dir:
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - /builds/task_1574016427/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Copying raptor results from /builds/task_1574016427/workspace/build/raptor.json to /builds/task_1574016427/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-11-17T19:49:35.812Z] 19:49:15 CRITICAL - Error copying results /builds/task_1574016427/workspace/build/raptor.json to upload dir /builds/task_1574016427/workspace/build/blobber_upload_dir/perfherder-data.json
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - [Errno 2] No such file or directory: u'/builds/task_1574016427/workspace/build/raptor.json'
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - /builds/task_1574016427/workspace/build/blobber_upload_dir/screenshots.html
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Copying raptor results from /builds/task_1574016427/workspace/build/screenshots.html to /builds/task_1574016427/workspace/build/blobber_upload_dir/screenshots.html
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Running post-action listener: _package_coverage_data
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Running post-action listener: _resource_record_post_action
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Running post-action listener: process_java_coverage_data
[task 2019-11-17T19:49:35.812Z] 19:49:15 INFO - Running post-action listener: stop_device
[task 2019-11-17T19:49:35.812Z] 19:49:22 INFO - /data/anr/traces.txt deleted
[task 2019-11-17T19:49:35.812Z] 19:49:28 INFO - /data/tombstones/dsps deleted
[task 2019-11-17T19:49:35.812Z] 19:49:30 INFO - /data/tombstones/lpass deleted
[task 2019-11-17T19:49:35.812Z] 19:49:32 INFO - /data/tombstones/modem deleted
[task 2019-11-17T19:49:35.812Z] 19:49:34 INFO - /data/tombstones/wcnss deleted
[task 2019-11-17T19:49:35.812Z] 19:49:34 INFO - Killing logcat pid 605

Depends on: 1614275
OS: Unspecified → Android
Hardware: Unspecified → ARM

There are page load failures:

[task 2020-02-27T19:47:11.407Z] 19:47:11 INFO - raptor-control-server Info: received webext_raptor-page-timeout: [u'raptor-youtube-playback-geckoview-live', u'http://yttest.prod.mozaws.net/2019/main.html?muted=true&exclude=1,2,9,10,17,18,21,22,26,28,30,32,39,40,47,48,55,56,63,64,71,72,79,80,83,84,89,90,95,96&test_type=playbackperf-test&command=run&raptor=true']

Depends on: 1614898
Summary: Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: no raptor test results were found for raptor-youtube-playback-geckoview-live → Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-youtube-playback-geckoview-live' timed out loading test page: http://yttest.prod.mozaws.net/2019/main.html
Summary: Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-youtube-playback-geckoview-live' timed out loading test page: http://yttest.prod.mozaws.net/2019/main.html → Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-youtube-playback-<product>-live' timed out loading test page: http://yttest.prod.mozaws.net/2019/main.html
Summary: Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-youtube-playback-<product>-live' timed out loading test page: http://yttest.prod.mozaws.net/2019/main.html → Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-youtube-playback-<product>-live' timed out loading test page: waiting for pending metrics
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Whiteboard: [perftest:triage]
Whiteboard: [perftest:triage]
Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=346688106&repo=mozilla-central&lineNumber=7370

[task 2021-07-29T06:15:46.414Z] 06:15:46     INFO -  PID 3965 | console.info: "[raptor-runnerjs] results pending..."
[task 2021-07-29T06:15:46.552Z] 06:15:46     INFO -  PID 3965 | console.error: "ERROR: [raptor-runnerjs] raptor-page-timeout on https://yttest.prod.mozaws.net/2020/main.html?test_type=playbackperf-widevine-hfr-test&raptor=true&exclude=1,2&muted=true&command=run"
[task 2021-07-29T06:15:46.554Z] 06:15:46     INFO -  raptor-control-server Info: received webext_raptor-page-timeout: ['raptor-youtube-playback-widevine-hfr-firefox-live', 'https://yttest.prod.mozaws.net/2020/main.html?test_type=playbackperf-widevine-hfr-test&raptor=true&exclude=1,2&muted=true&command=run', 1]
[task 2021-07-29T06:15:46.554Z] 06:15:46     INFO -  PID 3965 | console.info: "[raptor-runnerjs] capturing screenshot"
[task 2021-07-29T06:15:46.682Z] 06:15:46     INFO -  raptor-control-server Info: received webext_screenshot
[task 2021-07-29T06:15:46.682Z] 06:15:46     INFO -  perftest-results-handler Info: received screenshot
[task 2021-07-29T06:15:46.683Z] 06:15:46     INFO -  PID 3965 | console.info: "[raptor-runnerjs] results pending..."
[task 2021-07-29T06:15:46.686Z] 06:15:46     INFO -  raptor-control-server Info: received webext_status: closing Tab: 2
[task 2021-07-29T06:15:46.709Z] 06:15:46     INFO -  raptor-control-server Info: received webext_status: closed tab: 2
[task 2021-07-29T06:15:46.710Z] 06:15:46     INFO -  PID 3965 | console.info: "[raptor-runnerjs] benchmark test finished"
[task 2021-07-29T06:15:46.714Z] 06:15:46     INFO -  raptor-control-server Info: received request to shutdown the browser
[task 2021-07-29T06:15:46.714Z] 06:15:46     INFO -  raptor-control-server Info: shutting down browser (pid: 3965)
[task 2021-07-29T06:15:47.055Z] 06:15:47     INFO -  PID 3965 | console.info: "[raptor-runnerjs] results pending..."
[task 2021-07-29T06:15:47.430Z] 06:15:47     INFO -  PID 3965 | console.info: "[raptor-runnerjs] results pending..."
[task 2021-07-29T06:15:47.758Z] 06:15:47     INFO -  PID 3965 | console.info: "[raptor-runnerjs] results pending..."
[task 2021-07-29T06:15:48.043Z] 06:15:48     INFO -  PID 3965 | console.info: "[raptor-runnerjs] results pending..."
[task 2021-07-29T06:15:49.310Z] 06:15:49     INFO -  raptor-webext Info: removing webext /opt/worker/tasks/task_162753155321219/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2021-07-29T06:15:49.312Z] 06:15:49     INFO -  perftest-results-handler Info: summarizing raptor test results
[task 2021-07-29T06:15:49.312Z] 06:15:49     INFO -  perftest-output Error: no raptor test results found for raptor-youtube-playback-widevine-hfr-firefox-live
[task 2021-07-29T06:15:49.312Z] 06:15:49     INFO -  perftest-output Info: error: no raptor test results found, so no need to combine browser cycles
[task 2021-07-29T06:15:49.313Z] 06:15:49     INFO -  perftest-output Error: no summarized raptor results found for raptor-youtube-playback-widevine-hfr-firefox-live
[task 2021-07-29T06:15:49.313Z] 06:15:49     INFO -  perftest-output Info: screen captures can be found locally at: /opt/worker/tasks/task_162753155321219/build/screenshots.html
[task 2021-07-29T06:15:49.319Z] 06:15:49     INFO -  perftest-results-handler Critical: PERFHERDER_DATA was seen 0 times, expected 1.
[task 2021-07-29T06:15:49.319Z] 06:15:49     INFO -  raptor-control-server Info: shutting down control server
[task 2021-07-29T06:15:49.431Z] 06:15:49     INFO -  raptor-webext Info: finished
[task 2021-07-29T06:15:49.432Z] 06:15:49    ERROR -  raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-youtube-playback-widevine-hfr-firefox-live' timed out loading test page: waiting for pending metrics
[task 2021-07-29T06:15:49.678Z] 06:15:49    ERROR - Return code: 1
[task 2021-07-29T06:15:49.678Z] 06:15:49  WARNING - setting return code to 1
[task 2021-07-29T06:15:49.678Z] 06:15:49     INFO - Copying Raptor results to upload dir:
[task 2021-07-29T06:15:49.678Z] 06:15:49     INFO - /opt/worker/tasks/task_162753155321219/build/blobber_upload_dir/perfherder-data.json
[task 2021-07-29T06:15:49.678Z] 06:15:49     INFO - Copying raptor results from /opt/worker/tasks/task_162753155321219/build/raptor.json to /opt/worker/tasks/task_162753155321219/build/blobber_upload_dir/perfherder-data.json
[task 2021-07-29T06:15:49.679Z] 06:15:49 CRITICAL - Error copying results /opt/worker/tasks/task_162753155321219/build/raptor.json to upload dir /opt/worker/tasks/task_162753155321219/build/blobber_upload_dir/perfherder-data.json
[task 2021-07-29T06:15:49.679Z] 06:15:49     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_162753155321219/build/raptor.json'
[task 2021-07-29T06:15:49.679Z] 06:15:49     INFO - /opt/worker/tasks/task_162753155321219/build/blobber_upload_dir/screenshots.html
[task 2021-07-29T06:15:49.679Z] 06:15:49     INFO - Copying raptor results from /opt/worker/tasks/task_162753155321219/build/screenshots.html to /opt/worker/tasks/task_162753155321219/build/blobber_upload_dir/screenshots.html
[task 2021-07-29T06:15:49.680Z] 06:15:49     INFO - Running post-action listener: _package_coverage_data
[task 2021-07-29T06:15:49.680Z] 06:15:49     INFO - Running post-action listener: _resource_record_post_action
[task 2021-07-29T06:15:49.680Z] 06:15:49     INFO - Running post-action listener: process_java_coverage_data
[task 2021-07-29T06:15:49.680Z] 06:15:49     INFO - Running post-action listener: stop_device
[task 2021-07-29T06:15:49.681Z] 06:15:49     INFO - [mozharness: 2021-07-29 06:15:49.680992Z] Finished run-tests step (success)
[task 2021-07-29T06:15:49.681Z] 06:15:49     INFO - Running post-run listener: _resource_record_post_run
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - Total resource usage - Wall time: 2232s; CPU: 2%; Read bytes: 94674944; Write bytes: 668352512; Read time: 1162; Write time: 3560
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - TinderboxPrint: CPU usage<br/>2.4%
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - TinderboxPrint: I/O read bytes / time<br/>94,674,944 / 1,162
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - TinderboxPrint: I/O write bytes / time<br/>668,352,512 / 3,560
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - TinderboxPrint: CPU idle<br/>25,985.4 (97.0%)
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - TinderboxPrint: CPU system<br/>426.8 (1.6%)
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - TinderboxPrint: CPU user<br/>365.0 (1.4%)
[task 2021-07-29T06:15:49.879Z] 06:15:49     INFO - TinderboxPrint: Swap in / out<br/>536,752,128 / 0
[task 2021-07-29T06:15:49.880Z] 06:15:49     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-07-29T06:15:49.881Z] 06:15:49     INFO - install - Wall time: 33s; CPU: 14%; Read bytes: 443237888; Write bytes: 490569728; Read time: 28446; Write time: 1928
[task 2021-07-29T06:15:49.909Z] 06:15:49     INFO - run-tests - Wall time: 2199s; CPU: 2%; Read bytes: 75526144; Write bytes: 147599360; Read time: 841; Write time: 1574
[task 2021-07-29T06:15:50.396Z] 06:15:50  WARNING - returning nonzero exit status 1
[taskcluster 2021-07-29T06:15:50.435Z]    Exit Code: 1
[taskcluster 2021-07-29T06:15:50.435Z]    User Time: 4m7.248312s
[taskcluster 2021-07-29T06:15:50.435Z]  Kernel Time: 1m16.264153s
[taskcluster 2021-07-29T06:15:50.435Z]    Wall Time: 38m10.580142s
[taskcluster 2021-07-29T06:15:50.435Z]       Result: FAILED
[taskcluster 2021-07-29T06:15:50.435Z] === Task Finished ===
[taskcluster 2021-07-29T06:15:50.435Z] Task Duration: 38m10.583651s
[taskcluster 2021-07-29T06:15:50.546Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2022-07-29T03:43:28.320Z
[taskcluster 2021-07-29T06:15:50.775Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2022-07-29T03:43:28.320Z
[taskcluster 2021-07-29T06:15:52.660Z] Uploading artifact public/test_info/screenshots.html from file build/blobber_upload_dir/screenshots.html with content encoding "gzip", mime type "text/html; charset=utf-8" and expiry 2022-07-29T03:43:28.320Z
[taskcluster 2021-07-29T06:15:54.264Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/dWNEMZA2SVurEmB6FJsbDQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-07-29T03:43:28.320Z
[taskcluster:error] exit status 1
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.