1310152 - [App Verifier] Critical section not initialized in sqlite3

Status: RESOLVED FIXED

(Toolkit :: Storage, defect, P1)

Description

[Cervantes Yu [:cyu] [:cervantes]]

Attachment: xpcshell.exe.2447.dat.xml

App verifier reports that a CRITICAL_SECTION is not initialized in running:
./mach xpcshell-test toolkit/components/places/tests/bookmarks/

Stacktrace:
vfbasics!+7ff90c996501 ( @ 0)
vfbasics!+7ff90c99768a ( @ 0)
vfcuzz!CuzzGetCustomSchedulerInterface+1632 ( @ 0)
nss3!sqlite3_mutex_enter+f (e:\hg\mozilla-central\db\sqlite3\src\sqlite3.c @ 22485)
xul!mozilla::storage::Connection::initializeClone+436 (e:\hg\mozilla-central\storage\mozstorageconnection.cpp @ 1407)
xul!mozilla::storage::`anonymous namespace'::AsyncInitializeClone::Run+1a (e:\hg\mozilla-central\storage\mozstorageconnection.cpp @ 432)
xul!nsThread::ProcessNextEvent+2bd (e:\hg\mozilla-central\xpcom\threads\nsthread.cpp @ 1082)
xul!NS_ProcessNextEvent+27 (e:\hg\mozilla-central\xpcom\glue\nsthreadutils.cpp @ 290)
xul!mozilla::ipc::MessagePumpForNonMainThreads::Run+203 (e:\hg\mozilla-central\ipc\glue\messagepump.cpp @ 338)
xul!MessageLoop::RunHandler+4b (e:\hg\mozilla-central\ipc\chromium\src\base\message_loop.cc @ 226)
xul!MessageLoop::Run+1e (e:\hg\mozilla-central\ipc\chromium\src\base\message_loop.cc @ 206)
xul!nsThread::ThreadFunc+102 (e:\hg\mozilla-central\xpcom\threads\nsthread.cpp @ 467)
nss3!_PR_NativeRunThread+ee (e:\hg\mozilla-central\nsprpub\pr\src\threads\combined\pruthr.c @ 419)
nss3!pr_root+a (e:\hg\mozilla-central\nsprpub\pr\src\md\windows\w95thred.c @ 96)
ucrtbase!o__realloc_base+60 ( @ 0)
vfbasics!+7ff90c99f0d4 ( @ 0)
KERNEL32!BaseThreadInitThunk+14 ( @ 0)
ntdll!RtlUserThreadStart+21 ( @ 0)

This error cannot be reproduced with --sequential.

Comment 1

[Nicholas Nethercote [inactive]]

CC'ing drh.

Comment 2

[D. Richard Hipp]

The "e:\hg\mozilla-central\db\sqlite3\src\sqlite3.c @ 22485" source location information from the stack trace maps to https://www.sqlite.org/src/artifact/40dc52f7525fa?ln=98 for SQLite 3.15.0 and to https://www.sqlite.org/src/artifact/40dc52f7525fa?ln=140 for SQLite 3.14.2.  From this I infer that the issue occurs using older SQLite 3.14.2, not the newly released 3.15.0  Am I correct?

Comment 3

[Marco Bonardo [:mak]]

we didn't upgrade to 3.15.0 yet, so yes.

Comment 4

[Ryan VanderMeulen [:RyanVM]]

We're on 3.14.1 at the moment.

Comment 5

[D. Richard Hipp]

Our current hypothesis is that an sqlite3_mutex object is being used after it has been freed.  The experimental sqlite3.c file found at https://sqlite.org/tmp/bug-1310152-test1.zip will assert() (with high probability) if that happens.  Can someone please rerun the test using the experimental sqlite3.c file above and let us know what happens?

Comment 6

[Marco Bonardo [:mak]]

Cervantes, can you do the run with that custom sqlite code from comment 5? Do you need assistance with that?

Comment 7

[Cervantes Yu [:cyu] [:cervantes]]

I got page not found with the above link. Would you attach the file or fix the link? Thanks.

Comment 8

[D. Richard Hipp]

(In reply to Cervantes Yu [:cyu] [:cervantes] from comment #7)
> I got page not found with the above link. Would you attach the file or fix
> the link? Thanks.

Typo on upload.  Fixed now.  Please try again.

Comment 9

[Cervantes Yu [:cyu] [:cervantes]]

Assertion failure caught inside visual studio debugger. The two threads that use the same critical section and cause the crash

The thread that calls DeleteCriticalSection:
 	00007ff811c02149	Unknown
 	00007ff8117765f8	Unknown
 	00007ff811776f4d	Unknown
>	winMutexFree Line 23708	C
content of p:
-		p	0x00007ff6ae6ce9c0 {mutex={DebugInfo=0x00000230cc895fd0 {Type=0x0000 CreatorBackTraceIndex=0x0234 CriticalSection=...} ...} ...}	sqlite3_mutex *
+		mutex	{DebugInfo=0x00000230cc895fd0 {Type=0x0000 CreatorBackTraceIndex=0x0234 CriticalSection=0x00007ff6ae6ce9c0 {...} ...} ...}	_RTL_CRITICAL_SECTION
		id	0x00000001	int
		nRef	0x00000001	volatile int
		owner	0x000016d0	volatile unsigned long
		magic	0x1f7a8074	volatile unsigned int
 	sqlite3_mutex_free Line 22482	C
 	sqlite3LeaveMutexAndCloseZombie Line 137740	C
 	sqlite3Close Line 137607	C
 	mozilla::storage::Connection::internalClose Line 963	C++
this == 0x00007ff6aec44340, refcnt == 14
 	mozilla::storage::`anonymous namespace'::AsyncCloseConnection::Run Line 380	C++
 	nsThread::ProcessNextEvent Line 1082	C++
 	NS_ProcessNextEvent Line 290	C++
 	mozilla::ipc::MessagePumpForNonMainThreads::Run Line 338	C++
 	MessageLoop::RunHandler Line 226	C++
 	MessageLoop::Run Line 206	C++
 	nsThread::ThreadFunc Line 467	C++
 	_PR_NativeRunThread Line 419	C
 	pr_root Line 96	C
 	[External Code]	

Thread 0x16D0, which uses the critical section and triggers the assertion:
 	[External Code]	
>	winMutexEnter Line 23739	C
assert( p->nRef>0 || p->owner==0 );
 	sqlite3_mutex_enter Line 22493	C
 	mozilla::storage::Connection::CreateFunction Line 1801	C++
 	mozilla::storage::Connection::initializeClone Line 1423	C++
this == 0x00007ff6aec44340 refcnt == 14
 	mozilla::storage::`anonymous namespace'::AsyncInitializeClone::Run Line 432	C++
 	nsThread::ProcessNextEvent Line 1082	C++
 	NS_ProcessNextEvent Line 290	C++
 	mozilla::ipc::MessagePumpForNonMainThreads::Run Line 338	C++
 	MessageLoop::RunHandler Line 226	C++
 	MessageLoop::Run Line 206	C++
 	nsThread::ThreadFunc Line 467	C++
 	_PR_NativeRunThread Line 419	C
 	pr_root Line 96	C
 	[External Code]	

It doesn't look like the problem lies in sqlite3. I guess test cases running on the 2 threads race in Sqlite.cloneStorageConnection() and gets the same instance. Marco, is this the expected behavior when running xpcshell?

Comment 10

[Marco Bonardo [:mak]]

Since it doesn't happen in sequential mode, I must think this is 2 different xpcshell executables running in parallel. It is strange since they should be acting on different connections and dbs too and we take the mutex from the connection (each xpcshell uses a separate profile folder). So far I don't have a clear idea on how one may end up reusing a section freed by the other one. I will keep thinking about it.
Let me also NI Andrew, who worked more widely on our threading model, and may have better ideas.

Comment 11

[D. Richard Hipp]

I think what is happening is that the sharedDBMutex is being initialized (in mozStorageConnection.cpp) by this line:

      // Properly wrap the database handle's mutex.
      sharedDBMutex.initWithMutex(sqlite3_db_mutex(mDBConn));

The sqlite3_db_mutex() interface returns the mutex that the SQLite database connection mDBConn is using. But then sharedDBMutex continues to be used after mDBConn is closed, and the closing of mDBConn will have deleted the mutex.  So the mutex is being used after it is freed.

Comment 12

[Marco Bonardo [:mak]]

It's possible, but that wouldn't explain why this only happens when tests are run in parallel... unless that parallelism makes the system busier and changes scheduling. That is a possibility.
If that's true, we may be trying to clone a closed connection.

Comment 13

[Marco Bonardo [:mak]]

Just random thoughts. If the stacks in comment 9 are trustable, there must be an AsyncInitializeClone runnable enqueued after an AsyncCloseConnection, but that means we'd have an asyncClose() before an asyncClone(), and if that happens, asyncClone should bail our before dispatching its runnable, cause asyncClose() nullifies mDBConn. It doesn't sound possible.
Hard to proceed from here without some debugging (my build is still ongoing and have other priorities atm, but plan to do some debugging asap). The best approach could probably involve using http://rr-project.org/, provided this is also reproducible on Linux, if normal debugging fails.

That said, off-hand it doesn't look like a problem in Sqlite, and we should not block 3.15.0 upgrade on this.

Comment 14

[Andrew Sutherland [:asuth] (he/him)]

The problem is that Connection::AsyncClone is doing:
  nsCOMPtr<nsIEventTarget> target = clone->getAsyncExecutionTarget();
and getting its own brand new async thread.  This allows the clone to race AsyncClose since they're on 2 different threads instead of being serialized on the source/existing connection's async thread.

It should just be doing `getAsyncExecutionTarget();` on the current instance, not the fresh clone.  The cloned connection is not made visible to the calling code until the runnable completes, so this should not introduce any new races.  Also, the MOZ_ASSERT in the AsyncInitializeClone runnable should be corrected and a comment should be added prior to the nsIEventTarget.  With the corrected assert, I don't think we need to get into complicated C++ test territory that would just be enforcing the same thing.


Impact-wise, it looks like use of asyncClone is limited to places:
* History.cpp's ConcurrentStatementsHolder: http://searchfox.org/mozilla-central/source/toolkit/components/places/History.cpp#1946
* via Sqlite.jsm's cloneStorageConnection: http://searchfox.org/mozilla-central/source/toolkit/modules/Sqlite.jsm#1023
  * http://searchfox.org/mozilla-central/source/toolkit/components/places/PlacesUtils.jsm#2106
  * http://searchfox.org/mozilla-central/source/toolkit/components/places/UnifiedComplete.js#1871

Since Places is singleton-y rather than something that has its lifecycle controlled by web content, it seems likely this shouldn't be happening in the wild too much, but seems super likely in unit tests, especially under load with the parallel execution.

Comment 15

[Marco Bonardo [:mak]]

Ah, good find, that makes completely sense, I didn't see that call on 2 different thread, that was the only possible explanation. I'll take this.

Comment 16

[Marco Bonardo [:mak]]

Attachment: Bug 1310152 - AsyncClone may try to reuse a freed Critical Section in Sqlite.

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

Comment 17

[Marco Bonardo [:mak]]

I think the original reason for using the clone thread, was to allow calling asyncClone from a non-async connection without forcing it to use asyncClose(). That was likely to simplify the conversion of existing consumers. Indeed one of the tests was exactly doing that.
In reality the only thing currently using this API is Sqlite.jsm, that always uses async connections, so it was probably over-engineered.

Comment 18

[Andrew Sutherland [:asuth] (he/him)]

Comment on attachment 8807166 [details]
Bug 1310152 - AsyncClone may try to reuse a freed Critical Section in Sqlite.

https://reviewboard.mozilla.org/r/90432/#review90132

Looks good!

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ef6bdef5db2c
AsyncClone may try to reuse a freed Critical Section in Sqlite. r=asuth

Comment 20

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

https://hg.mozilla.org/mozilla-central/rev/ef6bdef5db2c