1183845 - 5,200 instances of "NS_ENSURE_TRUE(domDoc && target) failed" and associated warnings emitted from dom/base/nsContentUtils.cpp during linux64 debug testing

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Eric Rahm [:erahm]]

+++ This bug was initially created as a clone of Bug #655517 +++

> 2566 [NNNNN] WARNING: NS_ENSURE_TRUE(domDoc && target) failed: file dom/base/nsContentUtils.cpp, line 3684

This warning [1], introduced in bug 655517 shows up in the following test suites:

> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-browser-chrome-3-bm118-tests1-linux64-build0.txt:972
> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-browser-chrome-2-bm67-tests1-linux64-build0.txt:799
> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-browser-chrome-1-bm53-tests1-linux64-build0.txt:481
> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-1-bm123-tests1-linux64-build25.txt:119
> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-5-bm52-tests1-linux64-build2.txt:45
> mozilla-central_ubuntu64_vm-debug_test-mochitest-browser-chrome-2-bm117-tests1-linux64-build8.txt:38
> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-4-bm122-tests1-linux64-build12.txt:30
> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-3-bm51-tests1-linux64-build0.txt:29
> mozilla-central_ubuntu64_vm-debug_test-mochitest-e10s-2-bm53-tests1-linux64-build12.txt:28
> mozilla-central_ubuntu64_vm-debug_test-mochitest-other-bm53-tests1-linux64-build0.txt:11
> mozilla-central_ubuntu64_vm-debug_test-mochitest-browser-chrome-3-bm122-tests1-linux64-build17.txt:11
> mozilla-central_ubuntu64_vm-debug_test-reftest-e10s-2-bm123-tests1-linux64-build2.txt:1
> mozilla-central_ubuntu64_vm-debug_test-reftest-e10s-1-bm68-tests1-linux64-build0.txt:1
> mozilla-central_ubuntu64_vm-debug_test-mochitest-4-bm121-tests1-linux64-build0.txt:1

It shows up in 913 tests. A few of the most prevalent:

> 41 - browser/components/sessionstore/test/browser_formdata_cc.js
> 37 - dom/manifest/test/browser_ManifestObtainer_obtain.js
> 36 - browser/base/content/test/general/browser_pageInfo.js
> 30 - browser/components/sessionstore/test/browser_615394-SSWindowState_events.js
> 29 - browser/components/sessionstore/test/browser_522545.js
> 28 - browser/base/content/test/general/browser_bug553455.js
> 21 - dom/html/test/browser_bug1108547.js
> 20 - browser/components/sessionstore/test/browser_595601-restore_hidden.js
> 19 - browser/components/sessionstore/test/browser_formdata_format.js
> 18 - toolkit/modules/tests/browser/browser_RemotePageManager.js

[1] https://hg.mozilla.org/mozilla-central/annotate/e786406bc683/dom/base/nsContentUtils.cpp#l3684

Comment 2

[Eric Rahm [:erahm]]

This is also related to:
> 2566 [NNNNN] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file dom/base/nsContentUtils.cpp, line 3739

Comment 3

[Eric Rahm [:erahm]]

Attachment: Don't warn if GetEventAndTarget fails due to invalid args

Comment 4

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8636887 [details] [diff] [review]
Don't warn if GetEventAndTarget fails due to invalid args

So... this is someone explicitly trying to dispatch an event and us not dispatching it.  If this is happening commonly, why is it happening, exactly?

The change in GetEventAndTarget is wrong, by the way: it needs to remove the NS_ENSURE_TRUE line.  But I'd still like to understand why we commonly hit this.

Comment 5

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=096f71d506c6

Comment 6

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ebee1d0c1464

Comment 7

[Eric Rahm [:erahm]]

It looks like the domDoc is null, full stack:

> Breakpoint 1, GetEventAndTarget (aDoc=aDoc@entry=0x0, aTarget=aTarget@entry=0x7f188c77e820, aEventName=..., aCanBubble=aCanBubble@entry=true, aCancelable=aCancelable@entry=true,
>     aTrusted=aTrusted@entry=true, aEvent=0x7ffec68668b0, aTargetOut=0x7ffec68668b8) at /home/erahm/dev/mozilla-central/dom/base/nsContentUtils.cpp:3716
> 3716        NS_WARNING("GetEventAndTarget: domDoc is null");
> (gdb) bt
> #0  GetEventAndTarget (aDoc=aDoc@entry=0x0, aTarget=aTarget@entry=0x7f188c77e820, aEventName=..., aCanBubble=aCanBubble@entry=true, aCancelable=aCancelable@entry=true,
>     aTrusted=aTrusted@entry=true, aEvent=0x7ffec68668b0, aTargetOut=0x7ffec68668b8) at /home/erahm/dev/mozilla-central/dom/base/nsContentUtils.cpp:3716
> #1  0x00007f18a4a191b8 in nsContentUtils::DispatchEvent (aDoc=0x0, aTarget=aTarget@entry=0x7f188c77e820, aEventName=..., aCanBubble=aCanBubble@entry=true,
>     aCancelable=aCancelable@entry=true, aTrusted=aTrusted@entry=true, aDefaultAction=0x0, aOnlyChromeDispatch=true)
>     at /home/erahm/dev/mozilla-central/dom/base/nsContentUtils.cpp:3777
> #2  0x00007f18a4a1929a in nsContentUtils::DispatchEventOnlyToChrome (aDoc=<optimized out>, aTarget=aTarget@entry=0x7f188c77e820, aEventName=..., aCanBubble=aCanBubble@entry=true,
>     aCancelable=aCancelable@entry=true, aDefaultAction=aDefaultAction@entry=0x0) at /home/erahm/dev/mozilla-central/dom/base/nsContentUtils.cpp:3827
> #3  0x00007f18a4b264d6 in nsFocusManager::ActivateOrDeactivate (this=this@entry=0x7f18989eaf60, aWindow=0x7f188c77e820, aActive=aActive@entry=true)
>     at /home/erahm/dev/mozilla-central/dom/base/nsFocusManager.cpp:1142
> #4  0x00007f18a4b2dc01 in nsFocusManager::ParentActivated (this=this@entry=0x7f18989eaf60, aWindow=<optimized out>, aActive=<optimized out>)
>     at /home/erahm/dev/mozilla-central/dom/base/nsFocusManager.cpp:1070
> #5  0x00007f18a57b9f82 in mozilla::dom::TabChild::RecvParentActivated (this=<optimized out>, aActivated=@0x7ffec6866abc: true)
>     at /home/erahm/dev/mozilla-central/dom/ipc/TabChild.cpp:2269
> #6  0x00007f18a57ba09f in mozilla::dom::TabChild::RecvShow (this=0x7f188c747000, aSize=..., aInfo=..., aTextureFactoryIdentifier=..., aLayersId=@0x7ffec6866ad0: 3, aRenderFrame=
>     0x7f188c7cfc00, aParentIsActive=@0x7ffec6866abc: true) at /home/erahm/dev/mozilla-central/dom/ipc/TabChild.cpp:2102
> #7  0x00007f18a44fa9ca in mozilla::dom::PBrowserChild::OnMessageReceived (this=0x7f188c7471b0, msg__=...)
>     at /home/erahm/dev/mozilla-central/obj-x86_64-unknown-linux-gnu/ipc/ipdl/PBrowserChild.cpp:2739
> #8  0x00007f18a42dfd0f in mozilla::ipc::MessageChannel::DispatchAsyncMessage (this=0x7f189a21d898, aMsg=...) at /home/erahm/dev/mozilla-central/ipc/glue/MessageChannel.cpp:1373
> #9  0x00007f18a42e9c35 in mozilla::ipc::MessageChannel::DispatchMessage (this=this@entry=0x7f189a21d898, aMsg=...) at /home/erahm/dev/mozilla-central/ipc/glue/MessageChannel.cpp:1293
> #10 0x00007f18a42eb2fe in mozilla::ipc::MessageChannel::OnMaybeDequeueOne (this=0x7f189a21d898) at /home/erahm/dev/mozilla-central/ipc/glue/MessageChannel.cpp:1264
> #11 0x00007f18a42b96dc in MessageLoop::RunTask (this=0x7ffec6868440, task=0x7f189893e6a0) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:364
> #12 0x00007f18a42be3cc in MessageLoop::DeferOrRunPendingTask (this=<optimized out>, pending_task=...) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:372
> #13 0x00007f18a42be4fb in MessageLoop::DoWork (this=0x7ffec6868440) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:459
> #14 0x00007f18a42e2b22 in mozilla::ipc::MessagePumpForChildProcess::Run (this=0x7f189a251dd0, aDelegate=0x7ffec6868440)
>     at /home/erahm/dev/mozilla-central/ipc/glue/MessagePump.cpp:284
> #15 0x00007f18a42ba413 in MessageLoop::RunInternal (this=this@entry=0x7ffec6868440) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:234
> #16 0x00007f18a42ba444 in RunHandler (this=0x7ffec6868440) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:227
> #17 MessageLoop::Run (this=0x7ffec6868440) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:201
> #18 0x00007f18a5970b53 in nsBaseAppShell::Run (this=0x7f1892217580) at /home/erahm/dev/mozilla-central/widget/nsBaseAppShell.cpp:165
> #19 0x00007f18a6163863 in XRE_RunAppShell () at /home/erahm/dev/mozilla-central/toolkit/xre/nsEmbedFunctions.cpp:785
> #20 0x00007f18a42e2b7a in mozilla::ipc::MessagePumpForChildProcess::Run (this=0x7f189a251dd0, aDelegate=0x7ffec6868440)
>     at /home/erahm/dev/mozilla-central/ipc/glue/MessagePump.cpp:259
> #21 0x00007f18a42ba413 in MessageLoop::RunInternal (this=this@entry=0x7ffec6868440) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:234
> #22 0x00007f18a42ba444 in RunHandler (this=0x7ffec6868440) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:227
> #23 MessageLoop::Run (this=this@entry=0x7ffec6868440) at /home/erahm/dev/mozilla-central/ipc/chromium/src/base/message_loop.cc:201
> #24 0x00007f18a616437a in XRE_InitChildProcess (aArgc=<optimized out>, aArgv=<optimized out>, aGMPLoader=<optimized out>)
>     at /home/erahm/dev/mozilla-central/toolkit/xre/nsEmbedFunctions.cpp:621
> #25 0x00000000004089a3 in content_process_main (argc=5, argv=0x7ffec6868738) at /home/erahm/dev/mozilla-central/ipc/app/../contentproc/plugin-container.cpp:236
> #26 0x00007f18a24f2ec5 in __libc_start_main (main=0x4084c1 <main(int, char**)>, argc=6, argv=0x7ffec6868738, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>,
>     stack_end=0x7ffec6868728) at libc-start.c:287
> #27 0x00000000004085f1 in _start ()

|aDoc| comes from:

> #3  0x00007f18a4b264d6 in nsFocusManager::ActivateOrDeactivate (this=this@entry=0x7f18989eaf60, aWindow=0x7f188967ac20, aActive=aActive@entry=true)
>     at /home/erahm/dev/mozilla-central/dom/base/nsFocusManager.cpp:1142
> 1142                                              true, true, nullptr);
> (gdb) l
> 1137    nsContentUtils::DispatchEventOnlyToChrome(aWindow->GetExtantDoc(),
> 1138                                              aWindow,
> 1139                                              aActive ?
> 1140                                                NS_LITERAL_STRING("activate") :
> 1141                                                NS_LITERAL_STRING("deactivate"),
> 1142                                              true, true, nullptr);

|aWindow| is a |nsGlobalWindow|, |GetExtantDoc| returns |nsGlobalWindow::mDoc| which is null.

We can see in the line above that, |aWindow->ActivateOrDeactivate(aActive)| is called, internally that handles mDoc being null gracefully [1] so presumably this is an expected condition.

That leaves us with a few options:
  - don't call |nsContentUtils::DispatchEventOnlyToChrome| if aWindow->GetExtantDoc() is null
  - remove the warning
  - perhaps there really is something wrong

[1] https://hg.mozilla.org/mozilla-central/annotate/2ddec2dedced/dom/base/nsGlobalWindow.cpp#l10094

Comment 8

[Boris Zbarsky [:bzbarsky]]

Eric, thank you for digging into that!

Neil, is it expected that the focus manager would be firing these events on a window with no document?

Comment 9

[Eric Rahm [:erahm]]

Try run confirms this is all null domDoc, virtually all the same relevant portion of the stack. 

For outliers (still the same top portion of the stack) 261 stacks involved:

> #06: mozilla::dom::TabChild::DoFakeShow(mozilla::layers::TextureFactoryIdentifier const&, unsigned long const&, mozilla::layout::PRenderFrameChild*) [dom/ipc/TabChild.cpp:1969]
> #07: mozilla::dom::TabChild::ProvideWindowCommon(nsIDOMWindow*, bool, unsigned int, bool, bool, bool, nsIURI*, nsAString_internal const&, nsAC

1 involved:

> #03: nsFocusManager::WindowLowered(nsIDOMWindow*) [xpcom/glue/nsCOMPtr.h:544]
> #04: nsFocusManager::WindowRaised(nsIDOMWindow*) [dom/base/nsFocusManager.cpp:681]
> #05: nsWebShellWindow::WindowActivated() [xpfe/appshell/nsWebShellWindow.cpp:421]
> #06: nsWindow::OnContainerFocusInEvent(_GdkEventFocus*) [widget/gtk/nsWindow.cpp:2749]
> #07: focus_in_event_cb [widget/gtk/nsWindow.cpp:5257]

Comment 10

[Eric Rahm [:erahm]]

This is now the #4 most verbose warning.

Comment 11

[Eric Rahm [:erahm]]

Actually, collectively these two warnings are the #1 most verbose.

Comment 12

[Neil Deakin]

When is this occurring? The page is getting torn down between the time that the parent process sends the message and before the child process receives the message (received at TabChild::RecvParentActivate)?

The activate event only needs to be sent to the top-level window in the parent process and doesn't need to be sent in the child process at all. I'm guessing here this is a chrome document loaded into a tab.

We can just null-check the document here and not send the event.

Comment 13

[Eric Rahm [:erahm]]

Attachment: Only send activation event if document is non-null

Comment 14

[Eric Rahm [:erahm]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=919bac253b36

Comment 15

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8641757 [details] [diff] [review]
Only send activation event if document is non-null

r=me

Comment 16

[Eric Rahm [:erahm]]

url:        https://hg.mozilla.org/integration/mozilla-inbound/rev/829ee40cf65526c7b1b96b289be9f11d3a9d05f5
changeset:  829ee40cf65526c7b1b96b289be9f11d3a9d05f5
user:       Eric Rahm <[e-mail]>
date:       Fri Jul 31 13:23:15 2015 -0700
description:
Bug 1183845 - Only send activation event if document is non-null. r=bz

Comment 17

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/829ee40cf655