Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=329847984&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GS9R6DGGStanylB7ap5YzQ/runs/0/artifacts/public/logs/live_backing.log
[task 2021-02-12T23:53:13.624Z] 23:53:13 INFO - raptor-browsertime Info: browsertime_chromedriver: /home/cltbld/tasks/task_161317393900713/fetches/{}chromedriver
[task 2021-02-12T23:53:13.624Z] 23:53:13 INFO - raptor-browsertime Info: browsertime_chromedriver: [Errno 2] No such file or directory: '/home/cltbld/tasks/task_161317393900713/fetches/{}chromedriver'
[task 2021-02-12T23:53:13.624Z] 23:53:13 INFO - raptor-perftest Info: starting test: paypal
[task 2021-02-12T23:53:13.624Z] 23:53:13 INFO - raptor-perftest Info: test uses playback tool: mitmproxy
[task 2021-02-12T23:53:13.624Z] 23:53:13 INFO - raptor-mitmproxy Info: mozproxy_dir used for mitmproxy downloads and exe files: /home/cltbld/tasks/task_161317393900713/testing/mozproxy
[task 2021-02-12T23:53:13.624Z] 23:53:13 INFO - raptor-mitmproxy Info: Playback tool: mitmproxy
[task 2021-02-12T23:53:13.625Z] 23:53:13 INFO - raptor-mitmproxy Info: Playback tool version: 5.1.1
[task 2021-02-12T23:53:13.625Z] 23:53:13 INFO - raptor-mitmproxy Info: create mitmproxy 5.1.1 dir
[task 2021-02-12T23:53:13.625Z] 23:53:13 INFO - raptor-mitmproxy Info: downloading mitmproxy binary
[task 2021-02-12T23:53:13.685Z] 23:53:13 INFO - raptor-mitmproxy Info: INFO - File mitmproxy-5.1.1-linux.tar.gz retrieved from local cache /builds/tooltool_cache
[task 2021-02-12T23:53:13.726Z] 23:53:13 INFO - raptor-mitmproxy Info: INFO - untarring "mitmproxy-5.1.1-linux.tar.gz"
[task 2021-02-12T23:53:13.842Z] 23:53:13 INFO - raptor-mitmproxy Info: downloading mitmproxy pageset
[task 2021-02-12T23:53:13.885Z] 23:53:13 INFO - raptor-mitmproxy Info: INFO - File mitm5-linux-firefox-paypal.zip not present in local cache folder /builds/tooltool_cache
[task 2021-02-12T23:53:13.885Z] 23:53:13 INFO - raptor-mitmproxy Info: INFO - Attempting to fetch from 'https://tooltool.mozilla-releng.net/'...
[task 2021-02-12T23:53:14.528Z] 23:53:14 INFO - raptor-mitmproxy Info: INFO - File mitm5-linux-firefox-paypal.zip fetched from https://tooltool.mozilla-releng.net/ as /home/cltbld/tasks/task_161317393900713/testing/mozproxy/tmphBAKcH
[task 2021-02-12T23:53:14.543Z] 23:53:14 INFO - raptor-mitmproxy Info: INFO - File integrity verified, renaming tmphBAKcH to mitm5-linux-firefox-paypal.zip
[task 2021-02-12T23:53:14.543Z] 23:53:14 INFO - raptor-mitmproxy Info: INFO - Updating local cache /builds/tooltool_cache...
[task 2021-02-12T23:53:14.543Z] 23:53:14 INFO - raptor-mitmproxy Info: INFO - Local cache /builds/tooltool_cache updated with mitm5-linux-firefox-paypal.zip
[task 2021-02-12T23:53:14.612Z] 23:53:14 INFO - raptor-mitmproxy Info: Adding /home/cltbld/tasks/task_161317393900713/testing/mozproxy/mitm5-linux-firefox-paypal.zip to recording list
[task 2021-02-12T23:53:14.619Z] 23:53:14 INFO - raptor-mitmproxy Info: Convert zip recording to new format
[task 2021-02-12T23:53:14.619Z] 23:53:14 INFO - raptor-mitmproxy Info: Renaming mitm5-linux-firefox-paypal.mp to dump.mp file
[task 2021-02-12T23:53:14.619Z] 23:53:14 INFO - raptor-mitmproxy Info: Renaming mitm5-linux-firefox-paypal.json to metadata.json file
[task 2021-02-12T23:53:14.619Z] 23:53:14 INFO - raptor-mitmproxy Info: Renaming mitm5-linux-firefox-paypal.png to screenshot.png file
[task 2021-02-12T23:53:14.620Z] 23:53:14 INFO - raptor-mitmproxy Info: Renaming mitm_netlocs_mitm5-linux-firefox-paypal.json to netlocs.json file
[task 2021-02-12T23:53:14.620Z] 23:53:14 INFO - raptor-mitmproxy Info: Old file type! Not confirming content!
[task 2021-02-12T23:53:14.620Z] 23:53:14 INFO - raptor-mitmproxy Info: mitmdump path: /home/cltbld/tasks/task_161317393900713/testing/mozproxy/mitmdump-5.1.1/mitmdump
[task 2021-02-12T23:53:14.620Z] 23:53:14 INFO - raptor-mitmproxy Info: browser path: /home/cltbld/tasks/task_161317393900713/build/application/firefox/firefox
[task 2021-02-12T23:53:14.620Z] 23:53:14 INFO - raptor-mitmproxy Info: Starting mitmproxy playback using env path: /home/cltbld/tasks/task_161317393900713/build/application/firefox:/home/cltbld/tasks/task_161317393900713/build/venv/bin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin
[task 2021-02-12T23:53:14.620Z] 23:53:14 INFO - raptor-mitmproxy Info: Starting mitmproxy playback using command: /home/cltbld/tasks/task_161317393900713/testing/mozproxy/mitmdump-5.1.1/mitmdump --listen-host 127.0.0.1 --listen-port 42049 -v --set upstream_cert=false --set upload_dir=/home/cltbld/tasks/task_161317393900713/build/blobber_upload_dir --set websocket=false --set server_replay_files=/home/cltbld/tasks/task_161317393900713/testing/mozproxy/mitm5-linux-firefox-paypal/dump.mp --scripts /home/cltbld/tasks/task_161317393900713/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/scripts/alternate-server-replay.py
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - raptor-mitmproxy Info: Mitmproxy playback successfully started on 127.0.0.1:42049 as pid 2837
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - raptor-mitmproxy Info: Installing mitmproxy CA certficate into Firefox
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - raptor-mitmproxy Info: creating folder: /home/cltbld/tasks/task_161317393900713/build/application/firefox/distribution
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - raptor-mitmproxy Info: writing: /home/cltbld/tasks/task_161317393900713/build/application/firefox/distribution/policies.json
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - raptor-mitmproxy Info: reading: /home/cltbld/tasks/task_161317393900713/build/application/firefox/distribution/policies.json
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - raptor-mitmproxy Info: Firefox policies file contents:
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - raptor-mitmproxy Info: {
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - "policies": {
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - "Certificates": {
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - "Install": ["/home/cltbld/.mitmproxy/mitmproxy-ca-cert.cer"]
[task 2021-02-12T23:53:15.380Z] 23:53:15 INFO - },
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - "Proxy": {
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - "Mode": "manual",
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - "HTTPProxy": "127.0.0.1:42049",
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - "SSLProxy": "127.0.0.1:42049",
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - "Passthrough": "127.0.0.1",
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - "Locked": true
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - }
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - }
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - }
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - raptor-mitmproxy Info: Verified mitmproxy CA certificate is installed in Firefox
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - raptor-perftest Info: Playback recording information not available
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - raptor-browsertime Info: test: {'expected_browser_cycles': 25, u'alert_threshold': u'2.0', u'playback_pageset_manifest': u'mitm5-linux-firefox-paypal.manifest', u'browser_cycles': u'25', 'here': u'/home/cltbld/tasks/task_161317393900713/build/tests/raptor/raptor/tests/tp6/desktop', u'measure': [u'fnbpaint', u'fcp', u'dcf', u'loadtime'], 'path': u'/home/cltbld/tasks/task_161317393900713/build/tests/raptor/raptor/tests/tp6/desktop/paypal', 'manifest_relpath': u'tests/tp6/desktop/browsertime-tp6.ini', 'cold': True, u'unit': u'ms', u'use_live_sites': u'false', u'alert_on': [u'fcp', u'loadtime'], u'type': u'pageload', 'name': u'paypal', u'playback_recordings': u'mitm5-linux-firefox-paypal.mp', u'page_cycles': 2, u'apps': u'firefox, chrome, chromium', u'test_url': u'https://www.paypal.com/myaccount/summary/', 'manifest': u'/home/cltbld/tasks/task_161317393900713/build/tests/raptor/raptor/tests/tp6/desktop/browsertime-tp6.ini', 'ancestor_manifest': 'raptor.ini', u'page_timeout': u'60000', u'playback_version': u'5.1.1', u'playback': u'mitmproxy', 'browser_cycle': 1, 'expected': 'pass', u'lower_is_better': True, 'relpath': u'tests/tp6/desktop/paypal'}
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - raptor-browsertime-desktop Info: binary_path: /home/cltbld/tasks/task_161317393900713/build/application/firefox/firefox
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - raptor-browsertime Info: Using Firefox Window Recorder for videos
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - raptor-browsertime Info: timeout (s): 60000
[task 2021-02-12T23:53:15.381Z] 23:53:15 INFO - raptor-browsertime Info: browsertime cwd: /home/cltbld/tasks/task_161317393900713/build
[task 2021-02-12T23:53:15.382Z] 23:53:15 INFO - raptor-browsertime Info: browsertime cmd: /home/cltbld/tasks/task_161317393900713/fetches/node/bin/node /home/cltbld/tasks/task_161317393900713/fetches/browsertime/node_modules/browsertime/bin/browsertime.js --firefox.geckodriverPath /home/cltbld/tasks/task_161317393900713/fetches/geckodriver /home/cltbld/tasks/task_161317393900713/build/tests/raptor/raptor/browsertime/../../browsertime/browsertime_pageload.js --viewPort 1024x768 --browser firefox --firefox.binaryPath /home/cltbld/tasks/task_161317393900713/build/application/firefox/firefox --browsertime.page_cycles 2 --browsertime.url https://www.paypal.com/myaccount/summary/ --browsertime.page_cycle_delay 1000 --browsertime.post_startup_delay 30000 --firefox.profileTemplate /tmp/tmpJHr2Ux.mozrunner --skipHar --pageLoadStrategy none --webdriverPageload true --firefox.disableBrowsertimeExtension true --pageCompleteCheckStartWait 5000 --pageCompleteCheckPollTimeout 1000 --timeouts.pageLoad 60000 --timeouts.script 120000 --resultDir /home/cltbld/tasks/task_161317393900713/build/blobber_upload_dir/browsertime-results/paypal --firefox.env MOZ_WEBRENDER=1 --firefox.env MOZ_ACCELERATED=1 --video true --visualMetrics false --firefox.windowRecorder true -n 25
[task 2021-02-12T23:53:15.382Z] 23:53:15 INFO - raptor-browsertime Info: browsertime_ffmpeg: /home/cltbld/tasks/task_161317393900713/fetches/ffmpeg-4.1.4-i686-static/ffmpeg
[task 2021-02-12T23:53:15.382Z] 23:53:15 INFO - raptor-browsertime Info: PATH: /home/cltbld/tasks/task_161317393900713/fetches/ffmpeg-4.1.4-i686-static:/home/cltbld/tasks/task_161317393900713/build/venv/bin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin
[task 2021-02-12T23:53:15.780Z] 23:53:15 INFO - raptor-browsertime Info: Running tests using Firefox - 25 iteration(s)
[task 2021-02-12T23:54:15.804Z] 23:54:15 INFO - raptor-browsertime Info: firefox failed to start, trying 2 more time(s): Failed to start firefox in 60 seconds.
[task 2021-02-12T23:55:15.817Z] 23:55:15 INFO - raptor-browsertime Info: firefox failed to start, trying 1 more time(s): Failed to start firefox in 60 seconds.
[task 2021-02-12T23:56:15.829Z] 23:56:15 INFO - raptor-browsertime Info: firefox failed to start, trying 0 more time(s): Failed to start firefox in 60 seconds.
[task 2021-02-12T23:56:15.829Z] 23:56:15 INFO - Exception in thread ProcessReader:
[task 2021-02-12T23:56:15.829Z] 23:56:15 ERROR - Traceback (most recent call last):
[task 2021-02-12T23:56:15.829Z] 23:56:15 INFO - File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
[task 2021-02-12T23:56:15.829Z] 23:56:15 INFO - self.run()
[task 2021-02-12T23:56:15.829Z] 23:56:15 INFO - File "/usr/lib/python2.7/threading.py", line 754, in run
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - self.__target(*self.__args, **self.__kwargs)
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - File "/home/cltbld/tasks/task_161317393900713/build/venv/lib/python2.7/site-packages/mozprocess/processhandler.py", line 1265, in _read
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - callback(line.rstrip())
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - File "/home/cltbld/tasks/task_161317393900713/build/venv/lib/python2.7/site-packages/mozprocess/processhandler.py", line 1171, in __call__
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - e(*args, **kwargs)
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - File "/home/cltbld/tasks/task_161317393900713/build/tests/raptor/raptor/browsertime/base.py", line 419, in _line_handler
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - raise Exception("Browsertime failed to run")
[task 2021-02-12T23:56:15.830Z] 23:56:15 INFO - Exception: Browsertime failed to run
[task 2021-02-13T00:56:16.012Z] 00:56:16 INFO - Automation Error: mozprocess timed out after 3600 seconds running ['/home/cltbld/tasks/task_161317393900713/build/venv/bin/python', u'/home/cltbld/tasks/task_161317393900713/build/tests/raptor/raptor/raptor.py', u'--chimera', u'--enable-webrender', u'--no-conditioned-profile', u'--browsertime-node', '/home/cltbld/tasks/task_161317393900713/fetches/node/bin/node', u'--browsertime-browsertimejs', '/home/cltbld/tasks/task_161317393900713/fetches/browsertime/node_modules/browsertime/bin/browsertime.js', u'--browsertime-chromedriver', '/home/cltbld/tasks/task_161317393900713/fetches/{}chromedriver', u'--browsertime-ffmpeg', '/home/cltbld/tasks/task_161317393900713/fetches/ffmpeg-4.1.4-i686-static/ffmpeg', u'--browsertime-geckodriver', '/home/cltbld/tasks/task_161317393900713/fetches/geckodriver', u'--browsertime-video', u'--browsertime', u'--binary', '/home/cltbld/tasks/task_161317393900713/build/application/firefox/firefox', u'--symbolsPath', u'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Nt2s9P4sS2K2xwtvCW2fMA/artifacts/public/build/target.crashreporter-symbols.zip', u'--app', 'firefox', u'--conditioned-profile-scenario', u'settled', u'--host', u'127.0.0.1', u'--test', 'paypal', u'--log-tbpl-level=debug']
[task 2021-02-13T00:56:16.020Z] 00:56:16 ERROR - timed out after 3600 seconds of no output
[task 2021-02-13T00:56:16.020Z] 00:56:16 ERROR - Return code: 1
[task 2021-02-13T00:56:16.020Z] 00:56:16 WARNING - setting return code to 1
[task 2021-02-13T00:56:16.020Z] 00:56:16 INFO - Copying Raptor results to upload dir:
[task 2021-02-13T00:56:16.020Z] 00:56:16 INFO - /home/cltbld/tasks/task_161317393900713/build/blobber_upload_dir/perfherder-data.json
[task 2021-02-13T00:56:16.020Z] 00:56:16 INFO - Copying raptor results from /home/cltbld/tasks/task_161317393900713/build/raptor.json to /home/cltbld/tasks/task_161317393900713/build/blobber_upload_dir/perfherder-data.json
[task 2021-02-13T00:56:16.020Z] 00:56:16 CRITICAL - Error copying results /home/cltbld/tasks/task_161317393900713/build/raptor.json to upload dir /home/cltbld/tasks/task_161317393900713/build/blobber_upload_dir/perfherder-data.json
[task 2021-02-13T00:56:16.020Z] 00:56:16 INFO - [Errno 2] No such file or directory: u'/home/cltbld/tasks/task_161317393900713/build/raptor.json'
[task 2021-02-13T00:56:16.021Z] 00:56:16 INFO - Running post-action listener: _package_coverage_data
[task 2021-02-13T00:56:16.021Z] 00:56:16 INFO - Running post-action listener: _resource_record_post_action
[task 2021-02-13T00:56:16.021Z] 00:56:16 INFO - Running post-action listener: process_java_coverage_data
[task 2021-02-13T00:56:16.021Z] 00:56:16 INFO - Running post-action listener: stop_device
[task 2021-02-13T00:56:16.021Z] 00:56:16 INFO - [mozharness: 2021-02-13 00:56:16.021729Z] Finished run-tests step (success)
[task 2021-02-13T00:56:16.021Z] 00:56:16 INFO - Running post-run listener: _resource_record_post_run
[task 2021-02-13T00:56:16.212Z] 00:56:16 INFO - Total resource usage - Wall time: 3790s; CPU: 1.0%; Read bytes: 210376704; Write bytes: 2559238144; Read time: 3140; Write time: 68872
[task 2021-02-13T00:56:16.212Z] 00:56:16 INFO - TinderboxPrint: CPU usage<br/>1.2%
[task 2021-02-13T00:56:16.212Z] 00:56:16 INFO - TinderboxPrint: I/O read bytes / time<br/>210,376,704 / 3,140
[task 2021-02-13T00:56:16.212Z] 00:56:16 INFO - TinderboxPrint: I/O write bytes / time<br/>2,559,238,144 / 68,872
[task 2021-02-13T00:56:16.212Z] 00:56:16 INFO - TinderboxPrint: CPU idle<br/>25,779.9 (85.2%)
[task 2021-02-13T00:56:16.212Z] 00:56:16 INFO - TinderboxPrint: CPU iowait<br/>4,224.0 (14.0%)
[task 2021-02-13T00:56:16.212Z] 00:56:16 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-02-13T00:56:16.213Z] 00:56:16 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-02-13T00:56:16.215Z] 00:56:16 INFO - install - Wall time: 9s; CPU: 13.0%; Read bytes: 32768; Write bytes: 718123008; Read time: 56; Write time: 5300
[task 2021-02-13T00:56:16.249Z] 00:56:16 INFO - run-tests - Wall time: 3783s; CPU: 1.0%; Read bytes: 159717376; Write bytes: 1841090560; Read time: 3036; Write time: 63572
[task 2021-02-13T00:56:17.014Z] 00:56:17 WARNING - returning nonzero exit status 1
[taskcluster 2021-02-13T00:56:17.045Z] Exit Code: 1
[taskcluster 2021-02-13T00:56:17.045Z] User Time: 1m58.08244s
[taskcluster 2021-02-13T00:56:17.045Z] Kernel Time: 36.458852s
[taskcluster 2021-02-13T00:56:17.045Z] Wall Time: 1h3m57.172585118s
[taskcluster 2021-02-13T00:56:17.045Z] Result: FAILED
[taskcluster 2021-02-13T00:56:17.045Z] === Task Finished ===
[taskcluster 2021-02-13T00:56:17.045Z] Task Duration: 1h3m57.173866365s
[taskcluster 2021-02-13T00:56:17.137Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2022-02-12T22:12:31.431Z
[taskcluster 2021-02-13T00:56:17.393Z] Uploading artifact public/test_info/mitmproxy.log from file build/blobber_upload_dir/mitmproxy.log with content encoding "gzip", mime type "text/plain" and expiry 2022-02-12T22:12:31.431Z
[taskcluster 2021-02-13T00:56:17.563Z] 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-02-12T22:12:31.431Z
[taskcluster 2021-02-13T00:56:18.054Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GS9R6DGGStanylB7ap5YzQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-02-12T22:12:31.431Z
[taskcluster:error] exit status 1```
Description
•