Closed Bug 1062096 Opened 6 years ago Closed 5 years ago

Intermittent browser_aboutHome.js | application crashed [@ nsSocketTransport::InitiateSocket()] (i.e. FATAL ERROR: Non-local network connections are disabled and a connection attempt to www.google.com (74.125.239.144) was made.)

Categories

(Firefox :: General, defect)

x86
Windows XP
defect
Not set
Points:
8

Tracking

()

RESOLVED FIXED
Firefox 36
Iteration:
36.2
Tracking Status
firefox34 --- fixed
firefox35 --- fixed
firefox36 --- fixed
firefox-esr31 --- unaffected

People

(Reporter: philor, Assigned: Gijs)

References

Details

Attachments

(2 files, 1 obsolete file)

https://tbpl.mozilla.org/php/getParsedLog.php?id=47284227&tree=Fx-Team
Windows XP 32-bit fx-team debug test mochitest-browser-chrome-1 on 2014-09-02 21:35:05 PDT for push 53ab51cc4eb0
slave: t-xp32-ix-064

20:37:08     INFO -  XML Parsing Error: mismatched tag. Expected: </b>.
20:37:08     INFO -  Location:
20:37:08     INFO -  Line Number 1, Column 221:
20:37:08     INFO -  <html xmlns="http://www.w3.org/1999/xhtml"><body xmlns="http://www.w3.org/1999/xhtml"><div xmlns="http://www.w3.org/1999/xhtml"><div xmlns="http://www.w3.org/1999/xhtml"><div xmlns="http://www.w3.org/1999/xhtml"><p><b></p></b></
20:37:08     INFO -  ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------^
20:37:08     INFO -  [3688] ###!!! ASSERTION: Want to fire DOMNodeRemoved event, but it's not safe: 'Error', file c:/builds/moz2_slave/fx-team-w32-d-0000000000000000/build/content/base/src/nsContentUtils.cpp, line 3900
(stack)
20:37:17     INFO -  [3688] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsSimpleURI.cpp, line 265
20:37:17     INFO -  ++DOCSHELL 14644C00 == 55 [pid = 3688] [id = 123]
20:37:17     INFO -  ++DOMWINDOW == 104 (14664800) [pid = 3688] [serial = 323] [outer = 00000000]
20:37:17     INFO -  ++DOMWINDOW == 105 (169C2C00) [pid = 3688] [serial = 324] [outer = 14664800]
20:37:17     INFO -  [3688] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsSimpleURI.cpp, line 265
20:37:17     INFO -  ++DOMWINDOW == 106 (0D0A8000) [pid = 3688] [serial = 325] [outer = 14664800]
20:37:17     INFO -  [3688] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsSimpleURI.cpp, line 265
20:37:17     INFO -  [3688] WARNING: attempt to modify an immutable nsStandardURL: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsStandardURL.cpp, line 1239
20:37:17     INFO -  [3688] WARNING: attempt to modify an immutable nsStandardURL: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsStandardURL.cpp, line 1239
20:37:17     INFO -  [3688] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\dom\quota\QuotaManager.cpp, line 2046
20:37:17     INFO -  [3688] WARNING: NS_ENSURE_TRUE(isFileURI) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\content\base\src\ThirdPartyUtil.cpp, line 314
20:37:18     INFO -  [3688] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsSimpleURI.cpp, line 265
20:37:18     INFO -  ++DOCSHELL 14322000 == 56 [pid = 3688] [id = 124]
20:37:18     INFO -  ++DOMWINDOW == 107 (14661C00) [pid = 3688] [serial = 326] [outer = 00000000]
20:37:18     INFO -  ++DOMWINDOW == 108 (174A5800) [pid = 3688] [serial = 327] [outer = 14661C00]
20:37:18     INFO -  [3688] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsSimpleURI.cpp, line 265
20:37:18     INFO -  ++DOMWINDOW == 109 (0C413400) [pid = 3688] [serial = 328] [outer = 14661C00]
20:37:18     INFO -  [3688] WARNING: NS_ENSURE_TRUE(mMutable) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsSimpleURI.cpp, line 265
20:37:18     INFO -  [3688] WARNING: attempt to modify an immutable nsStandardURL: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsStandardURL.cpp, line 1239
20:37:18     INFO -  [3688] WARNING: attempt to modify an immutable nsStandardURL: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\netwerk\base\src\nsStandardURL.cpp, line 1239
20:37:18     INFO -  [3688] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80070057: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\dom\quota\QuotaManager.cpp, line 2046
20:37:18     INFO -  [3688] WARNING: NS_ENSURE_TRUE(isFileURI) failed: file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\content\base\src\ThirdPartyUtil.cpp, line 314
20:37:19     INFO -  --DOCSHELL 110D8800 == 55 [pid = 3688] [id = 65]
(me GC you long time)
20:37:19     INFO -  FATAL ERROR: Non-local network connections are disabled and a connection attempt to www.google.com (74.125.239.144) was made.
20:37:19     INFO -  You should only access hostnames available via the test networking proxy (if running mochitests) or from a test-specific httpd.js server (if running xpcshell tests). Browser services should be disabled or redirected to a local server.
20:37:19     INFO -  Hit MOZ_CRASH(Attempting to connect to non-local address!) at c:/builds/moz2_slave/fx-team-w32-d-0000000000000000/build/netwerk/base/src/nsSocketTransport2.cpp:1202
20:37:19     INFO -  nsSocketTransport::OnSocketEvent(unsigned int,tag_nsresult,nsISupports *) [netwerk/base/src/nsSocketTransport2.cpp:1723]
20:37:19     INFO -  nsSocketEvent::Run() [netwerk/base/src/nsSocketTransport2.cpp:83]
20:37:19     INFO -  nsThread::ProcessNextEvent(bool,bool *) [xpcom/threads/nsThread.cpp:823]
20:37:19     INFO -  NS_ProcessNextEvent(nsIThread *,bool) [xpcom/glue/nsThreadUtils.cpp:265]
20:37:19     INFO -  nsSocketTransportService::Run() [netwerk/base/src/nsSocketTransportService2.cpp:746]
20:37:19     INFO -  nsThread::ProcessNextEvent(bool,bool *) [xpcom/threads/nsThread.cpp:823]
20:37:19     INFO -  NS_ProcessNextEvent(nsIThread *,bool) [xpcom/glue/nsThreadUtils.cpp:265]
20:37:19     INFO -  mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate *) [ipc/glue/MessagePump.cpp:355]
20:37:19     INFO -  MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:229]
20:37:19     INFO -  MessageLoop::RunHandler() [ipc/chromium/src/base/message_loop.cc:223]
20:37:19     INFO -  MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:197]
20:37:19     INFO -  nsThread::ThreadFunc(void *) [xpcom/threads/nsThread.cpp:359]
20:37:19     INFO -  _PR_NativeRunThread [nsprpub/pr/src/threads/combined/pruthr.c:397]
20:37:19     INFO -  pr_root [nsprpub/pr/src/md/windows/w95thred.c:90]
20:37:19     INFO -  MSVCR100 + 0x5c6de
20:37:19     INFO -  MSVCR100 + 0x5c788
20:37:19     INFO -  kernel32 + 0xb713
20:37:19     INFO -  [3688] ###!!! ABORT: Tear-off objects remain in hashtable at shutdown.: '!mTable', file c:\builds\moz2_slave\fx-team-w32-d-0000000000000000\build\content\svg\content\src\nsSVGAttrTearoffTable.h, line 28
20:37:19     INFO -  TEST-INFO | Main app process: exit status 80000003
20:37:19  WARNING -  TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
20:37:19     INFO -  32 INFO checking window state
20:37:19     INFO -  33 INFO Check that clearing cookies does not clear storage
20:37:19     INFO -  34 INFO Waiting for snippets map
20:37:19     INFO -  35 INFO Wait tab event: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  36 INFO Got snippets map: { last-update: undefined, cached-version: undefined }
20:37:19     INFO -  37 INFO Tab event received: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  38 INFO Running test
20:37:19     INFO -  39 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | snippets-last-update should have a value
20:37:19     INFO -  40 INFO Cleanup
20:37:19     INFO -  41 INFO Check default snippets are shown
20:37:19     INFO -  42 INFO Waiting for snippets map
20:37:19     INFO -  43 INFO Wait tab event: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  44 INFO Got snippets map: { last-update: undefined, cached-version: undefined }
20:37:19     INFO -  45 INFO Tab event received: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  46 INFO Running test
20:37:19     INFO -  47 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Found snippets element
20:37:19     INFO -  48 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | A default snippet is present.
20:37:19     INFO -  49 INFO Cleanup
20:37:19     INFO -  50 INFO Check default snippets are shown if snippets are invalid xml
20:37:19     INFO -  51 INFO Waiting for snippets map
20:37:19     INFO -  52 INFO Wait tab event: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  53 INFO Got snippets map: { last-update: undefined, cached-version: undefined }
20:37:19     INFO -  54 INFO Tab event received: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  55 INFO Console message: [JavaScript Error: "about:home : Unable to run script because scripts are blocked internally."]
20:37:19     INFO -  56 INFO Console message: [JavaScript Error: "mismatched tag. Expected: </b>."]
20:37:19     INFO -  57 INFO Running test
20:37:19     INFO -  58 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Found snippets element
20:37:19     INFO -  59 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | A default snippet is present.
20:37:19     INFO -  60 INFO Cleanup
20:37:19     INFO -  61 INFO Check that search engine logo has alt text
20:37:19     INFO -  62 INFO Waiting for snippets map
20:37:19     INFO -  63 INFO Wait tab event: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  64 INFO Got snippets map: { last-update: undefined, cached-version: undefined }
20:37:19     INFO -  65 INFO Tab event received: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  66 INFO Running test
20:37:19     INFO -  67 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Found search engine logo
20:37:19     INFO -  68 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Search engine logo's alt text is a nonempty string
20:37:19     INFO -  69 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Search engine logo's alt text shouldn't be the string 'undefined'
20:37:19     INFO -  70 INFO Cleanup
20:37:19     INFO -  71 INFO Check that performing a search fires a search event and records to Firefox Health Report.
20:37:19     INFO -  72 INFO Waiting for snippets map
20:37:19     INFO -  73 INFO Wait tab event: AboutHomeLoadSnippetsCompleted
20:37:19     INFO -  74 INFO Got snippets map: { last-update: undefined, cached-version: undefined }
20:37:19     INFO -  75 INFO Tab event received: AboutHomeLoadSnippetsCompleted
20:37:20     INFO -  76 INFO Running test
20:37:20     INFO -  77 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Health Reporter instance available.
20:37:20     INFO -  78 INFO waitForDocLoadAndStopIt: Waiting for URL: https://www.google.com/search?q=a+search&ie=utf-8&oe=utf-8&aq=t&rls=org.mozilla:en-US:unofficial&client=firefox-a&channel=np&source=hp
20:37:20     INFO -  79 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Searches provider is available.
20:37:20     INFO -  80 INFO Perform a search.
20:37:20     INFO -  81 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Detail is search engine name
20:37:20     INFO -  82 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Health Reporter instance available.
20:37:20     INFO -  83 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Searches provider is available.
20:37:20     INFO -  84 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | application terminated with exit code 2147483651
20:37:20     INFO -  runtests.py | Application ran for: 0:00:50.035000
20:37:20     INFO -  zombiecheck | Reading PID log: c:\docume~1\cltbld~1.t-x\locals~1\temp\tmpymdodvpidlog
20:37:28     INFO -  mozcrash Saved minidump as C:\slave\test\build\blobber_upload_dir\a79ac966-c934-48ff-a733-79447f2bfd67.dmp
20:37:28     INFO -  mozcrash Saved app info as C:\slave\test\build\blobber_upload_dir\a79ac966-c934-48ff-a733-79447f2bfd67.extra
20:37:28  WARNING -  PROCESS-CRASH | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | application crashed [@ nsSocketTransport::InitiateSocket()]
20:37:28     INFO -  Crash dump filename: c:\docume~1\cltbld~1.t-x\locals~1\temp\tmp7dkm0f.mozrunner\minidumps\a79ac966-c934-48ff-a733-79447f2bfd67.dmp
20:37:28     INFO -  Operating system: Windows NT
20:37:28     INFO -                    5.1.2600 Service Pack 3
20:37:28     INFO -  CPU: x86
20:37:28     INFO -       GenuineIntel family 6 model 30 stepping 5
20:37:28     INFO -       8 CPUs
20:37:28     INFO -  Crash reason:  EXCEPTION_BREAKPOINT
20:37:28     INFO -  Crash address: 0x1e94706
20:37:28     INFO -  Thread 5 (crashed)
20:37:28     INFO -   0  xul.dll!nsSocketTransport::InitiateSocket() [nsSocketTransport2.cpp:53ab51cc4eb0 : 1202 + 0x17]
20:37:28     INFO -      eip = 0x01e94706   esp = 0x090ffaac   ebp = 0x090ffc44   ebx = 0x00000001
20:37:28     INFO -      esi = 0x09167d28   edi = 0x0d362d50   eax = 0x00000000   ecx = 0x78abff12
20:37:28     INFO -      edx = 0x78b545b0   efl = 0x00000206
20:37:28     INFO -      Found by: given as instruction pointer in context
20:37:28     INFO -   1  xul.dll!nsSocketTransport::OnSocketEvent(unsigned int,tag_nsresult,nsISupports *) [nsSocketTransport2.cpp:53ab51cc4eb0 : 1723 + 0x6]
20:37:28     INFO -      eip = 0x01e94dca   esp = 0x090ffc4c   ebp = 0x090ffc58
20:37:28     INFO -      Found by: call frame info
20:37:28     INFO -   2  xul.dll!nsSocketEvent::Run() [nsSocketTransport2.cpp:53ab51cc4eb0 : 82 + 0x1a]
20:37:28     INFO -      eip = 0x01e94f1e   esp = 0x090ffc60   ebp = 0x090ffc6c
20:37:28     INFO -      Found by: call frame info
20:37:28     INFO -   3  xul.dll!nsThread::ProcessNextEvent(bool,bool *) [nsThread.cpp:53ab51cc4eb0 : 823 + 0xd]
20:37:28     INFO -      eip = 0x01e43655   esp = 0x090ffc74   ebp = 0x090ffd48
20:37:28     INFO -      Found by: call frame info

Rather mangled seeming log, with the start of the network-touching crash looking like it's well before the test stops running, but the smart money would bet on it actually being there where the end of the log indicates, in the FHR search code which was the reason the test was disabled in bug 995041, and according to my memory of it the reason for several disablings before that. Apparently this method of stopping the load works... quite a bit of the time. Other times, it kills the entire browser-chrome run by hitting the network.
Marco: Looking at what was done in bug 995041, I'm confused as to why we're even bothering to try to stop a load when the test could have just changed the URL of the engine used to be a local test domain, and thereby preventing this kind of issue ever occurring in the first place.
Flags: needinfo?(mak77)
It's out of the scope of that code to actually do a real search or load a page, stopping the request can still save precious resources.
Unfortunately looks like waitForDocLoadAndStopIt has issues :( 
That said, yes, I think it's a good idea to define a local search engine, thus ensuring we can't touch the network at all. We just didn't think about that.
Flags: needinfo?(mak77)
IIRC the test that was updated in bug 995041 has to load a page that's a known search provider to FHR, because that's what the test is testing.
the fact is that if I read that correctly, FHR tests themselves use a fake provider...
Oh, if I had known that was possible I would have fixed bug 995041 that way.  I should have thought to see if it was.  Lack of imagination.
The run-by-dir landing made this near perma-fail prior to being backed out, in case that helps.
Flags: firefox-backlog+
Flags: qe-verify?
Flags: qe-verify? → qe-verify-
Gavin, if adw is gone for the next couple weeks, is there someone else who can look into this frequent failure?
Flags: needinfo?(gavin.sharp)
Flags: needinfo?(gavin.sharp) → needinfo?(ttaubert)
Points: --- → 8
QA Whiteboard: [qa-]
QA Whiteboard: [qa-]
Added to the fx-team backlog. Just need to wait for someone to pick it up tomorrow.
Flags: needinfo?(ttaubert)
Don't worry, we know how (from having done it before) to disable the entire test to stop these failures in a part of it from killing the entire test suite's run.
Flags: needinfo?(ryanvm)
Gavin, per comment 69, it appears this should have been picked up a couple weeks ago? Any chance we could get some eyes on it soon?
Flags: needinfo?(ryanvm) → needinfo?(gavin.sharp)
We'll get it assigned tomorrow.
Flags: needinfo?(gavin.sharp)
Assignee: nobody → gijskruitbosch+bugs
Status: NEW → ASSIGNED
Iteration: --- → 36.2
So I would have expected something along these lines to work... but it seems the number of searches isn't incremented. I've checked that the relevant code gets called (recordSearch in SearchesProvider). The only thing I can see that might be different is that the field needs to be initialized, but even waiting for 5 seconds (see patch) doesn't help in terms of then getting the right value back from FHR. Greg, can you help clear up why FHR isn't updating for this search engine? Does the first increment call always result in the row being initialized at 0 or something?
Attachment #8514236 - Flags: feedback?(gps)
Comment on attachment 8514236 [details] [diff] [review]
browser_aboutHome should use a fake search engine instead of google to test FHR reporting,

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

I didn't look at the whole patch, just the part that looks like a smoking gun.

::: browser/base/content/test/general/browser_aboutHome.js
@@ +101,5 @@
>  {
>    desc: "Check that performing a search fires a search event and records to " +
>          "Firefox Health Report.",
>    setup: function () { },
> +  run: function* () {

You turned this into a generator and added a few yields below. I see no sign this function was previously being called as a Task. Therefore, I'd expect the function to execute until the first yield and then pause indefinitely. That may be the source of your bug.
Attachment #8514236 - Flags: feedback?(gps)
Comment on attachment 8514236 [details] [diff] [review]
browser_aboutHome should use a fake search engine instead of google to test FHR reporting,

The test completes, and there are pre-existing yields in that function. The test runner uses Task.spawn and yield with the result of test.run, too. That really isn't the issue (and if it was, the failure mode would be very different). The only thing happening here is that I get this:

249 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | One more search recorded. - Got 0, expected 1
Stack trace:
chrome://mochikit/content/browser-test.js:test_is:829
chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js:gTests<.run/</</<:140
resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:Handler.prototype.process:865
resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:this.PromiseWalker.walkerLoop:744
null:null:0
SUITE-END | took 218s
Attachment #8514236 - Flags: feedback?(gps)
Comment on attachment 8514236 [details] [diff] [review]
browser_aboutHome should use a fake search engine instead of google to test FHR reporting,

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

You should turn on full FHR debug logging and see what is and isn't happening.

See browser/base/content/test/general/browser_datareporting_notification.js for the pattern.

You may also be able to import services/common/modules-testing/logging.js and call initTestLogging("Trace") to do the same. Although I can't remember if that works for FHR like it does Sync and other components.

Please upload a log of that output for me to look at and I'll be able to tell you more.
Attachment #8514236 - Flags: feedback?(gps)
Attached file fhr-log.txt
Is this what you mean?
Flags: needinfo?(gps)
That log is exactly what is needed!

The important bits are near the end:

67 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Searches provider is available. 
68 INFO Perform a search.
waitForDocLoadAndStopIt: onStateChange f0001: http://browser-searchsuggestionengine.com/searchSuggestionEngine
waitForDocLoadAndStopIt: Document start: http://browser-searchsuggestionengine.com/searchSuggestionEngine
1414711927464	Services.Metrics.MetricsStorage	TRACE	Enqueueing operation.
1414711927464	Services.Metrics.MetricsStorage	TRACE	Performing queued operation.
1414711927464	Sqlite.Connection.healthreport.sqlite#0: 	TRACE	undefinedStmt #307 INSERT INTO fields (measurement_id, name, value_type)   VALUES (:measurement_id, :field, :value_type) - {"measurement_id":13,"field":"other-browser_searchSuggestionEngine searchSuggestionEngine.xml.abouthome","value_type":1}
69 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | waitForDocLoadAndStopIt: The expected URL was loaded 
1414711927471	Sqlite.Connection.healthreport.sqlite#0: 	DEBUG	undefinedStmt #307 finished.
1414711927472	Sqlite.Connection.healthreport.sqlite#0: 	TRACE	undefinedStmt #308 SELECT id FROM fields   WHERE measurement_id = :measurement_id     AND name = :field     AND value_type = :value_type  - {"measurement_id":13,"field":"other-browser_searchSuggestionEngine searchSuggestionEngine.xml.abouthome","value_type":1}
70 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Detail is search engine name 
71 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Health Reporter instance available. 
72 INFO TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | Searches provider is available. 
1414711927474	Services.Metrics.MetricsStorage	TRACE	Enqueueing operation.
1414711927474	Sqlite.Connection.healthreport.sqlite#0: 	DEBUG	undefinedStmt #308 finished.
1414711927475	Sqlite.Connection.healthreport.sqlite#0: 	TRACE	undefinedStmt #309 INSERT OR REPLACE INTO daily_counters VALUES (  :field_id,   :days,   COALESCE(    (SELECT value FROM daily_counters WHERE       field_id = :field_id AND day = :days     ),     0  ) + :by) - {"field_id":83,"days":16373,"by":1}
1414711927477	Sqlite.Connection.healthreport.sqlite#0: 	DEBUG	undefinedStmt #309 finished.
1414711927478	Services.Metrics.MetricsStorage	TRACE	Queued operation completed.
1414711927478	Services.Metrics.MetricsStorage	TRACE	Performing queued operation.
1414711927478	Sqlite.Connection.healthreport.sqlite#0: 	TRACE	undefinedStmt #310 SELECT field_name, day, value FROM v_daily_counters WHERE measurement_id = :measurement_id - {"measurement_id":13}
1414711927478	Sqlite.Connection.healthreport.sqlite#0: 	DEBUG	undefinedStmt #310 finished.
1414711927479	Services.Metrics.MetricsStorage	TRACE	Queued operation completed.
73 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js | One more search recorded. - Got 0, expected 1
Stack trace:
chrome://mochikit/content/browser-test.js:test_is:829
chrome://mochitests/content/browser/browser/base/content/test/general/browser_aboutHome.js:gTests<.run/</<:148
resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:Handler.prototype.process:865
resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:this.PromiseWalker.walkerLoop:744
null:null:0


We see the "other search engine" field being created:

1414711927464	Sqlite.Connection.healthreport.sqlite#0: 	TRACE	undefinedStmt #307 INSERT INTO fields (measurement_id, name, value_type)   VALUES (:measurement_id, :field, :value_type) - {"measurement_id":13,"field":"other-browser_searchSuggestionEngine searchSuggestionEngine.xml.abouthome","value_type":1}

We see the SQL incrementing the counter:

1414711927475	Sqlite.Connection.healthreport.sqlite#0: 	TRACE	undefinedStmt #309 INSERT OR REPLACE INTO daily_counters VALUES (  :field_id,   :days,   COALESCE(    (SELECT value FROM daily_counters WHERE       field_id = :field_id AND day = :days     ),     0  ) + :by) - {"field_id":83,"days":16373,"by":1}

We also see the SELECT (driven by the test comparison) immediately afterwards:

1414711927478	Sqlite.Connection.healthreport.sqlite#0: 	TRACE	undefinedStmt #310 SELECT field_name, day, value FROM v_daily_counters WHERE measurement_id = :measurement_id - {"measurement_id":13}

On first glance, this looks correct! We see the counter increment going to the DB. What is going on?

I suspect you are inserting to a different field than you are querying from. But there isn't enough info in the log to know for certain (we should probably log field IDs when they are created to make this thing easier).

Add a log statement to https://hg.mozilla.org/mozilla-central/file/21fbf1e35090/services/metrics/storage.jsm#l1107, |mach build services|, and trace the logs to see if the field IDs match up. I bet they don't. From there, you can start double checking your code for references to the wrong search engine or search type.
Flags: needinfo?(gps)
The increment happens with the correct field id, and the 'get' gets the right info, too. Still trying to figure out where the info gets lost on its way to the test.

(In reply to Gregory Szorc [:gps] from comment #134)
> |mach build services|

FWIW, this doesn't build browser/app, which it should, because that alone doesn't show me my changes. As a workaround, using |./mach build services browser/base| works.
Of course, it turns out the answer is very mundane: the test code here: http://hg.mozilla.org/mozilla-central/annotate/5999e92e89ff/browser/base/content/test/general/browser_aboutHome.js#l625 relies on an identifier, which non-builtin search engines don't have. FHR actually records things fine, but the filtering in that function then dumps everything. Having the test set an identifier on the engine's wrappedJSObject makes this issue go away.
Attachment #8514236 - Attachment is obsolete: true
Comment on attachment 8515973 [details] [diff] [review]
browser_aboutHome should use a fake search engine instead of google to test FHR reporting,

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

Thanks Gijs, nice that this turned out to be pretty simple.

::: browser/base/content/test/general/browser_aboutHome.js
@@ +115,5 @@
>        // Health Report disabled, or no SearchesProvider.
>        return Promise.resolve();
>      }
>  
> +    let engine = yield promiseNewEngine("searchSuggestionEngine.xml");

Nice, glad you could reuse this.

@@ +158,5 @@
>                        uri.spec;
>      let loadPromise = waitForDocLoadAndStopIt(expectedURL);
>  
> +    let completionPromise = Promise.all([searchEventDeferred.promise, loadPromise]);
> +    return completionPromise.then(function() {

Can't you just use yield and try-catch here since you've made this function a generator?  Would be nicer to read.
Attachment #8515973 - Flags: review?(adw) → review+
w/ nits:

remote:   https://hg.mozilla.org/integration/fx-team/rev/838442064267
Whiteboard: [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/838442064267

<3
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 36
Depends on: 1094421
Note that this bug was closed as FIXED 2 years ago.  I suspect many (maybe all) of the last 2 years' starrings on this bug are *actually* bug 1188692.  (At least -- I just hit an instance of bug 1188692 on treeherder*, and treeherder incorrectly suggested this bug here as the first match.)

*https://treeherder.mozilla.org/#/jobs?repo=mozilla-aurora&selectedJob=67309311
You need to log in before you can comment on or make changes to this bug.