894042 - Intermittent test_browserGlue_corrupt_nobackup_default.js | test failed (with xpcshell return code: -2147483645) | application crashed [@ mozilla::storage::AsyncExecuteStatements::execute()] (Assertion failure: target)

Status: RESOLVED FIXED

(Toolkit :: Storage, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=25294836&tree=Mozilla-Inbound

Windows XP 32-bit mozilla-inbound debug test xpcshell on 2013-07-15 12:49:49 PDT for push 7ae21b9549d0
slave: t-xp32-ix-008

12:55:23     INFO -  TEST-INFO | C:\slave\test\build\tests\xpcshell\tests\browser\components\places\tests\unit\test_browserGlue_corrupt_nobackup_default.js | running test ...
12:55:24  WARNING -  TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\browser\components\places\tests\unit\test_browserGlue_corrupt_nobackup_default.js | test failed (with xpcshell return code: -2147483645), see following log:
12:55:24     INFO -  >>>>>>>
12:55:24     INFO -  ### XPCOM_MEM_LEAK_LOG defined -- logging leaks to c:\docume~1\cltbld~1.t-x\locals~1\temp\tmphvw_jt\runxpcshelltests_leaks.log
12:55:24     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
12:55:24     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (2)
12:55:24     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/browser/components/places/tests/unit/test_browserGlue_corrupt_nobackup_default.js | [run_test : 56] true == true
12:55:24     INFO -  WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8052000B: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStorageConnection.cpp, line 593
12:55:24     INFO -  WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8052000B: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStorageService.cpp, line 825
12:55:24     INFO -  WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8052000B: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/toolkit/components/places/Database.cpp, line 474
12:55:24     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/browser/components/places/tests/unit/test_browserGlue_corrupt_nobackup_default.js | [run_test : 66] 2 == 2
12:55:24     INFO -  pldhash: for the table at address 037A21A0, the given entrySize of 144 definitely favors chaining over double hashing.
12:55:24     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2)
12:55:24     INFO -  TEST-INFO | (xpcshell/head.js) | running event loop
12:55:24     INFO -  pldhash: for the table at address 03A60060, the given entrySize of 96 definitely favors chaining over double hashing.
12:55:24     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/browser/components/places/tests/unit/test_browserGlue_corrupt_nobackup_default.js | [bookmarksObserver.onEndUpdateBatch : 25] 6 != -1
12:55:24     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/browser/components/places/tests/unit/test_browserGlue_corrupt_nobackup_default.js | [bookmarksObserver.onEndUpdateBatch : 25] 12 != -1
12:55:24     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/browser/components/places/tests/unit/test_browserGlue_corrupt_nobackup_default.js | [continue_test : 76] true == true
12:55:24     INFO -  TEST-PASS | C:/slave/test/build/tests/xpcshell/tests/browser/components/places/tests/unit/test_browserGlue_corrupt_nobackup_default.js | [continue_test : 77] "Getting Started" == "Getting Started"
12:55:24     INFO -  TEST-INFO | (xpcshell/head.js) | test finished (1)
12:55:24     INFO -  TEST-INFO | (xpcshell/head.js) | exiting test
12:55:24     INFO -  Assertion failure: target, at e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStorageAsyncStatementExecution.cpp:190
12:55:24     INFO -  nsStringStats
12:55:24     INFO -   => mAllocCount:           4007
12:55:24     INFO -   => mReallocCount:          372
12:55:24     INFO -   => mFreeCount:            2000  --  LEAKED 2007 !!!
12:55:24     INFO -   => mShareCount:           9865
12:55:24     INFO -   => mAdoptCount:            445
12:55:24     INFO -   => mAdoptFreeCount:        443  --  LEAKED 2 !!!
12:55:24     INFO -  <<<<<<<
12:55:31  WARNING -  PROCESS-CRASH | C:\slave\test\build\tests\xpcshell\tests\browser\components\places\tests\unit\test_browserGlue_corrupt_nobackup_default.js | application crashed [@ mozilla::storage::AsyncExecuteStatements::execute(nsTArray<mozilla::storage::StatementData> &,mozilla::storage::Connection *,mozIStorageStatementCallback *,mozIStoragePendingStatement * *)]
12:55:31     INFO -  Crash dump filename: C:\slave\test\build\tests\xpcshell\tests\browser\components\places\tests\unit\42c8b829-2037-4c70-88d3-f5168eec2607.dmp
12:55:31     INFO -  Operating system: Windows NT
12:55:31     INFO -                    5.1.2600 Service Pack 3
12:55:31     INFO -  CPU: x86
12:55:31     INFO -       GenuineIntel family 6 model 30 stepping 5
12:55:31     INFO -       8 CPUs
12:55:31     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
12:55:31     INFO -  Crash address: 0x112eb37e
12:55:31     INFO -  Thread 0 (crashed)
12:55:31     INFO -   0  xul.dll!mozilla::storage::AsyncExecuteStatements::execute(nsTArray<mozilla::storage::StatementData> &,mozilla::storage::Connection *,mozIStorageStatementCallback *,mozIStoragePendingStatement * *) [mozStorageAsyncStatementExecution.cpp:7ae21b9549d0 : 190 + 0x1b]
12:55:31     INFO -      eip = 0x112eb37e   esp = 0x0012ee18   ebp = 0x0012ee20   ebx = 0x00000000
12:55:31     INFO -      esi = 0x037844d8   edi = 0x00000000   eax = 0x00000000   ecx = 0x58d2c38c
12:55:31     INFO -      edx = 0x00e71f48   efl = 0x00000216
12:55:31     INFO -      Found by: given as instruction pointer in context
12:55:31     INFO -   1  xul.dll!mozilla::storage::StorageBaseStatementInternal::ExecuteAsync(mozIStorageStatementCallback *,mozIStoragePendingStatement * *) [StorageBaseStatementInternal.cpp:7ae21b9549d0 : 188 + 0x12]
12:55:31     INFO -      eip = 0x112e5832   esp = 0x0012ee28   ebp = 0x0012ee58
12:55:31     INFO -      Found by: call frame info
12:55:31     INFO -   2  xul.dll!mozilla::storage::AsyncStatement::ExecuteAsync(mozIStorageStatementCallback *,mozIStoragePendingStatement * *) [mozStorageAsyncStatement.cpp:7ae21b9549d0 : 361 + 0x21]
12:55:31     INFO -      eip = 0x112e860c   esp = 0x0012ee60   ebp = 0x0012ee6c
12:55:31     INFO -      Found by: call frame info
12:55:31     INFO -   3  xul.dll!`anonymous namespace'::AsyncGetBookmarksForURI<void ( nsNavBookmarks::*)(mozilla::places::ItemChangeData const &),mozilla::places::ItemChangeData>::Init() [nsNavBookmarks.cpp:7ae21b9549d0 : 116 + 0x23]
12:55:31     INFO -      eip = 0x11395b43   esp = 0x0012ee74   ebp = 0x0012eea4
12:55:31     INFO -      Found by: call frame info
12:55:31     INFO -   4  xul.dll!nsNavBookmarks::OnPageChanged(nsIURI *,unsigned int,nsAString_internal const &,nsACString_internal const &) [nsNavBookmarks.cpp:7ae21b9549d0 : 2857 + 0xe]
12:55:31     INFO -      eip = 0x11399eb5   esp = 0x0012eeac   ebp = 0x0012efc4
12:55:31     INFO -      Found by: call frame info
12:55:31     INFO -   5  xul.dll!nsNavHistory::SendPageChangedNotification(nsIURI *,unsigned int,nsAString_internal const &,nsACString_internal const &) [nsNavHistory.cpp:7ae21b9549d0 : 4102 + 0x80]
12:55:31     INFO -      eip = 0x11372552   esp = 0x0012efcc   ebp = 0x0012eff0
12:55:31     INFO -      Found by: call frame info
12:55:31     INFO -   6  xul.dll!nsFaviconService::SendFaviconNotifications(nsIURI *,nsIURI *,nsACString_internal const &) [nsFaviconService.cpp:7ae21b9549d0 : 208 + 0x32]
12:55:31     INFO -      eip = 0x11368231   esp = 0x0012eff8   ebp = 0x0012f104
12:55:31     INFO -      Found by: call frame info
12:55:31     INFO -   7  xul.dll!mozilla::places::NotifyIconObservers::SendGlobalNotifications(nsIURI *) [AsyncFaviconHelpers.cpp:7ae21b9549d0 : 1046 + 0x13]
12:55:31     INFO -      eip = 0x113aa279   esp = 0x0012f10c   ebp = 0x0012f17c
12:55:31     INFO -      Found by: call frame info
12:55:31     INFO -   8  xul.dll!mozilla::places::NotifyIconObservers::Run() [AsyncFaviconHelpers.cpp:7ae21b9549d0 : 1024 + 0x9]
12:55:31     INFO -      eip = 0x113aafe2   esp = 0x0012f184   ebp = 0x0012f19c
12:55:31     INFO -      Found by: call frame info

Comment 1

[Marco Bonardo [:mak]]

Somehow the async execution thread is null, that means something has executed a statement after asyncClose had been called.

and looks like that's AsyncGetBookmarksForURI... this is very likely fixable.

Comment 2

[Marco Bonardo [:mak]]

Attachment: patch v1.0

The problem is that Database.cpp allows to create a statement after asyncClose has been invoked, but before the database is actually closed.

That means that if a runnable ends up in this limbo and it tries to create and execute a statement, it will get the statement, but then will fail execution  cause the connection async thread is dead.
This may happen with AsyncGetBookmarksForURI.  Indeed async favicons may rarely schedule an onPageChanged notification to be sent in that limbo.  To notify we init an AsyncGetBookmarksForURI, that tries to get and execute an async statement to gather bookmarks to be notified.
This notification is not critical, has never been, indeed we knew we may lose it (see null checks in AsyncGetBookmarksForURI::Init). Still, it should not be able to get a statement at that point.

I already filed some time ago bug 726990 in Storage to try improving detection of these cases, but that's more complicated to fix than this misuse.

Finally, the test sucks, it's good just to land this and verify it fixes the problem, but it may become useless easily, cause it's strictly related to the internals. I couldn't find a reliable way to cause the problem through common APIs, that would be an intermittent test, even more pointless.

Comment 3

[Asaf Romano (gone)]

Comment on attachment 776792 [details] [diff] [review]
patch v1.0

So, as I said over IRC, the test is all but pointless, but I guess it doesn't hurt.

Comment 4

[Marco Bonardo [:mak]]

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

Comment 5

[Ryan VanderMeulen [:RyanVM]]

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

Comment 6

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=26153466&tree=Mozilla-Aurora
Windows XP 32-bit mozilla-aurora debug test xpcshell on 2013-08-04 23:38:25
revision: 26b9b6a2e8e3
slave: t-xp32-ix-013

TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\xpcshell\tests\browser\components\places\tests\unit\test_browserGlue_corrupt_nobackup_default.js | test failed (with xpcshell return code: -2147483645), see following log:
Assertion failure: target, at e:/builds/moz2_slave/m-aurora-w32-d-000000000000000/build/storage/src/mozStorageAsyncStatementExecution.cpp:190
PROCESS-CRASH | C:\slave\test\build\tests\xpcshell\tests\browser\components\places\tests\unit\test_browserGlue_corrupt_nobackup_default.js | application crashed [@ mozilla::storage::AsyncExecuteStatements::execute(nsTArray<mozilla::storage::StatementData> &,mozilla::storage::Connection *,mozIStorageStatementCallback *,mozIStoragePendingStatement * *)]
Return code: 1

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/6958214691c3