Closed Bug 1809134 Opened 1 year ago Closed 1 year ago

Ensure we get NotifiedImpendingShutdown before we call (the last) BrowserChild::RecvDestroy

Categories

(Core :: DOM: Content Processes, task)

task

Tracking

()

RESOLVED FIXED
111 Branch
Tracking Status
firefox111 --- fixed

People

(Reporter: jstutte, Assigned: jstutte)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 1 obsolete file)

As such this does not change much, but it gives us the possibility to react on ProcessChild::ExpectingShutdown while we process BrowserChild::RecvDestroy (probably inside some of the descendant things it triggers).

Assignee: nobody → jstutte
Status: NEW → ASSIGNED
Pushed by jstutte@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6729683a006a
Ensure we get ContentChild::NotifiedImpendingShutdown before (the last) BrowserChild::RecvDestroy. r=smaug

Oh, I see. That is TryToRecycle that wants to recycle the process in the non-fission case but we already did NotifyImpendingShutdown on that process, causing then all kind of fun by interrupting legitimate content JS. We would need to factor in the decision from TryToRecycle into CheckTabDestroyWillCauseShutdown to keep it symmetric.

Flags: needinfo?(jstutte)
Pushed by jstutte@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4130ec388aeb
Ensure we get ContentChild::NotifiedImpendingShutdown before (the last) BrowserChild::RecvDestroy. r=smaug

Backed out for causing geckoview-junit failures.

Push with failures

Failure log

Backout link

[task 2023-01-11T16:40:30.014Z] 16:40:30     INFO -  TEST-START | org.mozilla.geckoview.test.PrivateModeTest#privateModeStorageShared
[task 2023-01-11T16:40:31.213Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=976
[task 2023-01-11T16:40:31.213Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2023-01-11T16:40:31.213Z] 16:40:31     INFO -  org.mozilla.geckoview.test | Error in privateModeStorageShared(org.mozilla.geckoview.test.PrivateModeTest):
[task 2023-01-11T16:40:31.213Z] 16:40:31     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.rule.GeckoSessionTestRule$RejectedPromiseException: [Exception... "Failure"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: eval :: <TOP_LEVEL> :: line 2"  data: no]
[task 2023-01-11T16:40:31.213Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2465)
[task 2023-01-11T16:40:31.213Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2418)
[task 2023-01-11T16:40:31.213Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.evaluateJS(BaseSessionTest.kt:221)
[task 2023-01-11T16:40:31.214Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.PrivateModeTest.privateModeStorageShared(PrivateModeTest.kt:93)
[task 2023-01-11T16:40:31.214Z] 16:40:31     INFO -  org.mozilla.geckoview.test |
[task 2023-01-11T16:40:31.214Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2023-01-11T16:40:31.214Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=privateModeStorageShared
[task 2023-01-11T16:40:31.214Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.PrivateModeTest
[task 2023-01-11T16:40:31.214Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.mozilla.geckoview.test.rule.GeckoSessionTestRule$RejectedPromiseException: [Exception... "Failure"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: eval :: <TOP_LEVEL> :: line 2"  data: no]
[task 2023-01-11T16:40:31.214Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2465)
[task 2023-01-11T16:40:31.215Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2418)
[task 2023-01-11T16:40:31.215Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.BaseSessionTest.evaluateJS(BaseSessionTest.kt:221)
[task 2023-01-11T16:40:31.215Z] 16:40:31     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.PrivateModeTest.privateModeStorageShared(PrivateModeTest.kt:93)
[task 2023-01-11T16:40:31.215Z] 16:40:31     INFO -  org.mozilla.geckoview.test |
[task 2023-01-11T16:40:31.215Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=507
[task 2023-01-11T16:40:31.215Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2023-01-11T16:40:31.215Z] 16:40:31     INFO -  Printing logcat for test:
[task 2023-01-11T16:40:31.813Z] 16:40:31     INFO -  01-11 16:40:29.775 E/GeckoSessionTestRule( 3451): test_start 1f0befec-3ff2-40ff-89cf-b127eb38b1ec privateModeStorageShared(org.mozilla.geckoview.test.PrivateModeTest)
<...>
[task 2023-01-11T16:40:31.858Z] 16:40:31     INFO -  01-11 16:40:30.908 I/Gecko   ( 7494): [Child 7494, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/dom/localstorage/LSObject.cpp:564
[task 2023-01-11T16:40:31.858Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): Error
[task 2023-01-11T16:40:31.858Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): org.mozilla.geckoview.test.rule.GeckoSessionTestRule$RejectedPromiseException: [Exception... "Failure"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: eval :: <TOP_LEVEL> :: line 2"  data: no]
[task 2023-01-11T16:40:31.858Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForMessage(GeckoSessionTestRule.java:2465)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.evaluateJS(GeckoSessionTestRule.java:2418)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.mozilla.geckoview.test.BaseSessionTest.evaluateJS(BaseSessionTest.kt:221)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.mozilla.geckoview.test.PrivateModeTest.privateModeStorageShared(PrivateModeTest.kt:93)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2023-01-11T16:40:31.859Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.junit.rules.Verifier$1.evaluate(Verifier.java:35)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$org-mozilla-geckoview-test-rule-GeckoSessionTestRule$2(GeckoSessionTestRule.java:1470)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2$$ExternalSyntheticLambda0.run(D8$$SyntheticClass)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at android.os.Looper.loop(Looper.java:154)
[task 2023-01-11T16:40:31.860Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.911 E/GeckoSessionTestRule( 3451): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.913 D/GeckoViewContent( 3451): handleEvent: DOMWindowClose
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.915 D/GeckoViewContent( 3451): handleEvent: DOMWindowClose
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.917 I/Gecko   ( 3451): nsWindow[0x74e42e281200]::Show 0
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.919 I/Gecko   ( 3451): nsWindow[0x74e437080d00]::Show 1
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.922 D/GeckoViewSelectionActionDelegate[C]( 7494): handleEvent: visibilitychange
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.923 D/GeckoViewClipboardPermissionChild[C]( 7494): handleEvent: deactivate
[task 2023-01-11T16:40:31.861Z] 16:40:31     INFO -  01-11 16:40:30.923 D/GeckoViewNavigation( 3451): onDisable
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.923 D/GeckoViewProcessHangMonitor( 3451): onDisable
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.924 D/GeckoViewModule( 3451): unregisterListener
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.924 D/GeckoViewProcessHangMonitor( 3451): onDestroy
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.924 D/GeckoViewProgress( 3451): onDisable
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.924 D/GeckoViewModule( 3451): unregisterListener
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.925 D/GeckoViewSelectionAction( 3451): onDisable
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.925 D/GeckoViewModule( 3451): unregisterListener
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.926 D/GeckoViewModule( 3451): unregisterListener
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.926 D/GeckoViewMediaControl( 3451): onDisable
[task 2023-01-11T16:40:31.862Z] 16:40:31     INFO -  01-11 16:40:30.926 D/GeckoViewModule( 3451): unregisterListener
[task 2023-01-11T16:40:31.863Z] 16:40:31     INFO -  01-11 16:40:30.929 D/GeckoViewSessionStore( 3451): observe browsing-context-discarded
[task 2023-01-11T16:40:31.863Z] 16:40:31     INFO -  01-11 16:40:30.932 D/GeckoViewSelectionActionDelegate[C]( 7494): handleEvent: visibilitychange
[task 2023-01-11T16:40:31.863Z] 16:40:31     INFO -  01-11 16:40:30.932 D/GeckoViewClipboardPermissionChild[C]( 7494): handleEvent: pagehide
[task 2023-01-11T16:40:31.863Z] 16:40:31     INFO -  01-11 16:40:30.933 D/GeckoViewAutoFill[C]( 7494): handleEvent: pagehide
[task 2023-01-11T16:40:31.863Z] 16:40:31     INFO -  01-11 16:40:30.933 D/GeckoViewSessionStore( 3451): observe browsing-context-discarded
[task 2023-01-11T16:40:31.863Z] 16:40:31     INFO -  01-11 16:40:30.936 I/Gecko   ( 3451): [Parent 3451, Unnamed thread 74e447ef09a0] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2023-01-11T16:40:31.863Z] 16:40:31     INFO -  01-11 16:40:30.938 I/Gecko   ( 7494): [Child 7494, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  01-11 16:40:30.939 I/Gecko   ( 7494): [Child 7494, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  01-11 16:40:30.942 D/GeckoViewContent( 3451): handleEvent: DOMWindowClose
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  01-11 16:40:30.943 D/GeckoViewConsole( 3451): onEvent GeckoView:WebExtension:List null
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  01-11 16:40:30.948 E/GeckoSessionTestRule( 3451): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 privateModeStorageShared(org.mozilla.geckoview.test.PrivateModeTest)
[task 2023-01-11T16:40:31.864Z] 16:40:31  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.PrivateModeTest#privateModeStorageShared | org.mozilla.geckoview.test.rule.GeckoSessionTestRule$RejectedPromiseException: [Exception... "Failure"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: eval :: <TOP_LEVEL> :: line 2"  data: no]
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  TEST-INFO took 1799ms
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=976
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2023-01-11T16:40:31.864Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2023-01-11T16:40:31.865Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=privateDataNotShared
[task 2023-01-11T16:40:31.865Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.PrivateModeTest
[task 2023-01-11T16:40:31.865Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=508
[task 2023-01-11T16:40:31.865Z] 16:40:31     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: 1
[task 2023-01-11T16:40:31.865Z] 16:40:31     INFO -  TEST-START | org.mozilla.geckoview.test.PrivateModeTest#privateDataNotShared
Flags: needinfo?(jstutte)

The log shows we get an error from here and there we have an ExpectingShutdown condition.
I suspect (but can't really read geckoview tests) that mainSession.evaluateJS does not wait for the LS request to finish in the content process and that we shutdown the tab while the LS request is still in flight?

Flags: needinfo?(jstutte)

Apparently evaluateJS can return before the command actually finished to execute (localStorage.setItem
does spin the event loop while waiting for the DB to be initialized). This can make the test finish before
we actually ever had a chance to finish the LS operation, closing thus the tab and canceling the operation
throwing an error.

Attachment #9311998 - Attachment is obsolete: true
Pushed by jstutte@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2a9e0f5c854d
Ensure we get ContentChild::NotifiedImpendingShutdown before (the last) BrowserChild::RecvDestroy. r=smaug
Flags: needinfo?(jstutte)
Depends on: 1810666

(In reply to Sandor Molnar from comment #10)

Failure log: Assertion failure: !mIsSignaledImpendingShutdown, at /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1988

Failure log mochitest

Interesting. I added that assert just for symmetry and did not really expect to see it trigger.

This deserves probably its own bug 1810666.

Flags: needinfo?(jstutte)
Pushed by jstutte@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/521f45531857
Ensure we get ContentChild::NotifiedImpendingShutdown before (the last) BrowserChild::RecvDestroy. r=smaug
Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Resolution: --- → FIXED
Target Milestone: --- → 111 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: