1918787 - Assertion failure: !mAfterOnStartRequestBegun, at /builds/worker/checkouts/gecko/netwerk/protocol/http/HttpChannelParent.cpp:2189

Status: ASSIGNED

(Core :: Networking: HTTP, defect, P2)

Description

[Tyson Smith [:tsmith]]

Found with m-c 20240912-91f8ef13345e (--enable-debug --enable-fuzzing)

This was found by visiting a live website with a debug build.

This issue was triggered by visiting http://www.augustinerkeller.de/english/index.html. I have not been able to reproduce this issue.

Assertion failure: !mAfterOnStartRequestBegun, at /builds/worker/checkouts/gecko/netwerk/protocol/http/HttpChannelParent.cpp:2189

#0 0x73e9179542f8 in mozilla::net::HttpChannelParent::SetCookie(nsTString<char>&&) /builds/worker/checkouts/gecko/netwerk/protocol/http/HttpChannelParent.cpp:2189:3
#1 0x73e917a2b59a in mozilla::net::nsHttpChannel::ContinueProcessResponse1() /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:2663:21
#2 0x73e917a2adcb in mozilla::net::nsHttpChannel::ProcessResponse() /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:2615:10
#3 0x73e917a55e9c in mozilla::net::nsHttpChannel::OnStartRequest(nsIRequest*) /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:7856:31
#4 0x73e91749d64d in nsInputStreamPump::OnStateStart() /builds/worker/checkouts/gecko/netwerk/base/nsInputStreamPump.cpp:504:20
#5 0x73e91749d1f4 in nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) /builds/worker/checkouts/gecko/netwerk/base/nsInputStreamPump.cpp:409:21
#6 0x73e91749e57c in non-virtual thunk to nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) /builds/worker/checkouts/gecko/netwerk/base/nsInputStreamPump.cpp
#7 0x73e9172362ff in operator() /builds/worker/checkouts/gecko/xpcom/io/nsPipe3.cpp:86:47
#8 0x73e9172362ff in already_AddRefed<mozilla::CancelableRunnable> NS_NewCancelableRunnableFunction<CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::'lambda'()>(char const*, CallbackHolder::CallbackHolder(nsIAsyncOutputStream*, nsIOutputStreamCallback*, unsigned int, nsIEventTarget*)::'lambda'()&&)::FuncCancelableRunnable::Run() /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:636:9
#9 0x73e917275017 in mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:618:16
#10 0x73e91726aa86 in mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:945:26
#11 0x73e917269497 in mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:768:15
#12 0x73e917269915 in mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:554:36
#13 0x73e917278986 in operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:268:37
#14 0x73e917278986 in mozilla::detail::RunnableFunction<mozilla::TaskController::TaskController()::$_0>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:548:5
#15 0x73e91728c0ab in nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1155:16
#16 0x73e917292d8f in NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:480:10
#17 0x73e917dfb365 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:85:21
#18 0x73e917d4ebc1 in RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:363:3
#19 0x73e917d4ebc1 in MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:345:3
#20 0x73e91c871c68 in nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:148:27
#21 0x73e91c91f438 in nsAppShell::Run() /builds/worker/checkouts/gecko/widget/gtk/nsAppShell.cpp:469:33
#22 0x73e91d6ba4b4 in nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:295:30
#23 0x73e91d7d91a8 in XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5819:22
#24 0x73e91d7da9a4 in XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:6044:8
#25 0x73e91d7db7d8 in XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:6116:21
#26 0x5ef45e8a1316 in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:233:22
#27 0x5ef45e8a1316 in main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:470:16

Comment 1

[edgul]

It looks like this issue happens when HttpChannelParent::SetCookie is called after HttpChannelParent::OnStartRequest.

And since [the parent's SetCookie is triggered by nsHttpChannel's OnStartRequest](https://searchfox.org/mozilla-central/source/netwerk/protocol/http/nsHttpChannel.cpp#7856] we are looking for places where the Parent's OnStartRequest somehow gets called sooner than nsHttpChannel's OnStartRequest.

Having a quick look, it looks like there are a few places this maybe COULD happen,

• an HttpBaseChannel::DoNotifyListener here, maybe via asyncOpenFinal?
• an nsHttpChannel::OnStopRequest: https://searchfox.org/mozilla-central/source/netwerk/protocol/http/nsHttpChannel.cpp#8776-8778. Is this even possible for OnStop to get ahead of OnStart?
• others?

Kershaw, maybe you can provide some insight?

Regarding severity,
This codepath has a tendency to race and was introduced as a performance enhancement to get cookies to the content process faster.
I don't expect there to be much, if any, impact on this happening, but is good to know since we are working on resolving this race in other bugs right now.

Comment 2

[Kershaw Chang [:kershaw]]

(In reply to Ed Guloien [:edgul] from comment #1)

It looks like this issue happens when HttpChannelParent::SetCookie is called after HttpChannelParent::OnStartRequest.

And since [the parent's SetCookie is triggered by nsHttpChannel's OnStartRequest](https://searchfox.org/mozilla-central/source/netwerk/protocol/http/nsHttpChannel.cpp#7856] we are looking for places where the Parent's OnStartRequest somehow gets called sooner than nsHttpChannel's OnStartRequest.

Having a quick look, it looks like there are a few places this maybe COULD happen,

• an HttpBaseChannel::DoNotifyListener here, maybe via asyncOpenFinal?
• an nsHttpChannel::OnStopRequest: https://searchfox.org/mozilla-central/source/netwerk/protocol/http/nsHttpChannel.cpp#8776-8778. Is this even possible for OnStop to get ahead of OnStart?
• others?

Kershaw, maybe you can provide some insight?

I think this is caused by some listener betweennsHttpChannel and HttpChannelParent that calls HttpChannelParent::OnStartRequest before HttpChannelParent::SetCookie. A pernosco session should be helpful.

Regarding severity,
This codepath has a tendency to race and was introduced as a performance enhancement to get cookies to the content process faster.
I don't expect there to be much, if any, impact on this happening, but is good to know since we are working on resolving this race in other bugs right now.

I don't think there is a performance improvement, since the cookies is sent to in the OnStartRequest IPC message here.

Comment 3

[Kershaw Chang [:kershaw]]

Hi Tyson,

Could you try to get a pernosco session for debugging this issue?

Thanks.

Comment 4

[Tyson Smith [:tsmith]]

Sorry I haven't been able to reproduce this and there has only been one report. If I get another report I can try again.

Comment 5

[Tyson Smith [:tsmith]]

A Pernosco session is available here: https://pernos.co/debug/GfEmfV8oJ5Z5swn4aEFFVA/index.html

Comment 6

[Tyson Smith [:tsmith]]

(In reply to Kershaw Chang [:kershaw] from comment #3)

Could you try to get a pernosco session for debugging this issue?

Success! :)

Comment 7

[Anupam Kumar]

Attachment: WIP: Bug 1918787 - Fix assertion failure in SetCookie and OnStartRequest

Comment 8

[Kershaw Chang [:kershaw]]

(In reply to Tyson Smith [:tsmith] from comment #6)

(In reply to Kershaw Chang [:kershaw] from comment #3)

Could you try to get a pernosco session for debugging this issue?

Success! :)

Thanks for the pernosco session.
The reason HttpChannelParent::OnStartRequest is called before HttpChannelParent::SetCookie is that nsHttpChannel::OnStartRequest is invoked twice.
The first call to nsHttpChannel::OnStartRequest happens due to the cache pump, which then triggers HttpChannelParent::OnStartRequest. In nsHttpChannel::OnStopRequest, we initiate the range request. This creates a new transaction, causing nsHttpChannel::OnStartRequest to be called a second time by the transaction pump. At this point, HttpChannelParent::SetCookie is invoked, leading to the assertion failure.