Filed by: csabou [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=158267797&repo=autoland https://queue.taskcluster.net/v1/task/KRptRp9BRjCj8wDqC_Z6JA/runs/0/artifacts/public/logs/live_backing.log 11:22:48 INFO - TEST-UNEXPECTED-ERROR | tp6_google_heavy | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 11:22:48 ERROR - Traceback (most recent call last): 11:22:48 INFO - File "/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/run_tests.py", line 289, in run_tests 11:22:48 INFO - talos_results.add(mytest.runTest(browser_config, test)) 11:22:48 INFO - File "/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/ttest.py", line 62, in runTest 11:22:48 INFO - return self._runTest(browser_config, test_config, setup) 11:22:48 INFO - File "/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/ttest.py", line 277, in _runTest 11:22:48 INFO - else None) 11:22:48 INFO - File "/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/results.py", line 95, in add 11:22:48 INFO - global_counters=self.global_counters 11:22:48 INFO - File "/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/results.py", line 326, in __init__ 11:22:48 INFO - self.parse() 11:22:48 INFO - File "/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/results.py", line 353, in parse 11:22:48 INFO - % self.report_tokens) 11:22:48 INFO - File "/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/results.py", line 337, in error 11:22:48 INFO - raise utils.TalosError(message) 11:22:48 INFO - TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 11:22:48 INFO - TEST-INFO took 628607ms 11:22:48 INFO - SUITE-END | took 628s 12:22:48 INFO - Automation Error: mozprocess timed out after 3600 seconds running ['/Users/cltbld/tasks/task_1516819667/build/venv/bin/python', '/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/run_tests.py', '--title', 't-yosemite-r7-449', '--symbolsPath', 'https://queue.taskcluster.net/v1/task/Clag8400Q9C66pTUEYHMQg/artifacts/public/build/target.crashreporter-symbols.zip', '--mitmproxy', u'mitmproxy-recording-google.mp mitmproxy-recording-youtube.mp mitmproxy-recording-amazon.mp mitmproxy-recording-facebook.mp', '--suite', 'h2-e10s', '--executablePath', '/Users/cltbld/tasks/task_1516819667/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--mitmdumpPath', '/Users/cltbld/tasks/task_1516819667/build/tests/talos/talos/mitmproxy/mitmdump', '--webServer', 'localhost', '--webServer', 'localhost', '--webServer', 'localhost', '--webServer', 'localhost', '--log-tbpl-level=debug', '--log-errorsummary=/Users/cltbld/tasks/task_1516819667/build/blobber_upload_dir/h2-e10s_errorsummary.log', '--log-raw=/Users/cltbld/tasks/task_1516819667/build/blobber_upload_dir/h2-e10s_raw.log'] 12:22:49 ERROR - timed out after 3600 seconds of no output 12:22:49 ERROR - Return code: 2 12:22:49 WARNING - setting return code to 2 12:22:49 ERROR - # TBPL FAILURE #

Over the last 7 days there are 32 failures present on this bug. Most of them happen on OS X 10.10 but there are two occurrences on other operating systems, one on macosx64-nightly and another on Linux x64 Here is the most recent log: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=169079470&lineNumber=1087 Here is a relevant part of that log: 16:52:24 INFO - TEST-UNEXPECTED-ERROR | tp6_google | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 16:52:24 ERROR - Traceback (most recent call last): 16:52:24 INFO - File "/Users/cltbld/tasks/task_1521503367/build/tests/talos/talos/run_tests.py", line 296, in run_tests 16:52:24 INFO - talos_results.add(mytest.runTest(browser_config, test)) 16:52:24 INFO - File "/Users/cltbld/tasks/task_1521503367/build/tests/talos/talos/ttest.py", line 62, in runTest 16:52:24 INFO - return self._runTest(browser_config, test_config, setup) 16:52:24 INFO - File "/Users/cltbld/tasks/task_1521503367/build/tests/talos/talos/ttest.py", line 268, in _runTest 16:52:24 INFO - else None) 16:52:24 INFO - File "/Users/cltbld/tasks/task_1521503367/build/tests/talos/talos/results.py", line 95, in add 16:52:24 INFO - global_counters=self.global_counters 16:52:24 INFO - File "/Users/cltbld/tasks/task_1521503367/build/tests/talos/talos/results.py", line 326, in __init__ 16:52:24 INFO - self.parse() 16:52:24 INFO - File "/Users/cltbld/tasks/task_1521503367/build/tests/talos/talos/results.py", line 353, in parse 16:52:24 INFO - % self.report_tokens) 16:52:24 INFO - File "/Users/cltbld/tasks/task_1521503367/build/tests/talos/talos/results.py", line 337, in error 16:52:24 INFO - raise utils.TalosError(message) 16:52:24 INFO - TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]

Oh interesting, looks like a race condition where it is looking for the hero elementiming element in the page (to turn on the observer for it) before the element is actually available, and it seems to be mostly happening on OSX. 00:18:54 INFO - PID 614 | Could not find a tag with an elmenttiming attr on the page This needs more investigation, I have never seen this locally.

In the last 7 days, there have been 31 failures. For failure pattern, please see comment 9 Recent log file: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=171347678&lineNumber=1127 :rwood, do you have any updates? Thank you!

There are 34 failures in the past 7 days. Platforms: OS X 10.10 opt, macosx64-nightly opt, Linux x64 opt. Recent log failure: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=173136423&lineNumber=1045 Relevant part of the log: 10:38:54 INFO - Terminating psutil.Process(pid=590, name='firefox', started='10:38:52') 10:38:54 INFO - TEST-INFO | 590: exit 0 10:38:54 INFO - TEST-UNEXPECTED-ERROR | tp6_google | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 10:38:54 ERROR - Traceback (most recent call last): 10:38:54 INFO - File "/Users/cltbld/tasks/task_1523468184/build/tests/talos/talos/run_tests.py", line 296, in run_tests 10:38:54 INFO - talos_results.add(mytest.runTest(browser_config, test)) 10:38:54 INFO - File "/Users/cltbld/tasks/task_1523468184/build/tests/talos/talos/ttest.py", line 63, in runTest 10:38:54 INFO - return self._runTest(browser_config, test_config, setup) 10:38:54 INFO - File "/Users/cltbld/tasks/task_1523468184/build/tests/talos/talos/ttest.py", line 270, in _runTest 10:38:54 INFO - else None) 10:38:54 INFO - File "/Users/cltbld/tasks/task_1523468184/build/tests/talos/talos/results.py", line 95, in add 10:38:54 INFO - global_counters=self.global_counters 10:38:54 INFO - File "/Users/cltbld/tasks/task_1523468184/build/tests/talos/talos/results.py", line 326, in __init__ 10:38:54 INFO - self.parse() 10:38:54 INFO - File "/Users/cltbld/tasks/task_1523468184/build/tests/talos/talos/results.py", line 353, in parse 10:38:54 INFO - % self.report_tokens) 10:38:54 INFO - File "/Users/cltbld/tasks/task_1523468184/build/tests/talos/talos/results.py", line 337, in error 10:38:54 INFO - raise utils.TalosError(message) 10:38:54 INFO - TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))] 10:38:54 INFO - TEST-INFO took 7867ms 10:38:54 INFO - SUITE-END | took 7s :rwood Any updates here?

This is the same issue as in Bug 1439979; I am debugging the issue there.