Intermittent Wd TEST-UNEXPECTED-TIMEOUT | expected OK (hang during shutdown due to prealloc content processes)
Categories
(Remote Protocol :: Marionette, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=381756061&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/JIYT5LD4S-at7DHt35Wglg/runs/0/artifacts/public/logs/live_backing.log
[task 2022-06-17T22:56:29.284Z] 22:56:29 INFO - PID 25744 | 1655506589278 Marionette DEBUG Closed connection 0
[task 2022-06-17T22:56:37.159Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f845c3ead00 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3607
[task 2022-06-17T22:56:37.160Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f845c3ead00 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1808
[task 2022-06-17T22:56:37.162Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f8453a10500 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3607
[task 2022-06-17T22:56:37.163Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f8453a10500 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1808
[task 2022-06-17T22:56:37.165Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f8451e1f700 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3607
[task 2022-06-17T22:56:37.166Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f8451e1f700 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1808
[task 2022-06-17T22:56:37.166Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f8453a12800 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3607
[task 2022-06-17T22:56:37.167Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f8453a12800 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1808
[task 2022-06-17T22:56:37.192Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f845c3ead00 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1843
[task 2022-06-17T22:56:37.193Z] 22:56:37 INFO - PID 25744 | [Parent 25759, Main Thread] WARNING: ContentParent: id=7f845c3ead00 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3709
[task 2022-06-17T22:56:44.196Z] 22:56:44 INFO - PID 25744 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 381))
[task 2022-06-17T22:56:47.165Z] 22:56:47 INFO - PID 25744 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=7f8453a10500","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3700,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:164"]},{"name":"ContentParent: id=7f8451e1f700","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3700,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:164"]},{"name":"ContentParent: id=7f8453a12800","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3700,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:164"]}] Barrier: profile-before-change
[task 2022-06-17T22:57:15.738Z] 22:57:15 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/is_element_selected/selected.py | expected OK
[task 2022-06-17T22:57:15.740Z] 22:57:15 INFO - TEST-INFO took 55004ms
[task 2022-06-17T22:57:15.825Z] 22:57:15 INFO - Closing logging queue
[task 2022-06-17T22:57:15.826Z] 22:57:15 WARNING - Dropping log message: %r
[task 2022-06-17T22:57:15.828Z] 22:57:15 INFO - queue closed
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•3 years ago
|
||
Shutdown hang of Firefox:
https://treeherder.mozilla.org/logviewer?job_id=381756061&repo=mozilla-central&lineNumber=73463-73476
Nika, do you think that this could be related to the code in dom/ipc/ContentParent.cpp? If yes, I'm happy to file a specific bug for that. Thanks.
|
||
Comment 3•3 years ago
|
||
It looks like 4 content processes are taking too long to exit. I'm not sure that this is specifically ContentParent-related, but it could cause a shutdown hang if they take too long.
After this starts there is a 20 second (https://searchfox.org/mozilla-central/rev/2bbb0c0a90df20702df8c8011a8996536a83cb75/modules/libpref/init/StaticPrefList.yaml#2796-2806) timer which is started for each process to ShutdownKill that process. I'm not entirely sure why that didn't kick in in time, given that it should've expired at around 22:56:57, about 17 seconds before the timeout (assuming the timestamps are to be believed - not sure if they are). Perhaps the parent process main thread became busy or blocked somehow during that time? Not sure :-/
It is also somewhat interesting that all 3 of these processes which appear to be hanging are "prealloc" processes - that means they probably haven't done much. Perhaps there's some issue with when they were started somehow?
|
|
||
Comment 4•3 years ago
|
||
Thanks for the reply Nika! Given that this was a single failure mid of June and it never reproduced I would suggest that we just close this bug. To better find it again I'm going to make the summary more generic.
|
||
Comment 5•3 years ago
|
||
Description
•