Closed Bug 1569281 Opened 5 years ago Closed 4 years ago

Intermittent [TV] toolkit/components/normandy/test/browser/browser_RecipeRunner.js | Test timed out -

Categories

(Firefox :: Normandy Client, defect, P5)

Product:
Firefox
Component:
Normandy Client
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 74
Tracking Flags:
Tracking Status
firefox-esr68 --- unaffected
firefox71 --- unaffected
firefox72 --- wontfix
firefox73 --- fixed
firefox74 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: leplatrem)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell fixed:other])

Attachments

(1 file)

Bug 1569281 - Fix intermittent failure on Normandy Recipe Runner tests r?mythmon
47 bytes, text/x-phabricator-request
Details | Review

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

[task 2019-07-26T19:41:51.792Z] 19:41:51 INFO - TEST-START | toolkit/components/normandy/test/browser/browser_RecipeRunner.js
[task 2019-07-26T19:41:54.359Z] 19:41:54 INFO - GECKO(5260) | *** UTM:SVC TimerManager:unregisterTimer - id: recipe-client-addon-run
[task 2019-07-26T19:41:54.359Z] 19:41:54 INFO - GECKO(5260) | *** UTM:SVC TimerManager:registerTimer - timerID: recipe-client-addon-run interval: 1
[task 2019-07-26T19:41:54.359Z] 19:41:54 INFO - GECKO(5260) | *** UTM:SVC TimerManager:notify - fire timerID: addon-background-update-timer intended time: 86400 (1970-01-02T00:00:00.000Z)
[task 2019-07-26T19:41:54.359Z] 19:41:54 INFO - GECKO(5260) | *** UTM:SVC TimerManager:notify - notified @mozilla.org/addons/integration;1
[task 2019-07-26T19:41:55.208Z] 19:41:55 INFO - GECKO(5260) | *** UTM:SVC TimerManager:notify - fire timerID: blocklist-background-update-timer intended time: 86400 (1970-01-02T00:00:00.000Z)
[task 2019-07-26T19:41:55.213Z] 19:41:55 INFO - GECKO(5260) | *** UTM:SVC TimerManager:notify - notified @mozilla.org/extensions/blocklist;1
[task 2019-07-26T19:42:36.816Z] 19:42:36 INFO - TEST-INFO | started process screenshot
[task 2019-07-26T19:42:36.886Z] 19:42:36 INFO - TEST-INFO | screenshot: exit 0
[task 2019-07-26T19:42:36.887Z] 19:42:36 INFO - <snipped 39 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2019-07-26T19:42:36.887Z] 19:42:36 INFO - Buffered messages logged at 19:41:51
[task 2019-07-26T19:42:36.888Z] 19:42:36 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | User id is read from prefs when accessed -

[task 2019-07-26T19:42:36.933Z] 19:42:36 INFO - Entering test bound testRunCanRunOnlyOnce
[task 2019-07-26T19:42:36.933Z] 19:42:36 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() is no-op if already running -
[task 2019-07-26T19:42:36.933Z] 19:42:36 INFO - Leaving test bound testRunCanRunOnlyOnce
[task 2019-07-26T19:42:36.933Z] 19:42:36 INFO - Entering test bound testSyncDelaysTimer
[task 2019-07-26T19:42:36.933Z] 19:42:36 INFO - Console message: UTM:SVC TimerManager:unregisterTimer - id: recipe-client-addon-run
[task 2019-07-26T19:42:36.934Z] 19:42:36 INFO - Console message: UTM:SVC TimerManager:registerTimer - timerID: recipe-client-addon-run interval: 1
[task 2019-07-26T19:42:36.934Z] 19:42:36 INFO - Console message: UTM:SVC TimerManager:notify - fire timerID: addon-background-update-timer intended time: 86400 (1970-01-02T00:00:00.000Z)
[task 2019-07-26T19:42:36.934Z] 19:42:36 INFO - Console message: UTM:SVC TimerManager:notify - notified @mozilla.org/addons/integration;1
[task 2019-07-26T19:42:36.934Z] 19:42:36 INFO - Buffered messages logged at 19:41:55
[task 2019-07-26T19:42:36.934Z] 19:42:36 INFO - Console message: UTM:SVC TimerManager:notify - fire timerID: blocklist-background-update-timer intended time: 86400 (1970-01-02T00:00:00.000Z)
[task 2019-07-26T19:42:36.934Z] 19:42:36 INFO - Console message: UTM:SVC TimerManager:notify - notified @mozilla.org/extensions/blocklist;1
[task 2019-07-26T19:42:36.934Z] 19:42:36 INFO - Buffered messages finished
[task 2019-07-26T19:42:36.935Z] 19:42:36 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | Test timed out -
[task 2019-07-26T19:42:36.935Z] 19:42:36 INFO - GECKO(5260) | MEMORY STAT | vsize 2104139MB | vsizeMaxContiguous 65489207MB | residentFast 244MB | heapAllocated 96MB
[task 2019-07-26T19:42:36.935Z] 19:42:36 INFO - TEST-OK | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | took 45056ms
[task 2019-07-26T19:42:36.935Z] 19:42:36 INFO - checking window state
[task 2019-07-26T19:42:36.935Z] 19:42:36 INFO - GECKO(5260) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-07-26T19:42:36.935Z] 19:42:36 INFO - Console message: 1564170156819 app.normandy.recipe-runner WARN Disabling Shield because app.normandy.api_url is not an HTTPS url: http://example.com.
[task 2019-07-26T19:42:36.936Z] 19:42:36 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-07-26T19:42:38.193Z] 19:42:38 INFO - GECKO(5260) | Completed ShutdownLeaks collections in process 832
[task 2019-07-26T19:42:38.198Z] 19:42:38 INFO - GECKO(5260) | Completed ShutdownLeaks collections in process 7744
[task 2019-07-26T19:42:38.198Z] 19:42:38 INFO - GECKO(5260) | Completed ShutdownLeaks collections in process 3900
[task 2019-07-26T19:42:38.203Z] 19:42:38 INFO - GECKO(5260) | Completed ShutdownLeaks collections in process 4704
[task 2019-07-26T19:42:38.221Z] 19:42:38 INFO - GECKO(5260) | Completed ShutdownLeaks collections in process 6184
[task 2019-07-26T19:42:38.221Z] 19:42:38 INFO - GECKO(5260) | Completed ShutdownLeaks collections in process 4596
[task 2019-07-26T19:42:38.934Z] 19:42:38 INFO - GECKO(5260) | Completed ShutdownLeaks collections in process 1344
[task 2019-07-26T19:42:38.934Z] 19:42:38 INFO - TEST-START | Shutdown
[task 2019-07-26T19:42:38.934Z] 19:42:38 INFO - Browser Chrome Test Summary
[task 2019-07-26T19:42:38.934Z] 19:42:38 INFO - Passed: 183
[task 2019-07-26T19:42:38.934Z] 19:42:38 INFO - Failed: 1
[task 2019-07-26T19:42:38.935Z] 19:42:38 INFO - Todo: 0
[task 2019-07-26T19:42:38.935Z] 19:42:38 INFO - Mode: e10s
[task 2019-07-26T19:42:38.935Z] 19:42:38 INFO - *** End BrowserChrome Test Results ***

This started on a backout https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=258532266&revision=020b4a73328ab03ee24746f800bcf5485fd013d6

So far only TV failures.

Summary: Intermittent toolkit/components/normandy/test/browser/browser_RecipeRunner.js | Test timed out - → Intermittent [TV] toolkit/components/normandy/test/browser/browser_RecipeRunner.js | Test timed out -
Whiteboard: [retriggered]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=271378305&repo=autoland&lineNumber=1404

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE

New occurrence:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=278096287&repo=autoland&lineNumber=1984

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Reopened after Bug 1598930 landed.

Regressed by: 1598930

No failures since Nov 27th.

There are 27 failures for the past week. This is seen on linux and windows platforms.

This was the first occurrence in the past week:
https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=280408162&revision=cf1537e7065e8a11573f104e78fa071fe3738169

Log link:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=280408162&repo=autoland&lineNumber=1412

Log snippet:

[task 2019-12-10T01:31:23.651Z] 01:31:23 INFO - Entering test bound testPrefWatching
[task 2019-12-10T01:31:23.651Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | Enable should be idempotent -
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | Disable should be idempotent -
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - Leaving test bound testPrefWatching
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - Entering test bound testRunOnSyncRemoteSettings
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() should not be called if disabled -
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() should not be called if pref not set -
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() should be called if pref is set -
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() should not be called if disabled with pref set -
[task 2019-12-10T01:31:23.652Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() should be called at most once if runner is re-enabled -
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() should not be called if pref is unset -
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() should still not be called if disabled -
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - Leaving test bound testRunOnSyncRemoteSettings
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - Entering test bound testRunCanRunOnlyOnce
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - TEST-PASS | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | run() is no-op if already running -
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - Leaving test bound testRunCanRunOnlyOnce
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - Entering test bound testSyncDelaysTimer
[task 2019-12-10T01:31:23.653Z] 01:31:23 INFO - Console message: UTM:SVC TimerManager:unregisterTimer - id: recipe-client-addon-run
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - Console message: UTM:SVC TimerManager:registerTimer - timerID: recipe-client-addon-run interval: 1 skipFirst: false
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - Console message: UTM:SVC TimerManager:notify - fire timerID: addon-background-update-timer intended time: 86400 (1970-01-02T00:00:00.000Z)
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - Console message: UTM:SVC TimerManager:notify - notified @mozilla.org/addons/integration;1
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - Buffered messages logged at 01:30:42
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - Console message: UTM:SVC TimerManager:notify - fire timerID: blocklist-background-update-timer intended time: 86400 (1970-01-02T00:00:00.000Z)
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - Console message: UTM:SVC TimerManager:notify - notified @mozilla.org/extensions/blocklist;1
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - Buffered messages finished
[task 2019-12-10T01:31:23.654Z] 01:31:23 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | Test timed out -
[task 2019-12-10T01:31:23.655Z] 01:31:23 INFO - Console message: 1575941483530 app.normandy.recipe-runner WARN Disabling Shield because app.normandy.api_url is not set.
[task 2019-12-10T01:31:23.655Z] 01:31:23 INFO - GECKO(2164) | MEMORY STAT | vsize 762MB | vsizeMaxContiguous 763MB | residentFast 219MB | heapAllocated 99MB
[task 2019-12-10T01:31:23.655Z] 01:31:23 INFO - TEST-OK | toolkit/components/normandy/test/browser/browser_RecipeRunner.js | took 45038ms
[task 2019-12-10T01:31:23.655Z] 01:31:23 INFO - checking window state

Michael can you assign someone to take a look at he above?

Flags: needinfo?(mcooper)
Whiteboard: [retriggered] → [retriggered][stockwell needswork:owner]

Mat, this looks related to the sync/timer interaction you worked on. Do you have some time to take a look?

Flags: needinfo?(mcooper) → needinfo?(mathieu)

Yes, I started to look at it this morning ;)

Assignee: nobody → mathieu
Flags: needinfo?(mathieu)

Quick note...

The problem is that we have very little control over the timer that is about to be executed when this timer manager service interface is "notified".

The way we do it in this test assumes that no timer will overtake the one we're interested into (recipe-client-addon-run) when we notify.
In the logs, we can see that sometimes (🤷) another timer becomes the next in the list and is executed instead (eg. addon-background-update-timer)

The first solution that came into my mind was to simulate a run of the addon update timer by setting a pref, but looking at other occurrences of this intermittent, I could see that some other timers were triggered too sometimes (search-engine-update-timer, services-settings-poll-changes, ...).

One way to iterate through every registered timer is to use Services.catMan.enumerateCategory("update-timer"), or through the private _timers variable on the underlying JS implementation of the interface. And then disable every other known timer except ours.

Another reasonable way would be to add a new interface method to force the execution of a particular timer, but I really don't know what it takes to implement that.

I'll focus on the first solution and see what comes out.

No failures here since the 13th december: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-11-30&endday=2019-12-30&tree=trunk&bug=1569281
I think maybe https://hg.mozilla.org/mozilla-central/rev/0e667fc70d92a9fcabe6b9299727e62bc9dd4ebe took care of the failures here. Closing this but feel free to reopen if it hits again.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 4 years ago
status-firefox73: --- → fixed
Resolution: --- → FIXED
Whiteboard: [retriggered][stockwell needswork:owner] → [retriggered][stockwell fixed:other]
Target Milestone: --- → Firefox 73

Mike, should we land the changes of the patch?

I think we should, yeah. Let me take a look at the state of reviews on that patch.

Pushed by mleplatre@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ea061e56322b
Fix intermittent failure on Normandy Recipe Runner tests r=mythmon,mconley
status-firefox73: fixed → ---
status-firefox74: --- → fixed
Target Milestone: Firefox 73 → Firefox 74

Since the status are different for nightly and release, what's the status for beta?
For more information, please visit auto_nag documentation.

status-firefox73: --- → ?
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: