1591115 - Intermittent Last test finished | application crashed [@ nsIEventTarget::IsOnCurrentThread()]

Status: RESOLVED WORKSFORME

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

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=272767485&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/W4WtHhLPR8u6kNYl_EgNNg/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/W4WtHhLPR8u6kNYl_EgNNg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2019-10-24T14:40:37.669Z] 14:40:37 INFO - [Parent 5980, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file z:/build/build/src/xpcom/base/nsCycleCollector.cpp, line 3361
[task 2019-10-24T14:40:37.736Z] 14:40:37 INFO - nsStringStats
[task 2019-10-24T14:40:37.736Z] 14:40:37 INFO - => mAllocCount: 87575
[task 2019-10-24T14:40:37.737Z] 14:40:37 INFO - => mReallocCount: 0
[task 2019-10-24T14:40:37.737Z] 14:40:37 INFO - => mFreeCount: 87575
[task 2019-10-24T14:40:37.737Z] 14:40:37 INFO - => mShareCount: 109156
[task 2019-10-24T14:40:37.738Z] 14:40:37 INFO - => mAdoptCount: 2409
[task 2019-10-24T14:40:37.738Z] 14:40:37 INFO - => mAdoptFreeCount: 2501
[task 2019-10-24T14:40:37.738Z] 14:40:37 INFO - => Process ID: 5980, Thread ID: 5064
[task 2019-10-24T14:40:37.785Z] 14:40:37 INFO - REFTEST INFO | Copy/paste: Z:\task_1571924493\build\win32-minidump_stackwalk.exe c:\users\task_1571924493\appdata\local\temp\tmpiefibe.mozrunner\minidumps\5229bd72-9d66-40dd-a4be-6d93a6295ca6.dmp Z:\task_1571924493\build\symbols
[task 2019-10-24T14:41:04.514Z] 14:41:04 INFO - REFTEST INFO | Saved minidump as Z:\task_1571924493\build\blobber_upload_dir\5229bd72-9d66-40dd-a4be-6d93a6295ca6.dmp
[task 2019-10-24T14:41:06.473Z] 14:41:06 INFO - REFTEST PROCESS-CRASH | Last test finished | application crashed [@ nsIEventTarget::IsOnCurrentThread()]
[task 2019-10-24T14:41:06.473Z] 14:41:06 INFO - Crash dump filename: c:\users\task_1571924493\appdata\local\temp\tmpiefibe.mozrunner\minidumps\5229bd72-9d66-40dd-a4be-6d93a6295ca6.dmp
[task 2019-10-24T14:41:06.473Z] 14:41:06 INFO - Operating system: Windows NT
[task 2019-10-24T14:41:06.473Z] 14:41:06 INFO - 6.1.7601 Service Pack 1
[task 2019-10-24T14:41:06.474Z] 14:41:06 INFO - CPU: x86
[task 2019-10-24T14:41:06.474Z] 14:41:06 INFO - GenuineIntel family 6 model 45 stepping 7
[task 2019-10-24T14:41:06.474Z] 14:41:06 INFO - 8 CPUs
[task 2019-10-24T14:41:06.474Z] 14:41:06 INFO -
[task 2019-10-24T14:41:06.474Z] 14:41:06 INFO - GPU: UNKNOWN
[task 2019-10-24T14:41:06.474Z] 14:41:06 INFO -
[task 2019-10-24T14:41:06.474Z] 14:41:06 INFO - Crash reason: EXCEPTION_ACCESS_VIOLATION_READ
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - Crash address: 0x4
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - Assertion: Unknown assertion type 0x00000000
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - Process uptime: 6 seconds
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO -
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - Thread 30 (crashed)
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - 0 xul.dll!nsIEventTarget::IsOnCurrentThread() [nsThreadUtils.cpp:f0838766c33a5fc6f854892adb6f096d6839a19b : 617 + 0x0]
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - eip = 0x54542f54 esp = 0x0833f304 ebp = 0x0833f308 ebx = 0x00000000
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - esi = 0x0c738630 edi = 0x0c738630 eax = 0xac7e1b44 ecx = 0x00000000
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - edx = 0x00ffaa48 efl = 0x00010202
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - Found by: given as instruction pointer in context
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - 1 xul.dll!mozilla::MediaCacheStream::CloseInternal(mozilla::MonitorAutoLock &) [MediaCache.cpp:f0838766c33a5fc6f854892adb6f096d6839a19b : 2213 + 0x5]
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - eip = 0x572d28c9 esp = 0x0833f310 ebp = 0x0833f33c esi = 0x0c738630
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - Found by: call frame info
[task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - 2 xul.dll!nsresult mozilla::detail::RunnableFunction<lambda at z:/build/build/src/dom/media/MediaCache.cpp:2206:7'>::Run() [nsThreadUtils.h:f0838766c33a5fc6f854892adb6f096d6839a19b : 564 + 0x25] [task 2019-10-24T14:41:06.475Z] 14:41:06 INFO - eip = 0x57301481 esp = 0x0833f344 ebp = 0x0833f354 ebx = 0x00000000 [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - esi = 0x0c723430 edi = 0x0c738630 [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - 3 xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:f0838766c33a5fc6f854892adb6f096d6839a19b : 1225 + 0x6] [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - eip = 0x5454e78e esp = 0x0833f35c ebp = 0x0833f87c esi = 0x00000001 [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - edi = 0x08f92100 [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - 4 xul.dll!NS_ProcessNextEvent(nsIThread *,bool) [nsThreadUtils.cpp:f0838766c33a5fc6f854892adb6f096d6839a19b : 486 + 0xb] [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - eip = 0x545524e8 esp = 0x0833f884 ebp = 0x0833f8a0 ebx = 0x08f97100 [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - esi = 0x0833f893 edi = 0x0149d820 [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - 5 xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate *) [MessagePump.cpp:f0838766c33a5fc6f854892adb6f096d6839a19b : 333 + 0xa] [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - eip = 0x54c2bb8e esp = 0x0833f8a8 ebp = 0x0833f8d4 ebx = 0x08f97100 [task 2019-10-24T14:41:06.476Z] 14:41:06 INFO - esi = 0x08f97200 [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - 6 xul.dll!MessageLoop::RunInternal() [message_loop.cc:f0838766c33a5fc6f854892adb6f096d6839a19b : 315 + 0x5] [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - eip = 0x54bd9057 esp = 0x0833f8dc ebp = 0x0833f8f4 ebx = 0x08f97160 [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - esi = 0x0149d820 edi = 0x0149d820 [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - 7 xul.dll!MessageLoop::RunHandler() [message_loop.cc:f0838766c33a5fc6f854892adb6f096d6839a19b : 308 + 0x7] [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - eip = 0x54bd8f73 esp = 0x0833f8fc ebp = 0x0833f928 esi = 0x0149d820 [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - 8 xul.dll!MessageLoop::Run() [message_loop.cc:f0838766c33a5fc6f854892adb6f096d6839a19b : 290 + 0x5] [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - eip = 0x54bd8e37 esp = 0x0833f930 ebp = 0x0833f95c ebx = 0x08f97160 [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - esi = 0x08f92100 edi = 0x0149d820 [task 2019-10-24T14:41:06.477Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - 9 xul.dll!nsThread::ThreadFunc(void *) [nsThread.cpp:f0838766c33a5fc6f854892adb6f096d6839a19b : 458 + 0xa] [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - eip = 0x5454b006 esp = 0x0833f964 ebp = 0x0833f988 [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - 10 nss3.dll!_PR_NativeRunThread [pruthr.c:f0838766c33a5fc6f854892adb6f096d6839a19b : 399 + 0x6] [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - eip = 0x6afff02b esp = 0x0833f990 ebp = 0x0833f9b0 ebx = 0x00fef948 [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - esi = 0x01483a20 edi = 0x01483970 [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - 11 nss3.dll!static unsigned int pr_root(void *) [w95thred.c:f0838766c33a5fc6f854892adb6f096d6839a19b : 139 + 0x7] [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - eip = 0x6afed7ed esp = 0x0833f9b8 ebp = 0x0833f9bc ebx = 0x00fef948 [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - esi = 0x6afed7e0 edi = 0x00fef948 [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - 12 ucrtbase.dll!__RtlConvertUlongToLargeInteger + 0x8489 [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - eip = 0x6b1ce16f esp = 0x0833f9c4 ebp = 0x0833f9f8 [task 2019-10-24T14:41:06.478Z] 14:41:06 INFO - Found by: call frame info [task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - 13 kernel32.dll! ?? ?? ::FNODOBFM::string' + 0x46
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - eip = 0x76faef3c esp = 0x0833fa00 ebp = 0x0833fa04
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - Found by: previous frame's frame pointer
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - 14 mozglue.dll!static void patched_BaseThreadInitThunk(int, void *, void *) [WindowsDllBlocklist.cpp:f0838766c33a5fc6f854892adb6f096d6839a19b : 560 + 0x14]
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - eip = 0x6b2cef37 esp = 0x0833fa0c ebp = 0x0833fa40
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - Found by: previous frame's frame pointer
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - 15 ntdll.dll!__RtlUserThreadStart + 0x27
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - eip = 0x776e3618 esp = 0x0833fa48 ebp = 0x0833fa80 ebx = 0x00fef948
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - esi = 0x00000000 edi = 0x00000000
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - Found by: call frame info
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - 16 ntdll.dll!_RtlUserThreadStart + 0x1b
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - eip = 0x776e35eb esp = 0x0833fa88 ebp = 0x0833fa98
[task 2019-10-24T14:41:06.479Z] 14:41:06 INFO - Found by: call frame info
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO -
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - Thread 0
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - 0 ntdll.dll!KiFastSystemCallRet + 0x0
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - eip = 0x776c6c04 esp = 0x0039eca8 ebp = 0x0039ed00 ebx = 0x0039ed0c
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - esi = 0x00000000 edi = 0x00000000 eax = 0x00000184 ecx = 0x0c725100
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - edx = 0x0039ecb0 efl = 0x00000246
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - Found by: given as instruction pointer in context
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - 1 ntdll.dll!ZwWaitForKeyedEvent + 0xc
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - eip = 0x776c657c esp = 0x0039ecac ebp = 0x0039ed00 ebx = 0x0039ed0c
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - Found by: call frame info
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - 2 ntdll.dll!RtlSleepConditionVariableSRW + 0xda
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - eip = 0x77684a33 esp = 0x0039ecb0 ebp = 0x0039ed00 ebx = 0x0039ed0c
[task 2019-10-24T14:41:06.480Z] 14:41:06 INFO - Found by: call frame info
[task 2019-10-24T14:41:06.481Z] 14:41:06 INFO - 3 kernel32.dll!wcslen + 0x33c

Comment 1

[Andrew McCreight [:mccr8]]

Looks like mozilla::MediaCacheStream::CloseInternal() is using something on the wrong thread.

Comment 2

[Intermittent Failures Robot]

1 failures in 4182 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1591115&startday=2019-10-21&endday=2019-10-27&tree=all

Comment 3

[Intermittent Failures Robot]

2 failures in 4314 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-inbound: 1

Platform breakdown:

• windows7-32: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1591115&startday=2019-10-28&endday=2019-11-03&tree=all

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

The priority flag is not set for this bug.
:drno, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 5

[Paul Adenot (:padenot)]

Unclear what's up here. Can InvokeAsync end up calling something on a different thread? This is during shutdown if this matters.

Comment 6

[Jean-Yves Avenard [:jya]]

(In reply to Paul Adenot (:padenot) from comment #5)

Unclear what's up here. Can InvokeAsync end up calling something on a different thread? This is during shutdown if this matters.

at a glance:
this seems to be a null deref rather than running on the wrong thread.
so OwnerThread() would now return null

OwnerThread() is https://searchfox.org/mozilla-central/source/dom/media/MediaCache.cpp#2746
return mMediaCache->OwnerThread();

Which is returning https://searchfox.org/mozilla-central/source/dom/media/MediaCache.cpp#779 with sThread being cleared on shutdown.

so a race between sThread being cleared before InvokeAsync running ?
don't see how as sThread should only be cleared after the threads have shutdown, which only occurs when all tasks have run.

Is there a chance to retrieve a crash dump?
Does this crash occurred recently?

Comment 7

[Andrei Purice]

Marking this as Resolved > Worksforme since there are no more crashes in the last 6 months with this signature.