Intermittent startup_about_home_paint_realworld_webextensions | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
Categories
(Testing :: Talos, defect, P5)
Tracking
(firefox-esr78 unaffected, firefox83 unaffected, firefox84 disabled, firefox85 disabled, firefox86 fixed)
Tracking | Status | |
---|---|---|
firefox-esr78 | --- | unaffected |
firefox83 | --- | unaffected |
firefox84 | --- | disabled |
firefox85 | --- | disabled |
firefox86 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: mconley, NeedInfo)
References
(Regressed 1 open bug, Regression)
Details
(Keywords: intermittent-failure, regression)
Crash Data
Attachments
(1 file)
(deleted),
text/x-phabricator-request
|
Details |
Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=265555646&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/ft97ZEDhS7-SEt48Gv7f-A/runs/0/artifacts/public/logs/live_backing.log
[task 2019-09-07T23:46:45.925Z] 23:46:45 INFO - TEST-INFO | started process 5737 (/home/cltbld/tasks/task_1567899942/build/application/firefox/firefox -profile /tmp/tmpWAimka/profile)
[task 2019-09-07T23:46:46.022Z] 23:46:46 INFO - PID 5737 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:46.029Z] 23:46:46 INFO - PID 5737 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:46.105Z] 23:46:46 INFO - PID 5737 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:46.106Z] 23:46:46 INFO - PID 5737 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:47.496Z] 23:46:47 INFO - PID 5737 | __start_report1346__end_report
[task 2019-09-07T23:46:47.496Z] 23:46:47 INFO - PID 5737 |
[task 2019-09-07T23:46:47.496Z] 23:46:47 INFO - PID 5737 | __startTimestamp1567900007487__endTimestamp
[task 2019-09-07T23:46:47.586Z] 23:46:47 INFO - PID 5737 | [Parent 5737, Gecko_IOThread] WARNING: pipe error (115): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 358
[task 2019-09-07T23:46:47.755Z] 23:46:47 INFO - PID 5737 |
[task 2019-09-07T23:46:47.755Z] 23:46:47 INFO - PID 5737 | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-09-07T23:46:47.755Z] 23:46:47 INFO - PID 5737 |
[task 2019-09-07T23:46:47.755Z] 23:46:47 INFO - PID 5737 | [Parent 5737, Gecko_IOThread] WARNING: pipe error (54): Connection reset by peer: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 358
[task 2019-09-07T23:46:47.755Z] 23:46:47 INFO - PID 5737 |
[task 2019-09-07T23:46:47.755Z] 23:46:47 INFO - PID 5737 | ###!!! [Child][MessageChannel::SendAndWait] Error: Channel error: cannot send/recv
[task 2019-09-07T23:46:47.755Z] 23:46:47 INFO - PID 5737 |
[task 2019-09-07T23:46:47.803Z] 23:46:47 INFO - TEST-INFO | 5737: exit 0
[task 2019-09-07T23:46:48.062Z] 23:46:48 INFO - Running cycle 12/20 for startup_about_home_paint_realworld_webextensions test...
[task 2019-09-07T23:46:48.062Z] 23:46:48 INFO - Using env: {'COMPIZ_CONFIG_PROFILE': 'ubuntu',
[task 2019-09-07T23:46:48.062Z] 23:46:48 INFO - 'DBUS_SESSION_BUS_ADDRESS': 'unix:abstract=/tmp/dbus-IJ3J1O2F5D,guid=6bb8483211990a8cfd592b505d744125',
[task 2019-09-07T23:46:48.063Z] 23:46:48 INFO - 'DEFAULTS_PATH': '/usr/share/gconf/ubuntu.default.path',
[task 2019-09-07T23:46:48.063Z] 23:46:48 INFO - 'DESKTOP_AUTOSTART_ID': '106e90815f60dc063156789994168929000000027270001',
[task 2019-09-07T23:46:48.063Z] 23:46:48 INFO - 'DISPLAY': ':0',
[task 2019-09-07T23:46:48.063Z] 23:46:48 INFO - 'EXTRA_MOZHARNESS_CONFIG': '{"test_packages_url": "https://queue.taskcluster.net/v1/task/XTlO4XtGRxeJ8xJoYJMRIw/artifacts/public/build/target.test_packages.json", "installer_url": "https://queue.taskcluster.net/v1/task/XTlO4XtGRxeJ8xJoYJMRIw/artifacts/public/build/target.tar.bz2"}',
[task 2019-09-07T23:46:48.064Z] 23:46:48 INFO - 'GECKO_HEAD_REPOSITORY': 'https://hg.mozilla.org/mozilla-central',
[task 2019-09-07T23:46:48.064Z] 23:46:48 INFO - 'GECKO_HEAD_REV': '7a3378adb34084d5d19352d45abbaa1bee681ac8',
[task 2019-09-07T23:46:48.064Z] 23:46:48 INFO - 'GNOME_DESKTOP_SESSION_ID': 'this-is-deprecated',
[task 2019-09-07T23:46:48.065Z] 23:46:48 INFO - 'GTK2_MODULES': 'overlay-scrollbar',
[task 2019-09-07T23:46:48.065Z] 23:46:48 INFO - 'GTK_MODULES': 'gail:atk-bridge',
[task 2019-09-07T23:46:48.065Z] 23:46:48 INFO - 'HOME': '/home/cltbld',
[task 2019-09-07T23:46:48.065Z] 23:46:48 INFO - 'JSGC_DISABLE_POISONING': '1',
[task 2019-09-07T23:46:48.065Z] 23:46:48 INFO - 'LANG': 'en_US.UTF-8',
[task 2019-09-07T23:46:48.065Z] 23:46:48 INFO - 'LANGUAGE': 'en_US:en',
[task 2019-09-07T23:46:48.065Z] 23:46:48 INFO - 'LD_LIBRARY_PATH': '/home/cltbld/tasks/task_1567899942/build/application/firefox',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'LOGNAME': 'cltbld',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MAIL': '/var/mail/cltbld',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MANDATORY_PATH': '/usr/share/gconf/ubuntu.mandatory.path',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MINIDUMP_SAVE_PATH': '/home/cltbld/tasks/task_1567899942/build/blobber_upload_dir',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MINIDUMP_STACKWALK': '/home/cltbld/tasks/task_1567899942/build/linux64-minidump_stackwalk',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_ACCELERATED': '1',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_AUTOMATION': '1',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_CRASHREPORTER': '1',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_CRASHREPORTER_NO_REPORT': '1',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_DISABLE_NONLOCAL_CONNECTIONS': '1',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_SCM_LEVEL': '3',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_UPLOAD_DIR': '/home/cltbld/tasks/task_1567899942/build/blobber_upload_dir',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_USE_PAGELOADER': '1',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'MOZ_WEBRENDER': '1',
[task 2019-09-07T23:46:48.066Z] 23:46:48 INFO - 'NO_EM_RESTART': '1',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'PATH': '/home/cltbld/tasks/task_1567899942/build/venv/bin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'PWD': '/home/cltbld',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'PYTHONPATH': '/home/cltbld/tasks/task_1567899942/build/tests/talos',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'QT_ACCESSIBILITY': '1',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'QT_IM_MODULE': 'ibus',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'QT_LINUX_ACCESSIBILITY_ALWAYS_ON': '1',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'QT_QPA_PLATFORMTHEME': 'appmenu-qt5',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'RUST_BACKTRACE': 'full',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'SCCACHE_DISABLE': '1',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'SESSION_MANAGER': 'local/t-linux64-ms-358:@/tmp/.ICE-unix/2727,unix/t-linux64-ms-358:/tmp/.ICE-unix/2727',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'SHELL': '/bin/bash',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'SHLVL': '2',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'SSH_AGENT_PID': '2776',
[task 2019-09-07T23:46:48.067Z] 23:46:48 INFO - 'SSH_AUTH_SOCK': '/run/user/1000/keyring/ssh',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'STYLO_FORCE_ENABLED': '1',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'TASKCLUSTER_ROOT_URL': 'https://taskcluster.net',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'TASK_ID': 'ft97ZEDhS7-SEt48Gv7f-A',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'TERM': 'xterm-256color',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'TMOUT': '86400',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'USER': 'cltbld',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'VTE_VERSION': '4205',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'WINDOWID': '23068682',
[task 2019-09-07T23:46:48.068Z] 23:46:48 INFO - 'XDG_CONFIG_DIRS': '/etc/xdg/xdg-ubuntu:/etc/xdg',
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - 'XDG_CURRENT_DESKTOP': 'GNOME',
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - 'XDG_DATA_DIRS': '/usr/share/ubuntu:/usr/share/gnome:/usr/local/share/:/usr/share/:/var/lib/snapd/desktop',
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - 'XDG_MENU_PREFIX': 'gnome-',
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - 'XDG_RUNTIME_DIR': '/run/user/1000',
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - 'XDG_SESSION_ID': 'c1',
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - 'XMODIFIERS': '@im=ibus',
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - '_': '/usr/local/bin/generic-worker'}
[task 2019-09-07T23:46:48.069Z] 23:46:48 INFO - TEST-INFO | started process 5940 (/home/cltbld/tasks/task_1567899942/build/application/firefox/firefox -profile /tmp/tmpWAimka/profile)
[task 2019-09-07T23:46:48.165Z] 23:46:48 INFO - PID 5940 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:48.173Z] 23:46:48 INFO - PID 5940 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:48.254Z] 23:46:48 INFO - PID 5940 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:48.254Z] 23:46:48 INFO - PID 5940 | ATTENTION: default value of option force_s3tc_enable overridden by environment.
[task 2019-09-07T23:46:49.820Z] 23:46:49 INFO - PID 5940 | FATAL ERROR: Non-local network connections are disabled and a connection attempt to easylist-downloads.adblockplus.org (94.130.104.85) was made.
[task 2019-09-07T23:46:49.820Z] 23:46:49 INFO - PID 5940 | You should only access hostnames available via the test networking proxy (if running mochitests) or from a test-specific httpd.js server (if running xpcshell tests). Browser services should be disabled or redirected to a local server.
[task 2019-09-07T23:46:49.823Z] 23:46:49 INFO - PID 5940 | ExceptionHandler::GenerateDump cloned child 6156
[task 2019-09-07T23:46:49.823Z] 23:46:49 INFO - PID 5940 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2019-09-07T23:46:49.823Z] 23:46:49 INFO - PID 5940 | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2019-09-07T23:46:49.885Z] 23:46:49 INFO - PID 5940 | Exiting due to channel error.
[task 2019-09-07T23:46:49.885Z] 23:46:49 INFO - PID 5940 | Exiting due to channel error.
[task 2019-09-07T23:46:49.933Z] 23:46:49 INFO - Terminating psutil.Process(pid=5940, name='firefox-bin', started='23:46:47')
[task 2019-09-07T23:46:49.934Z] 23:46:49 INFO - TEST-INFO | 5940: exit 11
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - TEST-UNEXPECTED-ERROR | startup_about_home_paint_realworld_webextensions | Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2019-09-07T23:46:49.954Z] 23:46:49 ERROR - Traceback (most recent call last):
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - File "/home/cltbld/tasks/task_1567899942/build/tests/talos/talos/run_tests.py", line 276, in run_tests
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - talos_results.add(mytest.runTest(browser_config, test))
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - File "/home/cltbld/tasks/task_1567899942/build/tests/talos/talos/ttest.py", line 64, in runTest
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - return self._runTest(browser_config, test_config, setup)
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - File "/home/cltbld/tasks/task_1567899942/build/tests/talos/talos/ttest.py", line 279, in _runTest
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - else None)
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - File "/home/cltbld/tasks/task_1567899942/build/tests/talos/talos/results.py", line 95, in add
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - global_counters=self.global_counters
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - File "/home/cltbld/tasks/task_1567899942/build/tests/talos/talos/results.py", line 326, in init
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - self.parse()
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - File "/home/cltbld/tasks/task_1567899942/build/tests/talos/talos/results.py", line 353, in parse
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - % self.report_tokens)
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - File "/home/cltbld/tasks/task_1567899942/build/tests/talos/talos/results.py", line 337, in error
[task 2019-09-07T23:46:49.954Z] 23:46:49 INFO - raise utils.TalosError(message)
[task 2019-09-07T23:46:49.955Z] 23:46:49 INFO - TalosError: Could not find report in browser output: [('tsformat', ('__start_report', '__end_report')), ('tpformat', ('__start_tp_report', '__end_tp_report'))]
[task 2019-09-07T23:46:49.955Z] 23:46:49 INFO - TEST-INFO took 28491ms
[task 2019-09-07T23:46:49.955Z] 23:46:49 INFO - SUITE-END | took 28s
[task 2019-09-07T23:46:50.466Z] 23:46:50 ERROR - Return code: 2
[task 2019-09-07T23:46:50.467Z] 23:46:50 WARNING - setting return code to 2
Comment hidden (Intermittent Failures Robot) |
Comment 2•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 3•4 years ago
|
||
New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=306281326&repo=mozilla-central&lineNumber=836
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 6•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 7•4 years ago
|
||
New occurrence:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=316035482&repo=autoland&lineNumber=975
Comment hidden (Intermittent Failures Robot) |
Comment 9•4 years ago
|
||
Comment 10•4 years ago
|
||
New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=319657834&repo=autoland&lineNumber=855
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Comment 13•4 years ago
|
||
This seems to be happening because we can't get a particular value - I'm seeing this in all the failure logs:
PID 3938 | Failed to get timestamps.about_home_topsites_first_paint scalar probe in time.
Comment 14•4 years ago
|
||
Hmm looks like a lot of the failures are triggered in the profiling jobs. :gerald, would you have some time to look into this failure or know of someone who can?
Updated•4 years ago
|
There are reports from non-profiling tests, e.g.: https://treeherder.mozilla.org/logviewer?job_id=320446871&repo=mozilla-central
To add to that (My notes before I noticed the non-profiling tasks) :
I see one failure on 2020-09-17, and then it really started to happen multiple times a day from 2020-09-24.
That was one buggy profiler patch on the 17th, but it was fixed on the 22nd.
I don't see any obvious profiler patches around when the failures "exploded" on the 24th.
Back to you Greg. But please ping me again if you still suspect the profiler.
Comment hidden (Intermittent Failures Robot) |
Comment 18•4 years ago
|
||
Recent realworld-webextensions permanent failures are supposedly from bug 1672517.
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 21•4 years ago
|
||
In the last 7 days there have been 35 occurrences, most on linux64-shippable opt.
Recent failure: https://treeherder.mozilla.org/logviewer?job_id=322606855&repo=mozilla-central&lineNumber=1017
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 24•4 years ago
|
||
There have been 31 total failures in the last 7 days:
- Intermittent failures: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2020-11-27&endday=2020-12-04&tree=trunk&bug=1579683
- Recent log: https://treeherder.mozilla.org/logviewer?job_id=323606684&repo=mozilla-central&lineNumber=1076
Affected platforms:
- linux64-shippable opt
- linux64-shippable-qr opt
Comment hidden (Intermittent Failures Robot) |
Comment 26•4 years ago
|
||
Backfilling lots of jobs too identify where is the cause of the intermittent.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 29•4 years ago
|
||
This seems to be basically the same thing as bug 1220362. Let's disable the about:home startup cache for this Talos test until we can sort out bug 1220362, and re-enable for startup_about_home_paint_cached and startup_about_home_paint_realworld_webextensions.
Assignee | ||
Comment 30•4 years ago
|
||
The root cause of the intermittens on startup_about_home_paint_realworld_webextensions is
the same as bug 1220362. Fixing that should fix this one too. In the mean time, we'll
disable the configuration for this test.
Comment 31•4 years ago
|
||
Pushed by mconley@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/91d93df5ae3f Disable the about:home startup cache for startup_about_home_paint_realworld_webextensions. r=sparky,perftest-reviewers
Comment 32•4 years ago
|
||
bugherder |
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 35•3 years ago
|
||
It looks like we have intermittents again for this test: https://bugzilla.mozilla.org/show_bug.cgi?id=1713226
Updated•3 years ago
|
Updated•2 years ago
|
Updated•2 years ago
|
Updated•2 years ago
|
Updated•2 years ago
|
Description
•