1633378 - Intermittent Windows 10 x64 2017 Ref HW raptor-perftest Critical: Connection to Raptor webextension failed!

Status: RESOLVED INCOMPLETE

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-04-21T04:57:25.993Z] 04:57:25     INFO -  raptor-webext Info: installing webext C:\Users\task_1587442842\build\tests\raptor\raptor\webextension\..\..\webext\raptor
[task 2020-04-21T04:57:26.003Z] 04:57:26     INFO -  raptor-perftest Info: Making temp_download_dir from inside get_conditioned_profile c:\users\task_1587442842\appdata\local\temp\tmppsduv0
[task 2020-04-21T04:57:26.003Z] 04:57:26     INFO -  raptor-perftest Info: Platform used: win64
[task 2020-04-21T04:57:26.003Z] 04:57:26     INFO -  raptor-perftest Info: Getting profile from project mozilla-central
[task 2020-04-21T04:57:26.003Z] 04:57:26     INFO -  condprof INFO | Getting conditioned profile with arguments: {'repo': 'mozilla-central', 'platform': 'win64', 'task_id': None, 'customization': 'default', 'scenario': 'settled'}
[task 2020-04-21T04:57:26.003Z] 04:57:26     INFO -  condprof INFO | preparing download dir
[task 2020-04-21T04:57:26.004Z] 04:57:26     INFO -  condprof INFO | Downloaded archive path: C:\Users\task_1587442842/.condprof-cache\profile-win64-settled-default.tgz
[task 2020-04-21T04:57:26.004Z] 04:57:26     INFO -  condprof INFO | Getting https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64/artifacts/public/condprof/profile-win64-settled-default.tgz
[task 2020-04-21T04:57:26.004Z] 04:57:26     INFO -  condprof INFO | Getting headers at https://firefox-ci-tc.services.mozilla.com/api/index/v1/task/gecko.v2.mozilla-central.latest.firefox.condprof-win64/artifacts/public/condprof/profile-win64-settled-default.tgz
[task 2020-04-21T04:57:26.243Z] 04:57:26     INFO -  condprof INFO | Redirected
[task 2020-04-21T04:57:26.243Z] 04:57:26     INFO -  condprof INFO | Getting headers at https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Kk8uPShPS5-LdKxGrBe0ug/artifacts/public%2Fcondprof%2Fprofile-win64-settled-default.tgz
[task 2020-04-21T04:57:26.313Z] 04:57:26     INFO -  condprof INFO | Redirected
[task 2020-04-21T04:57:26.313Z] 04:57:26     INFO -  condprof INFO | Getting headers at https://firefoxci.taskcluster-artifacts.net/Kk8uPShPS5-LdKxGrBe0ug/0/public/condprof/profile-win64-settled-default.tgz
[task 2020-04-21T04:57:26.343Z] 04:57:26     INFO -  condprof INFO | Response code is 200
[task 2020-04-21T04:57:26.343Z] 04:57:26     INFO -  condprof INFO | Already Downloaded.
[task 2020-04-21T04:57:26.343Z] 04:57:26     INFO -  condprof INFO | Extracting the tarball content in c:\users\task_1587442842\appdata\local\temp\tmppsduv0
[task 2020-04-21T04:57:33.841Z] 04:57:33     INFO -  condprof INFO | Success, we have a profile to work with
[task 2020-04-21T04:57:33.841Z] 04:57:33     INFO -  raptor-perftest Info: self.conditioned_profile_dir is now set: c:\users\task_1587442842\appdata\local\temp\tmppsduv0
[task 2020-04-21T04:57:33.841Z] 04:57:33     INFO -  raptor-perftest Info: Merging profile: C:\Users\task_1587442842\build\tests\raptor\raptor\profile_data\base
[task 2020-04-21T04:57:33.841Z] 04:57:33     INFO -  raptor-perftest Info: Merging profile: C:\Users\task_1587442842\build\tests\raptor\raptor\profile_data\common
[task 2020-04-21T04:57:33.851Z] 04:57:33     INFO -  raptor-perftest Info: Merging profile: C:\Users\task_1587442842\build\tests\raptor\raptor\profile_data\perf
[task 2020-04-21T04:57:33.853Z] 04:57:33     INFO -  raptor-perftest Info: Merging profile: C:\Users\task_1587442842\build\tests\raptor\raptor\profile_data\raptor
[task 2020-04-21T04:57:33.855Z] 04:57:33     INFO -  raptor-perftest Info: Local browser profile: c:\users\task_1587442842\appdata\local\temp\tmppsduv0
[task 2020-04-21T04:57:34.241Z] 04:57:34     INFO -  raptor-perftest Info: starting test: raptor-tp6-outlook-firefox-cold
[task 2020-04-21T04:57:34.241Z] 04:57:34     INFO -  raptor-webext Info: starting web extension test: raptor-tp6-outlook-firefox-cold
[task 2020-04-21T04:57:34.241Z] 04:57:34     INFO -  raptor-webext Info: test settings: {'expected_browser_cycles': 25, u'alert_threshold': u'2.0', u'playback_pageset_manifest': u'mitm4-linux-firefox-outlook.manifest', u'browser_cycles': u'25', 'here': u'C:\\Users\\task_1587442842\\build\\tests\\raptor\\raptor\\tests\\tp6\\desktop', 'expected': 'pass', u'measure': [u'fnbpaint', u'fcp', u'dcf', u'loadtime'], 'path': u'C:\\Users\\task_1587442842\\build\\tests\\raptor\\raptor\\tests\\tp6\\desktop\\raptor-tp6-outlook-firefox-cold', u'cold': True, 'manifest_relpath': u'tests\\tp6\\desktop\\raptor-tp6-27-cold.ini', u'unit': u'ms', u'alert_on': [u'fcp', u'loadtime'], 'name': u'raptor-tp6-outlook-firefox-cold', u'playback_recordings': u'mitm4-linux-firefox-live.mp', 'page_cycles': 1, u'apps': u'firefox', u'test_url': u'https://outlook.live.com/mail/inbox', 'manifest': u'C:\\Users\\task_1587442842\\build\\tests\\raptor\\raptor\\tests\\tp6\\desktop\\raptor-tp6-27-cold.ini', 'ancestor_manifest': 'raptor.ini', u'page_timeout': u'60000', u'playback': u'mitmproxy', 'browser_cycle': 9, u'lower_is_better': True, u'type': u'pageload', 'relpath': u'tests\\tp6\\desktop\\raptor-tp6-outlook-firefox-cold'}
[task 2020-04-21T04:57:34.242Z] 04:57:34     INFO -  raptor-webext Info: web extension config: {'subtest_alert_on': [u'fcp', u'loadtime'], 'e10s': True, 'app': 'firefox', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Rks2iazYQMyR69BBLsiAVw/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'playback_binary_zip': None, 'run_local': False, 'playback_files': [u'C:\\Users\\task_1587442842\\testing\\mozproxy\\mitm4-linux-firefox-live.mp'], 'gecko_profile_interval': None, 'binary': 'C:\\Users\\task_1587442842\\build\\application\\firefox\\firefox.exe', 'local_profile_dir': 'c:\\users\\task_1587442842\\appdata\\local\\temp\\tmppsduv0', 'playback_binary_manifest': 'mitmproxy-rel-bin-4.0.4-{platform}.manifest', 'enable_control_server_wait': False, 'no_conditioned_profile': False, 'platform': 'win', 'playback_version': '4.0.4', 'conditioned_profile_scenario': 'settled', 'extra_prefs': {'extensions.logging.enabled': True}, 'gecko_profile': False, 'gecko_profile_entries': None, 'playback_pageset_manifest': u'C:\\Users\\task_1587442842\\build\\tests\\raptor\\raptor\\playback\\mitm4-linux-firefox-outlook.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, 'device_name': None, 'project': 'mozilla-central', 'cpu_test': False, 'is_release_build': False, 'using_condprof': True, 'processor': 'x86_64'}
[task 2020-04-21T04:57:34.242Z] 04:57:34     INFO -  raptor-gen-test-config Info: writing test settings into background js, so webext can get it
[task 2020-04-21T04:57:34.242Z] 04:57:34     INFO -  raptor-gen-test-config Info: finished writing test config to C:\Users\task_1587442842\build\tests\raptor\webext\raptor\auto_gen_test_config.js
[task 2020-04-21T04:57:34.242Z] 04:57:34     INFO -  raptor-webext Info: installing webext C:\Users\task_1587442842\build\tests\raptor\raptor\webextension\..\..\webext\raptor
[task 2020-04-21T04:57:34.252Z] 04:57:34     INFO -  raptor-webext-desktop Info: starting firefox
[task 2020-04-21T04:57:34.252Z] 04:57:34     INFO -  Application command: C:\Users\task_1587442842\build\application\firefox\firefox.exe --allow-downgrade --wait-for-browser -profile c:\users\task_1587442842\appdata\local\temp\tmppsduv0
[task 2020-04-21T05:00:07.366Z] 05:00:07 CRITICAL -  raptor-perftest Critical: Connection to Raptor webextension failed!
[task 2020-04-21T05:00:07.366Z] 05:00:07     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 6992
[task 2020-04-21T05:00:07.366Z] 05:00:07     INFO -  raptor-mitmproxy Info: Sending CTRL_BREAK_EVENT to mitmproxy
[task 2020-04-21T05:00:09.440Z] 05:00:09     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2020-04-21T05:00:09.440Z] 05:00:09     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2020-04-21T05:00:09.440Z] 05:00:09     INFO -  raptor-mitmproxy Info: writing: C:\Users\task_1587442842\build\application\firefox\distribution\policies.json
[task 2020-04-21T05:00:09.440Z] 05:00:09     INFO -  raptor-mitmproxy Info: Reading confidence values from: C:\Users\task_1587442842\build\blobber_upload_dir\mitm_netlocs_mitm4-linux-firefox-live.json
[task 2020-04-21T05:00:09.441Z] 05:00:09     INFO -  perftest-results-handler Info: RaptorResultsHandler.add_supporting_data received mozproxy-replay data
[task 2020-04-21T05:00:09.441Z] 05:00:09     INFO -  raptor-webext Info: removing webext C:\Users\task_1587442842\build\tests\raptor\raptor\webextension\..\..\webext\raptor
[task 2020-04-21T05:00:09.445Z] 05:00:09     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmpqulxip
[task 2020-04-21T05:00:10.629Z] 05:00:10     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmpg3obew
[task 2020-04-21T05:00:11.568Z] 05:00:11     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmpjbnzct
[task 2020-04-21T05:00:12.725Z] 05:00:12     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmprcqpea
[task 2020-04-21T05:00:14.097Z] 05:00:14     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmpd3d_ys
[task 2020-04-21T05:00:15.449Z] 05:00:15     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmpowtxr3
[task 2020-04-21T05:00:17.597Z] 05:00:17     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmpaiwwzs
[task 2020-04-21T05:00:18.989Z] 05:00:18     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmpyiatgq
[task 2020-04-21T05:00:19.826Z] 05:00:19     INFO -  raptor-perftest Info: Removing temporary directory: c:\users\task_1587442842\appdata\local\temp\tmppsduv0
[task 2020-04-21T05:00:20.448Z] 05:00:20     INFO -  raptor-control-server Info: shutting down control server
[task 2020-04-21T05:00:20.613Z] 05:00:20     INFO -  raptor-webext Info: finished
[task 2020-04-21T05:00:20.765Z] 05:00:20    ERROR - Return code: 1
[task 2020-04-21T05:00:20.765Z] 05:00:20  WARNING - setting return code to 1
[task 2020-04-21T05:00:20.766Z] 05:00:20     INFO - Copying Raptor results to upload dir:
[task 2020-04-21T05:00:20.766Z] 05:00:20     INFO - C:\Users\task_1587442842\build\blobber_upload_dir\perfherder-data.json
[task 2020-04-21T05:00:20.766Z] 05:00:20     INFO - Copying raptor results from C:\Users\task_1587442842\build\raptor.json to C:\Users\task_1587442842\build\blobber_upload_dir\perfherder-data.json
[task 2020-04-21T05:00:20.766Z] 05:00:20 CRITICAL - Error copying results C:\Users\task_1587442842\build\raptor.json to upload dir C:\Users\task_1587442842\build\blobber_upload_dir\perfherder-data.json
[task 2020-04-21T05:00:20.766Z] 05:00:20     INFO - [Errno 2] No such file or directory: u'C:\\Users\\task_1587442842\\build\\raptor.json'
[task 2020-04-21T05:00:20.767Z] 05:00:20     INFO - Running post-action listener: _package_coverage_data
[task 2020-04-21T05:00:20.767Z] 05:00:20     INFO - Running post-action listener: _resource_record_post_action
[task 2020-04-21T05:00:20.767Z] 05:00:20     INFO - Running post-action listener: process_java_coverage_data
[task 2020-04-21T05:00:20.767Z] 05:00:20     INFO - Running post-action listener: stop_device
[task 2020-04-21T05:00:20.767Z] 05:00:20     INFO - [mozharness: 2020-04-21 05:00:20.767000Z] Finished run-tests step (success)
[task 2020-04-21T05:00:20.768Z] 05:00:20     INFO - Running post-run listener: _resource_record_post_run
[task 2020-04-21T05:00:22.115Z] 05:00:22     INFO - Total resource usage - Wall time: 394s; CPU: 11.0%; Read bytes: 1201588736; Write bytes: 1302433792; Read time: 696; Write time: 641
[task 2020-04-21T05:00:22.115Z] 05:00:22     INFO - TinderboxPrint: CPU usage<br/>11.3%
[task 2020-04-21T05:00:22.115Z] 05:00:22     INFO - TinderboxPrint: I/O read bytes / time<br/>1,201,588,736 / 696
[task 2020-04-21T05:00:22.115Z] 05:00:22     INFO - TinderboxPrint: I/O write bytes / time<br/>1,302,433,792 / 641
[task 2020-04-21T05:00:22.116Z] 05:00:22     INFO - TinderboxPrint: CPU idle<br/>1,400.0 (88.6%)
[task 2020-04-21T05:00:22.116Z] 05:00:22     INFO - TinderboxPrint: CPU system<br/>65.4 (4.1%)
[task 2020-04-21T05:00:22.116Z] 05:00:22     INFO - TinderboxPrint: CPU user<br/>110.2 (7.0%)
[task 2020-04-21T05:00:22.116Z] 05:00:22     INFO - install - Wall time: 5s; CPU: 16.0%; Read bytes: 933888; Write bytes: 103964672; Read time: 5; Write time: 13
[task 2020-04-21T05:00:22.120Z] 05:00:22     INFO - run-tests - Wall time: 390s; CPU: 11.0%; Read bytes: 1200623616; Write bytes: 1159880704; Read time: 689; Write time: 624
[task 2020-04-21T05:00:22.212Z] 05:00:22  WARNING - returning nonzero exit status 1
[fetches 2020-04-21T05:00:22.264Z] removing C:/Users/task_1587442842/fetches
[fetches 2020-04-21T05:00:22.282Z] finished
[taskcluster 2020-04-21T05:00:22.449Z]    Exit Code: 1
[taskcluster 2020-04-21T05:00:22.449Z]    User Time: 0s
[taskcluster 2020-04-21T05:00:22.449Z]  Kernel Time: 15.625ms
[taskcluster 2020-04-21T05:00:22.449Z]    Wall Time: 10m1.3394436s
[taskcluster 2020-04-21T05:00:22.449Z]       Result: FAILED
[taskcluster 2020-04-21T05:00:22.472Z] === Task Finished ===
[taskcluster 2020-04-21T05:00:22.472Z] Task Duration: 10m1.394919s
[taskcluster 2020-04-21T05:00:22.667Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2021-04-21T02:11:39.173Z
[taskcluster 2020-04-21T05:00:23.213Z] Uploading artifact public/test_info/mitm_netlocs_mitm4-linux-firefox-live.json from file build\blobber_upload_dir\mitm_netlocs_mitm4-linux-firefox-live.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2021-04-21T02:11:39.173Z
[taskcluster 2020-04-21T05:00:23.312Z] 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-04-21T02:11:39.173Z
[taskcluster 2020-04-21T05:00:23.507Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2021-04-21T02:11:39.173Z
[taskcluster 2020-04-21T05:00:23.683Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/YWfs70C5TSuObQXideFUGw/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2021-04-21T02:11:39.173Z
[taskcluster:error] exit status 1

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2] (away July 24th - August 16th)]

The failure from yesterday:

[task 2020-04-26T13:39:43.375Z] 13:39:43 INFO - Application command: C:\Users\task_1587906414\build\application\firefox\firefox.exe --allow-downgrade --wait-for-browser -profile c:\users\task_1587906414\appdata\local\temp\tmpuykg51
[task 2020-04-26T13:42:16.467Z] 13:42:16 CRITICAL - raptor-perftest Critical: Connection to Raptor webextension failed!

I wonder why there are no webextension logs enabled as recently done by bug 1626522. Or maybe we don't even get that far and Firefox hangs during startup. Lets see how often the failure happens.

Comment 2

[Florin Strugariu [:Bebe]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Bogdan Tara[:bogdan_tara | bogdant]]

Seeing this today: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=302857935&repo=mozilla-central&lineNumber=3055

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ref-hw-2017: 1

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

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ref-hw-2017: 1

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

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 3

Platform breakdown:

• windows10-64-ref-hw-2017: 3

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

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• android-hw-p2-8-0-android-aarch64-shippable: 1

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

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ref-hw-2017: 1

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

Comment 9

[BugBot [:suhaib / :marco]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.