1271445 - (gloda-autocomplete) Gloda search crashes in debug build due to assertion failure: mSearchesOngoing > 0 and use of deprecated feature (see comment #10).

Status: RESOLVED FIXED

(MailNews Core :: Database, defect)

Description

[Jorg K (CEST = GMT+2)]

Gloda search crashes in debug build.

As it says.

Assertion failure: mSearchesOngoing > 0 && mSearches.Contains(aSearch), at c:/mozilla-source/comm-central/mozilla/toolkit/components/autocomplete/nsAutoCompleteController.cpp:812

JS call stack:
0 ACGR_markCompleted(aCompleter = [object Object]) ["file:///C:/mozilla-source/comm-central/obj-i686-pc-mingw32/dist/bin/components/glautocomp.js":93]
    this = [object Object]
1 ContactIdentityCompleter.prototype.onQueryCompleted(aCollection = [object Object]) ["file:///C:/mozilla-source/comm-central/obj-i686-pc-mingw32/dist/bin/components/glautocomp.js":325]
    this = [object Object]
2 gloda_coll_onQueryCompleted() ["resource:///modules/gloda/collection.js":631]
    this = [object Object]
3 QueryFromQueryResolver.onQueryCompleted(aCollection = [object Object]) ["resource:///modules/gloda/datastore.js":147]
    this = [object Object]
4 gloda_ds_qfq_handleCompletion(aReason = 0) ["resource:///modules/gloda/datastore.js":385]
    this = [object Object]

C++ code:
NS_IMETHODIMP
nsAutoCompleteController::OnSearchResult(nsIAutoCompleteSearch *aSearch, nsIAutoCompleteResult* aResult)
{
  MOZ_ASSERT(mSearchesOngoing > 0 && mSearches.Contains(aSearch));

I wanted to play around with gloda, check the columns and the message view, but it crashes when I enter a search term.

Comment 1

[Jorg K (CEST = GMT+2)]

This can be seen as a C-C Xpcshell test failure:

PROCESS | 420 | Assertion failure: mSearchesOngoing > 0 && mSearches.Contains(aSearch), at c:/builds/moz2_slave/tb-c-cen-w32-d-000000000000000/build/mozilla/toolkit/components/autocomplete/nsAutoCompleteController.cpp:812

First seen here: Mon May 9, 19:56:39
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=f845c406cebde33fccc49a3892ce5e5d83de9287

Comment 2

[aleth [:aleth]]

Maybe bug 1271338 comment 17 ?

Comment 3

[aleth [:aleth]]

Might not have anything to do with gloda:

"CONSOLE_MESSAGE: (error) [JavaScript Error: "PlacesRemoteTabsAutocompleteProvider is not defined" {file: "resource://gre/components/UnifiedComplete.js" line: 1240}]
17:47:27 INFO - _matchRemoteTabs@resource://gre/components/UnifiedComplete.js:1240:9

Comment 5

[Jorg K (CEST = GMT+2)]

Gloda search still crashes in debug build, as per comment #0.

On a local debug build I still crash when I try to use a gloda search. Doesn't crash on all searches but it crashes every time I enter a search term that triggers a list of auto-complete suggestions.

Comment 6

[aleth [:aleth]]

:-(

Comment 7

[Jorg K (CEST = GMT+2)]

Do you have a debug build to confirm the crash?

Comment 8

[Jorg K (CEST = GMT+2)]

I finally got around to trying this on a 100% fresh compile.

The condition that triggers the assert here
https://dxr.mozilla.org/mozilla-central/source/toolkit/components/autocomplete/nsAutoCompleteController.cpp#812
is mSearchesOngoing > 0 since we get here with mSearchesOngoing==0.

The call stack indicates that this is called directly from JS and the JS stack is:

0 ACGR_addRows(aRows = [object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[
object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object O
bject],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[
object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object Object],[object O
bject],[object Object],[object Object],[object Object],[object Object]) ["file:///C:/mozilla-source/comm-central/obj-i686-pc-mingw32/dist/bin/components/glautocomp.js":105]
    this = [object Object]
1 ContactIdentityCompleter.prototype.onQueryCompleted(aCollection = [object Object]) ["file:///C:/mozilla-source/comm-central/obj-i686-pc-mingw32/dist/bin/components/glautocomp.js":324]
    this = [object Object]
2 gloda_coll_onQueryCompleted() ["resource:///modules/gloda/collection.js":631]
    this = [object Object]
3 QueryFromQueryResolver.onQueryCompleted(aCollection = [object Object]) ["resource:///modules/gloda/datastore.js":147]
    this = [object Object]
4 gloda_coll_onQueryCompleted() ["resource:///modules/gloda/collection.js":631]
    this = [object Object]
5 QueryFromQueryResolver.onQueryCompleted(aCollection = [object Object]) ["resource:///modules/gloda/datastore.js":147]
    this = [object Object]
6 gloda_coll_onQueryCompleted() ["resource:///modules/gloda/collection.js":631]
    this = [object Object]
7 QueryFromQueryResolver.onQueryCompleted(aCollection = [object Object]) ["resource:///modules/gloda/datastore.js":147]
    this = [object Object]
8 gloda_ds_qfq_handleCompletion(aReason = 0) ["resource:///modules/gloda

So it gets called from here:
https://dxr.mozilla.org/comm-central/source/mailnews/db/gloda/components/glautocomp.js#105

Marco, would you be able to give me an idea how to debug this further?

Comment 9

[Marco Bonardo [:mak]]

Usually that assertion means that you tried to append a new result after stopSearch has been invoked.
You may have a race condition there, maybe not sending _ONGOING result at the right time?
If you can reproduce 100% of the times, you should be able to check that with some dumping. 

If this should become a real pain to debug, we can relax the MOZ_ASSERT to a non-fatal assertion.

Comment 10

[Jorg K (CEST = GMT+2)]

This is a real pain. Sometimes mSearchesOngoing is 0, sometimes it's not.

I've been playing with it for a while to see whether it can be reproduced reliably, but I didn't find a way.

Instead I got another assert:
Assertion failure: false (Passing new matches to OnSearchResult with a new nsIAutoCompleteResult every time is deprecated, please update the same result until the search is done), at c:/mozilla-source/comm-central/mozilla/toolkit/components/autocomplete/nsAutoCompleteController.cpp:1566

Maybe someone who knows about Gloda and autocomplete should look at this since I have no expertise in this area. I just noticed the crash when trying to use Gloda with a debug build.

Comment 11

[Marco Bonardo [:mak]]

(In reply to Jorg K (GMT+2, PTO during summer, NI me) from comment #10)
> Instead I got another assert:
> Assertion failure: false (Passing new matches to OnSearchResult with a new
> nsIAutoCompleteResult every time is deprecated, please update the same
> result until the search is done)

oh yes, autocomplete supported 2 different ways to provide results:
1. either keep updating the same result object with new matches and set searchResult accordingly
2. or every time you have new matches, create a new result object and pass it

This was a pointless complication, so 2. has been deprecated (the code works internally by merging the multiple results into a single one and taking path 1.).
There may be a relation with the previous assertion, since this code path is deprecated it may contain race conditions we never fixed.

Comment 12

[aleth [:aleth]]

I would suggest adding (or turning on if available) some logging to discover what the additional search results being added late are, i.e. if they are expected or not.

Comment 13

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

Gloda autocomplete is very old; it implemented multiplexing of multiple parallel search results itself because autocomplete could not at the time.  (Gloda may have even been using the pre-toolkit implementation.)  Autocomplete has definitely been enhanced since then.  It's probably easier to align it with the current idiom/flow than doing a lot of debugging of its current hacky use of the bindings.

I unfortunately am not available to assist in this endeavour for implementation or reviews.

Comment 14

[aleth [:aleth]]

Is this no longer showing up as an xpcshell failure because it got fixed along the way? I remember you or aceman touching gloda recently.

Comment 15

[Jorg K (CEST = GMT+2)]

Right, it doesn't show in any test. But when you use Gloda in a debug build, the autocomplete regularly crashes, see comment #8. For further assessment read following comments, especially comment comment #11 and #13.

Basically, Golda autocomplete is broken, but no on has noticed it yet.

Comment 16

[aleth [:aleth]]

(In reply to Jorg K (GMT+2) from comment #15)
> Right, it doesn't show in any test.

I just wanted to confirm comment 1 is (now?) wrong.

I guess we should put this one on the fix-for-the-next-ESR list...

Comment 17

[aleth [:aleth]]

We've now had complaints about broken autocomplete in current aurora/beta.

Comment 18

[Jorg K (CEST = GMT+2)]

Assertion failure: mSearchesOngoing > 0 && mSearches.Contains(aSearch), at c:/mozilla-source/comm-central/mozilla/toolkit/components/autocomplete/nsAutoCompleteController.cpp:860
#01: XPTC__InvokebyIndex (c:\mozilla-source\comm-central\mozilla\xpcom\reflect\xptcall\md\win32\xptcinvoke_asm_x86_64.asm:99)
#02: CallMethodHelper::Call (c:\mozilla-source\comm-central\mozilla\js\xpconnect\src\xpcwrappednative.cpp:1385)
#03: XPCWrappedNative::CallMethod (c:\mozilla-source\comm-central\mozilla\js\xpconnect\src\xpcwrappednative.cpp:1350)
#04: XPC_WN_CallMethod (c:\mozilla-source\comm-central\mozilla\js\xpconnect\src\xpcwrappednativejsops.cpp:1143)
#05: js::CallJSNative (c:\mozilla-source\comm-central\mozilla\js\src\jscntxtinlines.h:239)
#06: js::InternalCallOrConstruct (c:\mozilla-source\comm-central\mozilla\js\src\vm\interpreter.cpp:459)
#07: Interpret (c:\mozilla-source\comm-central\mozilla\js\src\vm\interpreter.cpp:2922)
#08: js::RunScript (c:\mozilla-source\comm-central\mozilla\js\src\vm\interpreter.cpp:405)
#09: js::InternalCallOrConstruct (c:\mozilla-source\comm-central\mozilla\js\src\vm\interpreter.cpp:477)
#10: js::jit::DoCallFallback (c:\mozilla-source\comm-central\mozilla\js\src\jit\baselineic.cpp:6012)
#11: ??? (???:???)
0 ACGR_addRows(aRows = [object Object],[object Object]) ["file:///C:/mozilla-source/comm-central/obj-x86_64-pc-mingw32/dist/bin/components/glautocomp.js":105]
    this = [object Object]
1 ContactIdentityCompleter.prototype.onQueryCompleted(aCollection = [object Object]) ["file:///C:/mozilla-source/comm-central/obj-x86_64-pc-mingw32/dist/bin/components/glautocomp.js":324]
    this = [object Object]
2 gloda_coll_onQueryCompleted() ["resource:///modules/gloda/collection.js":631]
    this = [object Object]
3 QueryFromQueryResolver.onQueryCompleted(aCollection = [object Object]) ["resource:///modules/gloda/datastore.js":147]
    this = [object Object]
4 gloda_ds_qfq_handleCompletion(aReason = 0) ["resource:///modules/gloda/datastore.js":385]
    this = [object Object]

Since there are no takers, I'll have to look at it myself. The crash is still there.

Comment 19

[Jorg K (CEST = GMT+2)]

OK, I added some debug and there are two problems here.

The first is that results are added after stopSearch was called. That looks like this:
=== start search being called, term=hen
=== calling onSearchResult in announceYourself
=== OnSearchResult: mSearchesOngoing = 1
=== OnSearchResult: mSearches.Contains(aSearch) = true
=== stop search being called
=== calling onSearchResult in addRows
=== OnSearchResult: mSearchesOngoing = 0
=== OnSearchResult: mSearches.Contains(aSearch) = true
Assertion failure: mSearchesOngoing > 0 && mSearches.Contains(aSearch)
Marco predicted this in comment #9.

The second problem is that we pass new results in a new result object every time. That looks like this:
=== start search being called, term=hen
=== calling onSearchResult in announceYourself
=== OnSearchResult: mSearchesOngoing = 1
=== OnSearchResult: mSearches.Contains(aSearch) = true
=== stop search being called

=== start search being called, term=henk
=== calling onSearchResult in announceYourself
=== OnSearchResult: mSearchesOngoing = 1
=== OnSearchResult: mSearches.Contains(aSearch) = true
=== calling onSearchResult in addRows
=== OnSearchResult: mSearchesOngoing = 1
=== OnSearchResult: mSearches.Contains(aSearch) = true
Assertion failure: false (Passing new matches to OnSearchResult with a new nsIAutoCompleteResult every time is deprecated, please update the same result until the search is done), at c:/mozilla-source/comm-central/mozilla/toolkit/components/autocomplete/nsAutoCompleteController.cpp:1625
Marco mentioned this in comment #11.

Comment 20

[Jorg K (CEST = GMT+2)]

Attachment: WIP: 1271445-gloda-autocomplete.patch (v1).

Gloda autocomplete results are derived asynchronously. That means that they arrive and get passed onto the autocomplete controller after it has already stopped the search. A simple gate suppresses late results so they don't get passed on. That fixed the first problem which doesn't always occur since it's timing related. I was lucky (or unlucky) to catch it a few times, the second time with the fix in place. That looks like this:

=== start search being called, term=hen
=== calling onSearchResult in announceYourself
=== OnSearchResult: mSearchesOngoing = 1
=== OnSearchResult: mSearches.Contains(aSearch) = true
=== stop search being called <<<<=== STOP!!
=== calling onSearchResult in addRows, searchActive=false <<<< results suppressed.
=== calling onSearchResult in markCompleted, searchActive=false <<<< results suppressed.

=== start search being called, term=henk
=== calling onSearchResult in announceYourself
=== OnSearchResult: mSearchesOngoing = 1

Now to the second problem of always delivering the results in the same object. I have the feeling that that just a different incarnation of the first problem. If the results arrive late, but another search has started, they will be delivered with the first object in the second search although they are no longer relevant. Let me try this.

Comment 21

[Jorg K (CEST = GMT+2)]

Attachment: 1271445-gloda-autocomplete.patch

This works. A simple gate protects against
- sending late async results when search has stopped
- sending late async results to new search when previous
  search has stopped and new one was started.

Andrew, you said you didn't want to participate in the fix or the review, but this solution is so dead-simple that you can review it in two minutes.

I ran it with additional debug and it clearly shows that both cases are fixed. It's hard to provoke it since you need the async results late so that the search has already stopped and even a new one has started. I hit both cases and they are both fixed.

Comment 22

[Jorg K (CEST = GMT+2)]

Attachment: 1271445-gloda-autocomplete.patch (v2).

This is nicer since it doesn't use a global variable.

Comment 23

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

Comment on attachment 8814264 [details] [diff] [review]
1271445-gloda-autocomplete.patch (v2).

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

Okay, but only because I'm a sucker for self-descriptive code and informative comments! :)

Excellent patch, thank you.

Comment 24

[Jorg K (CEST = GMT+2)]

Landed on trunk and branches:
C-C (TB 53): https://hg.mozilla.org/comm-central/rev/82f30d653e8a6e483aea2375b919571c4b253390
C-A (TB 52): https://hg.mozilla.org/releases/comm-aurora/rev/422cb090c018688a1df3c78312bed8a13af790f4
C-B (TB 51): https://hg.mozilla.org/releases/comm-beta/rev/063acd7aa29859208f0784b3b797263c6f304937