windows debug unit tests: test_connection_executeAsync.js and test_statement_executeAsync.js failing frequently (fatal assertion)

RESOLVED FIXED in mozilla1.9.3a1

Status

()

RESOLVED FIXED
9 years ago
6 years ago

People

(Reporter: dbaron, Assigned: sdwilsh)

Tracking

({intermittent-failure})

Trunk
mozilla1.9.3a1
x86
Windows Server 2003
intermittent-failure
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(status1.9.2 beta5-fixed)

Details

Attachments

(1 attachment, 3 obsolete attachments)

A very frequent (as in, possibly too frequent to enable the builds) random orange on the Windows debug everythingelse is:

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256837459.1256841719.26784.gz
WINNT 5.2 mozilla-central test debug everythingelse on 2009/10/29 10:30:59  
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_connection_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
###!!! ASSERTION: sqlite3_close failed. There are probably outstanding statements that are listed above!: 'srv == SQLITE_OK', file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 523

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256830304.1256834457.5855.gz
WINNT 5.2 mozilla-central test debug everythingelse on 2009/10/29 08:31:44  
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_connection_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
WARNING: NS_ENSURE_TRUE(mThread != PR_GetCurrentThread()) failed: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/xpcom/threads/nsThread.cpp, line 440
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
###!!! ASSERTION: sqlite3_close failed. There are probably outstanding statements that are listed above!: 'srv == SQLITE_OK', file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 523


http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1256827051.1256832725.16725.gz
WINNT 5.2 mozilla-central test debug everythingelse on 2009/10/29 07:37:31  
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_connection_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
WARNING: NS_ENSURE_TRUE(mThread != PR_GetCurrentThread()) failed: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/xpcom/threads/nsThread.cpp, line 440
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510
WARNING: SQL statement 'INSERT INTO test (id, string, number, nuller, blober) VALUES (:int, :text, :real, :null, :blob)' was not finalized: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 510

###!!! ASSERTION: sqlite3_close failed. There are probably outstanding statements that are listed above!: 'srv == SQLITE_OK', file e:/builds/moz2_slave/mozilla-central-win32-debug/build/storage/src/mozStorageConnection.cpp, line 523
(Assignee)

Comment 1

9 years ago
I'm betting these are the cached async statements from http://mxr.mozilla.org/mozilla-central/source/storage/test/unit/test_connection_executeAsync.js#164.  Not sure why they aren't being finalized though...
(Assignee)

Comment 2

9 years ago
I'd also love to know what WARNING: NS_ENSURE_TRUE(mThread != PR_GetCurrentThread()) failed: file e:/builds/moz2_slave/mozilla-central-win32-debug/build/xpcom/threads/nsThread.cpp, line 440 is from.  That happens right before my warnings.  Maybe we can add some debugging code there to get a stack?
Do you think we can change these sqlite assertions such that they trigger Breakpad, getting us an actual stack when they happen on debug unittests?
(See bug 524522 for the JS_ASSERT equivalent.)
This is just the standard NS_ASSERTION, but xpcshell tests are run with fatal assertions.
(Assignee)

Comment 5

9 years ago
This is actually a storage error - I just use NS_ERROR.  Do we have a macro that magically triggers breakpad?

I would love to see the stack in the error from comment 2 though.  I suspect that that may be related to the failure.
Ah, sorry. I think we get screwed by our stackwalking code here because the PDB files aren't where it expects them to be, since we're running from a packaged build. They are available though, in the symbols package (although they're compressed, but symsrv.dll knows how to deal with that as long as you give it a directory to use as a downstream store.)
(In reply to comment #6)
> Ah, sorry. I think we get screwed by our stackwalking code here because the PDB
> files aren't where it expects them to be, since we're running from a packaged
> build. They are available though, in the symbols package (although they're
> compressed, but symsrv.dll knows how to deal with that as long as you give it a
> directory to use as a downstream store.)

So, whats the next step here?

We're having to run unittests both ways until this is fixed, and the extra load is hurting wait times.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257533106.1257537408.23678.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/06 10:45:06
Blocks: 438871
Whiteboard: [orange]
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257704856.1257708862.14528.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/08 10:27:36
Now that we got build hiddenness sorted out, I decided to enable the build anyway, so this will probably be the most common random orange (or maybe second, behind the places test failures) until it's fixed.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257711194.1257715348.21867.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/08 12:13:14
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257711805.1257719485.1412.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/08 12:23:25
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257720058.1257725205.30622.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/08 14:40:58
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257804320.1257808970.32313.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/09 14:05:20
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257809907.1257814934.2245.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/09 15:38:27
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257791949.1257796777.25228.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/09 10:39:09
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257830788.1257836109.16111.gz#err0
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/09 21:26:28
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257875780.1257880442.12448.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/10 09:56:20
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257873050.1257879310.31228.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/10 09:10:50
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257870980.1257877644.13491.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/10 08:36:20
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257968262.1257973297.30961.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/11 11:37:42
"s: moz2-win32-slave38"
Btw, I filed bug 528019 on the failure in "test_statement_executeAsync.js" in that last log.  (Looks similar to this bug's failure, but it's in a different test, and I didn't see it mentioned here explicitly, so I figured it merited a different bug.)

I see now that some (but not all) of the earlier logs here have that failure as well -- I'll note those on the other bug.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258027033.1258031970.11637.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/12 03:57:13
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258060851.1258067808.2381.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/12 13:20:51
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258081555.1258086853.21997.gz#err1
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/12 19:05:55
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258070062.1258077904.19636.gz#err6
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/12 15:54:22
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258119658.1258125323.7599.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/13 05:40:58  
"s: moz2-win32-slave32"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258132314.1258139882.16485.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/13 09:11:54
"s: moz2-win32-slave19"
(Assignee)

Updated

9 years ago
Duplicate of this bug: 528019
(Assignee)

Updated

9 years ago
Summary: windows debug unit tests: test_storage\unit\test_connection_executeAsync.js failing frequently (fatal assertion) → windows debug unit tests: test_connection_executeAsync.js and test_statement_executeAsync.js failing frequently (fatal assertion)
(Assignee)

Comment 33

9 years ago
(In reply to comment #0)
> WARNING: NS_ENSURE_TRUE(mThread != PR_GetCurrentThread()) failed: file
> e:/builds/moz2_slave/mozilla-central-win32-debug/build/xpcom/threads/nsThread.cpp,
> line 440
So, this is the problem, and this is why the bug is happening.  The only way this could happen is if the connection's last reference was freed on the async thread, and then we call close, which calls Shutdown.  Doing more investigation now.
(Assignee)

Comment 34

9 years ago
So, AsyncStatementFinalizer (in mozStorageStatement.cpp) should really be holding onto (strong reference) the Connection that creates it.  However, that means the last reference to the connection would still be on the async thread, so we'd still hit some of this (the Shutdown call would fail).  However, I'm not sure we should care if that Shutdown call fails, since it'll shutdown anyway when the thread is released for the last time (I think - need to verify that.  Do not want it hanging around until xpcom-shutdown-threads).
(Assignee)

Comment 35

9 years ago
Also, this is a really subtle thread-safety bug.  I'm glad we caught this :)

This would result in a leaked connection in non-debug builds (sqlite3 object, not mozilla::storage::Connection).
(Assignee)

Comment 36

9 years ago
Confirmed that not shutting down will keep the thread alive.  Need to proxy the release, which is all sorts of sadfaces.
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258209183.1258216167.31854.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/14 06:33:03
"s: moz2-win32-slave22"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258248780.1258254353.1512.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/14 17:33:00  
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_statement_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258258769.1258264312.12608.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/14 20:19:29
"s: moz2-win32-slave37"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258295298.1258302436.6167.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/15 06:28:18
"s: moz2-win32-slave18"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258302997.1258308188.8545.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/15 08:36:37
"s: moz2-win32-slave16"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258313427.1258318393.27224.gz
Linux mozilla-central debug test everythingelse on 2009/11/15 11:30:27
s: moz2-linux-slave18

Comment 46

9 years ago
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258383331.1258390032.17057.gz
WINNT 5.2 mozilla-central debug test everythingelse
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258462064.1258469113.8433.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/17 04:47:44  
"s: moz2-win32-slave28"
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_connection_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_statement_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258459314.1258466689.12839.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/17 04:01:54
"s: moz2-win32-slave07"
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_connection_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_statement_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258485475.1258492471.16862.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/17 11:17:55
"s: moz2-win32-slave01"
(Assignee)

Updated

9 years ago
Assignee: nobody → sdwilsh
(Assignee)

Comment 56

9 years ago
Created attachment 413094 [details] [diff] [review]
v1.0
Attachment #413094 - Flags: review?(bugmail)
(Assignee)

Updated

9 years ago
Whiteboard: [orange] → [orange][needs review asuth]
Attachment #413094 - Flags: review?(bugmail) → review+
(Assignee)

Updated

9 years ago
Whiteboard: [orange][needs review asuth] → [orange][can land]
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258643242.1258648613.24170.gz
Linux mozilla-central debug test everythingelse on 2009/11/19 07:07:22  
s: moz2-linux-slave19
TEST-UNEXPECTED-FAIL | /builds/moz2_slave/mozilla-central-linux-debug-unittest-everythingelse/build/xpcshell/tests/test_storage/unit/test_connection_executeAsync.js | test failed (with xpcshell return code: 1), see following log:
TEST-UNEXPECTED-FAIL | /builds/moz2_slave/mozilla-central-linux-debug-unittest-everythingelse/build/xpcshell/tests/test_storage/unit/test_connection_executeAsync.js | application crashed (minidump found)

 2  libnspr4.so!PR_Abort [prlog.c:24ddb9b3d3ed : 548 + 0x4]
    eip = 0x00ae5605   esp = 0xb5dcecb0   ebp = 0xb5dcecb8
    Found by: previous frame's frame pointer
 3  libxul.so!_ZL5AbortPKc [nsDebugImpl.cpp:24ddb9b3d3ed : 370 + 0x4]
    eip = 0x0207ff54   esp = 0xb5dcecc0   ebp = 0xb5dcecc8
    Found by: previous frame's frame pointer
 4  libxul.so!NS_DebugBreak_P [nsDebugImpl.cpp:24ddb9b3d3ed : 350 + 0xd]
    eip = 0x02080564   esp = 0xb5dcecd0   ebp = 0xb5dcf0f8
    Found by: previous frame's frame pointer
 5  libxul.so!mozilla::storage::Connection::Close() [mozStorageConnection.cpp:24ddb9b3d3ed : 522 + 0x37]
    eip = 0x01ddc8f8   esp = 0xb5dcf100   ebp = 0xb5dcf1b8
    Found by: previous frame's frame pointer
...
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258642928.1258649496.1741.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/19 07:02:08  
"s: moz2-win32-slave34"
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_connection_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
I landed this (despite the freeze) as part of an effort to get the tree green enough again that people won't just ignore the orange:

http://hg.mozilla.org/mozilla-central/rev/4a0bf3ffd767


(Was this something you wanted to try to get on 1.9.2?)
Status: NEW → RESOLVED
Last Resolved: 9 years ago
Resolution: --- → FIXED
Whiteboard: [orange][can land] → [orange]
(Assignee)

Comment 61

9 years ago
So, the log is rather interesting:
Thread 6 (crashed)
 0  libxul.so!NS_ProxyRelease(nsIEventTarget*, nsISupports*, int) [nsProxyRelease.cpp : 75 + 0x8]
    eip = 0x0165d53d   esp = 0xb36ff280   ebp = 0xb36ff2b8   ebx = 0x019e150c
    esi = 0xb374d140   edi = 0x00000000   eax = 0x00000028   ecx = 0xb36ffc00
    edx = 0x0168b93b   efl = 0x00010246
    Found by: given as instruction pointer in context
 1  libxul.so!mozilla::storage::(anonymous namespace)::AsyncStatementFinalizer::Run() [nsProxyRelease.h : 61 + 0x8]
    eip = 0x01557315   esp = 0xb36ff2c0   ebp = 0xb36ff2d8
    Found by: previous frame's frame pointer
 2  libxul.so!nsThread::ProcessNextEvent(int, int*) [nsThread.cpp:c6991463f32a : 527 + 0xa]
    eip = 0x0168b842   esp = 0xb36ff2e0   ebp = 0xb36ff318
    Found by: previous frame's frame pointer
 3  libxul.so!NS_ProcessNextEvent_P(nsIThread*, int) [nsThreadUtils.cpp : 250 + 0xd]
    eip = 0x0165bd18   esp = 0xb36ff320   ebp = 0xb36ff348
    Found by: previous frame's frame pointer
 4  libxul.so!nsThread::ThreadFunc(void*) [nsThread.cpp:c6991463f32a : 253 + 0x9]
    eip = 0x0168bf8f   esp = 0xb36ff350   ebp = 0xb36ff388
    Found by: previous frame's frame pointer
 5  libnspr4.so!_pt_root [ptthread.c:c6991463f32a : 228 + 0x8]
    eip = 0x0013eec1   esp = 0xb36ff390   ebp = 0xb36ff3b8
    Found by: previous frame's frame pointer
 6  libpthread-2.5.so + 0x52da
    eip = 0x00c042db   esp = 0xb36ff3c0   ebp = 0xb36ff4a8
    Found by: previous frame's frame pointer

This means that it crashed in NS_RELEASE, which means the object was already free'd I guess.  This also implies that the thread that called finalize here is the background thread.  I cannot explain the double free, but I can explain how we end up being called on the background thread.  mozilla::storage::AsyncExecuteStatements::mStatements is an array of StatementData objects, each of which holds a reference to its owning mozilla::storage::Statement object.  If this is the last reference to that Statement, it'll be released on the background thread.  This is fixable, but I'll need the work in bug 496019 to do so.
Actually, that explains the double release too, since we unconditionally call Finalize in ~Statement.  Fix forthcoming.
Status: REOPENED → ASSIGNED
Depends on: 496019
(Assignee)

Comment 62

9 years ago
Created attachment 413450 [details] [diff] [review]
v2.0

Only a small difference here.  Hold onto the connection instead of the statement, and proxy to the connections opened thread to be sure.
Attachment #413094 - Attachment is obsolete: true
Attachment #413450 - Flags: review?(bugmail)
Comment on attachment 413450 [details] [diff] [review]
v2.0

It is safe to hand out a reference to the Connection because the Statement holds a reference to the Connection until its death, a death which cannot possibly occur until after Finalize returns.  This means that the refcount of Connection is >= 1 at the time we are adding a new reference to it and everything is safe.
Attachment #413450 - Flags: review?(bugmail) → review+
Hm, I think bugzilla has a new bug, as I'm pretty sure I pasted in a lot more than that last comment.  What I really wrote:

If I understand the rationale correctly, the idea is that Finalize is called during the destructor, so Finalize is not allowed to go around creating new references to the Statement.  This is why you are changing the patch to hold a reference to the Connection instead of the Statement.

It is safe to hand out a reference to the Connection because the Statement holds a reference to the Connection until its death, a death which cannot possibly occur until after Finalize returns.  This means that the refcount of Connection is >= 1 at the time we are adding a new reference to it and everything is safe.

We don't actually need a reference to the Connection saved in the finalizer, we just need something to proxy the release of the Connection reference to the main thread in the event we are on the async thread in case there is incorrect storage-using code at work.

Correct storage-using code would have manually finalized each statement and issued a call to asyncClose.  AsyncCloseConnection holds onto a copy of the Connection and dispatch itself to the main thread.  Since it ends up being the last piece of code being run on the async thread, there is also no chance of any other code trying to destroy the Connection on the async thread.

In the incorrect case, the dependence of the code on the statement finalizer to proxy the release raises an edge-case flag, since it's possible for bad code to call Finalize on that statement but not call asyncClose on the Statement.  Happily, in that case the AsyncStatementFinalizer must already be in the async thread's queue with a Connection reference and will still ensure that the proxy release happens when it runs.


It would be great if you could add some comments to the code about why we pass a reference to the Connection and why we must proxy its release; it's not particularly obvious.  At the minimum you should make the doxygen you are adding for the AsyncStatementFinalizer be correct.  ("@param aParent" is from the last iteration of the patch.)

PS: shouldn't threadOpenedOn be mThreadOpenedOn?
I was going to test attachment 413450 [details] [diff] [review], but it doesn't seem to apply on top of current mozilla-central.
You need https://bugzilla.mozilla.org/attachment.cgi?id=413085 from bug 496019 which this bug has been marked as depending on.
(In reply to comment #64)
> PS: shouldn't threadOpenedOn be mThreadOpenedOn?

Whoops, had missed that it was public.  Forget this point.
(Assignee)

Comment 68

9 years ago
Created attachment 413716 [details] [diff] [review]
v2.1

Updated per review comments.
Attachment #413450 - Attachment is obsolete: true
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258754362.1258759684.5620.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/20 13:59:22
"s: moz2-win32-slave35"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258772195.1258778892.21591.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/20 18:56:35
"s: moz2-win32-slave14"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258801904.1258807855.15341.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/21 03:11:44
"s: moz2-win32-slave16"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258921236.1258927942.10440.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/22 12:20:36
"s: moz2-win32-slave34"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1258991815.1258997565.15960.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/23 07:56:55
"s: moz2-win32-slave35"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259027894.1259035484.24432.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/23 17:58:14
"s: moz2-win32-slave25"

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259037109.1259042496.6635.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/23 20:31:49
"s: moz2-win32-slave30"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259039101.1259044408.27475.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/23 21:05:01  
"s: moz2-win32-slave15"
TEST-UNEXPECTED-FAIL | e:\builds\moz2_slave\mozilla-central-win32-debug-unittest-everythingelse\build\xpcshell\tests\test_storage\unit\test_statement_executeAsync.js | test failed (with xpcshell return code: 3), see following log:
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259082175.1259087400.6650.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/24 09:02:55
"s: moz2-win32-slave40"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259105905.1259113760.15775.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/24 15:38:25
"s: moz2-win32-slave41"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259136455.1259141974.6385.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/25 00:07:35  
"s: moz2-win32-slave38"

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259130697.1259136830.13874.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/24 22:31:37
"s: moz2-win32-slave35"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259190792.1259197152.30368.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/11/25 15:13:12
"s: moz2-win32-slave31"
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259668507.1259673927.16758.gz&fulltext=1
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/01 03:55:07
(Assignee)

Comment 88

9 years ago
I hope to land this later today.  I'll check with drivers for an exception to the freeze due to the orangeness of this bug.
(Assignee)

Comment 89

9 years ago
http://hg.mozilla.org/mozilla-central/rev/a93d705bb969
Status: ASSIGNED → RESOLVED
Last Resolved: 9 years ago9 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla1.9.3a1
(Assignee)

Comment 90

9 years ago
Created attachment 415471 [details] [diff] [review]
v2.1

Asking for review for a bit of a sanity check to make sure this still makes sense without the other changes.  I'm pretty sure it does, but an extra pair of eyes is always good.
Attachment #415471 - Flags: review?(bugmail)
Comment on attachment 415471 [details] [diff] [review]
v2.1

I understand the scope of this bug to be that sqlite3_close fails in a unit test where the Connection is implicitly closed due to its reference count hitting zero and the closing happening before the async thread has had a chance to process its async statement finalization.

I concur that this patch will fix this by causing the Connection to stay alive until after the statement has been finalized.
Attachment #415471 - Flags: review?(bugmail) → review+
(Assignee)

Comment 92

9 years ago
I do not know how yet, but we were leaking (suspect bug 496019, not this).  Backed out.  We can take the 1.9.2 patch on mozilla-central once it greens up, so we no longer need the dependency.

http://build.mozillamessaging.com/buildbot/production/builders/WINNT%205.2%20comm-central%20bloat/builds/257/steps/shell_23/logs/stdio

http://hg.mozilla.org/mozilla-central/rev/c9b4ceaff189
http://hg.mozilla.org/mozilla-central/rev/1da324b95182
Status: RESOLVED → REOPENED
No longer depends on: 496019
Resolution: FIXED → ---
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259762054.1259767545.18016.gz
WINNT 5.2 mozilla-central debug test everythingelse on 2009/12/02 05:54:14
(Assignee)

Updated

9 years ago
Attachment #413716 - Attachment is obsolete: true
(Assignee)

Updated

9 years ago
Attachment #415471 - Attachment description: v2.1 for 1.9.2 → v2.1
Comment on attachment 415471 [details] [diff] [review]
v2.1

a192=beltzner
Attachment #415471 - Flags: approval1.9.2+
(Assignee)

Comment 95

9 years ago
This should stick better.

http://hg.mozilla.org/mozilla-central/rev/23d7fdb2efb6
Status: REOPENED → RESOLVED
Last Resolved: 9 years ago9 years ago
Resolution: --- → FIXED
(Assignee)

Comment 96

9 years ago
http://hg.mozilla.org/releases/mozilla-1.9.2/rev/948221d7c5c4
status1.9.2: --- → final-fixed
Keywords: intermittent-failure
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.