Closed Bug 679993 Opened 13 years ago Closed 12 years ago

Intermittent ASSERTION: QueryInterface needed: 'query_result.get() == mRawPtr' resulting in test_fileReaderSync.xul | Exited with code 1 during test run

Categories

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

Product:
Core
Component:
DOM: Core & HTML
Platform:
x86
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: philor, Unassigned)

References

Details

(Keywords: assertion, intermittent-failure) 

http://tbpl.allizom.org/php/getParsedLog.php?id=6011080
Rev3 MacOSX Leopard 10.5.8 mozilla-inbound debug test mochitest-other on 2011-08-17 20:59:55 PDT for push e3a6de4920d0


8639 INFO TEST-START | chrome://mochitests/content/chrome/dom/workers/test/test_fileReaderSync.xul
++DOMWINDOW == 380 (0x29166338) [serial = 718] [outer = 0x254e83e0]
Couldn't convert chrome URL: chrome://mochitests/tests/SimpleTest/test.css
WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/slave/m-in-osx-dbg/build/netwerk/base/src/nsIOService.cpp, line 653
WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/slave/m-in-osx-dbg/build/layout/style/Loader.cpp, line 1866
Failed to load jar:file:///var/folders/Xr/Xr--yJnSEY0U11ET5NZuMU+++TM/-Tmp-/tmpObNtry/extensions/mochikit@mozilla.org/chrome/mochikit.jar!/content/MochiKit/packed.js
###!!! ASSERTION: QueryInterface needed: 'query_result.get() == mRawPtr', file ../../dist/include/nsCOMPtr.h, line 544
nsCOMPtr<nsIFactory>::Assert_NoQueryNeeded [nsCOMPtr.h:544]
nsCOMPtr<nsIFactory>::operator= [nsCOMPtr.h:665]
nsFactoryEntry::GetFactory [xpcom/components/nsComponentManager.cpp:1985]
nsComponentManagerImpl::CreateInstanceByContractID [xpcom/components/nsComponentManager.cpp:1293]
CallCreateInstance [obj-firefox/xpcom/build/nsComponentManagerUtils.cpp:170]
nsCreateInstanceByContractID::operator() [obj-firefox/xpcom/build/nsComponentManagerUtils.cpp:210]
nsCOMPtr<nsIConverterInputStream>::assign_from_helper [nsCOMPtr.h:1272]
nsCOMPtr<nsIConverterInputStream>::nsCOMPtr [nsCOMPtr.h:645]
mozilla::dom::workers::FileReaderSyncPrivate::ConvertStream [dom/workers/FileReaderSyncPrivate.cpp:194]
mozilla::dom::workers::FileReaderSyncPrivate::ReadAsText [dom/workers/FileReaderSyncPrivate.cpp:146]
FileReaderSync::ReadAsText [dom/workers/FileReaderSync.cpp:326]
js::CallJSNative [js/src/jscntxtinlines.h:281]
js::Invoke [js/src/jsinterp.cpp:657]
js::Interpret [js/src/jsinterp.cpp:4015]
js::RunScript [js/src/jsinterp.cpp:614]
js::Invoke [js/src/jsinterp.cpp:687]
js::Invoke [js/src/jsinterp.h:169]
js::ExternalInvoke [js/src/jsinterp.cpp:809]
JS_CallFunctionValue [js/src/jsapi.cpp:5040]
mozilla::dom::workers::events::ListenerManager::DispatchEvent [dom/workers/ListenerManager.cpp:429]
mozilla::dom::workers::events::EventTarget::DispatchEvent [dom/workers/EventTarget.cpp:204]
js::CallJSNative [js/src/jscntxtinlines.h:281]
js::Invoke [js/src/jsinterp.cpp:657]
js::Invoke [js/src/jsinterp.h:169]
js::ExternalInvoke [js/src/jsinterp.cpp:809]
JS_CallFunctionName [js/src/jsapi.cpp:5026]
mozilla::dom::workers::events::DispatchEventToTarget [dom/workers/Events.cpp:1121]
MessageEventRunnable::WorkerRun [dom/workers/WorkerPrivate.cpp:783]
mozilla::dom::workers::WorkerRunnable::Run [dom/workers/WorkerPrivate.cpp:1504]
mozilla::dom::workers::WorkerPrivate::DoRunLoop [dom/workers/WorkerPrivate.cpp:2330]
WorkerThreadRunnable::Run [dom/workers/RuntimeService.cpp:380]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:631]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x32155
libSystem.B.dylib + 0x32012
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/dom/workers/test/test_fileReaderSync.xul | Exited with code 1 during test run
INFO | automation.py | Application ran for: 0:05:55.568816
INFO | automation.py | Reading PID log: /var/folders/Xr/Xr--yJnSEY0U11ET5NZuMU+++TM/-Tmp-/tmp56yPKSpidlog
PROCESS-CRASH | chrome://mochitests/content/chrome/dom/workers/test/test_fileReaderSync.xul | application crashed (minidump found)
Crash dump filename: /var/folders/Xr/Xr--yJnSEY0U11ET5NZuMU+++TM/-Tmp-/tmpObNtry/minidumps/0FE8B8C8-C194-493D-8134-819F585D32C1.dmp
Operating system: Mac OS X
                  10.5.8 9L31a
CPU: x86
     GenuineIntel family 6 model 23 stepping 10
     2 CPUs

Crash reason:  EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
Crash address: 0x458b18ec

Thread 30 (crashed)
 0  0x458b18ec
    eip = 0x458b18ec   esp = 0xb12ba20c   ebp = 0xb12ba278   ebx = 0x040e914a
    esi = 0x0407cae0   edi = 0x00000000   eax = 0x458b18ec   ecx = 0x00000000
    edx = 0x29189dc0   efl = 0x00010206
    Found by: given as instruction pointer in context
 1  XUL!nsComponentManagerImpl::CreateInstanceByContractID [nsComponentManager.cpp:e3a6de4920d0 : 1293 + 0xa]
    eip = 0x040e944f   esp = 0xb12ba280   ebp = 0xb12ba2c8
    Found by: previous frame's frame pointer
 2  XUL!CallCreateInstance [nsComponentManagerUtils.cpp:e3a6de4920d0 : 170 + 0x26]
    eip = 0x0407cad4   esp = 0xb12ba2d0   ebp = 0xb12ba318   ebx = 0x0407ca58
    Found by: call frame info
 3  XUL!nsCreateInstanceByContractID::operator() [nsComponentManagerUtils.cpp:e3a6de4920d0 : 210 + 0x25]
    eip = 0x0407cb15   esp = 0xb12ba320   ebp = 0xb12ba358   ebx = 0x0348e236
    Found by: call frame info
 4  XUL!nsCOMPtr<nsIConverterInputStream>::assign_from_helper [nsCOMPtr.h : 1272 + 0x11]
    eip = 0x0348e0b7   esp = 0xb12ba360   ebp = 0xb12ba388   ebx = 0x0348e236
    Found by: call frame info
 5  XUL!nsCOMPtr<nsIConverterInputStream>::nsCOMPtr [nsCOMPtr.h : 644 + 0x1b]
    eip = 0x0348e25c   esp = 0xb12ba390   ebp = 0xb12ba3a8   ebx = 0x0348e236
    esi = 0x29189278
    Found by: call frame info
 6  XUL!mozilla::dom::workers::FileReaderSyncPrivate::ConvertStream [FileReaderSyncPrivate.cpp:e3a6de4920d0 : 193 + 0x31]
    eip = 0x0348ccb6   esp = 0xb12ba3b0   ebp = 0xb12ba428   ebx = 0x0348cc83
    esi = 0x29189278
    Found by: call frame info
 7  XUL!mozilla::dom::workers::FileReaderSyncPrivate::ReadAsText [FileReaderSyncPrivate.cpp:e3a6de4920d0 : 146 + 0x33]
    eip = 0x0348d80d   esp = 0xb12ba430   ebp = 0xb12ba4c8   ebx = 0x0348d37e
    esi = 0x29189278
    Found by: call frame info
 8  XUL!FileReaderSync::ReadAsText [FileReaderSync.cpp:e3a6de4920d0 : 326 + 0x1f]
    eip = 0x0348bf46   esp = 0xb12ba4d0   ebp = 0xb12ba548   ebx = 0x0348be29
    esi = 0x2ed00090
    Found by: call frame info
 9  XUL!js::CallJSNative [jscntxtinlines.h:e3a6de4920d0 : 281 + 0x2a]
    eip = 0x047f043e   esp = 0xb12ba550   ebp = 0xb12ba578   ebx = 0x047f03df
    esi = 0x2ed00090
    Found by: call frame info
10  XUL!js::Invoke [jsinterp.cpp:e3a6de4920d0 : 657 + 0x1b]
    eip = 0x045f65f1   esp = 0xb12ba580   ebp = 0xb12ba608   ebx = 0x045f63d9
    esi = 0x2ed00090
    Found by: call frame info
   192   nsCOMPtr<nsIConverterInputStream> converterStream =
   193     do_CreateInstance("@mozilla.org/intl/converter-input-stream;1");
   194   NS_ENSURE_TRUE(converterStream, NS_ERROR_FAILURE);


That's, uh, surprising, that that asserts.
Any idea where to start debugging this? The assertion is coming from code I'm not familiar with.
bsmedberg pointed out on IRC that it's interesting that we're crashing in trace-refcnty code when the main thread is in trace-refcnty code.
I think it's substantially *more* interesting that (at least in the log in comment 5) we're in the middle of instantiating a converter input stream on three different threads (Thread 31, Thread 32, and the crashed Thread 38).

(The allizom.org logs either seem to return garbage or a 404.)
To be clear, I think something has become corrupted before it gets to the nsTraceRefcnt code (where it's crashing trying to dynamic_cast<void*> the pointer it's told is being AddRef'd).

There are three useful stacks I see; the assertion stack in comment 0, crash stack in comment 0, and crash stack in comment 5.  The two crash stacks (comment 0 and comment 5) are essentially at the same place except that the one in comment 5 somehow survived the call to AddRef and got into nsTraceRefcnt, whereas the one in comment 0 didn't.  But the one in comment 0 also had an earlier assertion, which is likely to be closer to the problem.
When I was looking over this with Jonas, he pointed out that this might be caused by a race condition when initializing a Factory in nsFactoryEntry::GetFactory called from nsComponentManagerImpl::CreateInstanceByContractID. In particular, it looks like multiple threads can simultaneously call into GetFactory, see that the factory doesn't exist and create a new instance. However, it seems like this would be very rare because a factory would likely have been instantiated before running the FileReaderSync code in workers and there isn't much happening between checking for a factory and instantiating one.
At least, I presume that the crash in that opt build in comment 15 is the opt equivalent of what this assertion is protecting against:

Thread 31 (crashed)
 0  libxul.so!nsFactoryEntry::GetFactory [nsComponentManager.cpp:e58e98a89827 : 1990 + 0x7]
    rbx = 0x26a95cc0   r12 = 0x2ea7f060   r13 = 0xfc2fcfa0   r14 = 0xfc2fcf20
    r15 = 0x26a95cc0   rip = 0x2e5eaf91   rsp = 0xfc2fcef0   rbp = 0x14cfece0
    Found by: given as instruction pointer in context
 1  libxul.so!nsComponentManagerImpl::CreateInstanceByContractID [nsComponentManager.cpp:e58e98a89827 : 1295 + 0x7]
    rbx = 0x30db48c0   r12 = 0x2ea7f060   r13 = 0xfc2fcfa0   r14 = 0xfc2fcf20
    r15 = 0x26a95cc0   rip = 0x2e5eb12a   rsp = 0xfc2fcf10   rbp = 0x00000000
    Found by: call frame info
 2  libxul.so!nsCreateInstanceByContractID::operator() [nsComponentManagerUtils.cpp:e58e98a89827 : 170 + 0x7]
    rbx = 0xfc2fdff0   r12 = 0xfc2fe010   r13 = 0xfc2fe120   r14 = 0x00000000
    r15 = 0xfc2fe0a0   rip = 0x2e5b796b   rsp = 0xfc2fcf80   rbp = 0xfc2fcfa0
    Found by: call frame info
 3  libxul.so!nsCOMPtr_base::assign_from_helper [nsCOMPtr.cpp:e58e98a89827 : 150 + 0x7]
    rbx = 0xfc2fe010   r12 = 0xfc2fe010   r13 = 0xfc2fe120   r14 = 0x00000000
    r15 = 0xfc2fe0a0   rip = 0x2e5b6ce6   rsp = 0xfc2fcfa0   rbp = 0x0953d730
    Found by: call frame info
 4  libxul.so!mozilla::dom::workers::FileReaderSyncPrivate::GuessCharset [FileReaderSyncPrivate.cpp:e58e98a89827 : 225 + 0x4]
    rbx = 0x14cff400   r12 = 0xfc2fe010   r13 = 0xfc2fe120   r14 = 0x00000000
    r15 = 0xfc2fe0a0   rip = 0x2e01afd4   rsp = 0xfc2fcfc0   rbp = 0x0953d730
    Found by: call frame info
 5  libxul.so!mozilla::dom::workers::FileReaderSyncPrivate::ReadAsText [FileReaderSyncPrivate.cpp:e58e98a89827 : 125 + 0xc]
    rbx = 0x14cff400   r12 = 0xfc2fe130   r13 = 0xfc2fe120   r14 = 0x00000000
    r15 = 0x00000000   rip = 0x2e01b344   rsp = 0xfc2fe080   rbp = 0x07650f20
    Found by: call frame info
 6  libxul.so!FileReaderSync::ReadAsText [FileReaderSync.cpp:e58e98a89827 : 326 + 0x7]
    rbx = 0x23466800   r12 = 0x14cff400   r13 = 0x00000000   r14 = 0xfc2fe130
    r15 = 0x00000000   rip = 0x2e01a8f8   rsp = 0xfc2fe120   rbp = 0xfa0fe0c8
    Found by: call frame info
 7  libxul.so!js::InvokeKernel [jscntxtinlines.h:e58e98a89827 : 281 + 0x9]
    rbx = 0x06507580   r12 = 0x06507580   r13 = 0xfa0fe0d8   r14 = 0x00000000
    r15 = 0x00000000   rip = 0x2e831e66   rsp = 0xfc2fe180   rbp = 0x23466800
    Found by: call frame info
 8  libxul.so!js::Interpret [jsinterp.cpp:e58e98a89827 : 4015 + 0x11]
    rbx = 0x23466800   r12 = 0x06507580   r13 = 0xfa0fe0d8   r14 = 0xfc2fe310
    r15 = 0x00000000   rip = 0x2e981001   rsp = 0xfc2fe230   rbp = 0xfc2fe7a0
    Found by: call frame info
 9  libxul.so!js::InvokeKernel [jsinterp.cpp:e58e98a89827 : 687 + 0x4]
    rbx = 0x00000000   r12 = 0x0912f800   r13 = 0xfc2fe790   r14 = 0x0000c000
    r15 = 0xfa0fe050   rip = 0x2e831f08   rsp = 0xfc2fe760   rbp = 0x23466800
Depends on: 684887
Mass marking whiteboard:[orange] bugs WFM (to clean up TBPL bug suggestions) that:
* Haven't changed in > 6months
* Whose whiteboard contains none of the strings: {disabled,marked,random,fuzzy,todo,fails,failing,annotated,leave open,time-bomb}
* Passed a (quick) manual inspection of bug summary/whiteboard to ensure they weren't a false positive.

I've also gone through and searched for cases where the whiteboard wasn't labelled correctly after test disabling, by using attachment description & basic comment searches. However if the test for which this bug was about has in fact been disabled/annotated/..., please accept my apologies & reopen/mark the whiteboard appropriately so this doesn't get re-closed in the future (and please ping me via IRC or email so I can try to tweak the saved searches to avoid more edge cases).

Sorry for the spam! Filter on: #FFA500
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → WORKSFORME
Whiteboard: [orange]
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.