Closed Bug 1285864 Opened 8 years ago Closed 7 years ago

Intermittent toolkit/components/telemetry/tests/unit/test_TelemetryControllerShutdown.js | xpcshell return code: 139

Categories

(Toolkit :: Telemetry, defect, P3)

Product:
Toolkit
Component:
Telemetry
Platform:
All
Android
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: gbrown)

Details

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

Attachments

(1 file)

increase timeout
1.32 KB, patch
gfritzsche
: review+
Details | Diff | Splinter Review
Blocks: 1273889
OS: Unspecified → All
Priority: -- → P2
Hardware: Unspecified → All
Whiteboard: [measurement:client]
Version: unspecified → Trunk
No longer blocks: 1273889
There's a whole block of exceptions triggered by TelemetryEnvironment, which is stopping pref observation (but apparently these prefs were not being observed). That hints at bug 1273889.

Unfortunately, that's not the cause of the failure.
This shows many exceptions like this:
> "CONSOLE_MESSAGE: (info) 1468205679500	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_stopWatchingPrefs"
> "CONSOLE_MESSAGE: (error) [JavaScript Error: "Attempt to stop observing a preference "app.feedback.baseURL" that's not being observed" {file: "resource://gre/modules/Preferences.jsm" line: 323}]
> Preferences.ignore@resource://gre/modules/Preferences.jsm:323:5
> EnvironmentCache.prototype._stopWatchingPrefs@resource://gre/modules/TelemetryEnvironment.jsm:913:9

These are explained by bug 1273889, which made `Preferences.ignore()` report an error on trying to stop watching unwatched prefs.
That is just error output though and shouldn't make the test fail.
The problem here is an AsyncShutdownTimeout:

> 19:55:34     INFO -  PROCESS | toolkit/components/telemetry/tests/unit/test_TelemetryControllerShutdown.js | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"TelemetryController: shutting down","state":{"initialized":true,"initStarted":true,"haveDelayedInitTask":false,"shutdownBarrier":"Not started","connectionsBarrier":"Not started","sendModule":{"sendingEnabled":false,"pendingPingRequestCount":0,"pendingPingActivityCount":0,"unpersistedPingCount":0,"persistedPingCount":1,"schedulerState":{"shutdown":true,"hasSendTask":false,"sendsFailed":true,"sendTaskState":"bail out - shutdown & pending check after send","backoffDelay":60000}}},"filename":"resource://gre/modules/TelemetryController.jsm","lineNumber":729,"stack":["resource://gre/modules/TelemetryController.jsm:setupTelemetry:729","resource://gre/modules/TelemetryController.jsm:this.TelemetryController<.testSetup:157","test_TelemetryControllerShutdown.js:test_sendTelemetryShutsDownWithinReasonableTimeout:60","resource://gre/modules/Task.jsm:TaskImpl_run:319","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://gre/modules/Task.jsm:Task_spawn:168","/storage/sdcard/tests/xpc/head.js:_run_next_test:1564","/storage/sdcard/tests/xpc/head.js:do_execute_soon/<.run:712","/storage/sdcard/tests/xpc/head.js:_do_main:209","/storage/sdcard/tests/xpc/head.js:_execute_test:544","-e:null:1"]}] Barrier: profile-before-change-telemetry
> 19:55:34     INFO -  "CONSOLE_MESSAGE: (info) 1468205726973	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: cb9e205b-3dd4-46fd-bee7-02cb1c0da27e"
> 19:55:34     INFO -  "CONSOLE_MESSAGE: (info) 1468205727089	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: cb9e205b-3dd4-46fd-bee7-02cb1c0da27e"
> 19:55:34     INFO -  "CONSOLE_MESSAGE: (info) 1468205727124	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
> 19:55:34     INFO -  "CONSOLE_MESSAGE: (info) 1468205727129	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
> 19:55:34     INFO -  "CONSOLE_MESSAGE: (info) 1468205727137	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - can't send ping now, persisting to disk - canSendNow: false"
> 19:55:34     INFO -  PROCESS | toolkit/components/telemetry/tests/unit/test_TelemetryControllerShutdown.js | FATAL ERROR: AsyncShutdown timeout in profile-before-change-telemetry Conditions: [{"name":"TelemetryController: shutting down","state":{"initialized":true,"initStarted":true,"haveDelayedInitTask":false,"shutdownBarrier":"Not started","connectionsBarrier":"Not started","sendModule":{"sendingEnabled":false,"pendingPingRequestCount":0,"pendingPingActivityCount":0,"unpersistedPingCount":0,"persistedPingCount":1,"schedulerState":{"shutdown":true,"hasSendTask":false,"sendsFailed":true,"sendTaskState":"bail out - shutdown & pending check after send","backoffDelay":60000}}},"filename":"resource://gre/modules/TelemetryController.jsm","lineNumber":729,"stack":["resource://gre/modules/TelemetryController.jsm:setupTelemetry:729","resource://gre/modules/TelemetryController.jsm:this.TelemetryController<.testSetup:157","test_TelemetryControllerShutdown.js:test_sendTelemetryShutsDownWithinReasonableTimeout:60","resource://gre/modules/Task.jsm:TaskImpl_run:319","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://gre/modules/Task.jsm:Task_spawn:168","/storage/sdcard/tests/xpc/head.js:_run_next_test:1564","/storage/sdcard/tests/xpc/head.js:do_execute_soon/<.run:712","/storage/sdcard/tests/xpc/head.js:_do_main:209","/storage/sdcard/tests/xpc/head.js:_execute_test:544","-e:null:1"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
> 19:55:34 INFO - PROCESS | toolkit/components/telemetry/tests/unit/test_TelemetryControllerShutdown.js | \x07[15625] ###!!! ABORT: file resource://gre/modules/TelemetryController.jsm, line 729
OS: All → Android
(In reply to Georg Fritzsche [:gfritzsche] from comment #2)
> This shows many exceptions like this:

Moved that to bug 1285921.
This doesn't seem to have any more failures, closing.
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → WORKSFORME
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Something made this spike badly about a week ago.
Flags: needinfo?(alessio.placitelli)
Skipping this test on android-debug would avoid nearly all failures.
Assignee: nobody → alessio.placitelli
Flags: needinfo?(alessio.placitelli)
Priority: P2 → P1
Assignee: alessio.placitelli → nobody
Priority: P1 → P2
Whiteboard: [measurement:client] → [measurement:client][stockwell unknwon]
Whiteboard: [measurement:client][stockwell unknwon] → [measurement:client][stockwell unknown]
Priority: P2 → P3
Assignee: nobody → gbrown
Whiteboard: [measurement:client][stockwell unknown] → [measurement:client][stockwell needswork]
Attached patch increase timeout — — Splinter Review 
This test has been failing infrequently for a long time now. It became a frequent failure with the changes in bug 1361661:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=android%20debug%20xpcshell&tochange=9cc0b3e19072d6bd87e9823e9c98c64950333b25&fromchange=eaaf2913c680334b0426a93b7c27b0280f2a7f67

Increasing the timeout appears to avoid the failure:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0600fb72188551a72205003fcb601f35e0cfcd8f


All failures are on Android Debug, so skipping the test on Android Debug is also a viable solution here.
Attachment #8871329 - Flags: review?(gfritzsche)
Comment on attachment 8871329 [details] [diff] [review]
increase timeout

Review of attachment 8871329 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks!
Attachment #8871329 - Flags: review?(gfritzsche) → review+
Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/293c7f959f2f
Increase timeout in test_TelemetryControllerShutdown.js; r=gfritzsche
https://hg.mozilla.org/mozilla-central/rev/293c7f959f2f
Status: REOPENED → RESOLVED
Closed: 8 years ago → 7 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Whiteboard: [measurement:client][stockwell needswork] → [measurement:client][stockwell fixed]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: