Closed Bug 994102 Opened 8 years ago Closed 7 years ago

Search engines don't work right away after installation

Categories

(Mozilla QA Graveyard :: Mozmill Tests, defect)

defect
Not set
normal

Tracking

(firefox33 fixed, firefox34 fixed, firefox35 fixed, firefox36 fixed, firefox-esr31 fixed)

RESOLVED FIXED
Tracking Status
firefox33 --- fixed
firefox34 --- fixed
firefox35 --- fixed
firefox36 --- fixed
firefox-esr31 --- fixed

People

(Reporter: cosmin-malutan, Assigned: cosmin-malutan)

References

Details

Attachments

(3 files, 2 obsolete files)

I guess we need to wait for "write-cache-to-disk-complete" message under the "browser-search-service" topic, when we we install them in https://hg.mozilla.org/qa/mozmill-tests/file/abce34503500/firefox/lib/search.js#l324
No longer blocks: 942737
(In reply to Cosmin Malutan from comment #0)
> I guess we need to wait for "write-cache-to-disk-complete" message under the
> "browser-search-service" topic, when we we install them in
> https://hg.mozilla.org/qa/mozmill-tests/file/abce34503500/firefox/lib/search.
> js#l324

Sounds like a bit complex. Gavin, would you have an advice for us?
Flags: needinfo?(gavin.sharp)
Summary: Search engines doesn't work right away after installation → Search engines don't work right away after installation
You should never observe write-cache-to-disk-complete, in general.

What's the actual problem you're experiencing? There's very little detail here about the failures you're seeing.
Flags: needinfo?(gavin.sharp)
In our automated test, we install a local engine and the we type in a word and wait for suggestions, suggestions never come if we type right away after installation, they do if I add a delay of 1s. So I checked the nsSearchService file and I saw that the write-cache-to-disk-complete is the last event triggered. What so ever, I can disable the cache and wait for "write-metadata-to-disk-complete" which works much more better. 
http://mxr.mozilla.org/mozilla-central/source/toolkit/components/search/nsSearchService.js#3057

Again, after I install the engine, I type and wait for suggestion, they never come unless I add a delay  between installation and typing.
Where is the code / test in question?

As I said before, you should absolutely not use "write-metadata-to-disk-complete".
http://hg.mozilla.org/qa/mozmill-tests/file/d6197394e7d8/firefox/lib/search.js#l344
Here we install an engine and wait for it to be displayed, the observer get's notified latter after serchengine has been displayed. After we install the engine we type a text and we wait for suggestions, but they don't come if we type before this observer or "write-metadata-to-disk-complete" get's notified.

Here we fail to retrive the suggestions:
http://hg.mozilla.org/qa/mozmill-tests/file/d6197394e7d8/firefox/tests/functional/testSearch/testSearchSuggestions.js#l50

If I can't wait for that is there anything else I can wait for?
Flags: needinfo?(gavin.sharp)
The reliance on "assert.waitFor()" (which tries to make asynchronous code synchronous by spinning a nested event loop) in many mozmill tests is deeply problematic, and likely leads to a lot of the flaky test issues and crashes that you see. You'd avoid a lot of trouble by actually writing asynchronous code, which is easier to do now that we have Task.jsm and Promises. It would also make it much easier to debug failures, because reasoning about the event flow would be much less complicated.

Leaving that aside, which part of "retrieving the suggestions" fails? Where in getSuggestions do things go wrong?
Flags: needinfo?(gavin.sharp)
Attached patch patch_v1.0 (obsolete) — Splinter Review
Gavin as requested in bug 942737 comment 82, I made a patch in witch I wait for "engine-added" verb under the "browser-search-engine-modified" topic.


Just apply the patch on mozmill-tests and run:
mozmill -t mozmill-tests/firefox/tests/functional/testSearch/testSearchSuggestions.js -b <path to a nightly>

You will see that the engine is installed, selected but it doesn't get the suggestions after typing.
Assignee: nobody → cosmin.malutan
Attached file log.txt
If I ran the test with --debugger=gdb, I get a couple of:
>"Program received signal SIGSEGV, Segmentation fault."
Here is the log.
The gdb log isn't that useful, what's needed is to step through getSuggestions (or use dump()-debugging) and figure out why it is failing.
I had a better stack trace now, I called call DumpJSStack() when FF freezed searching for suggestions:

>Program received signal SIGSEGV, Segmentation fault.
>js::jit::PatchJump (jump=..., label=...) at /builds/slave/m-cen-l64-ntly-000000000000000/build/js/src/jit/x64/Assembler-x64.h:716
>716	/builds/slave/m-cen-l64-ntly-000000000000000/build/js/src/jit/x64/Assembler-x64.h: No such file or directory.
>(gdb) call DumpJSStack()
>[Thread 0x7fffdd1c9700 (LWP 4846) exited]
>0 dbCreate() ["resource://gre/modules/FormHistory.jsm":472]
>    this = [object BackstagePass]
>1 dbInit() ["resource://gre/modules/FormHistory.jsm":447]
>    this = [object BackstagePass]
>2 anonymous() ["resource://gre/modules/FormHistory.jsm":382]
>    this = [object BackstagePass]
>3 anonymous() ["resource://gre/modules/XPCOMUtils.jsm":177]
>    this = [object BackstagePass]
>4 dbCreateAsyncStatement(aQuery = "SELECT guid FROM moz_formhistory WHERE fieldname = :fieldname AND value = :value", aParams = [object Object]) ["resource://gre/modules/FormHistory.jsm":407]
>    this = [object BackstagePass]
>5 makeSearchStatement(aSearchData = [object Object], aSelectTerms = guid) ["resource://gre/modules/FormHistory.jsm":274]
>    this = [object BackstagePass]
>6 formHistorySearch(aSelectTerms = guid, aSearchData = [object Object], aCallbacks = [object Object]) ["resource://gre/modules/FormHistory.jsm":781]
>    this = [object Object]
>7 formHistoryUpdate(aChanges = [object Object], aCallbacks = [object Object]) ["resource://gre/modules/FormHistory.jsm":940]
>    this = [object Object]
>8 doSearch(aData = "mo", aWhere = "current") ["chrome://browser/content/search/search.xml":485]
>    this = [object XULElement]
>9 handleSearchCommand(aEvent = [object KeyboardEvent]) ["chrome://browser/content/search/search.xml":469]
>    this = [object XULElement]
>10 onTextEntered() ["chrome://browser/content/search/search.xml":750]
>    this = [object XULElement]
>11 onKeyPress(aEvent = [object KeyboardEvent]) ["chrome://global/content/bindings/autocomplete.xml":477]
>    this = [object XULElement]
>12 onxblkeypress(event = [object KeyboardEvent]) ["chrome://global/content/bindings/autocomplete.xml":561]
>    this = [object XULElement]

After hitting continue, the next js stack was exactly the test failure, waiting for suggestions:
>Program received signal SIGSEGV, Segmentation fault.
>js::jit::PatchJump (jump=..., label=...) at /builds/slave/m-cen-l64-ntly-000000000000000/build/js/src/jit/x64/Assembler-x64.h:716
>716	in /builds/slave/m-cen-l64-ntly-000000000000000/build/js/src/jit/x64/Assembler-x64.h
>(gdb) call DumpJSStack()
>0 Assert_waitFor(aCallback = [function], aMessage = "", aTimeout = 5000, aInterval = undefined, aThisObject = undefined) ["resource://mozmill/modules/assertions.js":594]
>    this = [object Object]
>1 waitFor(callback = [function], message = "", timeout = 5000, interval = undefined, thisObject = undefined) ["resource://mozmill/stdlib/utils.js":269]
>    this = [object Object]
>2 Assert_waitFor(aCallback = [function], aMessage = "", aTimeout = 5000) ["resource://mozmill/stdlib/securable-module.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/lib/assertions.js":555]
>    this = [object Object]
>3 anonymous(searchTerm = "mo") ["resource://mozmill/stdlib/securable-module.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/firefox/lib/search.js":742]
>    this = [object Object]
>4 anonymous(aEngine = [object Object], 1, [object Object],[object Object]) ["resource://mozmill/modules/frame.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/firefox/tests/functional/testSearch/testSearchSuggestions.js":47]
>5 testMultipleEngines(allSuggestions = undefined) ["resource://mozmill/modules/frame.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/firefox/tests/functional/testSearch/testSearchSuggestions.js":37]
>6 anonymous(func = [function]) ["resource://mozmill/modules/frame.js":752]
>    this = [object Object]
>7 anonymous(module = [object Sandbox]) ["resource://mozmill/modules/frame.js":706]
>    this = [object Object]
>8 anonymous(filename = "/home/cosmin/Projects/Mozilla/clean/mozmill-tests/firefox/tests/functional/testSearch/testSearchSuggestions.js", name = null) ["resource://mozmill/modules/frame.js":690]
>    this = [object Object]
>9 runTestFile(filename = "/home/cosmin/Projects/Mozilla/clean/mozmill-tests/firefox/tests/functional/testSearch/testSearchSuggestions.js", name = null) ["resource://mozmill/modules/frame.js":775]
>    this = [object BackstagePass]
Attached file testcase.js
Here is an testcase, I'm blocked here, and I need some directions.
(In reply to Cosmin Malutan from comment #10)
> I had a better stack trace now, I called call DumpJSStack() when FF freezed
> searching for suggestions:

> >0 dbCreate() ["resource://gre/modules/FormHistory.jsm":472]
> >    this = [object BackstagePass]

Was Firefox actually "hanging" (100% CPU) at this point? Or by "freezed" do you just mean it wasn't continuing with the test?

> After hitting continue, the next js stack was exactly the test failure,
> waiting for suggestions:

> >0 Assert_waitFor(aCallback = [function], aMessage = "", aTimeout = 5000, aInterval = undefined, aThisObject = undefined) ["resource://mozmill/modules/assertions.js":594]
> >    this = [object Object]
> >1 waitFor(callback = [function], message = "", timeout = 5000, interval = undefined, thisObject = undefined) ["resource://mozmill/stdlib/utils.js":269]
> >    this = [object Object]
> >2 Assert_waitFor(aCallback = [function], aMessage = "", aTimeout = 5000) ["resource://mozmill/stdlib/securable-module.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/lib/assertions.js":555]
> >    this = [object Object]
> >3 anonymous(searchTerm = "mo") ["resource://mozmill/stdlib/securable-module.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/firefox/lib/search.js":742]
> >    this = [object Object]

This is a waitFor called by getSuggestions waiting forever - which one? The line number suggests it's the one at https://hg.mozilla.org/qa/mozmill-tests/annotate/678d05fab339/lib/search.js#l736 - can you confirm?
(In reply to :Gavin Sharp (email gavin@gavinsharp.com) from comment #12)
> (In reply to Cosmin Malutan from comment #10)
> > I had a better stack trace now, I called call DumpJSStack() when FF freezed
> > searching for suggestions:
> 
> > >0 dbCreate() ["resource://gre/modules/FormHistory.jsm":472]
> > >    this = [object BackstagePass]
> 
> Was Firefox actually "hanging" (100% CPU) at this point? Or by "freezed" do
> you just mean it wasn't continuing with the test?
I can't know for sure as I'm new to gdb but I think it freezed/(as a breakpoint) when it caught an exception, then I printed the trace and hit "c" to continue, 

> > After hitting continue, the next js stack was exactly the test failure,
> > waiting for suggestions:
> 
> > >0 Assert_waitFor(aCallback = [function], aMessage = "", aTimeout = 5000, aInterval = undefined, aThisObject = undefined) ["resource://mozmill/modules/assertions.js":594]
> > >    this = [object Object]
> > >1 waitFor(callback = [function], message = "", timeout = 5000, interval = undefined, thisObject = undefined) ["resource://mozmill/stdlib/utils.js":269]
> > >    this = [object Object]
> > >2 Assert_waitFor(aCallback = [function], aMessage = "", aTimeout = 5000) ["resource://mozmill/stdlib/securable-module.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/lib/assertions.js":555]
> > >    this = [object Object]
> > >3 anonymous(searchTerm = "mo") ["resource://mozmill/stdlib/securable-module.js -> file:///home/cosmin/Projects/Mozilla/clean/mozmill-tests/firefox/lib/search.js":742]
> > >    this = [object Object]
> 
> This is a waitFor called by getSuggestions waiting forever - which one? The
> line number suggests it's the one at
> https://hg.mozilla.org/qa/mozmill-tests/annotate/678d05fab339/lib/search.
> js#l736 - can you confirm?
Yes, here the autocomplete popup should dropped down with the suggestions, it doesn't and we fail in waitFor.
(In reply to Cosmin Malutan from comment #13)
> > This is a waitFor called by getSuggestions waiting forever - which one? The
> > line number suggests it's the one at
> > https://hg.mozilla.org/qa/mozmill-tests/annotate/678d05fab339/lib/search.
> > js#l736 - can you confirm?
> Yes, here the autocomplete popup should dropped down with the suggestions,
> it doesn't and we fail in waitFor.

That waitFor is waiting for the popup to close again after having pressed escape, not waiting for it to appear.

Do you even need to wait for the popup to close? Why not just remove that line?

If you do need to wait for it to close, a spin of the event loop before triggering the escape might help.
(In reply to :Gavin Sharp (email gavin@gavinsharp.com) from comment #14)
> That waitFor is waiting for the popup to close again after having pressed
> escape, not waiting for it to appear.
Sorry I've got that wrong it failed at line https://hg.mozilla.org/qa/mozmill-tests/file/e386857a0a2b/firefox/lib/search.js#l725 the line number was the same with the one in my repo, but that was the code failing. 

> If you do need to wait for it to close, a spin of the event loop before
> triggering the escape might help.
I tried to spin the event loop but it doesn't help.
Status: NEW → ASSIGNED
After I builded firefox and I made dumps trough all functions that are called since a search is started and the result is expected I found that:
The suggestions are found and then we notify the observer that we found them in "onSearchResult":
https://github.com/mozilla/gecko-dev/blob/57c88ce89f84aa2b743536dcfbe43bd0af7e3931/toolkit/components/search/nsSearchSuggestions.js#L143

The observer receives the suggestions and updates them but it fails to open the pop-up:
https://github.com/mozilla/gecko-dev/commit/5f1fde8824e6a57d806fa05bfe8aae246226fea6#L1291

If I force-open the pop-up in the test it will pass every single time with the right suggestions.
I don't know how to debug the cpp file, so if someone can tell me how or do that, the function that needs debugged is:
https://github.com/mozilla/gecko-dev/commit/5f1fde8824e6a57d806fa05bfe8aae246226fea6#L1291
For that you could ran just the testcase.
(In reply to Cosmin Malutan from comment #16)
> https://github.com/mozilla/gecko-dev/commit/
> 5f1fde8824e6a57d806fa05bfe8aae246226fea6#L1291

Cosmin, this link is busted. Please use MXR or DXR to reference the code. Thanks.
http://mxr.mozilla.org/mozilla-central/source/toolkit/components/autocomplete/nsAutoCompleteController.cpp#703
This is called from nsSearchSuggestions.js then in ProcessResult it updates the suggestions but it fails to open the pop-up.
I debugged this but I can't find what's wrong it fails in multiple places, either on triggering the search or on displaying them if the request succeeded. 
Best would be to add a sleep or an waitFor as it will be impossible for an user to hit this problem, it will have to install an engine, select it and type for suggestions in less than 2 seconds. I would do this in bug 942737 so we can close it and avoid other test failures  and keep this open for finding and fixing the underlying problem.
Comment on attachment 8417908 [details] [diff] [review]
patch_v1.0

For search suggestions we have two issue, one is that we don't wait for engines to be ready and the other is that remote resources might not be available or they can take too long to be accessed bug 942737 comment 92.

For the first one it should be enough to wait for "browser-search-engine-modified"  as Gavin suggested in bug 942737 comment 78, this patch already does that.
For the other one we should make the engines to use local resources and make the to be completely functional, for that we would need wpt server.
Until then this patch fixes the issue with the engines being ready and it's good to have it now.
Attachment #8417908 - Flags: review?(andrei.eftimie)
Attachment #8417908 - Flags: review?(andreea.matei)
Attached patch patch v1.1 (obsolete) — Splinter Review
I just removed the change in test, this only needs to affect the library.
Attachment #8417908 - Attachment is obsolete: true
Attachment #8417908 - Flags: review?(andrei.eftimie)
Attachment #8417908 - Flags: review?(andreea.matei)
Attachment #8514986 - Flags: review?(andrei.eftimie)
Attachment #8514986 - Flags: review?(andreea.matei)
Comment on attachment 8514986 [details] [diff] [review]
patch v1.1

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

If this helps, even partially, lets get it in.
Attachment #8514986 - Flags: review?(hskupin)
Attachment #8514986 - Flags: review?(andrei.eftimie)
Attachment #8514986 - Flags: review?(andreea.matei)
Attachment #8514986 - Flags: review+
Comment on attachment 8514986 [details] [diff] [review]
patch v1.1

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

I kinda support this partial solution here. It should make this test indeed more stable. Please fix the mentioned issues and we are good to get this landed.

::: firefox/lib/search.js
@@ +342,5 @@
> +      }
> +    }
> +    Services.obs.addObserver(observer, TOPIC_SEARCH_ENGINE_MODIFIED, false);
> +    try {
> +      aAddEngineCallback();

I miss a couple of emtpy lines to separate different code blocks.
Attachment #8514986 - Flags: review?(hskupin) → review+
Attached patch patch v2.0Splinter Review
I added the empty lines.
Attachment #8515976 - Flags: review?(andrei.eftimie)
Attachment #8514986 - Attachment is obsolete: true
Comment on attachment 8515976 [details] [diff] [review]
patch v2.0

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

https://hg.mozilla.org/qa/mozmill-tests/rev/5831195b51a3 (default)
Attachment #8515976 - Flags: review?(andrei.eftimie)
Attachment #8515976 - Flags: review+
Attachment #8515976 - Flags: checkin+
We'll want this across branches.
The patch
The patch applies cleanly across all branches.
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
This is not fixed yet, we haven't landed it yet
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
No failure on the last nightly ran, let's backport it to aurora and beta.
http://mozmill-daily.blargon7.com/#/functional/top?app=All&branch=All&platform=All&from=2014-11-04&to=
All good on Aurora, transplanted:
https://hg.mozilla.org/qa/mozmill-tests/rev/260882fb593d (mozilla-aurora)
Lets get this in for the next beta run, all green for me on beta.
Transplanted:
https://hg.mozilla.org/qa/mozmill-tests/rev/b5dbb9e30b6b (mozilla-beta)
Transplanted:
https://hg.mozilla.org/qa/mozmill-tests/rev/abce00bc36d9 (mozilla-release)
https://hg.mozilla.org/qa/mozmill-tests/rev/55c9557e7c66 (mozilla-esr31)
Status: REOPENED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → FIXED
Product: Mozilla QA → Mozilla QA Graveyard
You need to log in before you can comment on or make changes to this bug.