Closed Bug 1605494 Opened 6 years ago Closed 5 years ago

Intermittent browser/components/aboutlogins/tests/browser/browser_aaa_eventTelemetry_run_first.js | Uncaught exception - waiting for telemetry event count of: 2 - timed out after 50 tries.

Categories

(Firefox :: about:logins, defect, P1)

defect

Tracking

()

RESOLVED FIXED
Firefox 76
Tracking Status
firefox76 --- fixed

People

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

References

(Regression)

Details

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

Attachments

(1 file)

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=282165852&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/DSExfiB0TUOjDrbZ_tNnbA/runs/0/artifacts/public/logs/live_backing.log


[task 2019-12-20T21:20:09.455Z] 21:20:09 INFO - TEST-START | browser/components/aboutlogins/tests/browser/browser_aaa_eventTelemetry_run_first.js
[task 2019-12-20T21:20:13.709Z] 21:20:13 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:13.810Z] 21:20:13 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:13.913Z] 21:20:13 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.014Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.115Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.214Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.318Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.417Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.517Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.619Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.718Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.823Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:14.924Z] 21:20:14 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.024Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.126Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.229Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.328Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.431Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.535Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.634Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.734Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.839Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:15.938Z] 21:20:15 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.039Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.140Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.241Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.345Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.445Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.544Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.646Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.747Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.852Z] 21:20:16 INFO - GECKO(3616) | Waiting for 2 events, got 1
[task 2019-12-20T21:20:16.952Z] 21:20:16 INFO - TEST-INFO | started process screenshot
[task 2019-12-20T21:20:17.032Z] 21:20:17 INFO - TEST-INFO | screenshot: exit 0
[task 2019-12-20T21:20:17.032Z] 21:20:17 INFO - Buffered messages logged at 21:20:09
[task 2019-12-20T21:20:17.032Z] 21:20:17 INFO - Entering test bound setup
[task 2019-12-20T21:20:17.032Z] 21:20:17 INFO - Leaving test bound setup
[task 2019-12-20T21:20:17.032Z] 21:20:17 INFO - Entering test bound setup
[task 2019-12-20T21:20:17.032Z] 21:20:17 INFO - Buffered messages logged at 21:20:11
[task 2019-12-20T21:20:17.032Z] 21:20:17 INFO - Leaving test bound setup
[task 2019-12-20T21:20:17.033Z] 21:20:17 INFO - Entering test bound test_telemetry_events
[task 2019-12-20T21:20:17.033Z] 21:20:17 INFO - Buffered messages finished
[task 2019-12-20T21:20:17.033Z] 21:20:17 INFO - TEST-UNEXPECTED-FAIL | browser/components/aboutlogins/tests/browser/browser_aaa_eventTelemetry_run_first.js | Uncaught exception - waiting for telemetry event count of: 2 - timed out after 50 tries.

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Matthew,
Could you please redirect this to someone who can take a look?

Flags: needinfo?(MattN+bmo)

This is probably related to bug 1194529 even though it's not in the range. Jared re-enabled that test for debug builds: https://hg.mozilla.org/mozilla-central/rev/f630ffb8bc0b86a97bc173fec31778759f2565df

Jared, maybe this bug can be where we switch to using the channel instead of only testing in debug builds?

Flags: needinfo?(MattN+bmo) → needinfo?(jaws)
Priority: P5 → P1
Regressed by: 1194529
Has Regression Range: --- → yes
Keywords: regression
Whiteboard: [stockwell needswork:owner]
Assignee: nobody → jaws
Status: REOPENED → ASSIGNED
Assignee: nobody → jaws
Pushed by jwein@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/356470def108 Use update channel instead of debug to determine if we can mock the OS auth dialog. r=MattN
Flags: needinfo?(jaws)
Pushed by jwein@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f0ba03f01bb7 Use update channel instead of debug to determine if we can mock the OS auth dialog. r=MattN
Pushed by jwein@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/b335ab938965 Use update channel instead of debug to determine if we can mock the OS auth dialog. r=MattN
Pushed by jwein@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f93685e544c5 Use update channel instead of debug to determine if we can mock the OS auth dialog. r=MattN

Backed out 2 changesets (bug 1611914, bug 1605494) for causing browser chrome failures at browser/components/aboutlogins/tests/browser/browser_osAuthDialog.js

Push with failure: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=293696648&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=b0ef46ae385361a8eac610adc5e1801117afe838

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293696648&repo=autoland&lineNumber=1970

Backout link: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=293696648&resultStatus=testfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=e9d4c770a20ce4d154d0d40ca436363db4ba533e


[task 2020-03-18T16:27:44.202Z] 16:27:44     INFO - Leaving test bound setup
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - Entering test bound test
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - updatechannel: nightly-autoland; platform: macosx
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - TEST-PASS | browser/components/aboutlogins/tests/browser/browser_osAuthDialog.js | skipping test since oskeystore cannot be automated in this environment - 
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - Buffered messages finished
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - TEST-UNEXPECTED-FAIL | browser/components/aboutlogins/tests/browser/browser_osAuthDialog.js | Test timed out - 
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - Console message: SENTINEL
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - GECKO(1848) | MEMORY STAT | vsize 7605MB | residentFast 349MB | heapAllocated 110MB
[task 2020-03-18T16:27:44.203Z] 16:27:44     INFO - TEST-OK | browser/components/aboutlogins/tests/browser/browser_osAuthDialog.js | took 45069ms
[task 2020-03-18T16:27:44.204Z] 16:27:44     INFO - checking window state
[task 2020-03-18T16:27:44.204Z] 16:27:44     INFO - GECKO(1848) | must wait for focus
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - Buffered messages finished
[task 2020-03-18T16:33:54.214Z] 16:33:54    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/aboutlogins/tests/browser/browser_osAuthDialog.js (finished) | application timed out after 370 seconds with no output
[task 2020-03-18T16:33:54.214Z] 16:33:54    ERROR - Force-terminating active process(es).
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - Determining child pids from psutil...
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - [1850, 1849, 1852, 1853, 1854, 1855, 1856, 1857, 1858, 1851]
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1849
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1850
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1851
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1852
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1853
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1854
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1855
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1856
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1857
[task 2020-03-18T16:33:54.214Z] 16:33:54     INFO - ==> process 1848 launched child process 1858
[task 2020-03-18T16:33:54.219Z] 16:33:54     INFO - Found child pids: set([1856, 1857, 1858, 1849, 1850, 1851, 1852, 1853, 1854, 1855])
[task 2020-03-18T16:33:54.219Z] 16:33:54     INFO - Killing process: 1856
[task 2020-03-18T16:33:54.219Z] 16:33:54     INFO - Not taking screenshot here: see the one that was previously logged
Flags: needinfo?(jaws)
Pushed by jwein@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/e0bee5295677 Use update channel instead of debug to determine if we can mock the OS auth dialog. r=MattN
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:patch
Whiteboard: [stockwell fixed:patch → [stockwell fixed:patch]
Status: ASSIGNED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 76

Does it only happen on CCov builds? If so I would like to skip this test in those builds. This is extremely hard for me to reproduce locally. I was only able to reproduce this once, the first time actually, and then not able to reproduce it in ~1000 subsequent runs.

Flags: needinfo?(jaws) → needinfo?(malexandru)
Flags: needinfo?(malexandru)

Thanks, I'll file a new bug and attach a patch.

(In reply to Intermittent Failures Robot from comment #32)

70 failures in 4955 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

Fixed by bug 1623644.

See Also: → 1627419
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: