1585198 - Perma tier2 raptor-main Critical: Error while attempting to run browsertime: [Error 216] <no description>

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=269152385&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/RTNeCVqvTayKGkmmZasDgg/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-09-30T22:30:22.947Z] 22:30:22 INFO - mozproxy Verified mitmproxy CA certificate is installed in Firefox
[task 2019-09-30T22:30:22.947Z] 22:30:22 INFO - raptor-main Info: Playback recording date: 2019-06-19
[task 2019-09-30T22:30:22.948Z] 22:30:22 INFO - raptor-main Info: test: {'expected_browser_cycles': 25, 'alert_threshold': '2.0', 'playback_pageset_manifest': 'mitm4-linux-firefox-amazon.manifest', 'browser_cycles': '25', 'alert_on': ['fcp', 'loadtime'], 'here': 'C:\tasks\task_1569880756\build\tests\raptor\raptor\tests\tp6\desktop', 'expected': 'pass', 'measure': ['fnbpaint', 'fcp', 'dcf', 'loadtime'], 'path': 'C:\tasks\task_1569880756\build\tests\raptor\raptor\tests\tp6\desktop\raptor-tp6-amazon-firefox-cold', 'cold': True, 'unit': 'ms', 'ancestor-manifest': 'C:\tasks\task_1569880756\build\tests\raptor\raptor\raptor.ini', 'name': 'raptor-tp6-amazon-firefox-cold', 'playback_recordings': 'amazon.mp', 'page_cycles': 1, 'apps': 'firefox', 'test_url': 'https://www.amazon.com/s?k=laptop&ref=nb_sb_noss_1', 'manifest': 'C:\tasks\task_1569880756\build\tests\raptor\raptor\tests\tp6\desktop\raptor-tp6-cold-1.ini', 'page_timeout': '60000', 'playback': 'mitmproxy', 'browser_cycle': 1, 'lower_is_better': True, 'type': 'pageload', 'relpath': 'tests\tp6\desktop\raptor-tp6-amazon-firefox-cold'}
[task 2019-09-30T22:30:22.948Z] 22:30:22 INFO - raptor-main Info: binary_path: C:\tasks\task_1569880756\build\application\firefox\firefox.exe
[task 2019-09-30T22:30:22.948Z] 22:30:22 INFO - raptor-main Info: timeout (s): 2000
[task 2019-09-30T22:30:22.949Z] 22:30:22 INFO - raptor-main Info: browsertime cwd: C:\tasks\task_1569880756\build
[task 2019-09-30T22:30:22.950Z] 22:30:22 INFO - raptor-main Info: browsertime cmd: ['C:/tasks/task_1569880756/fetches/node/node.exe', 'C:/tasks/task_1569880756/fetches/browsertime/node_modules/browsertime/bin/browsertime.js', '--firefox.geckodriverPath', 'C:/tasks/task_1569880756/fetches/geckodriver.exe', '--chrome.chromedriverPath', 'C:/tasks/task_1569880756/fetches/chromedriver.exe', 'C:\tasks\task_1569880756\build\tests\raptor\raptor\..\browsertime\browsertime_pageload.js', '--browser', 'firefox', '--firefox.binaryPath', 'C:\tasks\task_1569880756\build\application\firefox\firefox.exe', '--browsertime.page_cycles', '1', '--browsertime.url', 'https://www.amazon.com/s?k=laptop&ref=nb_sb_noss_1', '--browsertime.page_cycle_delay', '1000', '--browsertime.foreground_delay', '5000', '--skipHar', '--video', 'false', '--visualMetrics', 'false', '-vv', '--resultDir', 'C:\tasks\task_1569880756\build\blobber_upload_dir\browsertime-results\raptor-tp6-amazon-firefox-cold', '-n', '25']
[task 2019-09-30T22:30:22.950Z] 22:30:22 INFO - raptor-main Info: browsertime_ffmpeg: C:/tasks/task_1569880756/fetches/ffmpeg-4.1.1-win64-static/bin/ffmpeg.exe
[task 2019-09-30T22:30:22.951Z] 22:30:22 INFO - raptor-main Info: PATH: C:\tasks\task_1569880756\fetches\ffmpeg-4.1.1-win64-static\bin;C:\tasks\task_1569880756\build\venv\Scripts;C:\windows\system32;C:\windows;C:\windows\System32\Wbem;C:\windows\System32\WindowsPowerShell\v1.0;C:\windows\System32\OpenSSH;C:\Users\testdroid\AppData\Local\Microsoft\WindowsApps;;C:\windows\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\mozilla-build\python3\Scripts;C:\mozilla-build\python3;C:\windows\SysWOW64\config\systemprofile\AppData\Local\Programs\Python\Launcher;C:\Program Files (x86)\GNU\GnuPG\pub;C:\Program Files (x86)\Mercurial;C:\mozilla-build\7zip;C:\mozilla-build\info-zip;C:\mozilla-build\kdiff3;C:\mozilla-build\moztools-x64\bin;C:\mozilla-build\mozmake;C:\mozilla-build\msys\bin;C:\mozilla-build\msys\local\bin;C:\mozilla-build\nsis-3.0b3;C:\mozilla-build\nsis-2.46u;C:\mozilla-build\python;C:\mozilla-build\python\Scripts;C:\mozilla-build\python3;C:\mozilla-build\upx391w;C:\mozilla-build\wget;C:\mozilla-build\yasm;C:\Program Files\Microsoft Windows Performance Toolkit;C:\Users\testdroid.YOGA-018\AppData\Local\Microsoft\WindowsApps
[task 2019-09-30T22:30:22.956Z] 22:30:22 CRITICAL - raptor-main Critical: Error while attempting to run browsertime: [Error 216] <no description>
[task 2019-09-30T22:30:22.957Z] 22:30:22 INFO - mozproxy Stopping mitmproxy playback, killing process 11960
[task 2019-09-30T22:30:22.997Z] 22:30:22 INFO - mozproxy Mitmproxy exited with error code 572
[task 2019-09-30T22:30:22.997Z] 22:30:22 INFO - mozproxy Turning off the browser proxy
[task 2019-09-30T22:30:22.997Z] 22:30:22 INFO - mozproxy writing: C:\tasks\task_1569880756\build\application\firefox\distribution\policies.json
[task 2019-09-30T22:30:23.028Z] 22:30:23 INFO - ['C:/tasks/task_1569880756/fetches/node/node.exe', 'C:/tasks/task_1569880756/fetches/browsertime/node_modules/browsertime/bin/browsertime.js', '--firefox.geckodriverPath', 'C:/tasks/task_1569880756/fetches/geckodriver.exe', '--chrome.chromedriverPath', 'C:/tasks/task_1569880756/fetches/chromedriver.exe', 'C:\tasks\task_1569880756\build\tests\raptor\raptor\..\browsertime\browsertime_pageload.js', '--browser', 'firefox', '--firefox.binaryPath', 'C:\tasks\task_1569880756\build\application\firefox\firefox.exe', '--browsertime.page_cycles', '1', '--browsertime.url', 'https://www.amazon.com/s?k=laptop&ref=nb_sb_noss_1', '--browsertime.page_cycle_delay', '1000', '--browsertime.foreground_delay', '5000', '--skipHar', '--video', 'false', '--visualMetrics', 'false', '-vv', '--resultDir', 'C:\tasks\task_1569880756\build\blobber_upload_dir\browsertime-results\raptor-tp6-amazon-firefox-cold', '-n', '25']
[task 2019-09-30T22:30:23.028Z] 22:30:23 ERROR - Traceback (most recent call last):
[task 2019-09-30T22:30:23.028Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\tests\raptor\raptor\raptor.py", line 1482, in <module>
[task 2019-09-30T22:30:23.028Z] 22:30:23 INFO - main()
[task 2019-09-30T22:30:23.029Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\tests\raptor\raptor\raptor.py", line 1450, in main
[task 2019-09-30T22:30:23.029Z] 22:30:23 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-09-30T22:30:23.029Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\tests\raptor\raptor\raptor.py", line 202, in run_tests
[task 2019-09-30T22:30:23.030Z] 22:30:23 INFO - self.run_test(test, timeout=int(test.get('page_timeout')))
[task 2019-09-30T22:30:23.030Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\tests\raptor\raptor\raptor.py", line 469, in run_test
[task 2019-09-30T22:30:23.030Z] 22:30:23 INFO - outputTimeout=2*60)
[task 2019-09-30T22:30:23.030Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\venv\lib\site-packages\mozprocess\processhandler.py", line 811, in run
[task 2019-09-30T22:30:23.031Z] 22:30:23 INFO - self.proc = self.Process([self.cmd] + self.args, **args)
[task 2019-09-30T22:30:23.031Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\venv\lib\site-packages\mozprocess\processhandler.py", line 123, in init
[task 2019-09-30T22:30:23.031Z] 22:30:23 INFO - universal_newlines, startupinfo, creationflags)
[task 2019-09-30T22:30:23.031Z] 22:30:23 INFO - File "c:\mozilla-build\python\Lib\subprocess.py", line 710, in init
[task 2019-09-30T22:30:23.032Z] 22:30:23 INFO - errread, errwrite)
[task 2019-09-30T22:30:23.032Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\venv\lib\site-packages\mozprocess\processhandler.py", line 310, in _execute_child
[task 2019-09-30T22:30:23.032Z] 22:30:23 INFO - cwd, startupinfo)
[task 2019-09-30T22:30:23.033Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\venv\lib\site-packages\mozprocess\winprocess.py", line 212, in ErrCheckCreateProcess
[task 2019-09-30T22:30:23.033Z] 22:30:23 INFO - ErrCheckBool(result, func, args)
[task 2019-09-30T22:30:23.033Z] 22:30:23 INFO - File "C:\tasks\task_1569880756\build\venv\lib\site-packages\mozprocess\winprocess.py", line 57, in ErrCheckBool
[task 2019-09-30T22:30:23.033Z] 22:30:23 INFO - raise WinError()
[task 2019-09-30T22:30:23.034Z] 22:30:23 INFO - WindowsError: [Error 216] <no description>
[task 2019-09-30T22:30:23.091Z] 22:30:23 ERROR - Return code: 1
[task 2019-09-30T22:30:23.092Z] 22:30:23 WARNING - setting return code to 1
[task 2019-09-30T22:30:23.092Z] 22:30:23 INFO - Copying Raptor results to upload dir:
[task 2019-09-30T22:30:23.092Z] 22:30:23 INFO - C:\tasks\task_1569880756\build\blobber_upload_dir\perfherder-data.json
[task 2019-09-30T22:30:23.092Z] 22:30:23 INFO - Copying raptor results from C:\tasks\task_1569880756\build\raptor.json to C:\tasks\task_1569880756\build\blobber_upload_dir\perfherder-data.json
[task 2019-09-30T22:30:23.093Z] 22:30:23 CRITICAL - Error copying results C:\tasks\task_1569880756\build\raptor.json to upload dir C:\tasks\task_1569880756\build\blobber_upload_dir\perfherder-data.json

Comment 1

[Andreea Pavel [:apavel]]

This is a different issue: we didn't accommodate Windows on aarch64 yet, so we need to do like Bug 1582972 and make sure we're using the correct version of Node.js. I can try to get to this tomorrow.

Comment 2

[Nick Alexander :nalexander [he/him]]

Attachment: Bug 1585198 - Use win32-node for aarch64 Browsertime tests. r?#perftest-reviewers

Just like Bug 1582972.

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3e0f997b9cfe
Use win32-node for aarch64 Browsertime tests. r=stephendonner

Comment 4

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/3e0f997b9cfe

Comment 5

[Intermittent Failures Robot]

1 failures in 4292 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1585198&startday=2019-09-30&endday=2019-10-06&tree=all