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

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

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

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 #

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.

(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.

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

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

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).

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

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.

Just adding an ni? or myself here.

(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.

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?

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

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

(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.

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

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

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

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

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

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.

Hi Mark, I filed bug 1740999.