1805153 - WARNING: A blocker encountered an error while we were waiting (Blocker: Waiting for ping task)

Status: RESOLVED DUPLICATE of bug 1804692

(Toolkit :: Telemetry, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This warning can be seen in a lot of automated tests in CI right now during shutdown and it seems to cause a delay of ~5s. As result quite a lot of mochitest relalted tests are running into a task timeout (bug 1580652) because Firefox gets quit/started quiet often.

Here the details:

https://treeherder.mozilla.org/logviewer?job_id=399107857&repo=mozilla-central&lineNumber=5566

[task 2022-12-09T05:59:45.263Z] 05:59:45     INFO - GECKO(7817) | WARNING: A blocker encountered an error while we were waiting.
[task 2022-12-09T05:59:45.265Z] 05:59:45     INFO - GECKO(7817) |           Blocker:  Waiting for ping task
[task 2022-12-09T05:59:45.266Z] 05:59:45     INFO - GECKO(7817) |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-12-09T05:59:45.267Z] 05:59:45     INFO - GECKO(7817) |           State: (none)
[task 2022-12-09T05:59:45.270Z] 05:59:45     INFO - GECKO(7817) | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-12-09T05:59:45.274Z] 05:59:45     INFO - GECKO(7817) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:718:15
[task 2022-12-09T05:59:45.275Z] 05:59:45     INFO - GECKO(7817) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:523:26
[task 2022-12-09T05:59:45.283Z] 05:59:45     INFO - GECKO(7817) | addBlocker@resource://gre/modules/AsyncShutdown.jsm:462:15
[task 2022-12-09T05:59:45.284Z] 05:59:45     INFO - GECKO(7817) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2022-12-09T05:59:45.285Z] 05:59:45     INFO - GECKO(7817) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2022-12-09T05:59:45.286Z] 05:59:45     INFO - GECKO(7817) | @resource://gre/modules/osfile.jsm:12:30
[task 2022-12-09T05:59:45.287Z] 05:59:45     INFO - GECKO(7817) | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-12-09T05:59:45.288Z] 05:59:45     INFO - GECKO(7817) | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-12-09T05:59:45.289Z] 05:59:45     INFO - GECKO(7817) | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-12-09T05:59:45.290Z] 05:59:45     INFO - GECKO(7817) | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
[task 2022-12-09T05:59:45.291Z] 05:59:45     INFO - GECKO(7817) | send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
[task 2022-12-09T05:59:45.292Z] 05:59:45     INFO - GECKO(7817) | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-12-09T05:59:45.293Z] 05:59:45     INFO - GECKO(7817) | sendPing@resource://gre/modules/EventPing.jsm:51:30
[task 2022-12-09T05:59:45.294Z] 05:59:45     INFO - GECKO(7817) | _submitPing@resource://gre/modules/EventPing.jsm:229:12
[task 2022-12-09T05:59:45.295Z] 05:59:45     INFO - GECKO(7817) | shutdown@resource://gre/modules/EventPing.jsm:112:10
[task 2022-12-09T05:59:45.296Z] 05:59:45     INFO - GECKO(7817) | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:940:31
[task 2022-12-09T05:59:45.297Z] 05:59:45     INFO - GECKO(7817) | shutdown/<@resource://gre/modules/TelemetryControllerParent.jsm:1010:24
[task 2022-12-09T05:59:45.298Z] 05:59:45     INFO - GECKO(7817) | observe@resource://gre/modules/AsyncShutdown.jsm:572:16

Chris, can someone from the Telemetry team have a look? Is that maybe a recent regression?

Comment 1

[Jan-Erik Rediger [:janerik]]

Already filed as bug 1804692 with possible solutions mentioned last Friday. I figure we'll be able to tackle that this week.