1584961 - Intermittent (TV) toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | a telemetry experiment should be activated - [["activity-stream-extended-triplets","control"]

Status: RESOLVED FIXED

(Firefox :: Normandy Client, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=269021503&repo=mozilla-inbound
Full log: https://queue.taskcluster.net/v1/task/JB6gENfJR7yBfL3hJz_4vw/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://queue.taskcluster.net/v1/task/JB6gENfJR7yBfL3hJz_4vw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

INFO - TEST-START | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js
[task 2019-09-30T11:39:48.838Z] 11:39:48     INFO - TEST-INFO | started process screenshot
[task 2019-09-30T11:39:48.920Z] 11:39:48     INFO - TEST-INFO | screenshot: exit 0
[task 2019-09-30T11:39:48.920Z] 11:39:48     INFO - Buffered messages logged at 11:39:48
[task 2019-09-30T11:39:48.922Z] 11:39:48     INFO - Entering test bound simple_recipe_enrollment
[task 2019-09-30T11:39:48.925Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | lastError should be null - 
[task 2019-09-30T11:39:48.925Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | integer pref should be set - 
[task 2019-09-30T11:39:48.927Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | boolean pref should be set - 
[task 2019-09-30T11:39:48.930Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | string pref should be set - 
[task 2019-09-30T11:39:48.934Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | integer startup pref should be set - 
[task 2019-09-30T11:39:48.934Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | boolean startup pref should be set - 
[task 2019-09-30T11:39:48.934Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | string startup pref should be set - 
[task 2019-09-30T11:39:48.935Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | Rollout should be stored in db - [{"slug":"test-rollout","state":"active","preferences":[{"preferenceName":"test.pref1","value":1,"previousValue":null},{"preferenceName":"test.pref2","value":true,"previousValue":null},{"preferenceName":"test.pref3","value":"it works","previousValue":null}],"enrollmentId":"ee5046f3-b655-40c5-882d-3ff42be59342"}] deepEqual [{"slug":"test-rollout","state":"active","preferences":[{"preferenceName":"test.pref1","value":1,"previousValue":null},{"preferenceName":"test.pref2","value":true,"previousValue":null},{"preferenceName":"test.pref3","value":"it works","previousValue":null}],"enrollmentId":"ee5046f3-b655-40c5-882d-3ff42be59342"}] - 
[task 2019-09-30T11:39:48.935Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | Rollout should have a UUID enrollmentId - 
[task 2019-09-30T11:39:48.936Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | parent must be in snapshot. Has [parent]. - true == true - 
[task 2019-09-30T11:39:48.937Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | After filtering we must have the expected number of events. - 1 == 1 - 
[task 2019-09-30T11:39:48.938Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | category in event normandy#enroll#preference_rollout must match. - "normandy" matches "normandy" - 
[task 2019-09-30T11:39:48.941Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | method in event normandy#enroll#preference_rollout must match. - "enroll" matches "enroll" - 
[task 2019-09-30T11:39:48.941Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | object in event normandy#enroll#preference_rollout must match. - "preference_rollout" matches "preference_rollout" - 
[task 2019-09-30T11:39:48.941Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | value in event normandy#enroll#preference_rollout must match. - "test-rollout" matches "test-rollout" - 
[task 2019-09-30T11:39:48.942Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | Actual event normandy#enroll#preference_rollout expected to have extra. - true == true - 
[task 2019-09-30T11:39:48.942Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | Expected key enrollmentId must be in actual extra. Actual keys: [enrollmentId]. - true == true - 
[task 2019-09-30T11:39:48.942Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | extra[enrollmentId] must match in event normandy#enroll#preference_rollout. - "ee5046f3-b655-40c5-882d-3ff42be59342" matches "ee5046f3-b655-40c5-882d-3ff42be59342" - 
[task 2019-09-30T11:39:48.943Z] 11:39:48     INFO - Buffered messages finished
[task 2019-09-30T11:39:48.943Z] 11:39:48     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | a telemetry experiment should be activated - [["activity-stream-extended-triplets","control"],["test-rollout","active",{"type":"normandy-prefrollout","enrollmentId":"ee5046f3-b655-40c5-882d-3ff42be59342"}]] deepEqual [["test-rollout","active",{"type":"normandy-prefrollout","enrollmentId":"ee5046f3-b655-40c5-882d-3ff42be59342"}]] - JS frame :: chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js :: simple_recipe_enrollment :: line 109
[task 2019-09-30T11:39:48.943Z] 11:39:48     INFO - Stack trace:
[task 2019-09-30T11:39:48.943Z] 11:39:48     INFO - chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js:simple_recipe_enrollment:109
[task 2019-09-30T11:39:48.944Z] 11:39:48     INFO - chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/head.js:wrappedTestFunction:345
[task 2019-09-30T11:39:48.944Z] 11:39:48     INFO - chrome://mochitests/content/browser/toolkit/components/normandy/test/browser/head.js:wrappedTestFunction:304
[task 2019-09-30T11:39:48.944Z] 11:39:48     INFO - resource://normandy/lib/PreferenceRollouts.jsm:inner:194
[task 2019-09-30T11:39:48.944Z] 11:39:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1350
[task 2019-09-30T11:39:48.945Z] 11:39:48     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1385
[task 2019-09-30T11:39:48.945Z] 11:39:48     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-09-30T11:39:48.945Z] 11:39:48     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-09-30T11:39:48.945Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | Telemetry events should not fail - true == true - 
[task 2019-09-30T11:39:48.946Z] 11:39:48     INFO - Console message: [JavaScript Warning: "normandy.recipe_freshness - Truncating float/double number."]
[task 2019-09-30T11:39:48.946Z] 11:39:48     INFO - Leaving test bound simple_recipe_enrollment
[task 2019-09-30T11:39:48.947Z] 11:39:48     INFO - Entering test bound update_enrollment
[task 2019-09-30T11:39:48.947Z] 11:39:48     INFO - Console message: [JavaScript Warning: "normandy.recipe_freshness - Truncating float/double number."]
[task 2019-09-30T11:39:48.947Z] 11:39:48     INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_actions_PreferenceRolloutAction.js | lastError should be null - 

Comment 1

[Dorel Luca [:dluca]]

This bug is most likely a regression caused by Bug 1555176

Comment 2

[Michael Cooper [:mythmon]]

Dorel, how did you determine that bug 1555176 was the regressing bug? From my reading, it looks like bug 1572640 is the regressing bug, since it is the bug that added the activity-stream-extended-triplets experiment. That bug introduced an experiment that runs at Firefox startup, and has a small chance to call setExperimentActive.

Comment 3

[Michael Cooper [:mythmon]]

Attachment: Bug 1584961 - Use sinon matcher instead of exact call list in Normandy preference rollout test r=Gijs

This avoids an intermittent test failure when other parts of Firefox set experiments active while this test is running

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/97f48d8b40a6
Use sinon matcher instead of exact call list in Normandy preference rollout test r=Gijs

Comment 5

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/97f48d8b40a6

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-inbound: 4

Platform breakdown:

• linux64: 1
• windows7-32: 1
• linux64-shippable: 1
• windows7-32-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1584961&startday=2019-09-30&endday=2019-10-06&tree=all