Closed Bug 1579683 Opened 5 years ago Closed 3 years ago

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)

Version 3
defect

Tracking

(firefox-esr78 unaffected, firefox83 unaffected, firefox84 disabled, firefox85 disabled, firefox86 fixed)

RESOLVED FIXED
86 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox83 --- unaffected
firefox84 --- disabled
firefox85 --- disabled
firefox86 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: mconley, NeedInfo)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Crash Data

Attachments

(1 file)

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

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Severity: normal → --
Priority: P5 → --

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.

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?

Flags: needinfo?(gsquelart)
Severity: -- → S3
Priority: -- → P5

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.

Flags: needinfo?(gsquelart)

Thanks for taking a look :gerald, I'll keep digging into it.

Recent realworld-webextensions permanent failures are supposedly from bug 1672517.

Flags: needinfo?(mconley)

Thanks for finding that :aryx!

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

There have been 31 total failures in the last 7 days:

Affected platforms:

  • linux64-shippable opt
  • linux64-shippable-qr opt

Backfilling lots of jobs too identify where is the cause of the intermittent.

Seems like Bug 1672517 is the cause. Try confirmed that.

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: nobody → mconley
Flags: needinfo?(mconley)

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.

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
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 86 Branch

It looks like we have intermittents again for this test: https://bugzilla.mozilla.org/show_bug.cgi?id=1713226

Flags: needinfo?(mconley)
See Also: → 1713226
See Also: → 1220362
See Also: 1668592
Regressed by: 1672517
See Also: → 1674061, 1673716
Crash Signature: [@ nsPipeInputStream::ReadSegments] [@ nsPipeInputStream::ReadSegments(nsresult (*)(nsIInputStream*, void*, char const*, unsigned int, unsigned int, unsigned int*), void*, unsigned int, unsigned int*)]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: