539839 - Console service crash at shutdown (XPCShell testcase)

Status: VERIFIED DUPLICATE of bug 549388

(Core :: XPCOM, defect)

Description

[Alex Vincent [:WeirdAl]]

Attachment: xpcshell testcase for crash

I found this while writing a test for bug 539782.

Comment 1

[Alex Vincent [:WeirdAl]]

Attachment: stack trace

lock->owner = 0xdddddddd @ nspr4.dll!PR_Lock(PRLock * lock=0x00f44960)  Line 234	C

Comment 2

[Josh Matthews [:jdm]]

(gdb) bt
#0  0x0061f416 in __kernel_vsyscall ()
#1  0x00544899 in __lll_lock_wait () from /lib/libpthread.so.0
#2  0x0053fd50 in _L_lock_936 () from /lib/libpthread.so.0
#3  0x0053fc21 in pthread_mutex_lock () from /lib/libpthread.so.0
#4  0x003ccc80 in PR_Lock (lock=0x8d3b150) at /home/t_mattjo/src/firefox/electrolysis/nsprpub/pr/src/pthreads/ptsynch.c:206
#5  0x022d2214 in nsAutoUnlock::~nsAutoUnlock (this=0xbf8e2fe8, __in_chrg=<value optimized out>) at ../../../dist/include/nsAutoLock.h:272
#6  0x022d1c6c in nsProxyObject::LockedRelease (this=0x927b050) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEvent.cpp:405
#7  0x022d1aa1 in nsProxyObject::Release (this=0x927b050) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEvent.cpp:378
#8  0x022d3480 in nsCOMPtr<nsProxyObject>::~nsCOMPtr (this=0x927abfc, __in_chrg=<value optimized out>) at ../../../dist/include/nsCOMPtr.h:510
#9  0x022d277d in nsProxyEventObject::~nsProxyEventObject (this=0x927abe8, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEventObject.cpp:77
#10 0x022d298e in nsProxyEventObject::Release (this=0x927abe8) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEventObject.cpp:116
#11 0x022e1b90 in nsXPTCStubBase::Release (this=0x927ac10) at /home/t_mattjo/src/firefox/electrolysis/xpcom/reflect/xptcall/src/xptcall.cpp:65
#12 0x022788a6 in nsSupportsHashtable::ReleaseElement (aKey=0x927aca0, aData=0x927ac10, aClosure=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:794
#13 0x02276b95 in hashEnumerate (table=0x929fb2c, hdr=0x92a4b30, i=0, arg=0xbf8e31f4) at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:130
#14 0x0225860c in PL_DHashTableEnumerate (table=0x929fb2c, etor=0x2276b5e <hashEnumerate(PLDHashTable*, PLDHashEntryHdr*, PRUint32, void*)>, arg=0xbf8e31f4) at pldhash.c:754
#15 0x02277292 in nsHashtable::Enumerate (this=0x929fb24, aEnumFunc=0x2278882 <nsSupportsHashtable::ReleaseElement(nsHashKey*, void*, void*)>, aClosure=0x0)
    at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:318
#16 0x0122f693 in nsSupportsHashtable::Enumerate (this=0x929fb24, aEnumFunc=0x2278882 <nsSupportsHashtable::ReleaseElement(nsHashKey*, void*, void*)>, aClosure=0x0) at ../../dist/include/nsHashtable.h:218
#17 0x022788ee in nsSupportsHashtable::~nsSupportsHashtable (this=0x929fb24, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:800
#18 0x022d57b9 in nsConsoleService::~nsConsoleService (this=0x929fb08, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/base/nsConsoleService.cpp:99
#19 0x022d54c5 in nsConsoleService::Release (this=0x929fb08) at /home/t_mattjo/src/firefox/electrolysis/xpcom/base/nsConsoleService.cpp:62
#20 0x0173b1c6 in nsCOMPtr_base::assign_assuming_AddRef (this=0x8cfc6ac, newPtr=0x0) at ../../../../dist/include/nsCOMPtr.h:456
#21 0x0225a60c in nsCOMPtr_base::assign_with_AddRef (this=0x8cfc6ac, rawPtr=0x0) at nsCOMPtr.cpp:89
#22 0x00fb00b1 in nsCOMPtr<nsISupports>::operator= (this=0x8cfc6ac, rhs=0x0) at ../../../../dist/include/nsCOMPtr.h:975
#23 0x022bccb4 in FreeServiceContractIDEntryEnumerate (aTable=0x8ceb818, aHdr=0x8cf5560, aNumber=825, aData=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/components/nsComponentManager.cpp:1733
#24 0x0225860c in PL_DHashTableEnumerate (table=0x8ceb818, etor=0x22bcc78 <FreeServiceContractIDEntryEnumerate(PLDHashTable*, PLDHashEntryHdr*, PRUint32, void*)>, arg=0x0) at pldhash.c:754
#25 0x022bcd45 in nsComponentManagerImpl::FreeServices (this=0x8ceb7d0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/components/nsComponentManager.cpp:1746
#26 0x0226e5c1 in mozilla::ShutdownXPCOM (servMgr=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/build/nsXPComInit.cpp:811
#27 0x0226e21b in NS_ShutdownXPCOM_P (servMgr=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/build/nsXPComInit.cpp:723
#28 0x00cd6e74 in NS_ShutdownXPCOM (svcMgr=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/stub/nsXPComStub.cpp:179
#29 0x0804e330 in main (argc=19, argv=0xbf8e36a0, envp=0xbf8e36f0) at /home/t_mattjo/src/firefox/electrolysis/js/src/xpconnect/shell/xpcshell.cpp:1975


(gdb) fr 6
#6  0x022d1c6c in nsProxyObject::LockedRelease (this=0x927b050) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEvent.cpp:405
405	    return 0;
(gdb) list
400	
401	    nsAutoUnlock unlock(pom->GetLock());
402	    delete this;
403	    pom->Release();
404	
405	    return 0;
406	}
407	
408	NS_IMETHODIMP
409	nsProxyObject::QueryInterface(REFNSIID aIID, void **aResult)
(gdb) p pom
$15 = (nsProxyObjectManager *) 0x8d3a4e8
(gdb) p *pom
$16 = {
  <nsIProxyObjectManager> = {
    <nsISupports> = {
      _vptr.nsISupports = 0x904d2a0
    }, <No data fields>}, 
  members of nsProxyObjectManager: 
  mRefCnt = {
    mValue = 7938992
  }, 
  _mOwningThread = {
    mThread = 0x0
  }, 
  static sLog = 0x8cded38, 
  static mInstance = 0x0, 
  mProxyObjectMap = {
    _vptr.nsHashtable = 0x0, 
    mLock = 0x0, 
    mHashtable = {
      ops = 0x2a9b040, 
      data = 0x0, 
      hashShift = 24, 
      maxAlphaFrac = 192 '\300', 
      minAlphaFrac = 64 '@', 
      entrySize = 12, 
      entryCount = 0, 
      removedCount = 0, 
      generation = 0, 
      entryStore = 0x8d3a548 "\240\322\004\t\260#y"
    }, 
    mEnumerating = 0
  }, 
  mProxyClassMap = {
    <nsBaseHashtable<nsIDHashKey, nsAutoPtr<nsProxyEventClass>, nsProxyEventClass*>> = {
      <nsTHashtable<nsBaseHashtableET<nsIDHashKey, nsAutoPtr<nsProxyEventClass> > >> = {
        mTable = {
          ops = 0x2ad8ec0, 
          data = 0x0, 
          hashShift = 28, 
          maxAlphaFrac = 192 '\300', 
          minAlphaFrac = 64 '@', 
          entrySize = 24, 
          entryCount = 0, 
          removedCount = 0, 
          generation = 1, 
          entryStore = 0x904d2a8 "\330K*\t\340\244\323\b"
        }
      }, <No data fields>}, <No data fields>}, 
  mProxyCreationLock = 0x8d3b150
}

Looks like the proxy object manager is garbage here.

Comment 3

[Josh Matthews [:jdm]]

Breakpoint 1, nsProxyObjectManager::~nsProxyObjectManager (this=0x83f84e8, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyObjectManager.cpp:110
110	nsProxyObjectManager::~nsProxyObjectManager()
(gdb) bt
#0  nsProxyObjectManager::~nsProxyObjectManager (this=0x83f84e8, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyObjectManager.cpp:110
#1  0x01b38965 in nsProxyObjectManager::Release (this=0x83f84e8) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyObjectManager.cpp:101
#2  0x01b36c5c in nsProxyObject::LockedRelease (this=0x8939050) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEvent.cpp:403
#3  0x01b36aa1 in nsProxyObject::Release (this=0x8939050) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEvent.cpp:378
#4  0x01b38480 in nsCOMPtr<nsProxyObject>::~nsCOMPtr (this=0x8938bfc, __in_chrg=<value optimized out>) at ../../../dist/include/nsCOMPtr.h:510
#5  0x01b3777d in nsProxyEventObject::~nsProxyEventObject (this=0x8938be8, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEventObject.cpp:77
#6  0x01b3798e in nsProxyEventObject::Release (this=0x8938be8) at /home/t_mattjo/src/firefox/electrolysis/xpcom/proxy/src/nsProxyEventObject.cpp:116
#7  0x01b46b90 in nsXPTCStubBase::Release (this=0x8938c10) at /home/t_mattjo/src/firefox/electrolysis/xpcom/reflect/xptcall/src/xptcall.cpp:65
#8  0x01add8a6 in nsSupportsHashtable::ReleaseElement (aKey=0x8938ca0, aData=0x8938c10, aClosure=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:794
#9  0x01adbb95 in hashEnumerate (table=0x895db2c, hdr=0x8962bb4, i=0, arg=0xbff13f34) at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:130
#10 0x01abd60c in PL_DHashTableEnumerate (table=0x895db2c, etor=0x1adbb5e <hashEnumerate(PLDHashTable*, PLDHashEntryHdr*, PRUint32, void*)>, arg=0xbff13f34) at pldhash.c:754
#11 0x01adc292 in nsHashtable::Enumerate (this=0x895db24, aEnumFunc=0x1add882 <nsSupportsHashtable::ReleaseElement(nsHashKey*, void*, void*)>, aClosure=0x0)
    at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:318
#12 0x00a94693 in nsSupportsHashtable::Enumerate (this=0x895db24, aEnumFunc=0x1add882 <nsSupportsHashtable::ReleaseElement(nsHashKey*, void*, void*)>, aClosure=0x0) at ../../dist/include/nsHashtable.h:218
#13 0x01add8ee in nsSupportsHashtable::~nsSupportsHashtable (this=0x895db24, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/ds/nsHashtable.cpp:800
#14 0x01b3a7b9 in nsConsoleService::~nsConsoleService (this=0x895db08, __in_chrg=<value optimized out>) at /home/t_mattjo/src/firefox/electrolysis/xpcom/base/nsConsoleService.cpp:99
#15 0x01b3a4c5 in nsConsoleService::Release (this=0x895db08) at /home/t_mattjo/src/firefox/electrolysis/xpcom/base/nsConsoleService.cpp:62
#16 0x00fa01c6 in nsCOMPtr_base::assign_assuming_AddRef (this=0x83ba6ac, newPtr=0x0) at ../../../../dist/include/nsCOMPtr.h:456
#17 0x01abf60c in nsCOMPtr_base::assign_with_AddRef (this=0x83ba6ac, rawPtr=0x0) at nsCOMPtr.cpp:89
#18 0x008150b1 in nsCOMPtr<nsISupports>::operator= (this=0x83ba6ac, rhs=0x0) at ../../../../dist/include/nsCOMPtr.h:975
#19 0x01b21cb4 in FreeServiceContractIDEntryEnumerate (aTable=0x83a9818, aHdr=0x83b3560, aNumber=825, aData=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/components/nsComponentManager.cpp:1733
#20 0x01abd60c in PL_DHashTableEnumerate (table=0x83a9818, etor=0x1b21c78 <FreeServiceContractIDEntryEnumerate(PLDHashTable*, PLDHashEntryHdr*, PRUint32, void*)>, arg=0x0) at pldhash.c:754
#21 0x01b21d45 in nsComponentManagerImpl::FreeServices (this=0x83a97d0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/components/nsComponentManager.cpp:1746
#22 0x01ad35c1 in mozilla::ShutdownXPCOM (servMgr=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/build/nsXPComInit.cpp:811
#23 0x01ad321b in NS_ShutdownXPCOM_P (servMgr=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/build/nsXPComInit.cpp:723
#24 0x00205e74 in NS_ShutdownXPCOM (svcMgr=0x0) at /home/t_mattjo/src/firefox/electrolysis/xpcom/stub/nsXPComStub.cpp:179
#25 0x0804e330 in main (argc=19, argv=0xbff143e0, envp=0xbff14430) at /home/t_mattjo/src/firefox/electrolysis/js/src/xpconnect/shell/xpcshell.cpp:1975

It appears something is proxying the POM, so it dies here.

Comment 4

[Josh Matthews [:jdm]]

Attachment: Balance refcnt tree

Ignore the last note about proxying the POM; that was completely incorrect.  It feels like we're over-releasing somewhere, so I've compiled a refcnt log to try to narrow it down.

Comment 5

[Josh Matthews [:jdm]]

Attachment: Patch + test

It looks like the refcounting is correct here, we're just not taking into account the fact that the ProxyObjectManager service could end up dying via LockedRelease().  This obviously invalidates the lock which is accessed afterwards, so I work around it by doing the equivalent of a kungFuDeathGrip.

Comment 6

[Josh Matthews [:jdm]]

The reason the service ends up dying in this case is that the ProxyObjectManager service object is released before the console service, so only proxy objects end up keeping it alive.

Comment 7

[Josh Matthews [:jdm]]

Attachment: Patch + test

Found another instance where the problem could be repeated.

Comment 8

[Benjamin Smedberg]

Comment on attachment 443014 [details] [diff] [review]
Patch + test

We have a design error here: we shouldn't be releasing any XPCOM objects after we delete the POM, so something needs to be reordered in ShutdownXPCOM so that this is actually true.

This appears to be a dup of bug 549388 or the other way, please unify them if so.

Comment 9

[Josh Matthews [:jdm]]

I don't see any good way to reorder things to make this correct.  The service is released in FreeServices, and happens to come before ConsoleService in the hashtable.  We don't even reach nsProxyObjectManager::Shutdown before the crash happens.  I think bug 549388 has the correct solution for this, so I'll dup it forwards.