HighFreq artifact telemetry/marionette/tests/client/test_fog_user_activity.py TestClientActivity.test_user_activity | AssertionError: Error waiting for ping: Timed out after 60.1 seconds
Categories
(Toolkit :: Telemetry, defect, P1)
Tracking
()
| Tracking | Status | |
|---|---|---|
| firefox-esr140 | --- | unaffected |
| firefox145 | --- | unaffected |
| firefox146 | --- | unaffected |
| firefox147 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: janerik)
References
(Blocks 1 open bug, Regression)
Details
(Keywords: intermittent-failure, regression, regressionwindow-wanted)
Attachments
(1 file)
Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=535785967&repo=autoland&task=XCwM3alCQtev_9ZHuv5ttg.0
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XCwM3alCQtev_9ZHuv5ttg/runs/0/artifacts/public/logs/live_backing.log
[task 2025-11-14T22:05:48.076+00:00] 22:05:48 INFO - pingserver pings_handler received 'main' ping with reason 'environment-change'
[task 2025-11-14T22:05:48.077+00:00] 22:05:48 INFO - 1763157948076 Toolkit.Telemetry INFO TelemetrySend::_doPing - successfully loaded, status: 200
[task 2025-11-14T22:05:48.077+00:00] 22:05:48 INFO - 1763157948076 Toolkit.Telemetry TRACE TelemetrySend::_onPingRequestFinished - success: true, persisted: false
[task 2025-11-14T22:05:48.077+00:00] 22:05:48 INFO - 1763157948077 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - bailing out after sending, shutdown: false, pendingPingCount: 0
[task 2025-11-14T22:06:18.027+00:00] 22:06:18 INFO - 1763157978027 Marionette DEBUG 1 -> [0,15,"Marionette:GetContext",{}]
[task 2025-11-14T22:06:18.028+00:00] 22:06:18 INFO - 1763157978027 Marionette DEBUG 1 <- [1,15,null,{"value":"content"}]
[task 2025-11-14T22:06:18.029+00:00] 22:06:18 INFO - 1763157978028 Marionette DEBUG 1 -> [0,16,"Marionette:SetContext",{"value":"chrome"}]
[task 2025-11-14T22:06:18.029+00:00] 22:06:18 INFO - 1763157978028 Marionette DEBUG 1 <- [1,16,null,{"value":null}]
[task 2025-11-14T22:06:18.030+00:00] 22:06:18 INFO - 1763157978029 Marionette DEBUG 1 -> [0,17,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2025-11-14T22:06:18.066+00:00] 22:06:18 INFO - 1763157978065 Marionette DEBUG 1 <- [1,17,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAPMCAYAAAAdHhQCAAAgAElEQVR4XuzdB5hdZbnw7zdlMpOeAAlJqEmAAKGjoHQEwfYhiB4R69Hvb8EuiBwPWI8KCoigHxZsR ... GBCAAAAAAjAlAAAAAABgTgAAAAAAwJgABAAAAYEwAAgAAAMCYAAQAAACAMQEIAAAAAGMCEAAAAADGBCAAAAAAjAlAAAAAABgLg2cBD565J50AAAAASUVORK5CYII="}]
[task 2025-11-14T22:06:18.067+00:00] 22:06:18 INFO - 1763157978067 Marionette DEBUG 1 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2025-11-14T22:06:18.067+00:00] 22:06:18 INFO - 1763157978067 Marionette DEBUG 1 <- [1,18,null,{"value":null}]
[task 2025-11-14T22:06:18.068+00:00] 22:06:18 INFO - 1763157978067 Marionette DEBUG 1 -> [0,19,"Marionette:GetContext",{}]
[task 2025-11-14T22:06:18.068+00:00] 22:06:18 INFO - 1763157978068 Marionette DEBUG 1 <- [1,19,null,{"value":"content"}]
[task 2025-11-14T22:06:18.068+00:00] 22:06:18 INFO - 1763157978068 Marionette DEBUG 1 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2025-11-14T22:06:18.069+00:00] 22:06:18 INFO - 1763157978068 Marionette DEBUG 1 <- [1,20,null,{"value":null}]
[task 2025-11-14T22:06:18.069+00:00] 22:06:18 INFO - 1763157978069 Marionette DEBUG 1 -> [0,21,"WebDriver:GetPageSource",{}]
[task 2025-11-14T22:06:18.072+00:00] 22:06:18 INFO - 1763157978072 RemoteAgent TRACE WebDriverProcessData actor created for PID 12366
[task 2025-11-14T22:06:18.074+00:00] 22:06:18 INFO - 1763157978073 Marionette TRACE [3] MarionetteCommands actor created for window id 8589934593
[task 2025-11-14T22:06:18.076+00:00] 22:06:18 INFO - 1763157978075 Marionette DEBUG 1 <- [1,21,null,{"value":"<html><head></head><body></body></html>"}]
[task 2025-11-14T22:06:18.077+00:00] 22:06:18 INFO - 1763157978076 Marionette DEBUG 1 -> [0,22,"Marionette:SetContext",{"value":"content"}]
[task 2025-11-14T22:06:18.077+00:00] 22:06:18 INFO - 1763157978076 Marionette DEBUG 1 <- [1,22,null,{"value":null}]
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - TEST-UNEXPECTED-FAIL | telemetry/marionette/tests/client/test_fog_user_activity.py TestClientActivity.test_user_activity | AssertionError: Error waiting for ping: Timed out after 60.1 seconds
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - Traceback (most recent call last):
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - File "/task_176315753717187/build/venv/lib/python3.10/site-packages/marionette_harness/marionette_test/testcases.py", line 193, in run
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - testMethod()
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - File "/task_176315753717187/build/tests/telemetry/marionette/tests/client/test_fog_user_activity.py", line 90, in test_user_activity
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - [ping4, ping5] = self.wait_for_pings(
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - File "/task_176315753717187/build/venv/lib/python3.10/site-packages/telemetry_harness/testcase.py", line 129, in wait_for_pings
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - self.fail(f"Error waiting for ping: {e}")
[task 2025-11-14T22:06:18.100+00:00] 22:06:18 INFO - TEST-INFO took 127888ms
|
||
Updated•7 months ago
|
| Comment hidden (Intermittent Failures Robot) |
Backfills lead to Bug 1996347
|
||
Comment 3•7 months ago
|
||
Set release status flags based on info from the regressing bug 1996347
:thecount, since you are the author of the regressor, bug 1996347, could you take a look?
For more information, please visit BugBot documentation.
|
||
Comment 5•7 months ago
|
||
Is there a way I can run this test locally?
|
|
||
Comment 6•7 months ago
|
||
This seems to do the trick
./mach test test_fog_user_activity.py
|
|
||
Comment 7•7 months ago
•
|
||
I cannot get this test to pass locally with or without my patch. I'm guessing how I am running it locally is wrong.
|
|
||
Comment 8•7 months ago
|
||
Going to try running it on a full debug build.
|
||
Comment 9•7 months ago
|
||
Are we sure that this has been caused by bug 1996347? I can already see those failures on November 12th on mozilla-central when the patch for the referenced bug wasn't yet on mozilla-central:
Maybe we need more backfill jobs to figure out which merge on mozilla-central actually caused it.
Narcis, given that you filed the bug would you be able to do that backfill? Thanks.
|
|
||
Comment 10•7 months ago
|
||
Note that I checked out a revision from Oct 3rd and I can still not run this test on MacOS. It keeps hanging.
Jan-Erik maybe you could have a look at this issue? I would appreciate. Thanks!
|
|
||
Comment 11•7 months ago
|
||
When I run this test with an artifact and non debug build, it fails before and after my patch.
When I run this test with a non artifact and debug build, it passes before and after my patch.
I guess if it's fairly intermittent, so that could be totally expected. I did try to find a pattern, but just no luck seeing this patch causing this test to fail, yet.
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 13•7 months ago
|
||
Interestingly I have a similar issue with a different test (xpcshell) for Telemetry which only happens in artifact mode. See bug 2001545 for details.
Now I wonder if bug 1998248 might also have caused this one.
|
|
||
Updated•7 months ago
|
|
||
Updated•7 months ago
|
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 15•7 months ago
|
||
Also needinfo'ing Chris in case Erik is not around.
|
Assignee | |
Comment 16•7 months ago
|
||
*Jan-Erik.
Sorry, should have left a comment. With bug 2001545 looking similar I asked Charlie to take a look if they are connected. I'll check in today what the status is.
|
||
Updated•7 months ago
|
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Updated•6 months ago
|
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
|
Assignee | |
Comment 21•6 months ago
|
||
I never actually looked into the actual failures, because this bug mentioned "artifact".
This test is already disabled on artifact builds: https://searchfox.org/firefox-main/rev/965f7176dd09e26daca9efbfdf23dce16da43e97/toolkit/components/telemetry/tests/marionette/tests/client/manifest.toml#17-19
It's failing for me on a fresh build locally too. I'll take a look.
|
|
Assignee | |
Comment 22•6 months ago
|
||
Firefox can be quite chatty at startup, triggering the default-limit of
15 pings per minute.
That's fine in normal usage, where the browser runs longer and
eventually starts uploading again.
But the test can't wait for the timeout, so for now we raise the limit
and have all pings get through.
This also addresses bug 2000502 with the same "fix".
|
||
Comment 23•6 months ago
|
||
|
||
Comment 24•6 months ago
|
||
| bugherder | ||
| Comment hidden (Intermittent Failures Robot) |
Description
•