Closed Bug 1273973 Opened 4 years ago Closed 4 years ago

Intermittent telemetry/tests/unit/test_PingAPI.js | xpcshell return code: 0

Categories

(Toolkit :: Telemetry, defect, P2)

defect

Tracking

()

RESOLVED DUPLICATE of bug 1275144

People

(Reporter: aryx, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [measurement:client])

Priority: -- → P2
Whiteboard: [measurement:client]
Priority: P2 → P1
Assignee: nobody → alessio.placitelli
By examining the log from comment 0 (plus some other failures I stumbled upon), the culprit seems to be at [1], with this stack:

> 06:40:41     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_PingAPI.js | test_archiveCleanup - [test_archiveCleanup : 223] The ping should not be on the disk anymore. - true == true
> 06:40:41     INFO -  Unexpected exception Error: TelemetryStorage.loadArchivedPing - no ping with id 4e023a54-afbc-433e-8a39-ba16277d8a7a at resource://gre/modules/TelemetryStorage.jsm:690
> 06:40:41     INFO -  TelemetryStorageImpl.loadArchivedPing<@resource://gre/modules/TelemetryStorage.jsm:690:29
> 06:40:41     INFO -  test_archiveCleanup@/builds/slave/test/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_PingAPI.js:389:9
> 06:40:41     INFO -  _run_next_test@/builds/slave/test/build/tests/xpcshell/head.js:1540:9
> 06:40:41     INFO -  do_execute_soon/<.run@/builds/slave/test/build/tests/xpcshell/head.js:692:9
> 06:40:41     INFO -  _do_main@/builds/slave/test/build/tests/xpcshell/head.js:209:5
> 06:40:41     INFO -  _execute_test@/builds/slave/test/build/tests/xpcshell/head.js:533:5
> 06:40:41     INFO -  @-e:1:1
> 06:40:41     INFO -  exiting test
> 06:40:41     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1463578825946	Toolkit.Telemetry	> ERROR	TelemetrySend::_doPing - error making request to https://%(server)s/telemetry-dummy/submit/telemetry/30b0cd47-1b92-40cc-b359-fb8883e8b3a8/foo///default/?v=4: error" {file: "resource://gre/modules/Log.jsm" line: 753}]
> 06:40:41     INFO -  App_append@resource://gre/modules/Log.jsm:753:9
> 06:40:41     INFO -  Logger.prototype.log@resource://gre/modules/Log.jsm:389:7
> 06:40:41     INFO -  LoggerRepository.prototype.getLoggerWithMessagePrefix/proxy.log@resource://gre/modules/Log.jsm:504:44
> 06:40:41     INFO -  Logger.prototype.error@resource://gre/modules/Log.jsm:397:5
> 06:40:41     INFO -  TelemetrySendImpl._doPing/errorhandler@resource://gre/modules/TelemetrySend.jsm:940:7
> 06:40:41     INFO -  _do_main@/builds/slave/test/build/tests/xpcshell/head.js:209:5
> 06:40:41     INFO -  _execute_test@/builds/slave/test/build/tests/xpcshell/head.js:533:5
> 06:40:41     INFO -  @-e:1:1
> 06:40:41     INFO -  "

I'm investigating the cause for this.

[1] - https://dxr.mozilla.org/mozilla-central/rev/16663eb3dcfa759f25b5e27b101bc79270c156f2/toolkit/components/telemetry/tests/unit/test_PingAPI.js#389
Untaking, moving over to other work.
Assignee: alessio.placitelli → nobody
Priority: P1 → P2
On a closer look, this seems related to bug 1275144:

> 06:40:39     INFO -  "CONSOLE_MESSAGE: (info) 1463578812796	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_onPrefChanged"
> 06:40:39     INFO -  "CONSOLE_MESSAGE: (info) 1463578812821	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - isInitialized: false"
> 06:40:39     INFO -  "CONSOLE_MESSAGE: (info) 1463578812822	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_onEnvironmentChange for pref-changed"
> 06:40:39     INFO -  "CONSOLE_MESSAGE: (info) 1463578812822	Toolkit.Telemetry	DEBUG	TelemetryEnvironment::_onEnvironmentChange - calling TelemetrySession::onEnvironmentChange"
> 06:40:39     INFO -  "CONSOLE_MESSAGE: (info) 1463578812823	Toolkit.Telemetry	TRACE	TelemetrySession::_onEnvironmentChange: pref-changed"
> 06:40:39     INFO -  "CONSOLE_MESSAGE: (info) 1463578812823	Toolkit.Telemetry	TRACE	TelemetrySession::getSessionPayload - reason: environment-change, clearSubsession: true"

A pref change is detected and we're writing a "main" ping to the disk. The ping messes up with our quota calculations. I'll add some more debugging info to figure out which pref is changing.
It looks like the "xpinstall.signatures.required" pref is being changed.
Depends on: 1275144
The patch landed from bug 1275144 also fixed this. Closing it.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 1275144
You need to log in before you can comment on or make changes to this bug.