Currently I'm debugging a timeout in test `org.mozilla.geckoview.test.NavigationDelegateTest#redirectIntentLoad` on android. The timeout occurs in a call to [`waitForPageStop()`](https://searchfox.org/mozilla-central/rev/9e2239eb75e16204a6186c26f80aaa9723420919/mobile/android/geckoview/src/androidTest/java/org/mozilla/geckoview/test/NavigationDelegateTest.kt#852). In the logs, I see an assertion failure shortly before a timeout exception gets thrown, and the logs look like this: ``` 09-27 12:09:26.438 14813 14829 I Gecko : [Child 14813, Main Thread] ###!!! ASSERTION: We should have connected the pending channel!: 'pending', file /Users/agakhokidze/src/gecko/docshell/base/nsDocShell.cpp:13042 09-27 12:09:26.447 14786 14805 I Gecko : [Parent 14786, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, mozilla::ipc::IPCResult::Ok()) failed with result 0x80004002 (NS_NOINTERFACE): file /Users/agakhokidze/src/gecko/dom/ipc/ContentParent.cpp:4480 09-27 12:09:26.448 14786 14805 I Gecko : [Parent 14786, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /Users/agakhokidze/src/gecko/uriloader/exthandler/nsExternalHelperAppService.cpp:1101 09-27 12:09:26.453 14786 14805 I Gecko : [Parent 14786: Main Thread]: V/DocumentChannel DocumentLoadListener RedirectToRealChannelFinished [this=9f6cf8b0, aRv=804b0002 ] 09-27 12:09:26.454 14786 14805 I Gecko : [Parent 14786: Main Thread]: V/DocumentChannel DocumentLoadListener FinishReplacementChannelSetup [this=9f6cf8b0, aResult=804b0002] 09-27 12:09:26.454 14786 14805 I Gecko : [Parent 14786, Main Thread] WARNING: NS_ENSURE_TRUE(mSuspendCount > 0) failed: file /Users/agakhokidze/src/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5562 09-27 12:09:26.454 14786 14805 I Gecko : [Parent 14786: Main Thread]: V/DocumentChannel DocumentLoadListener dtor [this=9f6cf8b0] 09-27 12:09:49.875 9285 9339 D ConnectivityService: NetworkAgentInfo [MOBILE (LTE) - 102] validation failed 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: Error 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:50) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at android.os.Handler.handleCallback(Handler.java:751) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at android.os.Handler.dispatchMessage(Handler.java:95) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:153) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1714) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1502) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1477) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1467) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.NavigationDelegateTest.redirectIntentLoad(NavigationDelegateTest.kt:664) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at java.lang.reflect.Method.invoke(Native Method) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1429) ``` This assertion failure might be a hint as to what is going wrong, so I looked into it further. The assertion that fails is [this one](https://searchfox.org/mozilla-central/rev/1df999af9999ccb436512cfece57a68d94d36e08/docshell/base/nsDocShell.cpp#13043) in `nsDocShell::ResumeRedirectedLoad`. The channel in question, is the one created earlier in `ContentChild::RecvCrossProcessRedirect`. If the channel is not pending, we return `NS_BINDING_ABORTED` error in the callback `nsDocShell::ResumeRedirectedLoad`. The order of relevant events so far is the following: In `DocumentLoadListener::OnStartRequest`, we take [this code path](https://searchfox.org/mozilla-central/rev/1df999af9999ccb436512cfece57a68d94d36e08/netwerk/ipc/DocumentLoadListener.cpp#2215-2244). There is a call to ` browserParent->ResumeLoad(mLoadIdentifier);` (1) and a call to `TriggerRedirectToRealChannel(Some(mContentParent));` (2). (1) This call eventually causes `nsWebBrowser::ResumeRedirectedLoad` to be called, which then calls `nsDocShell::ResumeRedirectedLoad` (I matched up the load identifiers). There, we schedule a call (**) to `nsDocShell::InternalLoad` (and do some other things) once the pending channel is received. (2) `DocumentLoadListener::TriggerRedirectToRealChannel` calls `DocumentLoadListener::RedirectToRealChannel` which eventually calls `ContentParent::SendCrossProcessRedirect`. On the receiving side, `ContentChild::RecvCrossProcessRedirect` ends up calling `nsDocShellLoadState::CreateFromPendingChannel` at some point, which is where the aforementioned channel is created. In the end, it ends up calling ** callback with the new LoadState. The rough idea I have of channels is that once we create real network channel in DocumentLoadListener, we later connect it to the final destination after we have processed all redirects. In DocumentLoadListener::Open, I do see that we create a channel, and call AsyncOpen on it. However, I am not sure how the connecting of the channels work, so perhaps I should trace this to understand why the channel in docshell is not in the pending state.
Bug 1721217 Comment 17 Edit History
Note: The actual edited comment in the bug view page will always show the original commenter’s name and original timestamp.
Currently I'm debugging a timeout in test `org.mozilla.geckoview.test.NavigationDelegateTest#redirectIntentLoad` on android. The timeout occurs in a call to [`waitForPageStop()`](https://searchfox.org/mozilla-central/rev/9e2239eb75e16204a6186c26f80aaa9723420919/mobile/android/geckoview/src/androidTest/java/org/mozilla/geckoview/test/NavigationDelegateTest.kt#852). In the logs, I see an assertion failure shortly before a timeout exception gets thrown, and the logs look like this: ``` 09-27 12:09:26.438 14813 14829 I Gecko : [Child 14813, Main Thread] ###!!! ASSERTION: We should have connected the pending channel!: 'pending', file /Users/agakhokidze/src/gecko/docshell/base/nsDocShell.cpp:13042 09-27 12:09:26.447 14786 14805 I Gecko : [Parent 14786, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, mozilla::ipc::IPCResult::Ok()) failed with result 0x80004002 (NS_NOINTERFACE): file /Users/agakhokidze/src/gecko/dom/ipc/ContentParent.cpp:4480 09-27 12:09:26.448 14786 14805 I Gecko : [Parent 14786, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /Users/agakhokidze/src/gecko/uriloader/exthandler/nsExternalHelperAppService.cpp:1101 09-27 12:09:26.453 14786 14805 I Gecko : [Parent 14786: Main Thread]: V/DocumentChannel DocumentLoadListener RedirectToRealChannelFinished [this=9f6cf8b0, aRv=804b0002 ] 09-27 12:09:26.454 14786 14805 I Gecko : [Parent 14786: Main Thread]: V/DocumentChannel DocumentLoadListener FinishReplacementChannelSetup [this=9f6cf8b0, aResult=804b0002] 09-27 12:09:26.454 14786 14805 I Gecko : [Parent 14786, Main Thread] WARNING: NS_ENSURE_TRUE(mSuspendCount > 0) failed: file /Users/agakhokidze/src/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5562 09-27 12:09:26.454 14786 14805 I Gecko : [Parent 14786: Main Thread]: V/DocumentChannel DocumentLoadListener dtor [this=9f6cf8b0] 09-27 12:09:49.875 9285 9339 D ConnectivityService: NetworkAgentInfo [MOBILE (LTE) - 102] validation failed 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: Error 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 30000ms 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutRunnable.run(UiThreadUtils.java:50) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at android.os.Handler.handleCallback(Handler.java:751) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at android.os.Handler.dispatchMessage(Handler.java:95) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.util.UiThreadUtils.waitForCondition(UiThreadUtils.java:153) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitUntilCalled(GeckoSessionTestRule.java:1714) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStops(GeckoSessionTestRule.java:1502) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1477) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule.waitForPageStop(GeckoSessionTestRule.java:1467) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.NavigationDelegateTest.redirectIntentLoad(NavigationDelegateTest.kt:664) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at java.lang.reflect.Method.invoke(Native Method) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) 09-27 12:09:55.805 14786 14786 E GeckoSessionTestRule: at org.mozilla.geckoview.test.rule.GeckoSessionTestRule$2.lambda$evaluate$0$GeckoSessionTestRule$2(GeckoSessionTestRule.java:1429) ``` This assertion failure might be a hint as to what is going wrong, so I looked into it further. The assertion that fails is [this one](https://searchfox.org/mozilla-central/rev/1df999af9999ccb436512cfece57a68d94d36e08/docshell/base/nsDocShell.cpp#13043) in `nsDocShell::ResumeRedirectedLoad`. The channel in question, is the one created earlier in `ContentChild::RecvCrossProcessRedirect`. If the channel is not pending, we return `NS_BINDING_ABORTED` error in the callback `nsDocShell::ResumeRedirectedLoad`. The order of relevant events so far is the following: In `DocumentLoadListener::OnStartRequest`, we take [this code path](https://searchfox.org/mozilla-central/rev/1df999af9999ccb436512cfece57a68d94d36e08/netwerk/ipc/DocumentLoadListener.cpp#2215-2244). There is a call to ` browserParent->ResumeLoad(mLoadIdentifier);` (1) and a call to `TriggerRedirectToRealChannel(Some(mContentParent));` (2). (1) This call eventually causes `nsWebBrowser::ResumeRedirectedLoad` to be called, which then calls `nsDocShell::ResumeRedirectedLoad` (I matched up the load identifiers). There, we schedule a call (**) to `nsDocShell::InternalLoad` (and do some other things) once the pending channel is received. (2) `DocumentLoadListener::TriggerRedirectToRealChannel` calls `DocumentLoadListener::RedirectToRealChannel` which eventually calls `ContentParent::SendCrossProcessRedirect`. On the receiving side, `ContentChild::RecvCrossProcessRedirect` creates a new channel. In the end, it ends up calling ** callback with the new LoadState (which contains the channel) The rough idea I have of channels is that once we create real network channel in DocumentLoadListener, we later connect it to the final destination after we have processed all redirects. In DocumentLoadListener::Open, I do see that we create a channel, and call AsyncOpen on it. However, I am not sure how the connecting of the channels work, so perhaps I should trace this to understand why the channel in docshell is not in the pending state.