Closed Bug 1811675 Opened 2 years ago Closed 2 years ago

Intermittent FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"ContentParent: id=28205c32a00","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":389

Categories

(Core :: DOM: Content Processes, defect, P5)

Product:
Core
Component:
DOM: Content Processes
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1772350

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

[task 2023-01-21T11:13:13.263Z] 11:13:13     INFO - TEST-START | layout/svg/tests/test_use_tree_cycle.html
[task 2023-01-21T11:13:13.374Z] 11:13:13     INFO - GECKO(8020) | MEMORY STAT | vsize 2103949MB | vsizeMaxContiguous 85108660MB | residentFast 114MB | heapAllocated 13MB
[task 2023-01-21T11:13:13.385Z] 11:13:13     INFO - TEST-OK | layout/svg/tests/test_use_tree_cycle.html | took 119ms
[task 2023-01-21T11:13:13.445Z] 11:13:13     INFO - TEST-START | Shutdown
[task 2023-01-21T11:13:13.450Z] 11:13:13     INFO - Passed:  49
[task 2023-01-21T11:13:13.450Z] 11:13:13     INFO - Failed:  0
[task 2023-01-21T11:13:13.452Z] 11:13:13     INFO - Todo:    0
[task 2023-01-21T11:13:13.453Z] 11:13:13     INFO - Mode:    e10s
[task 2023-01-21T11:13:13.454Z] 11:13:13     INFO - Slowest: 3285ms - /tests/layout/svg/tests/test_embed_sizing.html
[task 2023-01-21T11:13:13.454Z] 11:13:13     INFO - SimpleTest FINISHED
[task 2023-01-21T11:13:13.456Z] 11:13:13     INFO - TEST-INFO | Ran 1 Loops
[task 2023-01-21T11:13:13.457Z] 11:13:13     INFO - SimpleTest FINISHED
[task 2023-01-21T11:13:13.534Z] 11:13:13     INFO - GECKO(8020) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 576: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2023-01-21T11:13:21.498Z] 11:13:21     INFO - GECKO(8020) | out of memory: 0x0000000000000000 bytes requested
[task 2023-01-21T11:13:21.690Z] 11:13:21    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:21.710Z] 11:13:21     INFO - GECKO(8020) | 1674299601712	Marionette	TRACE	Received observer notification quit-application
[task 2023-01-21T11:13:21.713Z] 11:13:21     INFO - GECKO(8020) | 1674299601712	Marionette	INFO	Stopped listening on port 2828
[task 2023-01-21T11:13:21.714Z] 11:13:21     INFO - GECKO(8020) | 1674299601713	Marionette	DEBUG	Marionette stopped listening
[task 2023-01-21T11:13:21.740Z] 11:13:21     INFO - GECKO(8020) | [GFX1-]: GFX: RenderThread detected a device reset in PostUpdate
[task 2023-01-21T11:13:22.062Z] 11:13:22    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:28.860Z] 11:13:28     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:28.860Z] 11:13:28     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:28.860Z] 11:13:28    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:28.860Z] 11:13:28    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:29.475Z] 11:13:29     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:29.489Z] 11:13:29    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:29.489Z] 11:13:29    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:29.553Z] 11:13:29     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:29.553Z] 11:13:29    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:29.604Z] 11:13:29     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:29.613Z] 11:13:29    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:29.878Z] 11:13:29     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:29.885Z] 11:13:29    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:30.261Z] 11:13:30     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:30.281Z] 11:13:30    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:30.564Z] 11:13:30     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:30.564Z] 11:13:30    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:31.057Z] 11:13:31     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:31.057Z] 11:13:31    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:32.143Z] 11:13:32     INFO - GECKO(8020) | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=282058f1600","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""},{"name":"ContentParent: id=2820489df00","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""},{"name":"ContentParent: id=282005bad00","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""},{"name":"ContentParent: id=28203feec00","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""},{"name":"ContentParent: id=28205c32a00","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""},{"name":"ContentParent: id=28205c31600","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""}] Barrier: profile-before-change
[task 2023-01-21T11:13:35.944Z] 11:13:35     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:35.966Z] 11:13:35    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:36.741Z] 11:13:36     INFO - GECKO(8020) | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.sys.mjs", 370))
[task 2023-01-21T11:13:37.366Z] 11:13:37     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:37.376Z] 11:13:37    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:37.742Z] 11:13:37     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:37.742Z] 11:13:37    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:13:38.027Z] 11:13:38     INFO - GECKO(8020) | [Parent 1056, IPC I/O Parent] WARNING: pipe error: 232: file Z:/task_167429423959274/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc:583
[task 2023-01-21T11:13:38.034Z] 11:13:38    ERROR - GECKO(8020) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2023-01-21T11:16:23.124Z] 11:16:23     INFO - GECKO(8020) | FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"ContentParent: id=28205c32a00","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""},{"name":"ContentParent: id=28205c31600","state":{"remoteTypePrefix":"prealloc"},"filename":"Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp","lineNumber":3897,"stack":""}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[task 2023-01-21T11:16:23.128Z] 11:16:23     INFO - GECKO(8020) | [Parent 1056, Main Thread] ###!!! ABORT: file Z:/task_167429423959274/build/src/dom/ipc/ContentParent.cpp:3897
[task 2023-01-21T11:16:23.394Z] 11:16:23     INFO - TEST-INFO | Main app process: exit 1
[task 2023-01-21T11:16:23.395Z] 11:16:23     INFO - Buffered messages finished
[task 2023-01-21T11:16:23.396Z] 11:16:23    ERROR - TEST-UNEXPECTED-FAIL | Last test finished | application terminated with exit code 1
[task 2023-01-21T11:16:23.397Z] 11:16:23     INFO - runtests.py | Application ran for: 0:03:19.687795

Hi Andrew! Can you please take a look at this? Could this fatal error be the cause for the crash in Bug 1811674?
Due to my uncertainty as to whether this is the root cause of the other bug, I filed both of them for the same failed job.
Thank you!

Flags: needinfo?(bugmail)

The AsyncShutdown timeout is indeed the cause of bug 1811674 and this is what bug 1772350 always tracked, so both are basically dupes of that one. However, the way we log changed slightly since that one was filed, giving hopefully more actionable information (including dumps of the children). And the instance I see here is on Windows ccov, while the original bug's last instance was on linux ccov.

We should probably spend some time to group/dupe these better, so I'll leave it open for now.

Status: NEW → RESOLVED
Closed: 2 years ago
Duplicate of bug: 1772350
Resolution: --- → DUPLICATE
Flags: needinfo?(bugmail)
You need to log in before you can comment on or make changes to this bug.