1401366 - Intermittent application crashed [@ mozilla::dom::HTMLMediaElement::ShutdownObserver::Observe(nsISupports *,char const *,char16_t const *)]

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: archaeopteryx [at] coole-files.de

https://treeherder.mozilla.org/logviewer.html#?job_id=132032192&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/SuaM_R4gS626m-d7z6rBZQ/runs/0/artifacts/public/logs/live_backing.log

17:42:08     INFO -  777 INFO TEST-START | dom/xul/templates/tests/chrome/test_tmpl_xmlquerywithsortotherfield.xul
17:42:08     INFO -  GECKO(5088) | MEMORY STAT | vsize 1892MB | vsizeMaxContiguous 132050192MB | residentFast 387MB | heapAllocated 176MB
17:42:08     INFO -  778 INFO TEST-OK | dom/xul/templates/tests/chrome/test_tmpl_xmlquerywithsortotherfield.xul | took 50ms
17:42:08     INFO -  779 INFO TEST-START | Shutdown
17:42:08     INFO -  780 INFO Passed:  523
17:42:08     INFO -  781 INFO Failed:  0
17:42:08     INFO -  782 INFO Todo:    77
17:42:08     INFO -  783 INFO Mode:    non-e10s
17:42:08     INFO -  784 INFO Slowest: 1049ms - chrome://mochitests/content/chrome/dom/xul/templates/tests/chrome/test_bug329335.xul
17:42:08     INFO -  785 INFO SimpleTest FINISHED
17:42:08     INFO -  786 INFO TEST-INFO | Ran 1 Loops
17:42:08     INFO -  787 INFO SimpleTest FINISHED
17:42:08     INFO -  GECKO(5088) | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping
17:42:09     INFO -  TEST-INFO | Main app process: exit 1
17:42:09     INFO -  Buffered messages finished
17:42:09    ERROR -  788 ERROR TEST-UNEXPECTED-FAIL | dom/xul/templates/tests/chrome/test_tmpl_xmlquerywithsortotherfield.xul | application terminated with exit code 1
17:42:09     INFO -  runtests.py | Application ran for: 0:00:16.689000
17:42:09     INFO -  zombiecheck | Reading PID log: c:\users\genericworker\appdata\local\temp\tmpiloqfopidlog
17:42:09     INFO -  mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/e6HxmsIIShi78PfJvkk3cA/artifacts/public/build/target.crashreporter-symbols.zip
17:42:21     INFO -  mozcrash Copy/paste: Z:\task_1505842326\build\win32-minidump_stackwalk.exe c:\users\genericworker\appdata\local\temp\tmpsprhoj.mozrunner\minidumps\16689e2f-1691-4c9c-9ff4-579592569a41.dmp c:\users\genericworker\appdata\local\temp\tmpohhgne
17:42:28     INFO -  mozcrash Saved minidump as Z:\task_1505842326\build\blobber_upload_dir\16689e2f-1691-4c9c-9ff4-579592569a41.dmp
17:42:28     INFO -  mozcrash Saved app info as Z:\task_1505842326\build\blobber_upload_dir\16689e2f-1691-4c9c-9ff4-579592569a41.extra
17:42:28  WARNING -  PROCESS-CRASH | dom/xul/templates/tests/chrome/test_tmpl_xmlquerywithsortotherfield.xul | application crashed [@ mozilla::dom::HTMLMediaElement::ShutdownObserver::Observe(nsISupports *,char const *,char16_t const *)]
17:42:28     INFO -  Crash dump filename: c:\users\genericworker\appdata\local\temp\tmpsprhoj.mozrunner\minidumps\16689e2f-1691-4c9c-9ff4-579592569a41.dmp
17:42:28     INFO -  Operating system: Windows NT
17:42:28     INFO -                    10.0.15063
17:42:28     INFO -  CPU: amd64
17:42:28     INFO -       family 6 model 63 stepping 2
17:42:28     INFO -       8 CPUs
17:42:28     INFO -  GPU: UNKNOWN
17:42:28     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
17:42:28     INFO -  Crash address: 0x7ffd93318b1b
17:42:28     INFO -  Process uptime: 16 seconds
17:42:28     INFO -  Thread 0 (crashed)
17:42:28     INFO -   0  xul.dll!mozilla::dom::HTMLMediaElement::ShutdownObserver::Observe(nsISupports *,char const *,char16_t const *) [HTMLMediaElement.cpp:5b0de4548020 : 3772 + 0x11]
17:42:28     INFO -      rax = 0x00007ffdb7636d58   rdx = 0x00000207acdbc148
17:42:28     INFO -      rcx = 0x00007ffd956c64c0   rbx = 0x000000000000012e
17:42:28     INFO -      rsi = 0x0000000000000000   rdi = 0x000000000000012e
17:42:28     INFO -      rbp = 0x00007ffd95323260   rsp = 0x0000004a1e7ff180
17:42:28     INFO -       r8 = 0x00007ffd95323260    r9 = 0x0000000000000000
17:42:28     INFO -      r10 = 0x00007ffd952d9d30   r11 = 0x00000207b729c000
17:42:28     INFO -      r12 = 0x0000004a1e7ff488   r13 = 0x0000000080000000
17:42:28     INFO -      r14 = 0x00000207acdbc148   r15 = 0x0000004a1e7ff460
17:42:28     INFO -      rip = 0x00007ffd93318b1b
17:42:28     INFO -      Found by: given as instruction pointer in context
17:42:28     INFO -   1  xul.dll!nsObserverList::NotifyObservers(nsISupports *,char const *,char16_t const *) [nsObserverList.cpp:5b0de4548020 : 112 + 0x1d]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff1b0   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffd92de6fc6
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   2  xul.dll!nsObserverService::NotifyObservers(nsISupports *,char const *,char16_t const *) [nsObserverService.cpp:5b0de4548020 : 296 + 0x11]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff1f0   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffd92de6e54
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   3  xul.dll!mozilla::ShutdownXPCOM(nsIServiceManager *) [XPCOMInit.cpp:5b0de4548020 : 877 + 0x17]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff270   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffd9300a3c0
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   4  xul.dll!ScopedXPCOMStartup::~ScopedXPCOMStartup() [nsAppRunner.cpp:5b0de4548020 : 1527 + 0x8]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff2d0   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffd92c3edef
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   5  xul.dll!mozilla::UniquePtr<ScopedXPCOMStartup,mozilla::DefaultDelete<ScopedXPCOMStartup> >::reset(ScopedXPCOMStartup *) [UniquePtr.h:5b0de4548020 : 345 + 0xe]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff300   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffd92c3ed6b
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   6  xul.dll!XREMain::XRE_main(int,char * * const,mozilla::BootstrapConfig const &) [nsAppRunner.cpp:5b0de4548020 : 4893 + 0xa]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff330   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffd9307133f
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   7  xul.dll!XRE_main(int,char * * const,mozilla::BootstrapConfig const &) [nsAppRunner.cpp:5b0de4548020 : 4960 + 0xd]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff3f0   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffd931c5c73
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   8  firefox.exe!NS_internal_main(int,char * *,char * *) [nsBrowserApp.cpp:5b0de4548020 : 309 + 0x23e]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff5e0   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ff6a0541a52
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -   9  firefox.exe!wmain [nsWindowsWMain.cpp:5b0de4548020 : 115 + 0x14]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ff9e0   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ff6a05411d0
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -  10  firefox.exe!__scrt_common_main_seh [exe_common.inl : 253 + 0x22]
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ffa30   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ff6a0546eb5
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -  11  kernel32.dll!BaseThreadInitThunk + 0x14
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ffa70   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffdc2362774
17:42:28     INFO -      Found by: call frame info
17:42:28     INFO -  12  ntdll.dll!SdbpCheckMatchingRegistryEntry + 0x29d
17:42:28     INFO -      rbx = 0x000000000000012e   rbp = 0x00007ffd95323260
17:42:28     INFO -      rsp = 0x0000004a1e7ffaa0   r12 = 0x0000004a1e7ff488
17:42:28     INFO -      r13 = 0x0000000080000000   r14 = 0x00000207acdbc148
17:42:28     INFO -      r15 = 0x0000004a1e7ff460   rip = 0x00007ffdc2470d61
17:42:28     INFO -      Found by: call frame info

Comment 1

[JW Wang [:jwwang] [:jw_wang]]

https://treeherder.mozilla.org/logviewer.html#?job_id=132137864&repo=try&lineNumber=3297
It crashed at HTMLMediaElement.cpp:3777

https://hg.mozilla.org/try/file/d7aa60020a02/dom/html/HTMLMediaElement.cpp#l3777

It shows Observe() is called after Unsubscribe() which calls nsContentUtils::UnregisterShutdownObserver(this) and set mPhase to Phase::Unsubscribed.

Hi smaug,
Is it possible for Observe() to be called after nsContentUtils::UnregisterShutdownObserver(this)? I expect UnregisterShutdownObserver() will prevent future notifications to come.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

If UnregisterShutdownObserver is called while some other observer is being handled, then Observe may be called, at least based on http://searchfox.org/mozilla-central/rev/d08b24e613cac8c9c5a4131452459241010701e0/xpcom/ds/nsObserverList.cpp#108-109,111-112

Comment 3

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Bug 1401366. P1 - format HTMLMediaElement::ShutdownObserver.

Review commit: https://reviewboard.mozilla.org/r/181684/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/181684/

Comment 4

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Bug 1401366. P2 - bail out Observe() if not subcribed per comment 2.

Review commit: https://reviewboard.mozilla.org/r/181686/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/181686/

Comment 5

[Tzuhao Kuo [:kaku]]

Comment on attachment 8910187 [details]
Bug 1401366. P1 - format HTMLMediaElement::ShutdownObserver.

https://reviewboard.mozilla.org/r/181684/#review187044

Comment 6

[Tzuhao Kuo [:kaku]]

Comment on attachment 8910188 [details]
Bug 1401366. P2 - bail out Observe() if not subcribed per comment 2.

https://reviewboard.mozilla.org/r/181686/#review187046

r+ assuming that https://bugzilla.mozilla.org/show_bug.cgi?id=1401366#c2 is right.
But why? Is it bacause that "removing observer" and "handling observer" are async operations?

Comment 7

[JW Wang [:jwwang] [:jw_wang]]

No. They are not async as far as I can tell. I guess this is because some other observer causes ~HTMLMediaElement() to run (either by spinning the event loop or dropping the last reference to it) which will call ShutdownObserver::Unsubscribe().

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0848279b2b72
P1 - format HTMLMediaElement::ShutdownObserver. r=kaku
https://hg.mozilla.org/integration/autoland/rev/f9e527aa4ba5
P2 - bail out Observe() if not subcribed per comment 2. r=kaku

Comment 9

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/0848279b2b72
https://hg.mozilla.org/mozilla-central/rev/f9e527aa4ba5

Comment 10

[Intermittent Failures Robot]

18 failures in 943 pushes (0.019 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 11
* mozilla-inbound: 7

Platform breakdown:
* windows7-32: 6
* windows7-32-stylo-disabled: 5
* windows10-64: 4
* windows10-64-stylo-disabled: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1401366&startday=2017-09-18&endday=2017-09-24&tree=all