Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=247815158&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/bkvg53-UTlmkXGdOLOIJKg/runs/0/artifacts/public/logs/live_backing.log
18:04:54 INFO - raptor-main starting chromium
18:04:54 INFO - Application command: C:\Users\task_1558544541\fetches\chrome-win\Chrome.exe --user-data-dir=c:\users\task_1558544541\appdata\local\temp\tmp4ecviq.mozrunner --profile-directory=Default --no-first-run --use-mock-keychain --no-default-browser-check --proxy-server=127.0.0.1:8080 --proxy-bypass-list=localhost;127.0.0.1 --ignore-certificate-errors --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --load-extension=C:\Users\task_1558544541\build\tests\raptor\raptor..\webext\raptor,C:\Users\task_1558544541\build\tests\raptor\raptor..\webext\raptor
18:04:54 INFO - raptor-control-server received webext_status: raptor runner.js is loaded!
18:04:54 INFO - raptor-control-server reading test settings from raptor-tp6-facebook-chromium-cold.json
18:04:54 INFO - raptor-control-server sent test settings to web ext runner
18:04:55 INFO - raptor-control-server received webext_status: * pausing 30 seconds to let browser settle... *
18:05:25 INFO - raptor-control-server received webext_status: running 1 pagecycles of https://www.facebook.com
18:05:25 INFO - raptor-control-server received webext_status: opened new empty tab: 3
18:05:26 INFO - raptor-control-server received webext_status: begin pagecycle 1
18:05:27 INFO - raptor-control-server received webext_status: update tab: 3
18:05:27 INFO - raptor-control-server received webext_status: test tab updated: 3
18:06:30 INFO - raptor-main application timed out after 100 seconds
18:06:37 INFO - raptor-control-server received webext_raptor-page-timeout: [u'raptor-tp6-facebook-chromium-cold', u'https://www.facebook.com', {u'fcp': True, u'hero': False, u'dcf': False, u'fnb paint': False, u'ttfi': False, u'load time': True}]
18:06:38 INFO - raptor-control-server received webext_status: results received
18:06:38 INFO - raptor-control-server received webext_results: {u'expected_browser_cycles': 25, u'subtest_unit': u'ms', u'name': u'raptor-tp6-facebook-chromium-cold', u'lower_is_better': True, u'measurements': {u'fcp': [17005.904999999984], u'loadtime': [68156]}, u'browser_cycle': u'13', u'subtest_lower_is_better': True, u'cold': True, u'browser': u'Chrome/76.0.3803.0', u'type': u'pageload', u'page': u'https://www.facebook.com', u'unit': u'ms', u'alert_threshold': 2}
18:06:38 INFO - results-handler received results in RaptorResultsHandler.add
18:06:38 INFO - raptor-control-server received webext_status: __raptor_shutdownBrowser
18:06:38 INFO - raptor-control-server shutting down browser (pid: 6760)
18:06:38 INFO - raptor-control-server received webext_status: Removed tab: 3
18:06:39 INFO - raptor-control-server received webext_screenshot
18:06:39 INFO - results-handler received screenshot
18:06:39 INFO - raptor-control-server received webext_status: __raptor_shutdownBrowser
18:06:39 INFO - raptor-control-server shutting down browser (pid: 6760)
18:06:46 INFO - raptor-main begin browser cycle 14 of 25 for test raptor-tp6-facebook-chromium-cold
18:06:46 INFO - raptor-main starting raptor test: raptor-tp6-facebook-chromium-cold
18:06:46 INFO - raptor-main test settings: {'expected_browser_cycles': 25, 'alert_threshold': '2.0', 'playback_pageset_manifest': 'mitmproxy-recordings-raptor-tp6-1.manifest', 'browser_cycles': '25', 'alert_on': ['fcp', 'loadtime'], 'here': 'C:\Users\task_1558544541\build\tests\raptor\raptor\tests', 'expected': 'pass', 'measure': ['fcp', 'loadtime'], 'path': 'C:\Users\task_1558544541\build\tests\raptor\raptor\tests\raptor-tp6-facebook-chromium-cold', 'cold': True, 'unit': 'ms', 'ancestor-manifest': 'C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.ini', 'playback_binary_manifest': 'mitmproxy-rel-bin-4.0.4-{platform}.manifest', 'name': 'raptor-tp6-facebook-chromium-cold', 'playback_recordings': 'facebook.mp', 'page_cycles': 1, 'apps': 'chromium', 'test_url': 'https://www.facebook.com', 'manifest': 'C:\Users\task_1558544541\build\tests\raptor\raptor\tests\raptor-tp6-cold-2.ini', 'page_timeout': '60000', 'playback_version': '4.0.4', 'playback': 'mitmproxy', 'browser_cycle': 14, 'lower_is_better': 'true', 'type': 'pageload', 'relpath': 'tests\raptor-tp6-facebook-chromium-cold'}
18:06:46 INFO - raptor-main raptor config: {'playback_binary_zip': None, 'gecko_profile_entries': None, 'playback_pageset_manifest': 'C:\Users\task_1558544541\build\tests\raptor\raptor\playback\mitmproxy-recordings-raptor-tp6-1.manifest', 'e10s': True, 'app': 'chromium', 'symbols_path': 'https://queue.taskcluster.net/v1/task/aR3MquXKSSafN-0NwXAEGA/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'playback_tool': 'mitmproxy', 'host': '127.0.0.1', 'subtest_alert_on': ['fcp', 'loadtime'], 'memory_test': False, 'obj_path': None, 'binary': 'C:\Users\task_1558544541\fetches\chrome-win\Chrome.exe', 'local_profile_dir': 'c:\users\task_1558544541\appdata\local\temp\tmpt72gne.mozrunner\Default', 'gecko_profile_interval': None, 'enable_control_server_wait': False, 'playback_tool_args': ['--scripts', 'C:\\\Users\\\task_1558544541\\\build\\\tests\\\raptor\\\raptor\\\playback\\\alternate-server-replay-4.0.4.py', '--set', 'server_replay=C:\\\Users\\\task_1558544541\\\testing\\\mozproxy\\\facebook.mp'], 'platform': 'win', 'playback_version': '4.0.4', 'is_release_build': False, 'playback_pageset_zip': None, 'playback_binary_manifest': 'mitmproxy-rel-bin-4.0.4-{platform}.manifest', 'processor': 'x86_64', 'gecko_profile': False}
18:06:46 INFO - raptor-gen-test-config writing test settings into background js, so webext can get it
18:06:46 INFO - raptor-gen-test-config finished writing test config to C:\Users\task_1558544541\build\tests\raptor\webext\raptor\auto_gen_test_config.js
18:06:46 INFO - raptor-main installing webext C:\Users\task_1558544541\build\tests\raptor\raptor..\webext\raptor
18:06:46 INFO - raptor-main Merging profile: C:\Users\task_1558544541\build\tests\raptor\raptor\profile_data\base
18:06:46 INFO - raptor-main Merging profile: C:\Users\task_1558544541\build\tests\raptor\raptor\profile_data\common
18:06:46 INFO - raptor-main Merging profile: C:\Users\task_1558544541\build\tests\raptor\raptor\profile_data\perf
18:06:46 INFO - raptor-main Merging profile: C:\Users\task_1558544541\build\tests\raptor\raptor\profile_data\raptor
18:06:46 INFO - raptor-main starting raptor test: raptor-tp6-facebook-chromium-cold
18:06:46 INFO - raptor-main test settings: {'expected_browser_cycles': 25, 'alert_threshold': '2.0', 'playback_pageset_manifest': 'mitmproxy-recordings-raptor-tp6-1.manifest', 'browser_cycles': '25', 'alert_on': ['fcp', 'loadtime'], 'here': 'C:\Users\task_1558544541\build\tests\raptor\raptor\tests', 'expected': 'pass', 'measure': ['fcp', 'loadtime'], 'path': 'C:\Users\task_1558544541\build\tests\raptor\raptor\tests\raptor-tp6-facebook-chromium-cold', 'cold': True, 'unit': 'ms', 'ancestor-manifest': 'C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.ini', 'playback_binary_manifest': 'mitmproxy-rel-bin-4.0.4-{platform}.manifest', 'name': 'raptor-tp6-facebook-chromium-cold', 'playback_recordings': 'facebook.mp', 'page_cycles': 1, 'apps': 'chromium', 'test_url': 'https://www.facebook.com', 'manifest': 'C:\Users\task_1558544541\build\tests\raptor\raptor\tests\raptor-tp6-cold-2.ini', 'page_timeout': '60000', 'playback_version': '4.0.4', 'playback': 'mitmproxy', 'browser_cycle': 14, 'lower_is_better': 'true', 'type': 'pageload', 'relpath': 'tests\raptor-tp6-facebook-chromium-cold'}
18:06:46 INFO - raptor-main raptor config: {'playback_binary_zip': None, 'gecko_profile_entries': None, 'playback_pageset_manifest': 'C:\Users\task_1558544541\build\tests\raptor\raptor\playback\mitmproxy-recordings-raptor-tp6-1.manifest', 'e10s': True, 'app': 'chromium', 'symbols_path': 'https://queue.taskcluster.net/v1/task/aR3MquXKSSafN-0NwXAEGA/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'playback_tool': 'mitmproxy', 'host': '127.0.0.1', 'subtest_alert_on': ['fcp', 'loadtime'], 'memory_test': False, 'obj_path': None, 'binary': 'C:\Users\task_1558544541\fetches\chrome-win\Chrome.exe', 'local_profile_dir': 'c:\users\task_1558544541\appdata\local\temp\tmpk1fapg.mozrunner\Default', 'gecko_profile_interval': None, 'enable_control_server_wait': False, 'playback_tool_args': ['--scripts', 'C:\\\Users\\\task_1558544541\\\build\\\tests\\\raptor\\\raptor\\\playback\\\alternate-server-replay-4.0.4.py', '--set', 'server_replay=C:\\\Users\\\task_1558544541\\\testing\\\mozproxy\\\facebook.mp'], 'platform': 'win', 'playback_version': '4.0.4', 'is_release_build': False, 'playback_pageset_zip': None, 'playback_binary_manifest': 'mitmproxy-rel-bin-4.0.4-{platform}.manifest', 'processor': 'x86_64', 'gecko_profile': False}
18:06:46 INFO - raptor-gen-test-config writing test settings into background js, so webext can get it
18:06:46 INFO - raptor-gen-test-config finished writing test config to C:\Users\task_1558544541\build\tests\raptor\webext\raptor\auto_gen_test_config.js
18:06:46 INFO - raptor-main installing webext C:\Users\task_1558544541\build\tests\raptor\raptor..\webext\raptor
18:06:46 INFO - raptor-main starting chromium
18:06:46 INFO - Application command: C:\Users\task_1558544541\fetches\chrome-win\Chrome.exe --user-data-dir=c:\users\task_1558544541\appdata\local\temp\tmp4ecviq.mozrunner --profile-directory=Default --no-first-run --use-mock-keychain --no-default-browser-check --proxy-server=127.0.0.1:8080 --proxy-bypass-list=localhost;127.0.0.1 --ignore-certificate-errors --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --use-mock-keychain --no-default-browser-check --load-extension=C:\Users\task_1558544541\build\tests\raptor\raptor..\webext\raptor,C:\Users\task_1558544541\build\tests\raptor\raptor..\webext\raptor
18:06:47 INFO - raptor-control-server received webext_status: raptor runner.js is loaded!
18:06:47 INFO - raptor-control-server reading test settings from raptor-tp6-facebook-chromium-cold.json
18:06:47 INFO - raptor-control-server sent test settings to web ext runner
18:06:48 INFO - raptor-control-server received webext_status: * pausing 30 seconds to let browser settle... *
18:07:18 INFO - raptor-control-server received webext_status: running 1 pagecycles of https://www.facebook.com
18:07:19 INFO - raptor-control-server received webext_status: begin pagecycle 1
18:07:20 INFO - raptor-control-server received webext_status: update tab: 0
18:07:25 INFO - raptor-control-server received webext_status: opened new empty tab: 11
18:07:27 INFO - raptor-control-server received webext_status: test tab updated: 11
18:08:19 INFO - raptor-control-server received webext_raptor-page-timeout: [u'raptor-tp6-facebook-chromium-cold', u'https://www.facebook.com', {u'fcp': True, u'hero': False, u'dcf': False, u'fnb paint': False, u'ttfi': False, u'load time': True}]
18:08:19 INFO - raptor-control-server received webext_screenshot
18:08:19 INFO - raptor-control-server received webext_status: __raptor_shutdownBrowser
18:08:19 INFO - results-handler received screenshot
18:08:19 INFO - raptor-control-server shutting down browser (pid: 3304)
18:08:19 INFO - raptor-control-server received webext_status: Removed tab: 11
18:08:22 INFO - raptor-main application timed out after 100 seconds
18:12:05 INFO - raptor-control-server shutting down control server
18:12:05 INFO - raptor-main finished
18:12:05 ERROR - Traceback (most recent call last):
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 550, in _custom_wait
18:12:05 ERROR - Traceback (most recent call last):
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 550, in _custom_wait
18:12:05 INFO - item = self._process_events.get(timeout=timeout)
18:12:05 INFO - item = self._process_events.get(timeout=timeout)
18:12:05 INFO - File "c:\mozilla-build\python\Lib\Queue.py", line 176, in get
18:12:05 INFO - File "c:\mozilla-build\python\Lib\Queue.py", line 176, in get
18:12:05 INFO - raise Empty
18:12:05 INFO - raise Empty
18:12:05 INFO - Empty
18:12:05 INFO - Empty
18:12:05 INFO - Exception in thread Thread-163:
18:12:05 ERROR - Traceback (most recent call last):
18:12:05 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 801, in __bootstrap_inner
18:12:05 INFO - self.run()
18:12:05 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 754, in run
18:12:05 INFO - self.__target(*self.__args, **self.__kwargs)
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\control_server.py", line 334, in wait_for_quit
18:12:05 INFO - self.browser_proc.wait(timeout)
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 917, in wait
18:12:05 INFO - self.returncode = self.proc.wait()
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 229, in wait
18:12:05 INFO - self.returncode = self._custom_wait(timeout=timeout)
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 556, in _custom_wait
18:12:05 INFO - raise OSError("IO Completion Port failed to signal process shutdown")
18:12:05 INFO - OSError: IO Completion Port failed to signal process shutdown
18:12:05 INFO - Exception in thread Thread-159:
18:12:05 ERROR - Traceback (most recent call last):
18:12:05 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 801, in __bootstrap_inner
18:12:05 INFO - self.run()
18:12:05 INFO - File "c:\mozilla-build\python\Lib\threading.py", line 754, in run
18:12:05 INFO - self.__target(*self.__args, **self.__kwargs)
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\control_server.py", line 334, in wait_for_quit
18:12:05 INFO - self.browser_proc.wait(timeout)
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 917, in wait
18:12:05 INFO - self.returncode = self.proc.wait()
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 229, in wait
18:12:05 INFO - self.returncode = self._custom_wait(timeout=timeout)
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 556, in _custom_wait
18:12:05 INFO - raise OSError("IO Completion Port failed to signal process shutdown")
18:12:05 INFO - OSError: IO Completion Port failed to signal process shutdown
18:12:05 ERROR - Traceback (most recent call last):
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 550, in _custom_wait
18:12:05 INFO - item = self._process_events.get(timeout=timeout)
18:12:05 INFO - File "c:\mozilla-build\python\Lib\Queue.py", line 176, in get
18:12:05 INFO - raise Empty
18:12:05 INFO - Empty
18:12:05 ERROR - Traceback (most recent call last):
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.py", line 1222, in <module>
18:12:05 INFO - main()
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.py", line 1190, in main
18:12:05 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.py", line 186, in run_tests
18:12:05 INFO - self.run_test(test, timeout=int(test['page_timeout']))
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.py", line 462, in run_test
18:12:05 INFO - self.run_test_cold(test, timeout)
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.py", line 517, in run_test_cold
18:12:05 INFO - self.wait_for_test_finish(test, timeout)
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\raptor.py", line 222, in wait_for_test_finish
18:12:05 INFO - self.control_server.wait_for_quit()
18:12:05 INFO - File "C:\Users\task_1558544541\build\tests\raptor\raptor\control_server.py", line 334, in wait_for_quit
18:12:05 INFO - self.browser_proc.wait(timeout)
18:12:05 INFO - File "C:\Users\task_1558544541\build\venv\lib\site-packages\mozprocess\processhandler.py", line 917, in wait
18:12:05 INFO - self.returncode = self.proc.wait()
[taskcluster:error] Aborting task...
[taskcluster 2019-05-22T18:17:04.873Z] SUCCESS: The process with PID 3076 (child process of PID 6664) has been terminated.
[taskcluster 2019-05-22T18:17:04.873Z] SUCCESS: The process with PID 6664 (child process of PID 1424) has been terminated.
[taskcluster 2019-05-22T18:17:04.873Z] SUCCESS: The process with PID 3744 (child process of PID 6256) has been terminated.
[taskcluster 2019-05-22T18:17:04.873Z] SUCCESS: The process with PID 1424 (child process of PID 6256) has been terminated.
[taskcluster 2019-05-22T18:17:04.873Z] SUCCESS: The process with PID 240 (child process of PID 5452) has been terminated.
[taskcluster 2019-05-22T18:17:04.873Z] SUCCESS: The process with PID 6256 (child process of PID 5452) has been terminated.
[taskcluster 2019-05-22T18:17:04.873Z] SUCCESS: The process with PID 5452 (child process of PID 592) has been terminated.
[taskcluster 2019-05-22T18:17:04.873Z]
[taskcluster 2019-05-22T18:17:04.873Z] === Task Finished ===
[taskcluster 2019-05-22T18:17:04.873Z] Task Duration: 29m58.9999833s
[taskcluster 2019-05-22T18:17:05.326Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-05-21T15:27:11.472Z
[taskcluster 2019-05-22T18:17:06.040Z] 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 2020-05-21T15:27:11.472Z
[taskcluster 2019-05-22T18:17:06.725Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/bkvg53-UTlmkXGdOLOIJKg/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2020-05-21T15:27:11.472Z
[taskcluster:error] Task aborted - max run time exceeded
Description
•