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)
Tracking
()
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.
Comment hidden (Intermittent Failures Robot) |
Comment 2•6 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Comment 3•5 years ago
|
||
New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=289711113&repo=autoland&lineNumber=2082
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 6•5 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 8•5 years ago
|
||
Matthew,
Could you please redirect this to someone who can take a look?
Comment 9•5 years ago
|
||
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?
Updated•5 years ago
|
Updated•5 years ago
|
Assignee | ||
Comment 10•5 years ago
|
||
Assignee | ||
Updated•5 years ago
|
Assignee | ||
Comment 11•5 years ago
|
||
Updated•5 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 15•5 years ago
|
||
Comment 16•5 years ago
|
||
Backed out for failing bc at browser_openSite.js
Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception&revision=356470def108537fb897e8baa01e127ace5ff017&selectedJob=293351829
Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293351829&repo=autoland&lineNumber=11774
Backout: https://hg.mozilla.org/integration/autoland/rev/d72cc8e3d9496e2b4dbc4e98800d0c25463e0c37
Assignee | ||
Updated•5 years ago
|
Comment 17•5 years ago
|
||
Comment 18•5 years ago
|
||
Backed out changeset f0ba03f01bb7 (Bug 1605494) for causing failures in browser_osAuthDialog.js CLOSED TREE
Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293400997&repo=autoland&lineNumber=1978
Backout: https://hg.mozilla.org/integration/autoland/rev/c08c7e279175f8386eba6fe75494b3fc9b7c4998
Comment hidden (Intermittent Failures Robot) |
Comment 20•5 years ago
|
||
Comment 21•5 years ago
|
||
Backed out 2 changesets (bug 1611914, bug 1605494) for causing browser_contextmenuFillLogins.js failures
https://hg.mozilla.org/integration/autoland/rev/3173bd3b7987d45c24fb7f6d63b91be9cf5b9e97
push that caused the backout: https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=293609623&revision=66b802c651c4bc2b2f8f155ed536aa45a50e825f&searchStr=linux%2C18.04%2Cx64%2Casan%2Copt%2Cmochitests%2Ctest-linux1804-64-asan%2Fopt-mochitest-browser-chrome-e10s-14%2Cm%28bc14%29
Comment hidden (Intermittent Failures Robot) |
Comment 23•5 years ago
|
||
Comment 24•5 years ago
•
|
||
Backed out 2 changesets (bug 1611914, bug 1605494) for causing browser chrome failures at browser/components/aboutlogins/tests/browser/browser_osAuthDialog.js
Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=293696648&repo=autoland&lineNumber=1970
[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
Assignee | ||
Updated•5 years ago
|
Comment 25•5 years ago
|
||
Updated•5 years ago
|
Updated•5 years ago
|
Comment 26•5 years ago
|
||
bugherder |
Comment 27•5 years ago
|
||
Jared, this is still happening on nightly:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&fromchange=f985871b3e622041babc71f3770275f045ae7f33&searchStr=linux%2C18.04%2Cx64%2Cccov%2Copt%2Cmochitests%2Ctest-linux1804-64-ccov%2Fopt-mochitest-browser-chrome-e10s-5%2Cm%28bc5%29&selectedJob=293844739
Should we reopen the bug?
Assignee | ||
Comment 28•5 years ago
|
||
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.
Comment 29•5 years ago
|
||
Did some retriggers on the jobs that should run that test:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&fromchange=f985871b3e622041babc71f3770275f045ae7f33&test_paths=browser%2Fcomponents%2Faboutlogins%2Ftests%2Fbrowser&tochange=f985871b3e622041babc71f3770275f045ae7f33
So far only happens on linux ccov opt so I guess it would be enough to disable it on that.
Assignee | ||
Comment 30•5 years ago
|
||
Thanks, I'll file a new bug and attach a patch.
Assignee | ||
Comment 31•5 years ago
|
||
Filed bug 1623644.
Comment hidden (Intermittent Failures Robot) |
Comment 33•5 years ago
|
||
(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.
Description
•