463988 - Gloda: mozStorageConnection holds lock while calling outside its module leading to PR_ASSERT(lock->owner != me) on shutting down while indexing is active

Reporter

Description

•

16 years ago

Another crash on shutdown, this time in nsAutoLock.

Stack at the time of the crash:
>	ntdll.dll!_DbgBreakPoint@0() 	
 	nspr4.dll!PR_Assert(const char * s=0x10041014, const char * file=0x10040f40, int ln=238)  Line 550	C
 	nspr4.dll!PR_Lock(PRLock * lock=0x04d4bfb8)  Line 238 + 0x21 bytes	C
 	xpcom_core.dll!nsAutoLock::nsAutoLock(PRLock * aLock=0x04d4bfb8)  Line 219 + 0xd bytes	C++
 	strgcmps.dll!mozStorageConnection::getAsyncExecutionTarget()  Line 941	C++
 	strgcmps.dll!NS_executeAsync(nsTArray<sqlite3_stmt *> & aStatements={...}, mozStorageConnection * aConnection=0x04ce91b8, mozIStorageStatementCallback * aCallback=0x07c51290, mozIStoragePendingStatement * * _stmt=0x0016bc6c)  Line 639 + 0xc bytes	C++
 	strgcmps.dll!mozStorageConnection::ExecuteAsync(mozIStorageStatement * * aStatements=0x0016bab8, unsigned int aNumStatements=1, mozIStorageStatementCallback * aCallback=0x07c51290, mozIStoragePendingStatement * * _stmt=0x0016bc6c)  Line 410 + 0x15 bytes	C++
 	strgcmps.dll!mozStorageStatement::ExecuteAsync(mozIStorageStatementCallback * aCallback=0x07c51290, mozIStoragePendingStatement * * _stmt=0x0016bc6c)  Line 582	C++
 	xpcom_core.dll!NS_InvokeByIndex_P(nsISupports * that=0x00000022, unsigned int methodIndex=2, unsigned int paramCount=1490012, nsXPTCVariant * params=0x0512d600)  Line 102	C++
 	xpc3250.dll!XPCWrappedNative::CallMethod(XPCCallContext & ccx={...}, XPCWrappedNative::CallMode mode=CALL_METHOD)  Line 2405 + 0x21 bytes	C++
 	xpc3250.dll!XPC_WN_CallMethod(JSContext * cx=0x00d36b88, JSObject * obj=0x04902200, unsigned int argc=1, long * argv=0x04be9078, long * vp=0x0016bf28)  Line 1477 + 0xe bytes	C++
 	js3250.dll!js_Invoke(JSContext * cx=0x00d36b88, unsigned int argc=1, long * vp=0x04be9070, unsigned int flags=2)  Line 1306 + 0x1a bytes	C++
 	js3250.dll!js_Interpret(JSContext * cx=0x00d36b88)  Line 5147 + 0x16 bytes	C++
 	js3250.dll!SendToGenerator(JSContext * cx=0x00d36b88, JSGeneratorOp op=JSGENOP_SEND, JSObject * obj=0x04913200, JSGenerator * gen=0x08294578, long arg=76627776)  Line 874 + 0x9 bytes	C++
 	js3250.dll!generator_op(JSContext * cx=0x00d36b88, JSGeneratorOp op=JSGENOP_SEND, long * vp=0x0849b704, unsigned int argc=1)  Line 987 + 0x19 bytes	C++
 	js3250.dll!generator_send(JSContext * cx=0x00d36b88, unsigned int argc=1, long * vp=0x0849b704)  Line 996 + 0x13 bytes	C++
 	js3250.dll!js_Interpret(JSContext * cx=0x00d36b88)  Line 5130 + 0x17 bytes	C++
 	js3250.dll!SendToGenerator(JSContext * cx=0x00d36b88, JSGeneratorOp op=JSGENOP_SEND, JSObject * obj=0x071a3140, JSGenerator * gen=0x0849b678, long arg=76627776)  Line 874 + 0x9 bytes	C++
 	js3250.dll!generator_op(JSContext * cx=0x00d36b88, JSGeneratorOp op=JSGENOP_SEND, long * vp=0x04be9300, unsigned int argc=1)  Line 987 + 0x19 bytes	C++
 	js3250.dll!generator_send(JSContext * cx=0x00d36b88, unsigned int argc=1, long * vp=0x04be9300)  Line 996 + 0x13 bytes	C++
 	js3250.dll!js_Interpret(JSContext * cx=0x00d36b88)  Line 5130 + 0x17 bytes	C++
 	js3250.dll!js_Invoke(JSContext * cx=0x00d36b88, unsigned int argc=3, long * vp=0x04be9454, unsigned int flags=0)  Line 1324 + 0x9 bytes	C++
 	xpc3250.dll!nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS * wrapper=0x0807bda8, unsigned short methodIndex=4, const XPTMethodDescriptor * info=0x03bdaef8, nsXPTCMiniVariant * nativeParams=0x0016ddcc)  Line 1549 + 0x1b bytes	C++
 	xpc3250.dll!nsXPCWrappedJS::CallMethod(unsigned short methodIndex=4, const XPTMethodDescriptor * info=0x03bdaef8, nsXPTCMiniVariant * params=0x0016ddcc)  Line 564	C++
 	xpcom_core.dll!PrepareAndDispatch(nsXPTCStubBase * self=0x07c4f2a0, unsigned int methodIndex=4, unsigned int * args=0x0016de8c, unsigned int * stackBytesToPop=0x0016de7c)  Line 114 + 0x21 bytes	C++
 	xpcom_core.dll!SharedStub()  Line 142	C++
 	mime.dll!nsStreamConverter::OnStopRequest(nsIRequest * request=0x06255538, nsISupports * ctxt=0x02b99d64, unsigned int status=0)  Line 1078	C++
 	msgimap.dll!nsImapCacheStreamListener::OnStopRequest(nsIRequest * request=0x060cdad8, nsISupports * aCtxt=0x02b99d64, unsigned int aStatus=0)  Line 8003 + 0x30 bytes	C++
 	necko.dll!nsInputStreamPump::OnStateStop()  Line 577	C++
 	necko.dll!nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream * stream=0x0849bdd8)  Line 401 + 0xb bytes	C++
 	xpcom_core.dll!nsInputStreamReadyEvent::Run()  Line 112	C++
 	xpcom_core.dll!nsThread::ProcessNextEvent(int mayWait=1, int * result=0x0016dfb4)  Line 511	C++
 	xpcom_core.dll!NS_ProcessNextEvent_P(nsIThread * thread=0x00c7ab00, int mayWait=1)  Line 227 + 0x16 bytes	C++
 	xpcom_core.dll!nsThread::Shutdown()  Line 465 + 0xb bytes	C++
 	strgcmps.dll!mozStorageConnection::Close()  Line 237	C++
 	xpcom_core.dll!NS_InvokeByIndex_P(nsISupports * that=0x00000003, unsigned int methodIndex=0, unsigned int paramCount=1499692, nsXPTCVariant * params=0x727209ef)  Line 102	C++
 	xpc3250.dll!XPCWrappedNative::CallMethod(XPCCallContext & ccx={...}, XPCWrappedNative::CallMode mode=CALL_METHOD)  Line 2405 + 0x21 bytes	C++
 	xpc3250.dll!XPC_WN_CallMethod(JSContext * cx=0x00d36b88, JSObject * obj=0x03fd29a0, unsigned int argc=0, long * argv=0x04be9448, long * vp=0x0016e4f8)  Line 1477 + 0xe bytes	C++
 	js3250.dll!js_Invoke(JSContext * cx=0x00d36b88, unsigned int argc=0, long * vp=0x04be9440, unsigned int flags=2)  Line 1306 + 0x1a bytes	C++
 	js3250.dll!js_Interpret(JSContext * cx=0x00d36b88)  Line 5147 + 0x16 bytes	C++
 	js3250.dll!js_Invoke(JSContext * cx=0x00d36b88, unsigned int argc=1, long * vp=0x02a6da40, unsigned int flags=0)  Line 1324 + 0x9 bytes	C++
 	xpc3250.dll!nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS * wrapper=0x0808cd70, unsigned short methodIndex=5, const XPTMethodDescriptor * info=0x04c125f8, nsXPTCMiniVariant * nativeParams=0x0016f1dc)  Line 1549 + 0x1b bytes	C++
 	xpc3250.dll!nsXPCWrappedJS::CallMethod(unsigned short methodIndex=5, const XPTMethodDescriptor * info=0x04c125f8, nsXPTCMiniVariant * params=0x0016f1dc)  Line 564	C++
...


JS stack at the time of the crash:
0 [native frame]
1 gloda_ds__queryFromSQLString(aMasterCollection = undefined, aExistingCollectio
n = undefined, aListenerData = undefined, [object Object], [object Object]) ["fi
le:///D:/mozilla-build/msys/comm-central/obj-i686-pc-mingw32/mozilla/dist/bin/mo
dules/datastore.js":2702]
    collection = [object Object]
    statement = [object mozStorageStatementJSHelper @ 0x8092188 (native @ 0x51de
b18)]
    this = [object Object]
2 gloda_ds_getMessagesByMessageID(010201c91c69$dcfe31c0$1e021fac@pgcseiitk, [fun
ction], [object Object]) ["file:///D:/mozilla-build/msys/comm-central/obj-i686-p
c-mingw32/mozilla/dist/bin/modules/datastore.js":2012]
    query = [object Object]
    listener = [object Object]
    nounDef = [object Object]
    sqlString = "SELECT * FROM messages WHERE headerMessageID IN ('010201c91c69$
dcfe31c0$1e021fac@pgcseiitk')"
    quotedIDs = '010201c91c69$dcfe31c0$1e021fac@pgcseiitk'
    this = [object Object]
3 gloda_indexMessage([xpconnect wrapped nsIMsgDBHdr @ 0x807d5a0 (native @ 0x8889
a60)], [object Object]) ["file:///D:/mozilla-build/msys/comm-central/obj-i686-pc
-mingw32/mozilla/dist/bin/modules/indexer.js":2045]
    isNew = undefined
    attachmentNames = undefined
    curMsg = undefined
    conversation = undefined
    conversationID = undefined
    this = [object Object]
4 gloda_index_workBatch() ["file:///D:/mozilla-build/msys/comm-central/obj-i686-
pc-mingw32/mozilla/dist/bin/modules/indexer.js":1059]
    commitTokens = 1
    this = [object Object]
5 gloda_index_callbackDriver([xpconnect wrapped nsIMsgDBHdr @ 0x807d5a0 (native
@ 0x8889a60)], [object Object]) ["file:///D:/mozilla-build/msys/comm-central/obj
-i686-pc-mingw32/mozilla/dist/bin/modules/indexer.js":939]
    this = [object Object]
6 anonymous(aStatusCode = 0, aContext = [xpconnect wrapped nsIURI @ 0x8083858 (n
ative @ 0x2b99d64)], aRequest = [xpconnect wrapped nsIRequest @ 0x808d660 (nativ
e @ 0x6255538)]) ["file:///D:/mozilla-build/msys/comm-central/obj-i686-pc-mingw3
2/mozilla/dist/bin/modules/mimemsg.js":92]
    message = [object Object]
    this = [object Object]


Gloda log just before the crash:
2008-11-10 13:11:11     gloda.indexer   INFO    Shutting Down
2008-11-10 13:11:11     gloda.indexer   INFO    Event-Driven Indexing is now fal
se
2008-11-10 13:11:11     gloda.datastore INFO    Closing pending transaction out
for shutdown.
--WEBSHELL 00CDABB8 == 2
2008-11-10 13:11:11     gloda.NS        DEBUG    found identity for '' (all@cse.
iitk.ac.in)
2008-11-10 13:11:11     gloda.NS        DEBUG    found identity for 'ACA' (aca@c
se.iitk.ac.in)
2008-11-10 13:11:11     gloda.NS        INFO      * provider: gloda.explattr
2008-11-10 13:11:11     gloda.NS        INFO      * optimizer: gloda.fundattr
2008-11-10 13:11:11     gloda.NS        INFO     ** done with providers.
2008-11-10 13:11:11     gloda.NS        DEBUG   %% no old, want to add Identity:
email:aca@cse.iitk.ac.in which map to 6,906
2008-11-10 13:11:11     gloda.NS        DEBUG   %% no old, want to add Identity:
email:all@cse.iitk.ac.in which map to 7,8
2008-11-10 13:11:11     gloda.NS        DEBUG   %% no old, want to add  which ma
p to
2008-11-10 13:11:11     gloda.NS        DEBUG   %% no old, want to add false whi
ch map to 18,0
2008-11-10 13:11:11     gloda.NS        DEBUG   %% no old, want to add false whi
ch map to 19,0
2008-11-10 13:11:11     gloda.NS        DEBUG   %% no old, want to add  which ma
p to
2008-11-10 13:11:11     gloda.NS        DEBUG   %% no old, want to add Identity:
email:aca@cse.iitk.ac.in,Identity:email:all@cse.iitk.ac.in which map to 11,906,1
1,8
2008-11-10 13:11:11     gloda.NS        DEBUG     json text: {"6":906,"7":[8],"8
":[],"18":false,"19":false,"17":[],"11":[906,8]}
2008-11-10 13:11:11     gloda.NS        DEBUG    inserting item
2008-11-10 13:11:11     gloda.NS        DEBUG    adjusting attributes, add: 6,90
6,7,8,18,0,19,0,11,906,11,8 rem:
2008-11-10 13:11:11     gloda.NS        DEBUG    done grokking.
2008-11-10 13:11:11     gloda.indexer   DEBUG   <<<  _indexMessage
2008-11-10 13:11:11     gloda.indexer   DEBUG   >>>  _indexMessage
2008-11-10 13:11:11     gloda.indexer   DEBUG   *** Indexing message: 120 : Stat
e of Art Seminar: Authentication System .....
2008-11-10 13:11:12     gloda.datastore INFO    Closing db connection
2008-11-10 13:11:12     gloda.indexer   DEBUG     * Got Mime Message!

Rain [:rain1] (inactive)

Reporter

Comment 1

•

16 years ago

Since nsAutoLock comes in here, I'd just like to mention that this is a debug build.

timeless

Comment 2

•

16 years ago

http://mxr.mozilla.org/comm-central/source/mozilla/xpcom/glue/nsAutoLock.h?mark=211-212,217-219#203
211     nsAutoLock(PRLock* aLock)
212         : nsAutoLockBase(aLock, eAutoLock),
217         // This will assert deep in the bowels of NSPR if you attempt
218         // to re-enter the lock.
219         PR_Lock(mLock);

http://mxr.mozilla.org/comm-central/source/mozilla/storage/src/mozStorageConnection.cpp?mark=218-219,234-236,937-939#212
     strgcmps.dll!mozStorageConnection::Close()  Line 237    C++
218 mozStorageConnection::Close()
234         nsAutoLock mutex(mAsyncExecutionMutex);
235         if (mAsyncExecutionThread) {
236             mAsyncExecutionThread->Shutdown();
     xpcom_core.dll!nsThread::Shutdown()  Line 465 + 0xb bytes    C++

Component: Backend → Storage

Product: MailNews Core → Toolkit

QA Contact: backend → storage

Summary: Gloda: Assertion in nspr4!PR_Lock on shutting down while indexing is active → Gloda: mozStorageConnection holds lock while calling outside its module leading to PR_ASSERT(lock->owner != me) on shutting down while indexing is active

Shawn Wilsher :sdwilsh

Comment 3

•

16 years ago

So, we could get around this by adding a new variable to tell when we can use the connection (instead of using mDBConn).  We'd set that once close was called (atomically!) so we do not need to use the lock in close?

Blocks: 460635

Dan Mosedale (:dmosedale, :dmose)

Updated

•

16 years ago

Whiteboard: tb3needs

Dan Mosedale (:dmosedale, :dmose)

Updated

•

16 years ago

Whiteboard: tb3needs → [tb3needs]

Shawn Wilsher :sdwilsh

Comment 4

•

16 years ago

Holding a lock while calling outside our module is very bad, so I'm requesting blocking.

Flags: blocking1.9.1?

Andrew Sutherland [:asuth] (he/him)

Assignee

Comment 5

•

16 years ago

I'll get on this promptly; I had been punting while the trees were frozen, and then got busy.  Clear tb3needs since gloda code no longer does dubious things in terms of storage after closing a connection.

Assignee: nobody → bugmail

Status: NEW → ASSIGNED

Whiteboard: [tb3needs]

Andrew Sutherland [:asuth] (he/him)

Assignee

Comment 6

•

16 years ago

Attached patch v1 add flag that indicates async thread is shutting down, don't call nsIThread::Shutdown with a lock held. (against 1.9.1) — Details — Splinter Review

No matter what we do, we need an extra variable (or allow for mAsyncExecutionThread to take on a non-null sentinel value) in order to capture the fact that we are shutting down.  We must do this because mDBConn has to stay valid until the async execution thread is shut down (so that all pending events can successfully run to completion), and simply nulling out mAsyncExecution thread is insufficient; a new execution thread could end up being created.

It would be more 'useful' to have a variable that captures the notion that we are shutting down the connection, but the async execution thread has specific/unique needs (pending async statements should succeed), so I am giving it its own variable.

I don't think I can write a unit test for this change that would be deterministic unless we have some means of stalling the async execution thread until Shutdown is called on it.  Brief investigation suggests this is difficult when MOZILLA_INTERNAL_API is defined, as is the case for storage.  I would want to wrap the nsIThread, which would require wrapping the nsIThreadManager, which I presume is only feasible when do_GetService enters the picture.  We could change to create its new thread that way, I suppose...

Attachment #352494 - Flags: review?(sdwilsh)

Shawn Wilsher :sdwilsh

Comment 7

•

16 years ago

Comment on attachment 352494 [details] [diff] [review]
v1 add flag that indicates async thread is shutting down, don't call nsIThread::Shutdown with a lock held.  (against 1.9.1)

r=sdwilsh

Looks good.  Testing this would be darn near impossible unless we used a whole bunch of mock-objects.

Attachment #352494 - Flags: review?(sdwilsh) → review+

Shawn Wilsher :sdwilsh

Updated

•

16 years ago

Priority: -- → P2

Whiteboard: [has patch][has review][can land]

Andrew Sutherland [:asuth] (he/him)

Assignee

Comment 8

•

16 years ago

Landed on trunk: http://hg.mozilla.org/mozilla-central/rev/54601bbd453c

This was done after a successful (if forever-taking) try build.

Whiteboard: [has patch][has review][can land] → [has patch][has review][baking on trunk]

Shawn Wilsher :sdwilsh

Updated

•

16 years ago

Attachment #352494 - Flags: approval1.9.1?

Shawn Wilsher :sdwilsh

Comment 9

•

16 years ago

Policy is to close bugs once they land on trunk.

Status: ASSIGNED → RESOLVED

Closed: 16 years ago

Resolution: --- → FIXED

Target Milestone: --- → mozilla1.9.2a1

Mike Beltzner [:beltzner, not reading bugmail]

Updated

•

16 years ago

Flags: blocking1.9.1? → blocking1.9.1+

Mike Beltzner [:beltzner, not reading bugmail]

Comment 10

•

16 years ago

Comment on attachment 352494 [details] [diff] [review]
v1 add flag that indicates async thread is shutting down, don't call nsIThread::Shutdown with a lock held.  (against 1.9.1)

(this is now blocking, so doesn't need explicit approval)

Attachment #352494 - Flags: approval1.9.1?

Shawn Wilsher :sdwilsh

Comment 11

•

16 years ago

http://hg.mozilla.org/releases/mozilla-1.9.1/rev/3d5b39441bda

Keywords: fixed1.9.1

Whiteboard: [has patch][has review][baking on trunk]

Bugzilla

Quick Search

Gloda: mozStorageConnection holds lock while calling outside its module leading to PR_ASSERT(lock->owner != me) on shutting down while indexing is active

Categories

(Toolkit :: Storage, defect, P2)

Tracking

()

People

(Reporter: rain1, Assigned: asuth)

References

Details

(Keywords: fixed1.9.1)

Crash Data

Security

(public)

User Story

Attachments

(1 file)

Description

Comment 1

Comment 2

Comment 3

Updated

Updated

Comment 4

Comment 5

Comment 6

Comment 7

Updated

Comment 8

Updated

Comment 9

Updated

Comment 10

Comment 11

Attachment

General

Description

File Name

Content Type