1736189 - Intermittent talos | Browser shutdown timed out after 20 seconds, killed process.

Status: RESOLVED FIXED

(Testing :: Talos, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-10-16T23:34:18.877Z] 23:34:18     INFO -  Browser shutdown timed out after 20 seconds, killing process.
[task 2021-10-16T23:34:18.878Z] 23:34:18     INFO -  Killing psutil.Process(pid=16741, name='GeckoMain', started='23:33:40') and writing a minidump file
[task 2021-10-16T23:34:18.885Z] 23:34:18     INFO -  Terminating psutil.Process(pid=16741, name='GeckoMain', started='23:33:40')
[task 2021-10-16T23:34:18.892Z] 23:34:18     INFO -  mozcrash checking /tmp/tmpq25yaqc1/profile/minidumps for minidumps...
[task 2021-10-16T23:34:18.892Z] 23:34:18     INFO -  TEST-UNEXPECTED-ERROR | sessionrestore_no_auto_restore | Browser shutdown timed out after 20 seconds, killed process.
[task 2021-10-16T23:34:18.892Z] 23:34:18    ERROR -  Traceback (most recent call last):
[task 2021-10-16T23:34:18.893Z] 23:34:18     INFO -    File "/home/cltbld/tasks/task_163442691467234/build/tests/talos/talos/run_tests.py", line 336, in run_tests
[task 2021-10-16T23:34:18.893Z] 23:34:18     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2021-10-16T23:34:18.893Z] 23:34:18     INFO -    File "/home/cltbld/tasks/task_163442691467234/build/tests/talos/talos/ttest.py", line 65, in runTest
[task 2021-10-16T23:34:18.893Z] 23:34:18     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2021-10-16T23:34:18.894Z] 23:34:18     INFO -    File "/home/cltbld/tasks/task_163442691467234/build/tests/talos/talos/ttest.py", line 215, in _runTest
[task 2021-10-16T23:34:18.894Z] 23:34:18     INFO -      debugger_args=browser_config["debugger_args"],
[task 2021-10-16T23:34:18.894Z] 23:34:18     INFO -    File "/home/cltbld/tasks/task_163442691467234/build/tests/talos/talos/talos_process.py", line 186, in run_browser
[task 2021-10-16T23:34:18.894Z] 23:34:18     INFO -      " process.".format(wait_for_quit_timeout)
[task 2021-10-16T23:34:18.895Z] 23:34:18     INFO -  talos.utils.TalosError: Browser shutdown timed out after 20 seconds, killed process.
[task 2021-10-16T23:34:18.895Z] 23:34:18     INFO -  TEST-INFO took 45705ms
[task 2021-10-16T23:34:18.895Z] 23:34:18     INFO -  SUITE-END | took 305s
[task 2021-10-16T23:34:18.976Z] 23:34:18    ERROR - Return code: 2
[task 2021-10-16T23:34:18.976Z] 23:34:18  WARNING - setting return code to 2
[task 2021-10-16T23:34:18.976Z] 23:34:18    ERROR - # TBPL FAILURE #
[task 2021-10-16T23:34:18.976Z] 23:34:18     INFO - Running post-action listener: _package_coverage_data
[task 2021-10-16T23:34:18.976Z] 23:34:18     INFO - Running post-action listener: _resource_record_post_action
[task 2021-10-16T23:34:18.976Z] 23:34:18     INFO - Running post-action listener: process_java_coverage_data
[task 2021-10-16T23:34:18.976Z] 23:34:18     INFO - [mozharness: 2021-10-16 23:34:18.976712Z] Finished run-tests step (success)
[task 2021-10-16T23:34:18.976Z] 23:34:18     INFO - Running post-run listener: _resource_record_post_run
[task 2021-10-16T23:34:19.033Z] 23:34:19     INFO - Total resource usage - Wall time: 316s; CPU: 9%; Read bytes: 11755520; Write bytes: 2690629632; Read time: 120; Write time: 51388
[task 2021-10-16T23:34:19.033Z] 23:34:19     INFO - TinderboxPrint: CPU usage<br/>9.2%
[task 2021-10-16T23:34:19.033Z] 23:34:19     INFO - TinderboxPrint: I/O read bytes / time<br/>11,755,520 / 120
[task 2021-10-16T23:34:19.033Z] 23:34:19     INFO - TinderboxPrint: I/O write bytes / time<br/>2,690,629,632 / 51,388
[task 2021-10-16T23:34:19.034Z] 23:34:19     INFO - TinderboxPrint: CPU idle<br/>2,269.8 (90.1%)
[task 2021-10-16T23:34:19.034Z] 23:34:19     INFO - TinderboxPrint: CPU system<br/>44.1 (1.8%)
[task 2021-10-16T23:34:19.034Z] 23:34:19     INFO - TinderboxPrint: CPU user<br/>175.3 (7.0%)
[task 2021-10-16T23:34:19.034Z] 23:34:19     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-10-16T23:34:19.034Z] 23:34:19     INFO - install - Wall time: 10s; CPU: 13%; Read bytes: 40960; Write bytes: 1062244352; Read time: 48; Write time: 14876
[task 2021-10-16T23:34:19.037Z] 23:34:19     INFO - run-tests - Wall time: 306s; CPU: 9%; Read bytes: 10461184; Write bytes: 1625575424; Read time: 64; Write time: 35936
[task 2021-10-16T23:34:19.095Z] 23:34:19  WARNING - returning nonzero exit status 2
[taskcluster 2021-10-16T23:34:19.119Z]    Exit Code: 2
[taskcluster 2021-10-16T23:34:19.119Z]    User Time: 3m0.34283s
[taskcluster 2021-10-16T23:34:19.119Z]  Kernel Time: 36.794189s
[taskcluster 2021-10-16T23:34:19.119Z]    Wall Time: 5m43.576713821s
[taskcluster 2021-10-16T23:34:19.119Z]       Result: FAILED
[taskcluster 2021-10-16T23:34:19.120Z] === Task Finished ===
[taskcluster 2021-10-16T23:34:19.120Z] Task Duration: 5m43.578853682s
[taskcluster 2021-10-16T23:34:19.242Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2022-10-16T21:48:40.793Z
[taskcluster 2021-10-16T23:34:19.450Z] Uploading artifact public/test_info/other_errorsummary.log from file build/blobber_upload_dir/other_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2022-10-16T21:48:40.793Z
[taskcluster 2021-10-16T23:34:19.540Z] Uploading artifact public/test_info/other_raw.log from file build/blobber_upload_dir/other_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2022-10-16T21:48:40.793Z
[taskcluster 2021-10-16T23:34:19.681Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2022-10-16T21:48:40.793Z
[taskcluster 2021-10-16T23:34:19.905Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/OkvY0AnbRrmLytC4BGLwsA/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-10-16T21:48:40.793Z
[taskcluster:error] exit status 2

Comment 3

[Intermittent Failures Robot]

8 failures in 3315 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 7
• autoland: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 8
  • opt: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-10-11&endday=2021-10-17&tree=all

Comment 7

[Intermittent Failures Robot]

18 failures in 638 pushes (0.028 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 7
• mozilla-central: 11

Platform and build breakdown:

• linux1804-64-shippable-qr: 17
  • opt: 17
• macosx1014-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-10-19&endday=2021-10-19&tree=all

Comment 8

[Greg Mierzwinski [:sparky]]

I see that someone has bisected this uptick in failures down to this commit: https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=talos%2Clinux&revision=c0e719d876173a56b16e89b64ef3eb536f352467

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1734262

Comment 10

[Intermittent Failures Robot]

20 failures in 653 pushes (0.031 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 11
• mozilla-central: 9

Platform and build breakdown:

• linux1804-64-shippable-qr: 20
  • opt: 20

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-10-21&endday=2021-10-21&tree=all

Comment 11

[Iulian Moraru]

Update:
There have been 70 failures within the last 7 days:
• 1 failures on OS X 10.14 WebRender Shippable opt
• 69 failures on Linux 18.04 x64 WebRender Shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=355629722&repo=autoland&lineNumber=3893

[task 2021-10-21T18:42:44.451Z] 18:42:44     INFO -  PID 15203 | ###!!! [Child][MessageChannel] Error: (msgtype=0xFFF7,name=BUILD_IDS_MATCH_MESSAGE) Channel error: cannot send/recv
[task 2021-10-21T18:42:44.451Z] 18:42:44     INFO -  PID 15203 |
[task 2021-10-21T18:43:22.058Z] 18:43:22     INFO -  Browser shutdown timed out after 20 seconds, killing process.
[task 2021-10-21T18:43:22.059Z] 18:43:22     INFO -  Killing psutil.Process(pid=15203, name='GeckoMain', started='18:42:32') and writing a minidump file
[task 2021-10-21T18:43:22.064Z] 18:43:22     INFO -  Terminating psutil.Process(pid=15203, name='GeckoMain', started='18:42:32')
[task 2021-10-21T18:43:22.073Z] 18:43:22     INFO -  mozcrash checking /tmp/tmprq4vphca/profile/minidumps for minidumps...
[task 2021-10-21T18:43:22.074Z] 18:43:22     INFO -  TEST-UNEXPECTED-ERROR | sessionrestore | Browser shutdown timed out after 20 seconds, killed process.
[task 2021-10-21T18:43:22.074Z] 18:43:22    ERROR -  Traceback (most recent call last):
[task 2021-10-21T18:43:22.074Z] 18:43:22     INFO -    File "/home/cltbld/tasks/task_163484149895539/build/tests/talos/talos/run_tests.py", line 336, in run_tests
[task 2021-10-21T18:43:22.074Z] 18:43:22     INFO -      talos_results.add(mytest.runTest(browser_config, test))
[task 2021-10-21T18:43:22.074Z] 18:43:22     INFO -    File "/home/cltbld/tasks/task_163484149895539/build/tests/talos/talos/ttest.py", line 65, in runTest
[task 2021-10-21T18:43:22.075Z] 18:43:22     INFO -      return self._runTest(browser_config, test_config, setup)
[task 2021-10-21T18:43:22.075Z] 18:43:22     INFO -    File "/home/cltbld/tasks/task_163484149895539/build/tests/talos/talos/ttest.py", line 215, in _runTest
[task 2021-10-21T18:43:22.075Z] 18:43:22     INFO -      debugger_args=browser_config["debugger_args"],
[task 2021-10-21T18:43:22.075Z] 18:43:22     INFO -    File "/home/cltbld/tasks/task_163484149895539/build/tests/talos/talos/talos_process.py", line 186, in run_browser
[task 2021-10-21T18:43:22.075Z] 18:43:22     INFO -      " process.".format(wait_for_quit_timeout)
[task 2021-10-21T18:43:22.075Z] 18:43:22     INFO -  talos.utils.TalosError: Browser shutdown timed out after 20 seconds, killed process.
[task 2021-10-21T18:43:22.075Z] 18:43:22     INFO -  TEST-INFO took 120120ms
[task 2021-10-21T18:43:22.076Z] 18:43:22     INFO -  SUITE-END | took 259s
[task 2021-10-21T18:43:22.298Z] 18:43:22    ERROR - Return code: 2
[task 2021-10-21T18:43:22.298Z] 18:43:22  WARNING - setting return code to 2
[task 2021-10-21T18:43:22.298Z] 18:43:22    ERROR - # TBPL FAILURE #

Comment 12

[Intermittent Failures Robot]

60 failures in 3186 pushes (0.019 failures/push) were associated with this bug in the last 7 days.

This is the #9 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 35
• mozilla-central: 25

Platform and build breakdown:

• linux1804-64-shippable-qr: 59
  • opt: 59
• macosx1014-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-10-18&endday=2021-10-24&tree=all

Comment 13

[Greg Mierzwinski [:sparky]]

Iulian, could you bisect which commit this started on? The increase is quite sharp so I'm hoping we'll be able to find one.

Comment 14

[Iulian Moraru]

(In reply to Greg Mierzwinski [:sparky] from comment #13)

Iulian, could you bisect which commit this started on? The increase is quite sharp so I'm hoping we'll be able to find one.

Yes, I'm waiting for the results. I will come back with an update on this.

Comment 15

[Iulian Moraru]

The backfill indicates this push as the one that it started on: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&selectedTaskRun=d4d7sTfvT6aoXAf01WROlg.0&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=os%2Cx%2C10.14%2Cwebrender%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable-qr%2Fopt-talos-other-e10s%2Co&revision=a4c999428d86bfa4d329e1ffc9826d75716e040c
This is the backfill range: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&fromchange=f27b70a61f59f79139296e59c3df0163ec59978e&searchStr=os%2Cx%2C10.14%2Cwebrender%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable-qr%2Fopt-talos-other-e10s%2Co&tochange=e7a8e61afbf8c208ff3ccd698668556866138b9d&group_state=expanded&selectedTaskRun=d4d7sTfvT6aoXAf01WROlg.0

Comment 16

[Intermittent Failures Robot]

47 failures in 643 pushes (0.073 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 25
• mozilla-central: 22

Platform and build breakdown:

• macosx1015-64-shippable-qr: 8
  • opt: 8
• macosx1014-64-shippable-qr: 34
  • opt: 34
• linux1804-64-shippable-qr: 3
  • opt: 3
• windows10-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-11-04&endday=2021-11-04&tree=all

Comment 17

[Greg Mierzwinski [:sparky]]

:standard8, it looks like your patch has caused a sharp spike in these intermittent failures (see previous comment). Could you look into it?

Comment 18

[Mark Banner (:standard8)]

My patch (bug 1703357) only changed a test, which couldn't have caused this.

One of the problems here is there's no stack information, which makes it really to know what might be the issue.

It could be bug 1733540, though I'd be a little surprised if that's causing crashes. I'll needinfo Rob just in case they have ideas.

Additionally, Are we sure this isn't bug 1737648 causing it - the previous commit? That's in the backfill range but has no test runs against it, it also touches c++ which makes it slightly more possible (1733540 is possible to cause crashes, if we're tickling something new but I'm not sure that's the case).

Comment 19

[Greg Mierzwinski [:sparky]]

Thanks for pointing that out, I've triggered the tests on the previous commit you mentioned to be sure: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=os%2Cx%2C10.14%2Cwebrender%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable-qr%2Fopt-talos-other-e10s%2Co&revision=06d4dd98d6eadcd800dbf16806d7b4d80cd71fe1

Comment 20

[Greg Mierzwinski [:sparky]]

Looks like there's an issue getting the mac build: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&revision=06d4dd98d6eadcd800dbf16806d7b4d80cd71fe1&searchStr=build%2Cmac%2Ccross%2Cship%2Caarch

I've added a few more retriggers but I have a feeling those will also fail. If they do, I'll run a test on try with that patch backedout to see.

Comment 21

[Greg Mierzwinski [:sparky]]

Just adding an ni? or myself here.

Comment 22

[Intermittent Failures Robot]

37 failures in 510 pushes (0.073 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 21
• mozilla-central: 10
• try: 6

Platform and build breakdown:

• macosx1014-64-shippable-qr: 25
  • opt: 25
• macosx1015-64-shippable-qr: 9
  • opt: 9
• linux1804-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-11-05&endday=2021-11-05&tree=all

Comment 23

[Cosmin Sabou [:CosminS]]

(In reply to Greg Mierzwinski [:sparky] from comment #19)

Thanks for pointing that out, I've triggered the tests on the previous commit you mentioned to be sure: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Crunnable&searchStr=os%2Cx%2C10.14%2Cwebrender%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable-qr%2Fopt-talos-other-e10s%2Co&revision=06d4dd98d6eadcd800dbf16806d7b4d80cd71fe1

So it looks like it really is Mark's push that caused this spike in failure rate.

Comment 24

[Mark Banner (:standard8)]

Is there any way we can get the crash stack here? Without that this is going to be pretty hard to know where to start looking.

Do we know if any other crashes have started on infra around this time?

Comment 25

[Cosmin Sabou [:CosminS]]

I'll look to see if I can find anything related and come back if I do.

Comment 26

[Cosmin Sabou [:CosminS]]

So what I've managed to find out is:

• this only happens on shippable builds (88% on mac OS, 8% on linux, 4% on windows)
• found a fail with a stack trace (only on linux), retriggered here: https://treeherder.mozilla.org/logviewer?job_id=357241459&repo=autoland
• those failures are tracked in Bug 1739550 and I think we should move this investigation over there as this bug was initially filed for a different failure

Stack trace:

task 2021-11-06T20:07:48.620Z] 20:07:48     INFO -  TEST-INFO | started process 12391 (/home/cltbld/tasks/task_163622052014541/build/application/firefox/firefox -profile /tmp/tmpm878gqwn/profile about:home)
[task 2021-11-06T20:07:49.208Z] 20:07:49     INFO -  PID 12391 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpm878gqwn/profile/search.json.mozlz4", (void 0)))
[task 2021-11-06T20:12:48.616Z] 20:12:48     INFO -  Timeout waiting for test completion; killing browser...
[task 2021-11-06T20:12:48.617Z] 20:12:48     INFO -  Killing psutil.Process(pid=12391, name='GeckoMain', started='20:07:48') and writing a minidump file
[task 2021-11-06T20:12:48.621Z] 20:12:48     INFO -  PID 12391 | ExceptionHandler::GenerateDump cloned child 12618
[task 2021-11-06T20:12:48.621Z] 20:12:48     INFO -  PID 12391 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2021-11-06T20:12:48.622Z] 20:12:48     INFO -  PID 12391 | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2021-11-06T20:12:48.624Z] 20:12:48     INFO -  Terminating psutil.Process(pid=12391, name='GeckoMain', started='20:07:48')
[task 2021-11-06T20:12:48.742Z] 20:12:48     INFO -  PID 12391 | Exiting due to channel error.
[task 2021-11-06T20:12:48.742Z] 20:12:48     INFO -  PID 12391 | Exiting due to channel error.
[task 2021-11-06T20:12:48.743Z] 20:12:48     INFO -  PID 12391 | Exiting due to channel error.
[task 2021-11-06T20:12:48.757Z] 20:12:48     INFO -  mozcrash checking /tmp/tmpm878gqwn/profile/minidumps for minidumps...
[task 2021-11-06T20:12:48.758Z] 20:12:48     INFO -  mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/MnYXuH_xTTeAWtUrsLcACw/artifacts/public/build/target.crashreporter-symbols.zip
[task 2021-11-06T20:12:51.236Z] 20:12:51     INFO -  mozcrash Copy/paste: /home/cltbld/tasks/task_163622052014541/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpm878gqwn/profile/minidumps/0fa9f41a-84f8-462a-bf90-2f0073da4625.dmp /tmp/tmpsa9wyxpx https://symbols.mozilla.org/
[task 2021-11-06T20:12:55.878Z] 20:12:55     INFO -  mozcrash Saved minidump as /home/cltbld/tasks/task_163622052014541/build/blobber_upload_dir/0fa9f41a-84f8-462a-bf90-2f0073da4625.dmp
[task 2021-11-06T20:12:55.878Z] 20:12:55     INFO -  PROCESS-CRASH | sessionrestore_no_auto_restore | application crashed [@ PollWrapper(_GPollFD*, unsigned int, int)]
[task 2021-11-06T20:12:55.878Z] 20:12:55     INFO -  Crash dump filename: /tmp/tmpm878gqwn/profile/minidumps/0fa9f41a-84f8-462a-bf90-2f0073da4625.dmp
[task 2021-11-06T20:12:55.878Z] 20:12:55     INFO -  Operating system: Linux
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -                    0.0.0 Linux 4.15.0-161-generic #169-Ubuntu SMP Fri Oct 15 13:41:54 UTC 2021 x86_64
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -  CPU: amd64
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -       family 6 model 94 stepping 3
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -       8 CPUs
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -  GPU: UNKNOWN
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -  Crash reason:  SIGABRT
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -  Crash address: 0x3ee00000bad
[task 2021-11-06T20:12:55.879Z] 20:12:55     INFO -  Process uptime: not available
[task 2021-11-06T20:12:55.880Z] 20:12:55     INFO -  Thread 0 tid 12391 (crashed) 0  libc.so.6!__GI___poll [poll.c : 29 + 0x18]
[task 2021-11-06T20:12:55.880Z] 20:12:55     INFO -      rax = 0xfffffffffffffffc   rdx = 0x00000000ffffffff
[task 2021-11-06T20:12:55.880Z] 20:12:55     INFO -      rcx = 0x00007f5a5d35bcb9   rbx = 0x00007f5a48512a90
[task 2021-11-06T20:12:55.880Z] 20:12:55     INFO -      rsi = 0x0000000000000006   rdi = 0x00007f5a48512a90
[task 2021-11-06T20:12:55.881Z] 20:12:55     INFO -      rbp = 0x0000000000000006   rsp = 0x00007ffc5c645260
[task 2021-11-06T20:12:55.881Z] 20:12:55     INFO -       r8 = 0x0000000000000000    r9 = 0x00007f5a5e5a50e0
[task 2021-11-06T20:12:55.881Z] 20:12:55     INFO -      r10 = 0x00007f5a418a4380   r11 = 0x0000000000000293
[task 2021-11-06T20:12:55.881Z] 20:12:55     INFO -      r12 = 0x00000000ffffffff   r13 = 0x0000000000000001
[task 2021-11-06T20:12:55.881Z] 20:12:55     INFO -      r14 = 0x00000000ffffffff   r15 = 0x0000000000000006
[task 2021-11-06T20:12:55.881Z] 20:12:55     INFO -      rip = 0x00007f5a5d35bcb9
[task 2021-11-06T20:12:55.881Z] 20:12:55     INFO -      Found by: given as instruction pointer in context
[task 2021-11-06T20:12:55.882Z] 20:12:55     INFO -   1  libxul.so!PollWrapper(_GPollFD*, unsigned int, int) [nsAppShell.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 61 + 0xf]
[task 2021-11-06T20:12:55.882Z] 20:12:55     INFO -      rbx = 0x00007f5a5d094280   rbp = 0x00007ffc5c6452e0
[task 2021-11-06T20:12:55.882Z] 20:12:55     INFO -      rsp = 0x00007ffc5c645290   r12 = 0x00007f5a48512a90
[task 2021-11-06T20:12:55.882Z] 20:12:55     INFO -      r13 = 0x0000000000000001   r14 = 0x00000000ffffffff
[task 2021-11-06T20:12:55.882Z] 20:12:55     INFO -      r15 = 0x0000000000000006   rip = 0x00007f5a4ec9c167
[task 2021-11-06T20:12:55.882Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.882Z] 20:12:55     INFO -   2  libglib-2.0.so.0!g_main_context_iterate.isra.26 [gmain.c : 3897 + 0x24]
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -      rbx = 0x00007f5a49307030   rbp = 0x0000000000000006
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -      rsp = 0x00007ffc5c6452f0   r12 = 0x00007f5a48512a90
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -      r13 = 0x00000000ffffffff   r14 = 0x00007f5a4ec9bfd0
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -      r15 = 0x0000000000000006   rip = 0x00007f5a58f0d6e9
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -   3  libglib-2.0.so.0!g_main_context_iteration [gmain.c : 3963 + 0x14]
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -      rbx = 0x00007f5a49307030   rbp = 0x0000000000000001
[task 2021-11-06T20:12:55.883Z] 20:12:55     INFO -      rsp = 0x00007ffc5c645350   r12 = 0x00007f5a48467180
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -      r13 = 0x00007f5a4ec9c5b0   r14 = 0x00007f5a4939a900
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x00007f5a58f0d7fc
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -   4  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 1091 + 0x18d]
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -      rbx = 0x00007f5a5d0e1e50   rbp = 0x00007ffc5c6455c0
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -      rsp = 0x00007ffc5c645370   r12 = 0x00007f5a48467180
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -      r13 = 0x00007f5a4ec9c5b0   r14 = 0x00007f5a4939a900
[task 2021-11-06T20:12:55.884Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x00007f5a4e9d7766
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -   5  libxul.so!mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [MessagePump.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 107 + 0x2e]
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -      rbx = 0x0000000000000000   rbp = 0x00007ffc5c645750
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -      rsp = 0x00007ffc5c6455d0   r12 = 0x0000000000000000
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -      r13 = 0x00007f5a2d6a2f00   r14 = 0x00007f5a493ccc00
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -      r15 = 0x00007f5a5d0df930   rip = 0x00007f5a4ea236b1
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.885Z] 20:12:55     INFO -   6  libxul.so!MessageLoop::Run() [message_loop.cc:a4c999428d86bfa4d329e1ffc9826d75716e040c : 306 + 0xc]
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -      rbx = 0x00007ffc5c645768   rbp = 0x00007ffc5c645790
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -      rsp = 0x00007ffc5c645760   r12 = 0x0003001100000000
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -      r13 = 0x00007ffc5c645898   r14 = 0x00007f5a5d0e1e50
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x00007f5a4f5afa1f
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -   7  libxul.so!nsBaseAppShell::Run() [nsBaseAppShell.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 137 + 0xd]
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -      rbx = 0x00007f5a4939a900   rbp = 0x00007ffc5c6457b0
[task 2021-11-06T20:12:55.886Z] 20:12:55     INFO -      rsp = 0x00007ffc5c6457a0   r12 = 0x0003001100000000
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      r13 = 0x00007ffc5c645898   r14 = 0x00007f5a5d0e1e50
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x00007f5a4fc99c69
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -   8  libxul.so!nsAppStartup::Run() [nsAppStartup.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 295 + 0xa]
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      rbx = 0x00007f5a49385330   rbp = 0x00007ffc5c6457e0
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      rsp = 0x00007ffc5c6457c0   r12 = 0x0003001100000000
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      r13 = 0x00007ffc5c645898   r14 = 0x00007ffc5c645840
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x00007f5a4d7a5855
[task 2021-11-06T20:12:55.887Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.888Z] 20:12:55     INFO -   9  libxul.so!XREMain::XRE_mainRun() [nsAppRunner.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 5293 + 0xd]
[task 2021-11-06T20:12:55.888Z] 20:12:55     INFO -      rbx = 0x0000000080004005   rbp = 0x00007ffc5c6459d0
[task 2021-11-06T20:12:55.888Z] 20:12:55     INFO -      rsp = 0x00007ffc5c6457f0   r12 = 0x0003001100000000
[task 2021-11-06T20:12:55.888Z] 20:12:55     INFO -      r13 = 0x00007ffc5c645898   r14 = 0x00007ffc5c645840
[task 2021-11-06T20:12:55.888Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x00007f5a4d81dda1
[task 2021-11-06T20:12:55.888Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.888Z] 20:12:55     INFO -  10  libxul.so!XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 5478 + 0x8]
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -      rbx = 0x00007f5a493ac4d8   rbp = 0x00007ffc5c645a40
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -      rsp = 0x00007ffc5c6459e0   r12 = 0x0000000000000000
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -      r13 = 0x000056451bb580ec   r14 = 0x0000000000000000
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -      r15 = 0x00007ffc5c645a50   rip = 0x00007f5a4d81e85e
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -  11  libxul.so!XRE_main(int, char**, mozilla::BootstrapConfig const&) [nsAppRunner.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 5537 + 0x10]
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -      rbx = 0x0000000000000004   rbp = 0x00007ffc5c645b80
[task 2021-11-06T20:12:55.889Z] 20:12:55     INFO -      rsp = 0x00007ffc5c645a50   r12 = 0x00007ffc5c645a50
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      r13 = 0x000056451bb580ec   r14 = 0x00007ffc5c645bd0
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      r15 = 0x00007ffc5c646ce8   rip = 0x00007f5a4d81ebb6
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -  12  firefox-bin!main [nsBrowserApp.cpp:a4c999428d86bfa4d329e1ffc9826d75716e040c : 395 + 0xa1]
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      rbx = 0x00007ffc5c645bbc   rbp = 0x00007ffc5c646c00
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      rsp = 0x00007ffc5c645b90   r12 = 0x0000000000000004
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      r13 = 0x000056451bb580ec   r14 = 0x00007ffc5c646ce8
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      r15 = 0x00007ffc5c645bd0   rip = 0x000056451bb3e1bb
[task 2021-11-06T20:12:55.890Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -  13  libc.so.6!__libc_start_main [libc-start.c : 310 + 0x1a]
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -      rbx = 0x0000000000000000   rbp = 0x000056451bb57110
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -      rsp = 0x00007ffc5c646c10   r12 = 0x000056451bb3de07
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -      r13 = 0x00007ffc5c646ce0   r14 = 0x0000000000000000
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x00007f5a5d268bf7
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -      Found by: call frame info
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -  14  firefox-bin!_start + 0x29
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -      rbx = 0x0000000000000000   rbp = 0x0000000000000000
[task 2021-11-06T20:12:55.891Z] 20:12:55     INFO -      rsp = 0x00007ffc5c646cd0   r12 = 0x000056451bb3de07
[task 2021-11-06T20:12:55.892Z] 20:12:55     INFO -      r13 = 0x00007ffc5c646ce0   r14 = 0x0000000000000000
[task 2021-11-06T20:12:55.892Z] 20:12:55     INFO -      r15 = 0x0000000000000000   rip = 0x000056451bb3de30
[task 2021-11-06T20:12:55.892Z] 20:12:55     INFO -      Found by: call frame info

Comment 27

[Rob Wu [:robwu]]

(In reply to Mark Banner (:standard8) from comment #18)

It could be bug 1733540, though I'd be a little surprised if that's causing crashes. I'll needinfo Rob just in case they have ideas.

I don't see anything immediately obvious in the patch.

I do know that IOUtils has some special logic tied to AsyncShutdown blockers (not sure about OS.File, but I guess not?). The timeout could be due to the shutdown being blocked temporarily. In that case I would expect log messages complaining about blocked shutdown.

If the issue cannot be resolved, then I recommend to back out the patch until we know the cause of this bug.

Comment 28

[Intermittent Failures Robot]

9 failures in 3030 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 9

Platform and build breakdown:

• macosx1014-64-shippable-qr: 7
  • opt: 7
• macosx1015-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-11-01&endday=2021-11-07&tree=all

Comment 29

[Narcis Beleuzu [:NarcisB]]

I`ve backed out Bug 1733540 and Bug 1703357.
Backout link: https://hg.mozilla.org/integration/autoland/rev/772dfe279def087d275150ef1cc57350c05cdae2

Comment 30

[Mark Banner (:standard8)]

I've split out the PrivacyFilter.jsm error to bug 1740261 - that has been happening for ages, before these patches landed.

Comment 31

[Cosmin Sabou [:CosminS]]

Backout merged to central: https://hg.mozilla.org/mozilla-central/rev/772dfe279def087d275150ef1cc57350c05cdae2

Comment 32

[Mark Banner (:standard8)]

I think we can call this fixed by backout. I'm following up with the crash issue in bug 1740301.

Comment 33

[Marian-Vasile Laza]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=357701385&repo=mozilla-central&lineNumber=2419

Comment 34

[Mark Banner (:standard8)]

Hi Marian-Vasile, please can you file a new bug for that.

The PrivacyFilter.jsm issue is bug 1740261 (though doesn't cause failure.

The crash referenced has a different stack signature to that which this bug was for: PROCESS-CRASH | sessionrestore | application crashed [@ replace_free(void*)]

They shouldn't be treated the same, that is a different issue.

Comment 35

[Marian-Vasile Laza]

Hi Mark, I filed bug 1740999.

Comment 36

[Intermittent Failures Robot]

15 failures in 2723 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 6
• autoland: 8
• try: 1

Platform and build breakdown:

• macosx1014-64-shippable-qr: 10
  • opt: 10
• macosx1015-64-shippable-qr: 3
  • opt: 3
• linux1804-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-11-08&endday=2021-11-14&tree=all

Comment 37

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-12-06&endday=2021-12-12&tree=all

Comment 38

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform and build breakdown:

• macosx1014-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-12-13&endday=2021-12-19&tree=all

Comment 39

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2021-12-20&endday=2021-12-26&tree=all

Comment 40

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1
• macosx1014-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2022-01-03&endday=2022-01-09&tree=all

Comment 41

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2022-01-10&endday=2022-01-16&tree=all

Comment 42

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2022-01-24&endday=2022-01-30&tree=all

Comment 43

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736189&startday=2022-02-07&endday=2022-02-13&tree=all