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

Status: RESOLVED DUPLICATE of bug 1275144

(Toolkit :: Telemetry, defect, P2)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://treeherder.mozilla.org/logviewer.html#?job_id=28133404&repo=mozilla-inbound

Comment 1

[Intermittent Failures Robot]

12 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 9
* try: 1
* mozilla-central: 1
* fx-team: 1

Platform breakdown:
* linux32: 12

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273973&startday=2016-05-16&endday=2016-05-22&tree=all

Comment 2

[Alessio Placitelli [:Dexter]]

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

Comment 3

[Alessio Placitelli [:Dexter]]

Untaking, moving over to other work.

Comment 4

[Alessio Placitelli [:Dexter]]

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.

Comment 5

[Alessio Placitelli [:Dexter]]

It looks like the "xpinstall.signatures.required" pref is being changed.

Comment 6

[Intermittent Failures Robot]

16 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 7
* fx-team: 7
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux32: 16

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273973&startday=2016-05-23&endday=2016-05-29&tree=all

Comment 7

[Intermittent Failures Robot]

9 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 4
* fx-team: 4
* mozilla-central: 1

Platform breakdown:
* linux32: 9

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273973&startday=2016-05-30&endday=2016-06-05&tree=all

Comment 8

[Alessio Placitelli [:Dexter]]

The patch landed from bug 1275144 also fixed this. Closing it.