1071360 - Intermittent 914521.html | Exited with code -11 during test run (after Assertion failure: !mAsyncExecutionThread (AsyncClose has not been invoked on this connection!), at mozStorageConnection.cpp:491

Status: RESOLVED FIXED

(Core :: SQLite and Embedded Database Bindings, defect)

Description

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

https://tbpl.mozilla.org/php/getParsedLog.php?id=48602887&tree=Mozilla-Inbound
Rev5 MacOSX Mountain Lion 10.8 mozilla-inbound debug test crashtest on 2014-09-22 11:48:17 PDT for push caadbd3acebf

slave: talos-mtnlion-r5-006



11:59:41     INFO -  ++DOMWINDOW == 132 (0x12063cc00) [pid = 1582] [serial = 1007] [outer = 0x0]
11:59:41     INFO -  ++DOMWINDOW == 133 (0x12076ec00) [pid = 1582] [serial = 1008] [outer = 0x12063cc00]
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  ++DOCSHELL 0x11e078000 == 9 [pid = 1582] [id = 63]
11:59:41     INFO -  ++DOMWINDOW == 134 (0x120e37c00) [pid = 1582] [serial = 1009] [outer = 0x0]
11:59:41     INFO -  ++DOCSHELL 0x11e079000 == 10 [pid = 1582] [id = 64]
11:59:41     INFO -  ++DOMWINDOW == 135 (0x120e38400) [pid = 1582] [serial = 1010] [outer = 0x0]
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  JavaScript strict warning: , line 0: TypeError: setting a property that has only a getter
11:59:41     INFO -  [1582] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/slave/m-in-osx64-d-00000000000000000/build/content/base/src/nsFrameLoader.cpp, line 287
11:59:41     INFO -  ++DOCSHELL 0x11ed17800 == 11 [pid = 1582] [id = 65]
11:59:41     INFO -  ++DOMWINDOW == 136 (0x120fb3800) [pid = 1582] [serial = 1011] [outer = 0x0]
11:59:41     INFO -  [1582] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/slave/m-in-osx64-d-00000000000000000/build/content/base/src/nsFrameLoader.cpp, line 287
11:59:41     INFO -  ++DOMWINDOW == 137 (0x121e28400) [pid = 1582] [serial = 1012] [outer = 0x120fb3800]
11:59:41     INFO -  [1582] WARNING: NS_ENSURE_TRUE(nsContentUtils::GetCurrentJSContext()) failed: file /builds/slave/m-in-osx64-d-00000000000000000/build/docshell/base/nsDocShell.cpp, line 9009
11:59:41     INFO -  [1582] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file /builds/slave/m-in-osx64-d-00000000000000000/build/content/html/document/src/nsHTMLContentSink.cpp, line 741
11:59:41     INFO -  [1582] WARNING: Subdocument container has no frame: file /builds/slave/m-in-osx64-d-00000000000000000/build/layout/base/nsDocumentViewer.cpp, line 2515
11:59:41     INFO -  ++DOMWINDOW == 138 (0x11d914000) [pid = 1582] [serial = 1013] [outer = 0x120e37c00]
11:59:41     INFO -  [1582] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file /builds/slave/m-in-osx64-d-00000000000000000/build/content/html/document/src/nsHTMLContentSink.cpp, line 741
11:59:41     INFO -  [1582] WARNING: Subdocument container has no frame: file /builds/slave/m-in-osx64-d-00000000000000000/build/layout/base/nsDocumentViewer.cpp, line 2515
11:59:41     INFO -  ++DOMWINDOW == 139 (0x121fc1800) [pid = 1582] [serial = 1014] [outer = 0x120e38400]
11:59:41     INFO -  ++DOMWINDOW == 140 (0x121fc3400) [pid = 1582] [serial = 1015] [outer = 0x120fb3800]
11:59:41     INFO -  ++DOMWINDOW == 141 (0x11adea400) [pid = 1582] [serial = 1016] [outer = 0x120fb3800]
11:59:41     INFO -  [1582] WARNING: NS_ENSURE_TRUE(mMutable) failed: file /builds/slave/m-in-osx64-d-00000000000000000/build/netwerk/base/src/nsSimpleURI.cpp, line 265
11:59:41     INFO -  OpenGL version detected: 210
11:59:41     INFO -  OpenGL vendor: Intel Inc.
11:59:41     INFO -  OpenGL renderer: Intel HD Graphics 3000 OpenGL Engine
11:59:41     INFO -  [1582] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/slave/m-in-osx64-d-00000000000000000/build/dom/events/ContentEventHandler.cpp, line 110
11:59:41     INFO -  [1582] WARNING: no buffer: 'mDTBuffer', file /builds/slave/m-in-osx64-d-00000000000000000/build/gfx/layers/RotatedBuffer.cpp, line 351
11:59:41     INFO -  --DOCSHELL 0x1143a6800 == 10 [pid = 1582] [id = 60]
11:59:41     INFO -  --DOCSHELL 0x1143b2000 == 9 [pid = 1582] [id = 61]
11:59:41     INFO -  JavaScript error: resource://gre/components/nsHandlerService.js, line 391: NS_ERROR_FILE_NOT_FOUND: Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIRDFRemoteDataSource.Flush]
11:59:41     INFO -  JavaScript error: resource://gre/components/nsHandlerService.js, line 391: NS_ERROR_FILE_NOT_FOUND: Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIRDFRemoteDataSource.Flush]
11:59:41     INFO -  Assertion failure: !mAsyncExecutionThread (AsyncClose has not been invoked on this connection!), at /builds/slave/m-in-osx64-d-00000000000000000/build/storage/src/mozStorageConnection.cpp:491
11:59:41     INFO -  nsTArray_Impl<nsRefPtr<mozilla::storage::Connection>, nsTArrayInfallibleAllocator>::RemoveElementsAt(unsigned long, unsigned long) [xpcom/glue/nsTArray.h:1672]
11:59:41     INFO -  mozilla::storage::Service::unregisterConnection(mozilla::storage::Connection*) [xpcom/glue/Mutex.h:169]
11:59:41     INFO -  mozilla::storage::Connection::Release() [storage/src/mozStorageConnection.cpp:524]
11:59:41     INFO -  nsProxyReleaseEvent::Run() [xpcom/glue/nsProxyRelease.cpp:18]
11:59:41     INFO -  nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:823]
11:59:41     INFO -  NS_ProcessPendingEvents(nsIThread*, unsigned int) [xpcom/glue/nsThreadUtils.cpp:207]
11:59:41     INFO -  nsBaseAppShell::NativeEventCallback() [widget/xpwidgets/nsBaseAppShell.cpp:99]
11:59:41     INFO -  nsAppShell::ProcessGeckoEvents(void*) [widget/cocoa/nsAppShell.mm:375]
11:59:41     INFO -  CoreFoundation + 0x12841
11:59:41     INFO -  CoreFoundation + 0x1222d
11:59:41     INFO -  CoreFoundation + 0x354e5
11:59:41     INFO -  CoreFoundation + 0x34dd2
11:59:41     INFO -  HIToolbox + 0x5f774
11:59:41     INFO -  HIToolbox + 0x5f512
11:59:41     INFO -  HIToolbox + 0x5f3a3
11:59:41     INFO -  AppKit + 0x156fa3
11:59:41     INFO -  -AppKit + 0x156862
11:59:41     INFO -  -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] [widget/cocoa/nsAppShell.mm:129]
11:59:41     INFO -  -AppKit + 0x14dc03
11:59:41     INFO -  nsAppShell::Run() [xpcom/glue/nsCOMPtr.h:643]
11:59:41     INFO -  nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:280]
11:59:41     INFO -  XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:4159]
11:59:41     INFO -  XREMain::XRE_main(int, char**, nsXREAppData const*) [toolkit/xre/nsAppRunner.cpp:4230]
11:59:41     INFO -  XRE_main [toolkit/xre/nsAppRunner.cpp:4444]
11:59:41     INFO -  main [browser/app/nsBrowserApp.cpp:282]
11:59:41     INFO -  ** Unknown exception behavior: 0
11:59:45     INFO -  TEST-INFO | Main app process: killed by out-of-range signal, number 117
11:59:45  WARNING -  TEST-UNEXPECTED-FAIL | file:///builds/slave/talos-slave/test/build/tests/reftest/tests/docshell/base/crashtests/914521.html | Exited with code -11 during test run
11:59:45     INFO -  INFO | automation.py | Application ran for: 0:01:50.935583
11:59:45     INFO -  Automation Error: PID log not found: /var/folders/sh/x3_cwy_x189_cj3v8yxlp9m000000w/T/tmpeXdqo4pidlog
11:59:45     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
11:59:45     INFO -  REFTEST INFO | runreftest.py | Running tests: end.
11:59:46    ERROR - Return code: 1

Comment 1

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-01T00:52:43
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-inbound&job_id=2675884
repository: mozilla-inbound
who: tomcat[at]mozilla[dot]com
machine: t-w864-ix-015
buildname: WINNT 6.2 mozilla-inbound debug test xpcshell
revision: 6122db43cad3

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: -2147483645), see following log:
Assertion failure: !mAsyncExecutionThread (AsyncClose has not been invoked on this connection!), at c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStorageConnection.cpp:491
PROCESS-CRASH | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | application crashed [@ mozilla::storage::Connection::~Connection()]
Return code: 1

Comment 2

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-05T08:33:52
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-central&job_id=450227
repository: mozilla-central
who: philringnalda[at]gmail[dot]com
machine: t-w864-ix-079
buildname: WINNT 6.2 mozilla-central debug test xpcshell
revision: 4b3d816c21fd

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: -2147483645), see following log:
Assertion failure: !mAsyncExecutionThread (AsyncClose has not been invoked on this connection!), at c:/builds/moz2_slave/m-cen-w32-d-000000000000000000/build/storage/src/mozStorageConnection.cpp:491
PROCESS-CRASH | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | application crashed [@ mozilla::storage::Connection::~Connection()]
Return code: 1

Comment 3

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-09T09:45:50
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-inbound&job_id=2891125
repository: mozilla-inbound
who: rvandermeulen[at]mozilla[dot]com
machine: t-w864-ix-057
buildname: WINNT 6.2 mozilla-inbound debug test xpcshell
revision: d3e3fc74801b

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 1), see following log:
Assertion failure: !mAsyncExecutionThread (AsyncClose has not been invoked on this connection!), at c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStorageConnection.cpp:491
PROCESS-CRASH | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | application crashed [@ mozilla::storage::Connection::~Connection()]
Return code: 1

Comment 4

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-16T06:31:50
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-inbound&job_id=3035838
repository: mozilla-inbound
who: rvandermeulen[at]mozilla[dot]com
machine: talos-mtnlion-r5-079
buildname: Rev5 MacOSX Mountain Lion 10.8 mozilla-inbound debug test xpcshell
revision: 5ce2fc3939da

TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/components/places/tests/unit/test_null_interfaces.js | test failed (with xpcshell return code: 1), see following log:
Assertion failure: !mAsyncExecutionThread (AsyncClose has not been invoked on this connection!), at /builds/slave/m-in-osx64-d-00000000000000000/build/storage/src/mozStorageConnection.cpp:491
PROCESS-CRASH | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/toolkit/components/places/tests/unit/test_null_interfaces.js | application crashed [@ mozilla::storage::Connection::~Connection()]
Return code: 1

Comment 5

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-20T06:35:46
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-aurora&job_id=333300
repository: mozilla-aurora
who: rvandermeulen[at]mozilla[dot]com
machine: t-w864-ix-052
buildname: WINNT 6.2 mozilla-aurora debug test xpcshell
revision: ed68a14922fe

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | test failed (with xpcshell return code: 1), see following log:
Assertion failure: !mAsyncExecutionThread (AsyncClose has not been invoked on this connection!), at c:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/storage/src/mozStorageConnection.cpp:491
PROCESS-CRASH | C:\slave\test\build\tests\xpcshell\tests\services\healthreport\tests\xpcshell\test_healthreporter.js | application crashed [@ mozilla::storage::Connection::~Connection()]
Return code: 1

Comment 6

[Ben Turner (not reading bugmail, use the needinfo flag!)]

This is a storage bug.

Comment 7

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Attachment: Patch, v1

I need this to land bug 866846 and its siblings.

Comment 8

[Ben Turner (not reading bugmail, use the needinfo flag!)]

The problem is that AsyncOpen doesn't handle failure correctly. It notifies the caller but doesn't properly shut down the half-opened connection that it created.

Comment 9

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

Comment on attachment 8585314 [details] [diff] [review]
Patch, v1

Hm, yes, it does seem like it would be hard for the caller to clean-up the object properly without a reference to it.

Good eye finding this.

Comment 10

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

Huh, but your try build at https://treeherder.mozilla.org/#/jobs?repo=try&revision=0e2144a7057a with this patch still resulted in the same failure on dt4.  This patch still seems correct, but it's probably best if I don't try and helpfully land this for you since I'm about to turn into a pumpkin.

Comment 11

[Marco Bonardo [:mak]]

Is it possible your closeRunnable ends up running after we reach the assertion point?
Maybe you could try using NS_DISPATCH_SYNC. Or, since you are already on the async thread, directly create an AsyncCloseConnection object, .forget() the execution thread to it, an invoke its Run(). The only difference will be we don't call SetClosedState, but that's not critical since this connection won't work.

Comment 12

[Marco Bonardo [:mak]]

this is provided you verified the problem is with Sqlite.jsm (currently the only consumer of openAsyncDatabase), cause, as Andrew said, any connection using an async statement must invoke asyncClose, also synchronous ones.
Is this failure reproducible locally?

Comment 13

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Attachment: Patch, v1.1

Slightly improved. Depending on where in initializeInternal we fail sometimes mDBConn is null and sometimes it's not. (Aside: This seems kinda dumb...)

Comment 14

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to Marco Bonardo [::mak] from comment #11)
> Is it possible your closeRunnable ends up running after we reach the
> assertion point?

No, the assertion is in the destructor, and we're holding references throughout this whole async close sequence. It's just that sometimes mDBConn is nulled out in initializeInternal, and that caused a short-circuit return in AsyncClose.

Comment 15

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to Marco Bonardo [::mak] from comment #12)
> this is provided you verified the problem is with Sqlite.jsm (currently the
> only consumer of openAsyncDatabase)

Yeah, this test uses SQLite.jsm via StorageActors (http://mxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/storage.js)

Comment 16

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

Comment on attachment 8585543 [details] [diff] [review]
Patch, v1.1

(In reply to Ben Turner <unresponsive until 3/30> (use the needinfo flag!) from comment #13)
> (Aside: This seems kinda dumb...)

Yeah, the mozStorage state machine is too complex leading to a variety of edge-cases like this.  Which are eventually caught this way.  It would be great if there were engineering resources to engage in a more protracted cleanup, but most changes to mozStorage are incidental/fires being put out.  Maybe someone has an intern soon? :)

Comment 17

[Ben Turner (not reading bugmail, use the needinfo flag!)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d4fdf509f242

Comment 18

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

Backed out for frequent bc1 oranges
https://treeherder.mozilla.org/logviewer.html#?job_id=8256324&repo=mozilla-inbound

https://hg.mozilla.org/integration/mozilla-inbound/rev/93bab937c624

Comment 19

[Ben Turner (not reading bugmail, use the needinfo flag!)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ce2692d64bcf

Comment 20

[Ryan VanderMeulen [:RyanVM]]

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

Comment 21

[Ryan VanderMeulen [:RyanVM]]

Can we nominate this for Aurora/Beta as well?

Comment 22

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 8585543 [details] [diff] [review]
Patch, v1.1

Approval Request Comment
[Feature/regressing bug #]: Unclear, probably a very old bug
[User impact if declined]: In rare circumstances connections will keep their threads alive until app shutdown, and DEBUG builds will assert.
[Describe test coverage new/current, TreeHerder]: The assertion failure is hit on tinderbox
[Risks and why]: This seems like a pretty safe patch, especially since it handles a condition that is only rarely hit.
[String/UUID change made/needed]: None

Comment 23

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 8585543 [details] [diff] [review]
Patch, v1.1

Actually I don't know that it's worth the (small) risk for beta... Ryan, maybe you could clarify whether or not this is a big pain point for sheriffs?

Comment 24

[Ryan VanderMeulen [:RyanVM]]

I'm fine deferring to your judgment on that. Just trying to get 38 as solid as possible since we've got it for the next year.

Comment 25

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Andrew, what do you think about the safety of this for beta?

Comment 26

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

I think this is safe for uplift.

Rationale:
- Because the connection was never reported to the caller, the permutation-space for things that can happen and interact and reorder is extremely constrained.  The one edge-case expected was the one in comment 13 and this patch explicitly caught that.  (We've had other changes that can result in things bouncing around threads different for release.  Though they have generally been safe/an improvement, this patch has none of that.)
- It wouldn't be surprising for use of Sqlite.jsm to pick up in extensions, so it wouldn't be surprising for the number of impacted users to increase over time.

Comment 27

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Ok, thanks!

Comment 28

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8585543 [details] [diff] [review]
Patch, v1.1

should be in 38 beta 2

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/6de4a352d5f2

Comment 30

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/0e9a4f42d12a