1062472 - PHttpChannelParent sends OnStartRequest/OnStopRequest after PBrowserChild is destroyed

Status: RESOLVED WORKSFORME

(Core :: Networking, defect, P5)

Description

[Andrew McCreight [:mccr8]]

This happens, I think, in dom/browser-element/mochitest/priority/test_BackgroundLRU.html

This in turn causes us to not get leak logs for this process.  Here's some info from the log, with the NS_WARNING turned into an NS_ASSERTION in the content child abort code, but there's not a lot to go on.

329 INFO [Child 6178] WARNING: NS_ENSURE_TRUE(inBrowser) failed: file /home/amccreight/mc/embedding/browser/nsDocShellTreeOwner.cpp, line 82
331 INFO ###!!! [Child][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
332 INFO [Child 6178] ###!!! ASSERTION: content process _exit()ing: 'false', file /home/amccreight/mc/dom/ipc/ContentChild.cpp, line 1500
333 INFO mozilla::dom::ContentChild::QuickExit() (/home/amccreight/mc/dom/ipc/ContentChild.cpp:1500)
334 INFO mozilla::dom::ContentChild::ProcessingError(mozilla::ipc::HasResultCodes::Result) (/home/amccreight/mc/dom/ipc/ContentChild.cpp:1477)
335 INFO mozilla::dom::PContentChild::OnProcessingError(mozilla::ipc::HasResultCodes::Result) (/tmp/./PContentChild.cpp:5329)
336 INFO mozilla::ipc::MessageChannel::ReportConnectionError(char const*) const (/home/amccreight/mc/ipc/glue/MessageChannel.cpp:1558)
337 INFO mozilla::ipc::MessageChannel::DequeueOne(IPC::Message*) (/home/amccreight/mc/ipc/glue/MessageChannel.cpp:1045)
338 INFO mozilla::ipc::MessageChannel::OnMaybeDequeueOne() (/home/amccreight/mc/ipc/glue/MessageChannel.cpp:1080)
339 INFO void DispatchToMethod<mozilla::ipc::MessageChannel, bool (mozilla::ipc::MessageChannel::*)()>(mozilla::ipc::MessageChannel*, bool (mozilla::ipc::MessageChannel::*)(), Tuple0 const&) (/home/amccreight/mc/ipc/chromium/src/base/tuple.h:384)
340 INFO RunnableMethod<mozilla::ipc::MessageChannel, bool (mozilla::ipc::MessageChannel::*)(), Tuple0>::Run() (/home/amccreight/mc/ipc/chromium/src/base/task.h:308)
341 INFO mozilla::ipc::MessageChannel::RefCountedTask::Run() (/home/amccreight/mc/obj-dbg/ipc/glue/../../dist/include/mozilla/ipc/MessageChannel.h:411)
342 INFO mozilla::ipc::MessageChannel::DequeueTask::Run() (/home/amccreight/mc/obj-dbg/ipc/glue/../../dist/include/mozilla/ipc/MessageChannel.h:428)
343 INFO MessageLoop::RunTask(Task*) (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:358)
344 INFO MessageLoop::DeferOrRunPendingTask(MessageLoop::PendingTask const&) (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:368)
345 INFO MessageLoop::DoWork() (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:443)
346 INFO mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) (/home/amccreight/mc/ipc/glue/MessagePump.cpp:297)
347 INFO MessageLoop::RunInternal() (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:230)
348 INFO MessageLoop::RunHandler() (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:223)
349 INFO MessageLoop::Run() (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:196)
350 INFO nsBaseAppShell::Run() (/home/amccreight/mc/widget/xpwidgets/nsBaseAppShell.cpp:164)
351 INFO XRE_RunAppShell (/home/amccreight/mc/toolkit/xre/nsEmbedFunctions.cpp:702)
352 INFO mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) (/home/amccreight/mc/ipc/glue/MessagePump.cpp:272)
353 INFO MessageLoop::RunInternal() (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:230)
354 INFO MessageLoop::RunHandler() (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:223)
355 INFO MessageLoop::Run() (/home/amccreight/mc/ipc/chromium/src/base/message_loop.cc:196)
356 INFO XRE_InitChildProcess (/home/amccreight/mc/toolkit/xre/nsEmbedFunctions.cpp:539)
357 INFO content_process_main(int, char**) (/home/amccreight/mc/ipc/app/../contentproc/plugin-container.cpp:150)

Comment 1

[Andrew McCreight [:mccr8]]

Kyle said this stack looks like something is sending us a message and it is too late, and that I should use IPC logging to figure out what the message is.

Comment 2

[Ben Turner (not reading bugmail, use the needinfo flag!)]

I bet it's either DataStore (bug 1037625, oops!) or WebApps (bug 1035454)

Comment 3

[Andrew McCreight [:mccr8]]

Attachment: IPDL log

It looks more like PHttpChannel to me:
  [PHttpChannelParent] Received Msg_Cancel([TODO])
  [PRenderFrameParent] Received Msg___delete__([TODO])
  [PBrowserParent] Received Msg___delete__([TODO])
  [PHttpChannelParent] Sending Msg_OnStartRequest([TODO])
  [PHttpChannelParent] Sending Msg_OnStopRequest([TODO])

Comment 4

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Hrm, yeah. Looks like... Jason might want to see this.

Comment 5

[Andrew McCreight [:mccr8]]

Jason, do you have some ideas here?  I guess PBrowserParent could tell PHttpeChannelParent to not send anything to the child after it is destroyed?

Comment 6

[Josh Matthews [:jdm]]

PBrowser being deleted does not indicate anything particularly actionable from the point of view of the HTTP channel. We probably want a closing/ack dance to occur when the child process knows it's shutting down, after which the parent transport should refuse to send any more messages. Until the ack is received, the child could just discard messages silently.

Comment 7

[Andrew McCreight [:mccr8]]

Hmm, it is possible that one of my other patches is causing the child to send Cancel where it wasn't before, thereby triggering this issue, as I'm not seeing this failure on trunk.  I'll try to figure out if that's the case.  I might be able to just prevent that.

Comment 8

[Andrew McCreight [:mccr8]]

Well, so this particular case is in TabChild::BrowserFrameProvideWindow, where we create a new TabChild, then decide we don't need it, so we tear it down.  Maybe it is some weird half-setup stage, which is why we get this error.  Without running the tear down (DestroyWindow()), we leak, and maybe by leaking the TabChild, we keep it alive long enough to get the message, or some other mechanism is stopping PHttpChannelParent.

Comment 9

[Firefox Bug Husbandry Bot]

Bulk change to priority: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258

Comment 10

[Firefox Bug Husbandry Bot]

Bulk change to priority: https://bugzilla.mozilla.org/show_bug.cgi?id=1399258

Comment 11

[Jens Stutte [:jstutte]]

Bulk-downgrade of unassigned, untouched DOM/Storage bug's priority.

If you have reason to believe, this is wrong, please write a comment and ni :jstutte.

Comment 12

[Andrew McCreight [:mccr8]]

This test is gone and I got debug content processes working a long time ago, so eh.