1659120 - Perma [tier 2] gdoc raptor-perftest Critical: [chromium/chrome] Test failed to finish. Application timed out after 1821 seconds

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.YXqwgDkycM/Listeners',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  'TASK_ID': 'dOIe17Y2RCC6c9vE1C9hGA',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  'TMPDIR': '/var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  'USER': 'cltbld',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  'XPC_FLAGS': '0x0',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  'XPC_SERVICE_NAME': '0',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  '_': '/usr/local/bin/generic-worker',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  '__CF_USER_TEXT_ENCODING': '0x27:0:0',
[task 2020-08-14T13:07:34.821Z] 13:07:34     INFO -  '__PYVENV_LAUNCHER__': '/usr/local/bin/python3'}
[task 2020-08-14T13:07:34.822Z] 13:07:34     INFO - Calling ['/Users/cltbld/tasks/task_1597407866/build/venv/bin/python', u'/Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/raptor.py', u'--setpref=extensions.logging.enabled=true', u'--binary', u'/Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', u'--symbolsPath', u'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BP8S0TQqRwiuZ64x8cEDMA/artifacts/public/build/target.crashreporter-symbols.zip', u'--app', 'chromium', u'--conditioned-profile-scenario', u'settled', u'--host', u'127.0.0.1', u'--test', 'raptor-tp6-docs-chromium', u'--log-tbpl-level=debug'] with output_timeout 3600
[task 2020-08-14T13:07:35.210Z] 13:07:35     INFO -  raptor-main Info: Python version: 2.7.16 (v2.7.16:413a49145e, Mar  2 2019, 14:32:10)
[task 2020-08-14T13:07:35.210Z] 13:07:35     INFO -  [GCC 4.2.1 Compatible Apple LLVM 6.0 (clang-600.0.57)]
[task 2020-08-14T13:07:35.210Z] 13:07:35     INFO -  raptor-main Info: raptor-start
[task 2020-08-14T13:07:35.210Z] 13:07:35     INFO -  raptor-main Info: received command line arguments: Namespace(activity=None, app='chromium', binary='/Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', browser_cycles=None, browsertime=False, browsertime_browsertimejs=None, browsertime_chromedriver=None, browsertime_ffmpeg=None, browsertime_geckodriver=None, browsertime_no_ffwindowrecorder=False, browsertime_node=None, browsertime_video=False, chimera=False, cold=False, conditioned_profile_scenario='settled', cpu_test=False, debug_mode=False, device_name=None, disable_perf_tuning=False, e10s=True, enable_fission=False, enable_webrender=False, extra_prefs={'extensions.logging.enabled': True}, gecko_profile=False, gecko_profile_entries=None, gecko_profile_interval=None, gecko_profile_threads=None, host='127.0.0.1', installerpath=None, intent=None, is_release_build=False, live_sites=False, log_errorsummary=None, log_grouped=None, log_html=None, log_mach=None, log_mach_buffer=None, log_mach_level=None, log_mach_screenshot=None, log_mach_verbose=None, log_raw=None, log_raw_level=None, log_tbpl=None, log_tbpl_buffer=None, log_tbpl_compact=None, log_tbpl_level='debug', log_unittest=None, log_xunit=None, memory_test=False, no_conditioned_profile=False, noinstall=False, obj_path=None, page_cycles=None, page_timeout=None, post_startup_delay=30000, power_test=False, project='mozilla-central', run_local=False, symbols_path='https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BP8S0TQqRwiuZ64x8cEDMA/artifacts/public/build/target.crashreporter-symbols.zip', test='raptor-tp6-docs-chromium', test_url_params=None, verbose=False)
[task 2020-08-14T13:07:35.211Z] 13:07:35     INFO -  raptor-manifest Info: /Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/raptor.ini
[task 2020-08-14T13:07:35.242Z] 13:07:35     INFO -  raptor-manifest Info: configuring settings for test raptor-tp6-docs-chromium
[task 2020-08-14T13:07:35.242Z] 13:07:35     INFO -  raptor-main Info: raptor tests scheduled to run:
[task 2020-08-14T13:07:35.242Z] 13:07:35     INFO -  raptor-main Info: raptor-tp6-docs-chromium
[task 2020-08-14T13:07:35.242Z] 13:07:35     INFO -  raptor-perftest Info: Using a conditioned profile.
[task 2020-08-14T13:07:35.246Z] 13:07:35     INFO -  raptor-perftest Warning: [chromium] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS
[task 2020-08-14T13:07:35.246Z] 13:07:35     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-08-14T13:07:35.413Z] 13:07:35     INFO -  Chromium 86.0.4234.0
[task 2020-08-14T13:07:35.445Z] 13:07:35     INFO -  raptor-perftest Info: Browser name: chromium
[task 2020-08-14T13:07:35.445Z] 13:07:35     INFO -  raptor-perftest Info: Browser version: 86.0.4234.0
[task 2020-08-14T13:07:35.445Z] 13:07:35     INFO -  raptor-perftest Warning: [chromium] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS
[task 2020-08-14T13:07:35.445Z] 13:07:35     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-08-14T13:07:35.514Z] 13:07:35     INFO -  Chromium 86.0.4234.0
[task 2020-08-14T13:07:35.515Z] 13:07:35     INFO -  raptor-perftest Info: Browser name: chromium
[task 2020-08-14T13:07:35.515Z] 13:07:35     INFO -  raptor-perftest Info: Browser version: 86.0.4234.0
[task 2020-08-14T13:07:35.516Z] 13:07:35     INFO -  raptor-perftest Info: Post startup delay set to 1000 ms
[task 2020-08-14T13:07:35.516Z] 13:07:35     INFO -  raptor-perftest Info: main raptor init, config is: {'verbose': False, 'e10s': True, 'app': 'chromium', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BP8S0TQqRwiuZ64x8cEDMA/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'chimera': False, 'cold': False, 'gecko_profile_interval': None, 'binary': '/Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', 'enable_control_server_wait': False, 'no_conditioned_profile': False, 'platform': 'mac', 'conditioned_profile_scenario': 'settled', 'extra_prefs': {'extensions.logging.enabled': True}, 'gecko_profile': False, 'gecko_profile_entries': None, 'disable_perf_tuning': False, 'host': '127.0.0.1', 'enable_fission': False, 'memory_test': False, 'enable_webrender': False, 'obj_path': None, 'live_sites': False, 'device_name': None, 'project': 'mozilla-central', 'cpu_test': False, 'is_release_build': False, 'using_condprof': True, 'processor': 'x86_64'}
[task 2020-08-14T13:07:35.517Z] 13:07:35     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/profile_data/base
[task 2020-08-14T13:07:35.517Z] 13:07:35     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/profile_data/common
[task 2020-08-14T13:07:35.518Z] 13:07:35     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/profile_data/perf
[task 2020-08-14T13:07:35.518Z] 13:07:35     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/profile_data/raptor
[task 2020-08-14T13:07:35.518Z] 13:07:35     INFO -  raptor-perftest Info: Local browser profile: /var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpqxPDP5.mozrunner/Default
[task 2020-08-14T13:07:35.527Z] 13:07:35     INFO -  raptor-perftest Warning: [chromium] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS
[task 2020-08-14T13:07:35.527Z] 13:07:35     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-08-14T13:07:35.573Z] 13:07:35     INFO -  Chromium 86.0.4234.0
[task 2020-08-14T13:07:35.574Z] 13:07:35     INFO -  raptor-perftest Info: Browser name: chromium
[task 2020-08-14T13:07:35.575Z] 13:07:35     INFO -  raptor-perftest Info: Browser version: 86.0.4234.0
[task 2020-08-14T13:07:35.583Z] 13:07:35     INFO -  raptor-control-server Info: raptor control server running on port 50009...
[task 2020-08-14T13:07:35.583Z] 13:07:35     INFO -  raptor-webext-desktop Info: creating browser runner using mozrunner
[task 2020-08-14T13:07:35.583Z] 13:07:35     INFO -  raptor-perftest Info: starting test: raptor-tp6-docs-chromium
[task 2020-08-14T13:07:35.583Z] 13:07:35     INFO -  raptor-perftest Info: test uses playback tool: mitmproxy
[task 2020-08-14T13:07:35.583Z] 13:07:35     INFO -  raptor-mitmproxy Info: mitmproxy was not provided with a 'playback_binary_manifest' Using default playback_binary_manifest
[task 2020-08-14T13:07:35.583Z] 13:07:35     INFO -  raptor-mitmproxy Info: mozproxy_dir used for mitmproxy downloads and exe files: /Users/cltbld/tasks/task_1597407866/testing/mozproxy
[task 2020-08-14T13:07:35.584Z] 13:07:35     INFO -  raptor-mitmproxy Info: Playback tool: mitmproxy
[task 2020-08-14T13:07:35.584Z] 13:07:35     INFO -  raptor-mitmproxy Info: Playback tool version: 5.1.1
[task 2020-08-14T13:07:35.584Z] 13:07:35     INFO -  raptor-mitmproxy Info: create mitmproxy 5.1.1 dir
[task 2020-08-14T13:07:35.584Z] 13:07:35     INFO -  raptor-mitmproxy Info: downloading mitmproxy binary
[task 2020-08-14T13:07:35.761Z] 13:07:35     INFO -  raptor-mitmproxy Info: INFO - File mitmproxy-5.1.1-osx.tar.gz retrieved from local cache /builds/tooltool_cache
[task 2020-08-14T13:07:35.761Z] 13:07:35     INFO -  raptor-mitmproxy Info: INFO - untarring "mitmproxy-5.1.1-osx.tar.gz"
[task 2020-08-14T13:07:36.064Z] 13:07:36     INFO -  raptor-mitmproxy Info: downloading mitmproxy pageset
[task 2020-08-14T13:07:36.372Z] 13:07:36     INFO -  raptor-mitmproxy Info: INFO - File mitm5-linux-firefox-google-docs.zip retrieved from local cache /builds/tooltool_cache
[task 2020-08-14T13:07:36.487Z] 13:07:36     INFO -  raptor-mitmproxy Info: INFO - unzipping "mitm5-linux-firefox-google-docs.zip"
[task 2020-08-14T13:07:36.815Z] 13:07:36     INFO -  raptor-mitmproxy Info: mitmdump path: /Users/cltbld/tasks/task_1597407866/testing/mozproxy/mitmdump-5.1.1/mitmdump
[task 2020-08-14T13:07:36.815Z] 13:07:36     INFO -  raptor-mitmproxy Info: browser path: /Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium
[task 2020-08-14T13:07:36.815Z] 13:07:36     INFO -  raptor-mitmproxy Info: Starting mitmproxy playback using env path: /Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS:/Users/cltbld/tasks/task_1597407866/build/venv/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin
[task 2020-08-14T13:07:36.815Z] 13:07:36     INFO -  raptor-mitmproxy Info: Starting mitmproxy playback using command: /Users/cltbld/tasks/task_1597407866/testing/mozproxy/mitmdump-5.1.1/mitmdump --listen-host 127.0.0.1 --listen-port 50010 -v --set upstream_cert=false --set upload_dir=/Users/cltbld/tasks/task_1597407866/build/blobber_upload_dir --set websocket=false --set server_replay_files=/Users/cltbld/tasks/task_1597407866/testing/mozproxy/mitm5-linux-firefox-google-docs.mp --scripts /Users/cltbld/tasks/task_1597407866/build/venv/lib/python2.7/site-packages/mozproxy/backends/mitm/scripts/alternate-server-replay.py
[task 2020-08-14T13:07:37.614Z] 13:07:37     INFO -  raptor-mitmproxy Info: Mitmproxy playback successfully started on 127.0.0.1:50010 as pid 4092
[task 2020-08-14T13:07:37.614Z] 13:07:37     INFO -  raptor-perftest Info: Playback recording date: 2020-06-24
[task 2020-08-14T13:07:37.614Z] 13:07:37     INFO -  raptor-webext Info: starting web extension test: raptor-tp6-docs-chromium
[task 2020-08-14T13:07:37.617Z] 13:07:37     INFO -  raptor-webext Info: test settings: {'expected_browser_cycles': 1, u'alert_threshold': u'2.0', u'playback_pageset_manifest': u'mitm5-linux-firefox-google-docs.manifest', u'browser_cycles': 1, 'here': u'/Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/tests/tp6/desktop', u'measure': [u'fcp', u'loadtime'], 'path': u'/Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/tests/tp6/desktop/raptor-tp6-docs-chromium', 'manifest_relpath': u'tests/tp6/desktop/google-docs.ini', 'cold': False, u'unit': u'ms', u'alert_on': [u'fcp', u'loadtime'], u'type': u'pageload', 'name': u'raptor-tp6-docs-chromium', u'playback_recordings': u'mitm5-linux-firefox-google-docs.mp', u'page_cycles': u'25', u'apps': u'chromium', u'test_url': u'https://docs.google.com/document/d/1US-07msg12slQtI_xchzYxcKlTs6Fp7WqIc6W5GK5M8/edit?usp=sharing', 'manifest': u'/Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/tests/tp6/desktop/google-docs.ini', 'ancestor_manifest': u'tests/tp6/desktop-tests.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/raptor-tp6-docs-chromium'}
[task 2020-08-14T13:07:37.617Z] 13:07:37     INFO -  raptor-webext Info: web extension config: {'subtest_alert_on': [u'fcp', u'loadtime'], 'verbose': False, 'e10s': True, 'app': 'chromium', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BP8S0TQqRwiuZ64x8cEDMA/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'playback_binary_zip': None, 'run_local': False, 'playback_files': [u'/Users/cltbld/tasks/task_1597407866/testing/mozproxy/mitm5-linux-firefox-google-docs.mp'], 'chimera': False, 'cold': False, 'gecko_profile_interval': None, 'binary': '/Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', 'local_profile_dir': '/var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpqxPDP5.mozrunner/Default', 'playback_binary_manifest': u'mitmproxy-rel-bin-5.1.1-{platform}.manifest', 'enable_control_server_wait': False, 'no_conditioned_profile': False, 'platform': 'mac', 'playback_version': u'5.1.1', 'conditioned_profile_scenario': 'settled', 'extra_prefs': {'extensions.logging.enabled': True}, 'gecko_profile': False, 'gecko_profile_entries': None, 'playback_pageset_manifest': u'/Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/tooltool-manifests/playback/mitm5-linux-firefox-google-docs.manifest', 'playback_pageset_zip': None, 'disable_perf_tuning': False, 'playback_tool': u'mitmproxy', 'host': '127.0.0.1', 'enable_fission': False, 'memory_test': False, 'enable_webrender': False, 'obj_path': None, 'live_sites': False, 'device_name': None, 'project': 'mozilla-central', 'cpu_test': False, 'is_release_build': False, 'using_condprof': True, 'processor': 'x86_64'}
[task 2020-08-14T13:07:37.617Z] 13:07:37     INFO -  raptor-gen-test-config Info: writing test settings into background js, so webext can get it
[task 2020-08-14T13:07:37.617Z] 13:07:37     INFO -  raptor-gen-test-config Info: finished writing test config to /Users/cltbld/tasks/task_1597407866/build/tests/raptor/webext/raptor/auto_gen_test_config.js
[task 2020-08-14T13:07:37.617Z] 13:07:37     INFO -  raptor-webext Info: installing webext /Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-08-14T13:07:37.618Z] 13:07:37     INFO -  raptor-webext-desktop Info: starting chromium
[task 2020-08-14T13:07:37.618Z] 13:07:37     INFO -  Application command: /Users/cltbld/tasks/task_1597407866/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium --allow-downgrade --user-data-dir=/var/folders/q5/3_6bkrf10r173w_j8jqrs6xr000017/T/tmpqxPDP5.mozrunner --profile-directory=Default --no-first-run --use-mock-keychain --no-default-browser-check --proxy-server=127.0.0.1:50010 --proxy-bypass-list=localhost;127.0.0.1 --ignore-certificate-errors --load-extension=/Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-08-14T13:07:39.999Z] 13:07:39     INFO -  raptor-control-server Info: received webext_loaded: raptor runner.js is loaded!
[task 2020-08-14T13:07:40.064Z] 13:07:40     INFO -  raptor-control-server Info: received webext_status: testing on Chrome 86.0.4234.0
[task 2020-08-14T13:07:40.064Z] 13:07:40     INFO -  raptor-control-server Info: received webext_status: test name is: raptor-tp6-docs-chromium
[task 2020-08-14T13:07:40.065Z] 13:07:40     INFO -  raptor-control-server Info: received webext_status: test settings url is: http://127.0.0.1:50009/json/raptor-tp6-docs-chromium.json
[task 2020-08-14T13:07:40.078Z] 13:07:40     INFO -  raptor-control-server Info: received webext_status: starting raptorRunner
[task 2020-08-14T13:07:40.092Z] 13:07:40     INFO -  raptor-control-server Info: reading test settings from json/raptor-tp6-docs-chromium.json
[task 2020-08-14T13:07:40.093Z] 13:07:40     INFO -  raptor-control-server Info: sent test settings to webext runner
[task 2020-08-14T13:07:40.110Z] 13:07:40     INFO -  raptor-control-server Info: received webext_status: * pausing 1 seconds to let browser settle... *
[task 2020-08-14T13:07:41.184Z] 13:07:41     INFO -  raptor-control-server Info: received webext_status: opening new tab
[task 2020-08-14T13:07:41.222Z] 13:07:41     INFO -  raptor-control-server Info: received webext_status: opened new empty tab: 3
[task 2020-08-14T13:07:41.239Z] 13:07:41     INFO -  raptor-control-server Info: received webext_status: found active tab with id 3
[task 2020-08-14T13:07:41.247Z] 13:07:41     INFO -  raptor-control-server Info: received webext_status: running 25 pagecycles of https://docs.google.com/document/d/1US-07msg12slQtI_xchzYxcKlTs6Fp7WqIc6W5GK5M8/edit?usp=sharing
[task 2020-08-14T13:07:42.254Z] 13:07:42     INFO -  raptor-control-server Info: received webext_status: begin page cycle 1
[task 2020-08-14T13:07:42.255Z] 13:07:42     INFO -  raptor-control-server Info: received webext_status: update tab 3 for https://docs.google.com/document/d/1US-07msg12slQtI_xchzYxcKlTs6Fp7WqIc6W5GK5M8/edit?usp=sharing
[task 2020-08-14T13:07:42.266Z] 13:07:42     INFO -  raptor-control-server Info: received webext_status: tab 3 updated
[task 2020-08-14T13:07:42.274Z] 13:07:42     INFO -  raptor-control-server Info: received webext_status: ended page cycle 1
[task 2020-08-14T13:07:47.543Z] 13:07:47     INFO -  raptor-control-server Info: received webext_status: results received
[task 2020-08-14T13:07:48.681Z] 13:07:48     INFO -  raptor-control-server Info: received webext_status: begin page cycle 2
[task 2020-08-14T13:07:48.685Z] 13:07:48     INFO -  raptor-control-server Info: received webext_status: update tab 3 for https://docs.google.com/document/d/1US-07msg12slQtI_xchzYxcKlTs6Fp7WqIc6W5GK5M8/edit?usp=sharing
[task 2020-08-14T13:07:48.717Z] 13:07:48     INFO -  raptor-control-server Info: received webext_status: tab 3 updated
[task 2020-08-14T13:07:48.717Z] 13:07:48     INFO -  raptor-control-server Info: received webext_status: ended page cycle 2
[task 2020-08-14T13:07:53.293Z] 13:07:53     INFO -  raptor-control-server Info: received webext_status: results received
[task 2020-08-14T13:07:54.438Z] 13:07:54     INFO -  raptor-control-server Info: received webext_status: begin page cycle 3
[task 2020-08-14T13:07:54.438Z] 13:07:54     INFO -  raptor-control-server Info: received webext_status: update tab 3 for https://docs.google.com/document/d/1US-07msg12slQtI_xchzYxcKlTs6Fp7WqIc6W5GK5M8/edit?usp=sharing
[task 2020-08-14T13:07:54.442Z] 13:07:54     INFO -  raptor-control-server Info: received webext_status: tab 3 updated
[task 2020-08-14T13:07:54.446Z] 13:07:54     INFO -  raptor-control-server Info: received webext_status: ended page cycle 3
[task 2020-08-14T13:38:11.542Z] 13:38:11 CRITICAL -  raptor-perftest Critical: [chromium] Test failed to finish. Application timed out after 1821 seconds
[task 2020-08-14T13:38:11.543Z] 13:38:11     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 4092
[task 2020-08-14T13:38:11.798Z] 13:38:11     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2020-08-14T13:38:11.798Z] 13:38:11     INFO -  raptor-mitmproxy Info: Reading confidence values from: /Users/cltbld/tasks/task_1597407866/build/blobber_upload_dir/mitm_netlocs_mitm5-linux-firefox-google-docs.json
[task 2020-08-14T13:38:11.798Z] 13:38:11     INFO -  perftest-results-handler Info: RaptorResultsHandler.add_supporting_data received mozproxy data
[task 2020-08-14T13:38:11.798Z] 13:38:11     INFO -  raptor-webext Info: removing webext /Users/cltbld/tasks/task_1597407866/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-08-14T13:38:11.798Z] 13:38:11     INFO -  raptor-control-server Info: shutting down control server
[task 2020-08-14T13:38:12.285Z] 13:38:12     INFO -  raptor-webext Info: finished
[task 2020-08-14T13:38:12.454Z] 13:38:12    ERROR - Return code: 1
[task 2020-08-14T13:38:12.454Z] 13:38:12  WARNING - setting return code to 1
[task 2020-08-14T13:38:12.454Z] 13:38:12     INFO - Copying Raptor results to upload dir:
[task 2020-08-14T13:38:12.454Z] 13:38:12     INFO - /Users/cltbld/tasks/task_1597407866/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-14T13:38:12.454Z] 13:38:12     INFO - Copying raptor results from /Users/cltbld/tasks/task_1597407866/build/raptor.json to /Users/cltbld/tasks/task_1597407866/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-14T13:38:12.454Z] 13:38:12 CRITICAL - Error copying results /Users/cltbld/tasks/task_1597407866/build/raptor.json to upload dir /Users/cltbld/tasks/task_1597407866/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-14T13:38:12.454Z] 13:38:12     INFO - [Errno 2] No such file or directory: u'/Users/cltbld/tasks/task_1597407866/build/raptor.json'
[task 2020-08-14T13:38:12.455Z] 13:38:12     INFO - Running post-action listener: _package_coverage_data
[task 2020-08-14T13:38:12.455Z] 13:38:12     INFO - Running post-action listener: _resource_record_post_action
[task 2020-08-14T13:38:12.455Z] 13:38:12     INFO - Running post-action listener: process_java_coverage_data
[task 2020-08-14T13:38:12.455Z] 13:38:12     INFO - Running post-action listener: stop_device
[task 2020-08-14T13:38:12.455Z] 13:38:12     INFO - [mozharness: 2020-08-14 13:38:12.455627Z] Finished run-tests step (success)
[task 2020-08-14T13:38:12.455Z] 13:38:12     INFO - Running post-run listener: _resource_record_post_run
[task 2020-08-14T13:38:12.583Z] 13:38:12     INFO - Total resource usage - Wall time: 1856s; CPU: 14.0%; Read bytes: 213831680; Write bytes: 542273536; Read time: 3908; Write time: 2477
[task 2020-08-14T13:38:12.583Z] 13:38:12     INFO - TinderboxPrint: CPU usage<br/>13.6%
[task 2020-08-14T13:38:12.583Z] 13:38:12     INFO - TinderboxPrint: I/O read bytes / time<br/>213,831,680 / 3,908
[task 2020-08-14T13:38:12.583Z] 13:38:12     INFO - TinderboxPrint: I/O write bytes / time<br/>542,273,536 / 2,477
[task 2020-08-14T13:38:12.583Z] 13:38:12     INFO - TinderboxPrint: CPU idle<br/>5,876.8 (79.2%)
[task 2020-08-14T13:38:12.584Z] 13:38:12     INFO - TinderboxPrint: CPU system<br/>826.5 (11.1%)
[task 2020-08-14T13:38:12.584Z] 13:38:12     INFO - TinderboxPrint: CPU user<br/>719.9 (9.7%)
[task 2020-08-14T13:38:12.584Z] 13:38:12     INFO - TinderboxPrint: Swap in / out<br/>436,338,688 / 0
[task 2020-08-14T13:38:12.585Z] 13:38:12     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 2020-08-14T13:38:12.586Z] 13:38:12     INFO - install - Wall time: 19s; CPU: 48.0%; Read bytes: 234522112; Write bytes: 222527488; Read time: 13802; Write time: 357
[task 2020-08-14T13:38:12.600Z] 13:38:12     INFO - run-tests - Wall time: 1838s; CPU: 13.0%; Read bytes: 206450688; Write bytes: 292655104; Read time: 3839; Write time: 2066
[task 2020-08-14T13:38:12.941Z] 13:38:12  WARNING - returning nonzero exit status 1
[resource_monitor 2020-08-14T13:38:12.960Z] terminating
[fetches 2020-08-14T13:38:13.171Z] removing /Users/cltbld/tasks/task_1597407866/fetches
[fetches 2020-08-14T13:38:13.204Z] finished
[taskcluster 2020-08-14T13:38:13.213Z]    Exit Code: 1
[taskcluster 2020-08-14T13:38:13.213Z]    User Time: 9m8.674235s
[taskcluster 2020-08-14T13:38:13.213Z]  Kernel Time: 8m46.135796s
[taskcluster 2020-08-14T13:38:13.213Z]    Wall Time: 32m20.192112476s
[taskcluster 2020-08-14T13:38:13.213Z]       Result: FAILED
[taskcluster 2020-08-14T13:38:13.213Z] === Task Finished ===
[taskcluster 2020-08-14T13:38:13.213Z] Task Duration: 32m20.196260692s
[taskcluster 2020-08-14T13:38:13.348Z] Uploading artifact public/monitoring/resource-monitor.json from file monitoring/resource-monitor.json with content encoding "gzip", mime type "application/json" and expiry 2021-08-14T13:05:44.217Z
[taskcluster 2020-08-14T13:38:15.024Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2021-08-14T13:05:44.217Z
[taskcluster 2020-08-14T13:38:15.225Z] Uploading artifact public/test_info/mitm_netlocs_mitm5-linux-firefox-google-docs.json from file build/blobber_upload_dir/mitm_netlocs_mitm5-linux-firefox-google-docs.json with content encoding "gzip", mime type "application/json" and expiry 2021-08-14T13:05:44.217Z
[taskcluster 2020-08-14T13:38:15.771Z] 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 2021-08-14T13:05:44.217Z
[taskcluster 2020-08-14T13:38:17.647Z] 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 2021-08-14T13:05:44.217Z
[taskcluster:error] exit status 1

Comment 1

[Alexandru Michis [:malexandru]]

This looks to have appeared on the merge from autoland to central from August 7th:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Craptor%2Cperformance%2Ctests%2Con%2Cgoogle%2Cchromium%2Ctest-macosx1014-64-shippable%2Fopt-raptor-tp6-chromium-docs-e10s%2Cgdoc&tochange=d1de0bdfee4fcc742faa7126c9c4d1c18d89bfe3&fromchange=cc8993c8140a06f97b7f91208e608c01c350961b&selectedTaskRun=dOIe17Y2RCC6c9vE1C9hGA.0

Affected platforms are OS X 10.14 Shippable opt, Windows 10 x64 Shippable opt, Windows 7 Shippable opt and Linux x64 shippable opt

Greg, could you please take a look?

Comment 2

[Intermittent Failures Robot]

25 failures in 662 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 25

Platform breakdown:

• linux64-shippable: 5
• windows10-64-shippable: 5
• windows7-32-shippable: 10
• macosx1014-64-shippable: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-08-14&endday=2020-08-14&tree=all

Comment 3

[Intermittent Failures Robot]

25 failures in 3601 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

This is the #32 most frequent failure this week.

Repository breakdown:

• mozilla-central: 25

Platform breakdown:

• linux64-shippable: 5
• windows10-64-shippable: 5
• windows7-32-shippable: 10
• macosx1014-64-shippable: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-08-10&endday=2020-08-16&tree=all

Comment 4

[Alexandru Michis [:malexandru]]

Modified the summary to include "chrome" raptor jobs as well, they started permafailing too:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&resultStatus=testfailed%2Cbusted%2Cexception&revision=c105f961424c3a56aafccc82205d797d012f3b64&searchStr=Rap%2CCHr&selectedTaskRun=UgRYUhOpQ0OFRrqiVTUWfg.0

Comment 5

[Intermittent Failures Robot]

31 failures in 4100 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 20
• autoland: 11

Platform breakdown:

• windows7-32-shippable: 12
• macosx1014-64-shippable: 4
• windows10-64-shippable: 9
• linux64-shippable: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-08-17&endday=2020-08-23&tree=all

Comment 6

[Greg Mierzwinski [:sparky]]

:alexandrui will look into this failure.

Comment 8

[Intermittent Failures Robot]

24 failures in 4046 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

This is the #36 most frequent failure this week.

Repository breakdown:

• mozilla-central: 24

Platform breakdown:

• windows10-64-shippable: 9
• linux64-shippable: 5
• macosx1014-64-shippable: 5
• windows7-32-shippable: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-08-24&endday=2020-08-30&tree=all

Comment 9

[Alexandru Ionescu (needinfo me) [:alexandrui]]

Bebe will continue my investigation to bisect or whatever is needed as I will be in PTO starting tomorrow until Sept 11th.

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 12

Platform breakdown:

• linux64-shippable: 3
• macosx1014-64-shippable: 3
• windows7-32-shippable: 3
• windows10-64-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-08-31&endday=2020-09-06&tree=all

Comment 11

[Intermittent Failures Robot]

23 failures in 3410 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

This is the #48 most frequent failure this week.

Repository breakdown:

• mozilla-central: 23

Platform breakdown:

• linux64-shippable: 6
• macosx1014-64-shippable: 5
• windows10-64-shippable: 6
• windows7-32-shippable: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-09-07&endday=2020-09-13&tree=all

Comment 12

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Can you take another look at this?

Comment 13

[Alexandru Ionescu (needinfo me) [:alexandrui]]

Yes

Comment 14

[Intermittent Failures Robot]

21 failures in 3760 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 21

Platform breakdown:

• macosx1014-64-shippable: 6
• windows10-64-shippable: 5
• linux64-shippable: 6
• windows7-32-shippable: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-09-14&endday=2020-09-20&tree=all

Comment 15

[Alexandru Ionescu (needinfo me) [:alexandrui]]

Attachment: Bug 1659120 Fix gdocs recording due to perma r?#perftest,bebe

Removed zero-sized packages from the recording.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bf3b025f25e0
Fix gdocs recording due to perma r=perftest-reviewers,sparky

Comment 17

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/bf3b025f25e0

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• windows7-32-shippable: 1
• linux64-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659120&startday=2020-09-21&endday=2020-09-27&tree=all