Intermittent test_818587_compress-bookmarks-backups.js | application crashed [@ nsXPCWrappedJS::AddRef()]

RESOLVED FIXED in Firefox 41

Status

()

defect
--
critical
RESOLVED FIXED
4 years ago
4 years ago

People

(Reporter: RyanVM, Assigned: mak)

Tracking

({crash, intermittent-failure, regression})

unspecified
mozilla42
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox40 unaffected, firefox41+ fixed, firefox42 fixed, firefox-esr38 unaffected)

Details

(crash signature)

Attachments

(1 attachment)

08:28:21 INFO - TEST-START | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js
08:28:22 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | xpcshell return code: 1
08:28:22 INFO - TEST-INFO took 914ms
08:28:22 INFO - >>>>>>>
08:28:22 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
08:28:22 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
08:28:22 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
08:28:22 INFO - running event loop
08:28:22 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "SyntaxError: octal literals and octal escape sequences are deprecated" {file: "/builds/slave/test/build/tests/xpcshell/tests/toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js" line: 15 column: 70 source: "yFilename = PlacesBackups.getFilenameForDate(new Date(2014, 04, 15), true);
08:28:22 INFO - "}]"
08:28:22 INFO - toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | Starting compress_bookmark_backups_test
08:28:22 INFO - (xpcshell/head.js) | test compress_bookmark_backups_test pending (2)
08:28:22 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
08:28:22 INFO - TEST-PASS | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | compress_bookmark_backups_test - [compress_bookmark_backups_test : 16] "bookmarks-2014-05-15.jsonlz4" == "bookmarks-2014-05-15.jsonlz4"
08:28:22 INFO - TEST-PASS | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | compress_bookmark_backups_test - [compress_bookmark_backups_test : 21] 1 == 1
08:28:22 INFO - TEST-PASS | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | compress_bookmark_backups_test - [compress_bookmark_backups_test : 23] "/var/folders/B4/B4XoaBuCEPK-jLmv4KyxFk+++-k/-Tmp-/xpc-profile-njb2Vi/bookmarkbackups/bookmarks-2015-06-02_4_Sbgfcd-BcrrOFQ3E7g6 != null
08:28:22 INFO - TEST-PASS | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | compress_bookmark_backups_test - [compress_bookmark_backups_test : 24] true == true
08:28:22 INFO - TEST-PASS | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | compress_bookmark_backups_test - [compress_bookmark_backups_test : 30] true == true
08:28:22 INFO - TEST-PASS | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | compress_bookmark_backups_test - [compress_bookmark_backups_test : 36] 1 == 1
08:28:22 INFO - TEST-PASS | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | compress_bookmark_backups_test - [compress_bookmark_backups_test : 52] "http://www.mozilla.org/en-US/" == "http://www.mozilla.org/en-US/"
08:28:22 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
08:28:22 INFO - (xpcshell/head.js) | test compress_bookmark_backups_test finished (2)
08:28:22 INFO - (xpcshell/head.js) | test run_next_test 1 finished (1)
08:28:22 INFO - exiting test
08:28:22 INFO - <<<<<<<
08:28:22 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/RDLDHuVSTNukFW59gbRoGw/artifacts/public/build/firefox-41.0a1.en-US.mac.crashreporter-symbols.zip
08:29:33 INFO - mozcrash Saved minidump as /builds/slave/test/build/blobber_upload_dir/0A6C0211-6B19-4443-B3A6-B5F99FD5B9B3.dmp
08:29:33 INFO - mozcrash Saved app info as /builds/slave/test/build/blobber_upload_dir/0A6C0211-6B19-4443-B3A6-B5F99FD5B9B3.extra
08:29:33 WARNING - PROCESS-CRASH | toolkit/components/places/tests/bookmarks/test_818587_compress-bookmarks-backups.js | application crashed [@ nsXPCWrappedJS::AddRef()]
08:29:33 INFO - Crash dump filename: /var/folders/B4/B4XoaBuCEPK-jLmv4KyxFk+++-k/-Tmp-/xpc-other-lFEeJ3/0A6C0211-6B19-4443-B3A6-B5F99FD5B9B3.dmp
08:29:33 INFO - Operating system: Mac OS X
08:29:33 INFO - 10.6.8 10K549
08:29:33 INFO - CPU: amd64
08:29:33 INFO - family 6 model 23 stepping 10
08:29:33 INFO - 2 CPUs
08:29:33 INFO - Crash reason: EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
08:29:33 INFO - Crash address: 0x0
08:29:33 INFO - Thread 21 (crashed)
08:29:33 INFO - 0 XUL!nsXPCWrappedJS::AddRef() [XPCWrappedJS.cpp:9eae3880b132 : 232 + 0x0]
08:29:33 INFO - rbx = 0x000000010f02c040 r12 = 0x0000000000000001
08:29:33 INFO - r13 = 0x0000000109559280 r14 = 0x000000010f069080
08:29:33 INFO - r15 = 0x000000010552d030 rip = 0x0000000100bbf427
08:29:33 INFO - rsp = 0x000000010ee02e60 rbp = 0x000000010ee02e70
08:29:33 INFO - Found by: given as instruction pointer in context
08:29:33 INFO - 1 XUL!mozilla::services::GetAsyncShutdown() [nsCOMPtr.h:9eae3880b132 : 432 + 0x8]
08:29:33 INFO - rbx = 0x000000010f02c040 r12 = 0x0000000000000001
08:29:33 INFO - r13 = 0x0000000109559280 r14 = 0x000000010ee02ee0
08:29:33 INFO - r15 = 0x000000010552d030 rip = 0x0000000100483128
08:29:33 INFO - rsp = 0x000000010ee02e80 rbp = 0x000000010ee02ea0
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 2 XUL!mozilla::places::Database::Database() [Database.cpp:9eae3880b132 : 374 + 0x4]
08:29:33 INFO - rbx = 0x000000010f2e73c0 r12 = 0x0000000000000001
08:29:33 INFO - r13 = 0x0000000109559280 r14 = 0x0000000109559280
08:29:33 INFO - r15 = 0x000000010552d030 rip = 0x00000001028d5043
08:29:33 INFO - rsp = 0x000000010ee02eb0 rbp = 0x000000010ee02f10
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 3 XUL!mozilla::places::CalculateFrecencyFunction::OnFunctionCall(mozIStorageValueArray*, nsIVariant**) [Database.cpp:9eae3880b132 : 602 + 0x7]
08:29:33 INFO - rbx = 0x000000010f2e4e00 r12 = 0x0000000000000001
08:29:33 INFO - r13 = 0x0000000109559280 r14 = 0x000000008000ffff
08:29:33 INFO - r15 = 0x000000010ef29870 rip = 0x00000001028e2084
08:29:33 INFO - rsp = 0x000000010ee02f20 rbp = 0x000000010ee03100
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 4 XUL!mozilla::storage::(anonymous namespace)::basicFunctionHelper(sqlite3_context*, int, Mem**) [mozStorageConnection.cpp:9eae3880b132 : 215 + 0xb]
08:29:33 INFO - rbx = 0x000000010ee034b0 r12 = 0x00000001028e1f40
08:29:33 INFO - r13 = 0x0000000000000001 r14 = 0x000000010f2e4e00
08:29:33 INFO - r15 = 0x000000010ef29870 rip = 0x0000000100c1d19f
08:29:33 INFO - rsp = 0x000000010ee03110 rbp = 0x000000010ee03140
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 5 libnss3.dylib!sqlite3VdbeExec [sqlite3.c:9eae3880b132 : 72433 + 0xf]
08:29:33 INFO - rbx = 0x000000010e37c400 r12 = 0x000000000000001e
08:29:33 INFO - r13 = 0x000000010d422800 r14 = 0x000000010f9a3dd8
08:29:33 INFO - r15 = 0x0000000000000001 rip = 0x00000001001c23a3
08:29:33 INFO - rsp = 0x000000010ee03150 rbp = 0x000000010ee039a0
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 6 libnss3.dylib!sqlite3_step [sqlite3.c:9eae3880b132 : 69486 + 0x11]
08:29:33 INFO - rbx = 0x000000010e37c400 r12 = 0x000000010f4fa400
08:29:33 INFO - r13 = 0x000000010f4fa400 r14 = 0x000000010f0247c0
08:29:33 INFO - r15 = 0x000000010e37c400 rip = 0x0000000100109662
08:29:33 INFO - rsp = 0x000000010ee039b0 rbp = 0x000000010ee03b80
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 7 XUL!mozilla::storage::Connection::stepStatement(sqlite3*, sqlite3_stmt*) [mozStorageConnection.cpp:9eae3880b132 : 1030 + 0x7]
08:29:33 INFO - rbx = 0x000000010f4fa400 r12 = 0x000000010f4fa400
08:29:33 INFO - r13 = 0x000000010f0247e0 r14 = 0x000000010f0247c0
08:29:33 INFO - r15 = 0x000000010e37c400 rip = 0x0000000100c1b221
08:29:33 INFO - rsp = 0x000000010ee03b90 rbp = 0x000000010ee03bd0
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 8 XUL!mozilla::storage::AsyncExecuteStatements::executeStatement(sqlite3_stmt*) [mozStorageAsyncStatementExecution.cpp:9eae3880b132 : 346 + 0xc]
08:29:33 INFO - rbx = 0x000000010f4fa400 r12 = 0x000000010f939a00
08:29:33 INFO - r13 = 0x000000010f0247e0 r14 = 0x000000010f4fa400
08:29:33 INFO - r15 = 0x00000001037418a2 rip = 0x0000000100c22d05
08:29:33 INFO - rsp = 0x000000010ee03be0 rbp = 0x000000010ee03c20
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 9 XUL!mozilla::storage::AsyncExecuteStatements::executeAndProcessStatement(sqlite3_stmt*, bool) [mozStorageAsyncStatementExecution.cpp:9eae3880b132 : 293 + 0xa]
08:29:33 INFO - rbx = 0x000000010f4fa400 r12 = 0x000000010f4fa400
08:29:33 INFO - r13 = 0x000000010f939a00 r14 = 0x0000000000000000
08:29:33 INFO - r15 = 0x0000000000000001 rip = 0x0000000100c22bdb
08:29:33 INFO - rsp = 0x000000010ee03c30 rbp = 0x000000010ee03c60
08:29:33 INFO - Found by: call frame info
08:29:33 INFO - 10 XUL!mozilla::storage::AsyncExecuteStatements::bindExecuteAndProcessStatement(mozilla::storage::StatementData&, bool) [mozStorageAsyncStatementExecution.cpp:9eae3880b132 : 275 + 0xd]
08:29:33 INFO - rbx = 0x000000010f4fa400 r12 = 0x000000010f939a00
08:29:33 INFO - r13 = 0x0000000000000000 r14 = 0x0000000000000000
08:29:33 INFO - r15 = 0x0000000000000001 rip = 0x0000000100c228eb
08:29:33 INFO - rsp = 0x000000010ee03c70 rbp = 0x000000010ee03cd0
08:29:33 INFO - Found by: call frame info
Any idea what's going on here, Mak?
Flags: needinfo?(mak77)
fancy stack!

CalculateFrecencyFunction gets a handle on nsNavHistory::GetConstHistoryService, and this somehow tries to create a Database object that tries to get mozilla::services::GetAsyncShutdown...
I suppose CalculateFrecencyFunction here is running off the main-thread, and this would explain the crash since nsXPCWrappedJS is main-thread only.

Now, how do we reach CalculateFrecencyFunction if history is not alive already?

Another instance of the crash comes from AsyncFaviconHelperBase::AsyncFaviconHelperBase

I'm pretty sure this is not a test-only problem and can happen in real life.

cc-ing David too, who added the async shutdown bits.
Severity: normal → critical
Keywords: regression
OS: Mac OS X → All
Hardware: x86_64 → All
I wonder if here we already shutdown Database and we are trying to create a new one. all the stacks are going through Database::GetDatabase
we might need to add a static bool telling us if the database has already been shutdown and in such a case return nullptr

Interesting that the MOZ_ASSERT(NS_IsMainThread()) in DatabaseShutdown didn't trigger in debug builds. These are all opt builds, we should have seen some assert in debug builds, but maybe due to timing issues that happens only in fast builds.

David, what do you think, is my analysis somehow correct? Do you think tracking shutdown status in a static would do?
Flags: needinfo?(mak77) → needinfo?(dteller)
[Tracking Requested - why for this release]: this is a new possible cause of crashes in Firefox 41.
Flags: needinfo?(mak77)
I haven't checked all the stacks, but yes, from what I see, I agree with you.

Now, when I made Places AsyncShutdown-compatible, I seem to remember that you asked me to make sure that we could re-open a Database after we had closed one, so that sounds incompatible with the idea of this `static`.

Unless you wish to return `nullptr` if we're trying to re-open the Database from a non-main thread? That sounds a bit over-complicated.

Perhaps we should forbid creation of the Database off the main thread? Since `gDatabase` is not atomic, anyway, making it possible to create it from any thread is a race condition.
Flags: needinfo?(dteller)
(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #26)
> Now, when I made Places AsyncShutdown-compatible, I seem to remember that
> you asked me to make sure that we could re-open a Database after we had
> closed one, so that sounds incompatible with the idea of this `static`.

Strange, was that required for some tests? I don't recall. Doesn't look like we need this for the product, if you could find my comment maybe that would help...
I wonder if it was to support some tests actually closing and reopening Places? Well, we could just do a Try run and see.

> Perhaps we should forbid creation of the Database off the main thread? Since
> `gDatabase` is not atomic, anyway, making it possible to create it from any
> thread is a race condition.

Yes, we could do this too, it would still require a way to track whether the db has already been created, so it's about the same solution.

I'm taking the bug cause we don't have much better way to track them.
Assignee: nobody → mak77
Flags: needinfo?(mak77)
Crash Signature: [@ nsXPCWrappedJS::AddRef()]
Posted patch patch v1Splinter Review
let's assume Try will be happy (otherwise we can fallback to the suggested main-thread only recreation), so far there is only a failure in oth due to another patch in my queue.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d64bd8959f8f
Attachment #8638498 - Flags: review?(dteller)
Comment on attachment 8638498 [details] [diff] [review]
patch v1

Review of attachment 8638498 [details] [diff] [review]:
-----------------------------------------------------------------

LGTM if it passes tests.

::: toolkit/components/places/Database.cpp
@@ +359,5 @@
>    // give the instances of `DatabaseShutdown` unique names.
>    uint16_t mCounter;
>    static uint16_t sCounter;
>  
> +  static bool sIsStarted;

Shouldn't this be an Atomic<bool>?
Attachment #8638498 - Flags: review?(dteller) → review+
(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #29)
> Shouldn't this be an Atomic<bool>?

yeah, sounds like a good idea.
Tracked.
Blocks: 1043863
Comment on attachment 8638498 [details] [diff] [review]
patch v1

Approval Request Comment
[Feature/regressing bug #]: bug 1043863
[User impact if declined]: new possible source of crashes on shutdown
[Describe test coverage new/current, TreeHerder]: Nightly
[Risks and why]: low risk change to avoid re-entering after shutdown
[String/UUID change made/needed]: none
Attachment #8638498 - Flags: approval-mozilla-aurora?
https://hg.mozilla.org/mozilla-central/rev/3cfb284f730c
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla42
(In reply to Treeherder Robot from comment #36)

This was from a push prior to comment 35 :)
Comment on attachment 8638498 [details] [diff] [review]
patch v1

This has been in m-c for a few days so seems safe to uplift to Aurora.
Attachment #8638498 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
You need to log in before you can comment on or make changes to this bug.