1845380 - Intermittent browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | single tracking bug

Status: NEW

(Firefox :: Search, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=423830491&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NaBhCi_ySqWG5bMz_jnV-w/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/NaBhCi_ySqWG5bMz_jnV-w/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2023-07-25T17:34:11.420Z] 17:34:11     INFO - TEST-START | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js
[task 2023-07-25T17:34:11.697Z] 17:34:11     INFO - GECKO(28869) | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
[task 2023-07-25T17:34:13.507Z] 17:34:13     INFO - GECKO(28869) | console.debug: SearchTelemetry: "Impression:" "example:tagged:ff" "https://example.org/browser/browser/components/search/test/browser/telemetry/searchTelemetryAd_shopping.html?s=test&abc=ff"
[task 2023-07-25T17:34:13.645Z] 17:34:13     INFO - GECKO(28869) | console.debug: SearchTelemetry: "Reported Impression:" ({impressionId:"0cdf211f-4ab8-4504-8448-6d7b3d612bb7", provider:"example", tagged:true, partnerCode:"ff", source:"unknown", isShoppingPage:false, shoppingTabDisplayed:true})
[task 2023-07-25T17:34:14.565Z] 17:34:14     INFO - GECKO(28869) | console.debug: SearchTelemetry: "Counting ad:" ({type:"shopping_tab", adsLoaded:1, adsVisible:1, adsHidden:0})
[task 2023-07-25T17:36:15.697Z] 17:36:15     INFO - TEST-INFO | started process screentopng
[task 2023-07-25T17:36:16.023Z] 17:36:16     INFO - TEST-INFO | screentopng: exit 0
[task 2023-07-25T17:36:16.024Z] 17:36:16     INFO - Buffered messages logged at 17:34:11
[task 2023-07-25T17:36:16.025Z] 17:36:16     INFO - Entering setup bound 
[task 2023-07-25T17:36:16.026Z] 17:36:16     INFO - Console message: [JavaScript Error: "Error: Can't find profile directory." {file: "resource://gre/modules/XULStore.sys.mjs" line: 60}]
[task 2023-07-25T17:36:16.027Z] 17:36:16     INFO - load@resource://gre/modules/XULStore.sys.mjs:60:15
[task 2023-07-25T17:36:16.028Z] 17:36:16     INFO - XULStore@resource://gre/modules/XULStore.sys.mjs:17:10
[task 2023-07-25T17:36:16.029Z] 17:36:16     INFO - 
[task 2023-07-25T17:36:16.031Z] 17:36:16     INFO - Buffered messages logged at 17:34:12
[task 2023-07-25T17:36:16.032Z] 17:36:16     INFO - Leaving setup bound 
[task 2023-07-25T17:36:16.033Z] 17:36:16     INFO - Entering test bound test_inspect_shopping_tab_regexp_on_serp
[task 2023-07-25T17:36:16.035Z] 17:36:16     INFO - Buffered messages logged at 17:34:14
[task 2023-07-25T17:36:16.037Z] 17:36:16     INFO - TEST-PASS | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | Should have the correct number of impressions. - 1 == 1 - 
[task 2023-07-25T17:36:16.038Z] 17:36:16     INFO - TEST-PASS | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | Should have an impression_id with a valid UUID. - true == true - 
[task 2023-07-25T17:36:16.040Z] 17:36:16     INFO - TEST-PASS | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | Should have a unique impression_id. - true == true - 
[task 2023-07-25T17:36:16.042Z] 17:36:16     INFO - TEST-PASS | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | Should have matched impression values. - {"tagged":"true","is_shopping_page":"false","impression_id":"0cdf211f-4ab8-4504-8448-6d7b3d612bb7","partner_code":"ff","source":"unknown","shopping_tab_displayed":"true","provider":"example"} deepEqual {"provider":"example","tagged":"true","partner_code":"ff","source":"unknown","is_shopping_page":"false","shopping_tab_displayed":"true","impression_id":"0cdf211f-4ab8-4504-8448-6d7b3d612bb7"} - 
[task 2023-07-25T17:36:16.043Z] 17:36:16     INFO - TEST-PASS | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | Should have equal number of engagements. - 0 == 0 - 
[task 2023-07-25T17:36:16.067Z] 17:36:16     INFO - Buffered messages finished
[task 2023-07-25T17:36:16.073Z] 17:36:16     INFO - TEST-UNEXPECTED-FAIL | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | Test timed out - 
[task 2023-07-25T17:36:16.074Z] 17:36:16     INFO - GECKO(28869) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2023-07-25T17:36:16.076Z] 17:36:16     INFO - GECKO(28869) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2023-07-25T17:36:16.077Z] 17:36:16     INFO - GECKO(28869) | MEMORY STAT | vsize 130552039MB | residentFast 1061MB
[task 2023-07-25T17:36:16.079Z] 17:36:16     INFO - TEST-OK | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | took 124519ms
[task 2023-07-25T17:36:16.081Z] 17:36:16     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-07-25T17:36:16.082Z] 17:36:16     INFO - TEST-UNEXPECTED-FAIL | browser/components/search/test/browser/telemetry/browser_search_telemetry_shopping.js | Found a tab after previous test timed out: https://example.org/browser/browser/components/search/test/browser/telemetry/searchTelemetryAd_shopping.html?s=test&abc=ff - 
[task 2023-07-25T17:36:16.123Z] 17:36:16     INFO - GECKO(28869) | console.debug: SearchTelemetry: "Recording an abandonment event for impression id 0cdf211f-4ab8-4504-8448-6d7b3d612bb7 with reason: tab_close"
[task 2023-07-25T17:36:16.303Z] 17:36:16     INFO - checking window state
[task 2023-07-25T17:36:19.644Z] 17:36:19     INFO - GECKO(28869) | Completed ShutdownLeaks collections in process 29022
[task 2023-07-25T17:36:19.691Z] 17:36:19     INFO - GECKO(28869) | Completed ShutdownLeaks collections in process 28963
[task 2023-07-25T17:36:19.719Z] 17:36:19     INFO - GECKO(28869) | Completed ShutdownLeaks collections in process 29087
[task 2023-07-25T17:36:19.973Z] 17:36:19     INFO - GECKO(28869) | Completed ShutdownLeaks collections in process 28937
[task 2023-07-25T17:36:21.563Z] 17:36:21     INFO - GECKO(28869) | Completed ShutdownLeaks collections in process 28869
[task 2023-07-25T17:36:21.565Z] 17:36:21     INFO - TEST-START | Shutdown
[task 2023-07-25T17:36:21.566Z] 17:36:21     INFO - Browser Chrome Test Summary
[task 2023-07-25T17:36:21.568Z] 17:36:21     INFO - Passed:  5
[task 2023-07-25T17:36:21.571Z] 17:36:21     INFO - Failed:  2
[task 2023-07-25T17:36:21.571Z] 17:36:21     INFO - Todo:    0
[task 2023-07-25T17:36:21.572Z] 17:36:21     INFO - Mode:    e10s
[task 2023-07-25T17:36:21.573Z] 17:36:21     INFO - *** End BrowserChrome Test Results ***
[task 2023-07-25T17:36:22.276Z] 17:36:22     INFO - GECKO(28869) | 1690306582274	Marionette	TRACE	Received observer notification quit-application
[task 2023-07-25T17:36:22.280Z] 17:36:22     INFO - GECKO(28869) | 1690306582276	Marionette	INFO	Stopped listening on port 2828
[task 2023-07-25T17:36:22.286Z] 17:36:22     INFO - GECKO(28869) | 1690306582285	Marionette	DEBUG	Marionette stopped listening
[task 2023-07-25T17:36:23.170Z] 17:36:23     INFO - GECKO(28869) | console.error: ({})
[task 2023-07-25T17:36:26.527Z] 17:36:26     INFO - TEST-INFO | Main app process: exit 0
[task 2023-07-25T17:36:26.527Z] 17:36:26     INFO - runtests.py | Application ran for: 0:02:48.820624

Comment 1

[Intermittent Failures Robot]

1 failures in 3403 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1845380&startday=2023-07-24&endday=2023-07-30&tree=all

Comment 2

[Serban Stanca [:SerbanS]]

It started to fail on tier 1, as it can be seen here.

Comment 3

[Intermittent Failures Robot]

1 failures in 3952 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1845380&startday=2024-01-29&endday=2024-02-04&tree=all