1819321 - Intermittent TV browser/components/search/test/browser/browser_search_telemetry_sources_ads.js | single tracking bug

Status: RESOLVED FIXED

(Firefox :: Search, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=407264173&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WF99Rwj4SyqWELs1u--7-g/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WF99Rwj4SyqWELs1u--7-g/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2023-02-28T12:23:00.792Z] 12:23:00     INFO - TEST-PASS | browser/components/search/test/browser/browser_search_telemetry_sources_ads.js | Should have equal number of engagements. - 0 == 0 - 
[task 2023-02-28T12:23:00.792Z] 12:23:00     INFO - Leaving test bound test_track_no_ad_on_data_attributes_and_hrefs
[task 2023-02-28T12:23:00.792Z] 12:23:00     INFO - Entering test bound test_track_ad_on_DOMContentLoaded
[task 2023-02-28T12:23:00.793Z] 12:23:00     INFO - Buffered messages logged at 12:22:58
[task 2023-02-28T12:23:00.793Z] 12:23:00     INFO - Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/browser/browser/components/search/test/browser/SearchTelemetry.html" line: 0}]
[task 2023-02-28T12:23:00.794Z] 12:23:00     INFO - Buffered messages logged at 12:22:59
[task 2023-02-28T12:23:00.794Z] 12:23:00     INFO - Console message: [JavaScript Error: "TypeError: msg.wrappedJSObject.arguments[0].includes is not a function" {file: "chrome://mochitests/content/browser/browser/components/search/test/browser/browser_search_telemetry_sources_ads.js" line: 352}]
[task 2023-02-28T12:23:00.794Z] 12:23:00     INFO - Buffered messages finished
[task 2023-02-28T12:23:00.795Z] 12:23:00     INFO - TEST-UNEXPECTED-FAIL | browser/components/search/test/browser/browser_search_telemetry_sources_ads.js | Uncaught exception in test bound test_track_ad_on_DOMContentLoaded - at chrome://mochitests/content/browser/browser/components/search/test/browser/browser_search_telemetry_sources_ads.js:352 - TypeError: msg.wrappedJSObject.arguments[0].includes is not a function
[task 2023-02-28T12:23:00.796Z] 12:23:00     INFO - Stack trace:
[task 2023-02-28T12:23:00.796Z] 12:23:00     INFO - test_track_ad_on_DOMContentLoaded/observeAdPreviouslyRecorded<@chrome://mochitests/content/browser/browser/components/search/test/browser/browser_search_telemetry_sources_ads.js:352:45
[task 2023-02-28T12:23:00.796Z] 12:23:00     INFO - observe@resource://testing-common/TestUtils.sys.mjs:61:27
[task 2023-02-28T12:23:00.796Z] 12:23:00     INFO - CS_recordEvent@resource://gre/modules/ConsoleAPIStorage.jsm:172:19
[task 2023-02-28T12:23:00.796Z] 12:23:00     INFO - notify/<@resource://services-settings/RemoteSettingsComponents.sys.mjs:20:15
[task 2023-02-28T12:23:00.796Z] 12:23:00     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - TEST-UNEXPECTED-FAIL | browser/components/search/test/browser/browser_search_telemetry_sources_ads.js | A promise chain failed to handle a rejection: msg.wrappedJSObject.arguments[0].includes is not a function - stack: test_track_ad_on_DOMContentLoaded/observeAdPreviouslyRecorded<@chrome://mochitests/content/browser/browser/components/search/test/browser/browser_search_telemetry_sources_ads.js:352:45
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - observe@resource://testing-common/TestUtils.sys.mjs:61:27
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - CS_recordEvent@resource://gre/modules/ConsoleAPIStorage.jsm:172:19
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - notify/<@resource://services-settings/RemoteSettingsComponents.sys.mjs:20:15
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - Rejection date: Tue Feb 28 2023 12:22:59 GMT+0000 (Greenwich Mean Time) - false == true - {"filename":"resource://testing-common/PromiseTestUtils.sys.mjs","name":"assertNoUncaughtRejections","sourceId":584,"lineNumber":266,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":550,"lineNumber":1065,"columnNumber":22,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"handleTask@chrome://mochikit/content/browser-test.js:1065:22\n","nativeSavedFrame":{}},"formattedStack":"assertNoUncaughtRejections@resource://testing-common/PromiseTestUtils.sys.mjs:266:14\nhandleTask@chrome://mochikit/content/browser-test.js:1065:22\n","nativeSavedFrame":{}}
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - Stack trace:
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - resource://testing-common/PromiseTestUtils.sys.mjs:assertNoUncaughtRejections:266
[task 2023-02-28T12:23:00.798Z] 12:23:00     INFO - chrome://mochikit/content/browser-test.js:handleTask:1065
[task 2023-02-28T12:23:00.799Z] 12:23:00     INFO - Leaving test bound test_track_ad_on_DOMContentLoaded
[task 2023-02-28T12:23:00.799Z] 12:23:00     INFO - Entering test bound test_track_ad_on_load_event
[task 2023-02-28T12:23:00.799Z] 12:23:00     INFO - GECKO(2159) | [Child 2496: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 1218d2000 == 1 [pid = 2496] [id = 0]
[task 2023-02-28T12:23:00.800Z] 12:23:00     INFO - GECKO(2159) | [Child 2496: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (11cb1a5e0) [pid = 2496] [serial = 1] [outer = 0]
[task 2023-02-28T12:23:00.800Z] 12:23:00     INFO - GECKO(2159) | [Child 2496: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (1218d6400) [pid = 2496] [serial = 2] [outer = 11cb1a5e0]
[task 2023-02-28T12:23:01.408Z] 12:23:01     INFO - GECKO(2159) | [Child 2496: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (1218d8400) [pid = 2496] [serial = 3] [outer = 11cb1a5e0]
[task 2023-02-28T12:23:01.577Z] 12:23:01     INFO - GECKO(2159) | console.debug: SearchTelemetry: "Impression:" "4affe638-723b-4597-bc60-fedf05f6bb66" "slow-page-load:tagged:ff" "http://mochi.test:8888/browser/browser/components/search/test/browser/slow_loading_page_with_ads_on_load_event.html?s=test&abc=ff"
[task 2023-02-28T12:23:01.805Z] 12:23:01     INFO - GECKO(2159) | console.debug: SearchTelemetry: "Ad was previously reported for browser with URI" "http://mochi.test:8888/browser/browser/components/search/test/browser/slow_loading_page_with_ads.html?s=test&abc=ff"
[task 2023-02-28T12:23:02.157Z] 12:23:02     INFO - GECKO(2159) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/mq/nh4qy7tx44z95mb3_6rjsphc000014/T/tmprlz06ax9.mozrunner/runtests_leaks_tab_pid2507.log
[task 2023-02-28T12:23:02.157Z] 12:23:02     INFO - GECKO(2159) | [2507, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:345
[task 2023-02-28T12:23:02.191Z] 12:23:02     INFO - GECKO(2159) | [Child 2507, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-02-28T12:23:02.211Z] 12:23:02     INFO - GECKO(2159) | [Child 2507, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-02-28T12:23:02.212Z] 12:23:02     INFO - GECKO(2159) | [Child 2507, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-02-28T12:23:02.252Z] 12:23:02     INFO - GECKO(2159) | [Child 2507, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:475
[task 2023-02-28T12:23:03.552Z] 12:23:03     INFO - GECKO(2159) | [Child 2496: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 1218d7400 == 2 [pid = 2496] [id = 1]
[task 2023-02-28T12:23:03.553Z] 12:23:03     INFO - GECKO(2159) | [Child 2496: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (11cb1c6d0) [pid = 2496] [serial = 4] [outer = 0]
[task 2023-02-28T12:23:03.553Z] 12:23:03     INFO - GECKO(2159) | [Child 2496: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (1218dc400) [pid = 2496] [serial = 5] [outer = 11cb1c6d0]
[task 2023-02-28T12:23:04.079Z] 12:23:04     INFO - Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/browser/browser/components/search/test/browser/searchTelemetry.html" line: 0}]
[task 2023-02-28T12:23:05.224Z] 12:23:05     INFO - GECKO(2159) | console.debug: SearchTelemetry: "Counting ads in page for" "slow-page-load" "tagged" "unknown" "http://mochi.test:8888/browser/browser/components/search/test/browser/slow_loading_page_with_ads_on_load_event.html?s=test&abc=ff"
[task 2023-02-28T12:23:05.361Z] 12:23:05     INFO - TEST-PASS | browser/components/search/test/browser/browser_search_telemetry_sources_ads.js | Should only have one key - 0 == 0 - 

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

:jteow, since you are the author of the regressor, bug 1814773, could you take a look?

For more information, please visit auto_nag documentation.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1814773

Comment 3

[James Teow [:jteow]]

This might be a good indicator we should split the test out into a couple files.

Also not sure why the first argument to the log is not a string.

Comment 4

[Mark Banner (:standard8)]

(In reply to James Teow [:jteow] from comment #3)

Also not sure why the first argument to the log is not a string.

The error message here:

Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/browser/browser/components/search/test/browser/SearchTelemetry.html" line: 0}]

is probably what's triggering this. Depending on how these logs are called, we can get different message structures from consoleMessageObserved, e.g. console.log("foo") will provide a different structure to console.log(new Error("foo").

Though we could also add a <meta charset="utf-8"> to searchTelemetry.html which would avoid this log.

Also, I just spotted a couple of cases here, using the capital S for searchTelemetry.html we should probably correct those for consistency, even though it doesn't really matter.

Comment 5

[James Teow [:jteow]]

Oh of course, thanks Mark. I thought the reason was another part of the application was logging a non-string as the first argument, I didn't realize the answer was literally right in front of me.

Comment 6

[James Teow [:jteow]]

Attachment: Bug 1819321 - Add meta attribute to .html files used in search tests - r?standard8

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ca87d4fd6a26
Add meta attribute to .html files used in search tests - r=Standard8

Comment 8

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/ca87d4fd6a26

Comment 9

[Intermittent Failures Robot]

3 failures in 3752 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• macosx1015-64-qr: 2
  • debug: 1
  • opt: 1
• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1819321&startday=2023-02-27&endday=2023-03-05&tree=all