https://treeherder.mozilla.org/logviewer.html#?job_id=38755008&repo=mozilla-inbound [task 2016-11-07T09:11:42.681786Z] 09:11:42 INFO - TEST-START | browser/modules/test/browser_UsageTelemetry_searchbar.js [task 2016-11-07T09:13:12.873420Z] 09:13:12 INFO - TEST-INFO | started process screentopng [task 2016-11-07T09:13:14.511217Z] 09:13:14 INFO - TEST-INFO | screentopng: exit 0 [task 2016-11-07T09:13:14.514550Z] 09:13:14 INFO - Buffered messages logged at 09:11:42 [task 2016-11-07T09:13:14.516456Z] 09:13:14 INFO - Entering test bound setup [task 2016-11-07T09:13:14.521368Z] 09:13:14 INFO - Leaving test bound setup [task 2016-11-07T09:13:14.523218Z] 09:13:14 INFO - Entering test bound test_plainQuery [task 2016-11-07T09:13:14.524888Z] 09:13:14 INFO - Buffered messages logged at 09:11:43 [task 2016-11-07T09:13:14.526795Z] 09:13:14 INFO - Simulate entering a simple search. [task 2016-11-07T09:13:14.531121Z] 09:13:14 INFO - Buffered messages logged at 09:11:45 [task 2016-11-07T09:13:14.533550Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | browser.engagement.navigation.searchbar must be recorded. - true == true - [task 2016-11-07T09:13:14.535855Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | browser.engagement.navigation.searchbar must contain the 'search_enter' key. - true == true - [task 2016-11-07T09:13:14.542919Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | 1 - 1 == true - [task 2016-11-07T09:13:14.545615Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | This search must only increment one entry in the scalar. - 1 == 1 - [task 2016-11-07T09:13:14.550787Z] 09:13:14 INFO - Leaving test bound test_plainQuery [task 2016-11-07T09:13:14.553192Z] 09:13:14 INFO - Entering test bound test_oneOff [task 2016-11-07T09:13:14.558634Z] 09:13:14 INFO - Buffered messages logged at 09:11:46 [task 2016-11-07T09:13:14.560608Z] 09:13:14 INFO - Perform a one-off search using the first engine. [task 2016-11-07T09:13:14.563017Z] 09:13:14 INFO - Pressing Alt+Down to highlight the first one off engine. [task 2016-11-07T09:13:14.568247Z] 09:13:14 INFO - Buffered messages logged at 09:11:47 [task 2016-11-07T09:13:14.570500Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | browser.engagement.navigation.searchbar must be recorded. - true == true - [task 2016-11-07T09:13:14.574946Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | browser.engagement.navigation.searchbar must contain the 'search_oneoff' key. - true == true - [task 2016-11-07T09:13:14.577310Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | 1 - 1 == true - [task 2016-11-07T09:13:14.579852Z] 09:13:14 INFO - TEST-PASS | browser/modules/test/browser_UsageTelemetry_searchbar.js | This search must only increment one entry in the scalar. - 1 == 1 - [task 2016-11-07T09:13:14.589940Z] 09:13:14 INFO - Leaving test bound test_oneOff [task 2016-11-07T09:13:14.591672Z] 09:13:14 INFO - Entering test bound test_suggestion [task 2016-11-07T09:13:14.593591Z] 09:13:14 INFO - Buffered messages logged at 09:11:49 [task 2016-11-07T09:13:14.595446Z] 09:13:14 INFO - Perform a one-off search using the first engine. [task 2016-11-07T09:13:14.597231Z] 09:13:14 INFO - Buffered messages logged at 09:11:50 [task 2016-11-07T09:13:14.599365Z] 09:13:14 INFO - Console message: [JavaScript Error: "SearchSuggestionController: HTTP Timeout" {file: "resource://gre/modules/SearchSuggestionController.jsm" line: 341}] [task 2016-11-07T09:13:14.601209Z] 09:13:14 INFO - this.SearchSuggestionController.prototype._dedupeAndReturnResults@resource://gre/modules/SearchSuggestionController.jsm:341:9 [task 2016-11-07T09:13:14.604446Z] 09:13:14 INFO - Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:932:23 [task 2016-11-07T09:13:14.609942Z] 09:13:14 INFO - this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:813:7 [task 2016-11-07T09:13:14.611839Z] 09:13:14 INFO - Promise*this.PromiseWalker.scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:744:11 [task 2016-11-07T09:13:14.614039Z] 09:13:14 INFO - this.PromiseWalker.schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:776:7 [task 2016-11-07T09:13:14.617838Z] 09:13:14 INFO - this.PromiseWalker.completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:711:7 [task 2016-11-07T09:13:14.619733Z] 09:13:14 INFO - this.SearchSuggestionController.prototype._onRemoteTimeout@resource://gre/modules/SearchSuggestionController.jsm:315:7 [task 2016-11-07T09:13:14.621187Z] 09:13:14 INFO - [task 2016-11-07T09:13:14.623002Z] 09:13:14 INFO - Clicking the searchbar suggestion. [task 2016-11-07T09:13:14.626761Z] 09:13:14 INFO - Buffered messages finished [task 2016-11-07T09:13:14.628850Z] 09:13:14 INFO - TEST-UNEXPECTED-FAIL | browser/modules/test/browser_UsageTelemetry_searchbar.js | Test timed out - [task 2016-11-07T09:13:14.631253Z] 09:13:14 INFO - MEMORY STAT | vsize 20972938MB | residentFast 651MB [task 2016-11-07T09:13:14.634292Z] 09:13:14 INFO - TEST-OK | browser/modules/test/browser_UsageTelemetry_searchbar.js | took 90867ms [task 2016-11-07T09:13:14.636367Z] 09:13:14 INFO - Not taking screenshot here: see the one that was previously logged [task 2016-11-07T09:13:14.639351Z] 09:13:14 INFO - TEST-UNEXPECTED-FAIL | browser/modules/test/browser_UsageTelemetry_searchbar.js | Found a tab after previous test timed out: about:blank -

I think Alessio may be interested into this

(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #0) > [task 2016-11-07T09:13:14.589940Z] 09:13:14 INFO - Leaving test bound test_oneOff > [task 2016-11-07T09:13:14.591672Z] 09:13:14 INFO - Entering test bound test_suggestion > [task 2016-11-07T09:13:14.593591Z] 09:13:14 INFO - Buffered messages logged at 09:11:49 > [task 2016-11-07T09:13:14.595446Z] 09:13:14 INFO - Perform a one-off search using the first engine. > [task 2016-11-07T09:13:14.597231Z] 09:13:14 INFO - Buffered messages logged at 09:11:50 > [task 2016-11-07T09:13:14.599365Z] 09:13:14 INFO - Console message: [JavaScript Error: "SearchSuggestionController: HTTP Timeout" {file: "resource://gre/modules/SearchSuggestionController.jsm" line: 341}] It looks like the culprit is this last line, which is triggered from [1] after 0.5s. Other tests are overriding this timeout to prevent intermittents, see [2]. [1] - https://dxr.mozilla.org/mozilla-central/rev/8103c612b79c2587ea4ca1b0a9f9f82db4b185b8/toolkit/components/search/SearchSuggestionController.jsm#315 [2] - https://dxr.mozilla.org/mozilla-central/rev/8103c612b79c2587ea4ca1b0a9f9f82db4b185b8/browser/base/content/test/general/browser_aboutHome.js#320

Marco, any idea on how to access the controller for BrowserSearch.searchBar? I'm a bit confused, I thought that I could access it using |BrowserSearch.searchBar.textbox.controller| but apparently that's not the same controller I'm expecting (as it has no remoteTimeout). Any clue/suggestion?

The controller in this case appears to be this one http://searchfox.org/mozilla-central/rev/f680e72cc6579f90b992b63ca14d923d2afea612/toolkit/components/search/nsSearchSuggestions.js#27 that is part of SuggestAutoComplete SuggestAutoComplete is an instance of nsIAutoCompleteSearch, and as such you can only access the xpcom interface for it, uless you add wrappedJSObject to it. SuggestAutoComplete is instanced as a service so you could access it through getService of @mozilla.org/autocomplete/search;1?name=search-autocomplete Off-hand looks like here something is trying to http access a search engine suggestion url, and that timeouts, that could even be normal considered the test harness disallows that access... I guess you should probably check what may try to access search suggestions of a remote engine before you set your local one as the current engine?

As discussed over IRC, this patch adds a new hidden pref that controls the timeout for the search suggestion controller, so that we can override it for the searchbar test (it wasn't possible in a non-hackish way). As a consequence, I changed the other tests to rely on the same pref instead of trying to override the property manually. The timeout is now globally set for tests to a very conservative value: 10 seconds.

Here's a try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8fc4c5b6aa3d2249283ea3cc0e87a8c3a60fab91&selectedJob=33029357 No sign of intermittents or other failures here, the only proble m seems to be the WIndows 7 VM debug bc5 bustage on browser_ContentSearch.js, but it's unrelated to this patch and covered by bug 1188692.

Comment on attachment 8820182 [details] [diff] [review] bug1315650.patch Review of attachment 8820182 [details] [diff] [review]: ----------------------------------------------------------------- LGTM! ::: browser/modules/test/browser_ContentSearch.js @@ -191,5 @@ > type: "GetSuggestions", > data: { > engineName: engine.name, > searchString: searchStr, > - remoteTimeout: SUGGESTIONS_TIMEOUT, sounds like you can now remove const SUGGESTIONS_TIMEOUT = 10000; and the comment above it. ::: browser/modules/test/browser_UsageTelemetry_searchbar.js @@ +69,5 @@ > > // Enable Extended Telemetry. > + yield SpecialPowers.pushPrefEnv({"set": [ > + ["toolkit.telemetry.enabled", true], > + ["browser.search.suggest.timeout", 5000] do we actually need this, since you already set the pref in prefs_general? ::: toolkit/components/search/SearchSuggestionController.jsm @@ +17,5 @@ > const DEFAULT_FORM_HISTORY_PARAM = "searchbar-history"; > const HTTP_OK = 200; > const REMOTE_TIMEOUT = 500; // maximum time (ms) to wait before giving up on a remote suggestions > const BROWSER_SUGGEST_PREF = "browser.search.suggest.enabled"; > +const SUGGEST_REMOTE_TIMEOUT_PREF = "browser.search.suggest.timeout"; please move REMOTE_TIMEOUT after the pref const, and just rename them to: REMOTE_TIMEOUT_PREF REMOTE_TIMEOUT_DEFAULT (and update the callpoints, of course)

https://hg.mozilla.org/integration/mozilla-inbound/rev/02514bc7bc54bb207d6e9aab664368968ed15c90 Bug 1315650 - Add a longer timeout for searchbar suggestions in tests. r=mak

Worth taking on Aurora?

(In reply to [PTO 20-Dec to 28-Dec] Ryan VanderMeulen [:RyanVM] from comment #12) > Worth taking on Aurora? This patch also touches a bit of the search behaviour (refactors the timeout of the search controller), so I'd rather have this follow the trains normally. But thanks for asking!