Closed Bug 1550634 Opened 5 months ago Closed 4 months ago

Intermittent telemetry [taskcluster:error] Aborting task...

Categories

(Firefox Build System :: General, defect, P5)

defect

Tracking

(firefox-esr60 unaffected, firefox67 unaffected, firefox68 fixed, firefox69 fixed)

RESOLVED FIXED
mozilla69
Tracking Status
firefox-esr60 --- unaffected
firefox67 --- unaffected
firefox68 --- fixed
firefox69 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=245602565&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/bw6XTZzhSy2SErfDQDuh9A/runs/0/artifacts/public/logs/live_backing.log


19:11:36 INFO - ++DOCSHELL 08DA3C00 == 4 [pid = 5244] [id = {8c674f07-c9ee-4669-930e-be12e1dec616}]
19:11:36 INFO - ++DOMWINDOW == 4 (08D45B80) [pid = 5244] [serial = 4] [outer = 00000000]
19:11:36 INFO - [Child 5244, Main Thread] WARNING: Fallback to BasicLayerManager: file z:/build/build/src/dom/ipc/BrowserChild.cpp, line 2678
19:11:36 INFO - ++DOCSHELL 08DA5000 == 5 [pid = 5244] [id = {9f41a807-1d1f-4c0f-bd79-1936ed6202ff}]
19:11:36 INFO - ++DOMWINDOW == 5 (08D45DC0) [pid = 5244] [serial = 5] [outer = 00000000]
19:11:36 INFO - [Child 5244, Main Thread] WARNING: Fallback to BasicLayerManager: file z:/build/build/src/dom/ipc/BrowserChild.cpp, line 2678
19:11:36 INFO - ++DOMWINDOW == 6 (08DA6800) [pid = 5244] [serial = 6] [outer = 08D453A0]
19:11:36 INFO - [Parent 1152, Main Thread] WARNING: nsIEditActionListener installed, this editor becomes slower: 'mActionListeners.Length() != 1', file z:/build/build/src/editor/libeditor/EditorBase.cpp, line 2126
19:11:36 INFO - 1557429096563 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: distribution-customization-complete, aData: null
19:11:36 INFO - [Child 5244, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file z:/build/build/src/widget/windows/nsLookAndFeel.cpp, line 481
19:11:36 INFO - ++DOMWINDOW == 7 (0A534400) [pid = 5244] [serial = 7] [outer = 08D45700]
19:11:36 INFO - ++DOMWINDOW == 8 (0A535800) [pid = 5244] [serial = 8] [outer = 08D45940]
19:11:36 INFO - ++DOMWINDOW == 9 (0A536800) [pid = 5244] [serial = 9] [outer = 08D45B80]
19:11:36 INFO - ++DOMWINDOW == 10 (0A537C00) [pid = 5244] [serial = 10] [outer = 08D45DC0]
19:11:36 INFO - ++DOMWINDOW == 11 (0A539400) [pid = 5244] [serial = 11] [outer = 08D453A0]
19:11:36 INFO - 1557429096616 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: write-cache-to-disk-complete
19:11:36 INFO - ++DOMWINDOW == 12 (0A53A400) [pid = 5244] [serial = 12] [outer = 08D45700]
19:11:36 INFO - ++DOMWINDOW == 13 (0A53B400) [pid = 5244] [serial = 13] [outer = 08D45940]
19:11:36 INFO - ++DOMWINDOW == 14 (0A53C400) [pid = 5244] [serial = 14] [outer = 08D45B80]
19:11:36 INFO - ++DOMWINDOW == 15 (0A53DC00) [pid = 5244] [serial = 15] [outer = 08D45DC0]
19:11:36 INFO - [Parent 1152, StreamTrans #3] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 371
19:11:36 INFO - 1557429096701 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: settings-update-complete
19:11:36 INFO - [Parent 1152, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
19:11:36 INFO - [Parent 1152, StreamTrans #4] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 371
19:11:36 INFO - [Parent 1152, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
19:11:36 INFO - [Parent 1152, StreamTrans #1] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 371
19:11:36 INFO - [Parent 1152, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
19:11:36 INFO - [Parent 1152, StreamTrans #1] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 371
19:11:36 INFO - [Parent 1152, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
19:11:37 INFO - 1557429097146 Marionette TRACE Received observer notification marionette-startup-requested
19:11:37 INFO - 1557429097147 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
19:11:37 INFO - 1557429097183 Toolkit.Telemetry TRACE TelemetrySend::setup
19:11:37 INFO - 1557429097183 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
19:11:37 INFO - 1557429097187 Toolkit.Telemetry TRACE TelemetryStorage::_scanPendingPings
19:11:37 INFO - 1557429097188 Toolkit.Telemetry TRACE TelemetryStorage::_migrateAppDataPings
19:11:37 INFO - 1557429097188 Toolkit.Telemetry TRACE TelemetryStorage::_iterateAppDataPings
19:11:37 INFO - 1557429097207 Toolkit.Telemetry INFO TelemetrySend::_checkPendingPings - pending ping count: 0
19:11:37 INFO - 1557429097207 Toolkit.Telemetry TRACE TelemetrySend::_checkPendingPings - no pending pings
19:11:37 INFO - 1557429097208 Toolkit.Telemetry TRACE TelemetryStorage::_enforcePendingPingsQuota
19:11:37 INFO - 1557429097208 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true
19:11:37 INFO - 1557429097208 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask iteration
19:11:37 INFO - 1557429097209 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0
19:11:37 INFO - 1557429097209 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0
19:11:37 INFO - 1557429097209 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out
19:11:37 INFO - 1557429097209 Toolkit.Telemetry TRACE TelemetrySession::delayedInit
19:11:37 INFO - 1557429097210 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
19:11:37 INFO - 1557429097212 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
19:11:37 INFO - 1557429097219 Marionette TRACE All scripts recorded.
19:11:37 INFO - 1557429097257 Marionette INFO Listening on port 2828
19:11:37 INFO - 1557429097257 Marionette DEBUG Remote service is active
19:11:37 INFO - 1557429097269 Toolkit.Telemetry TRACE TelemetryStorage::loadPingfile - unreadable ping Z:\task_1557426010\build\tmpja8oub.mozrunner\datareporting\aborted-session-ping: {"operation":"open","path":"Z:\task_1557426010\build\tmpja8oub.mozrunner\datareporting\aborted-session-ping","winLastError":2}
19:11:37 INFO - 1557429097270 Toolkit.Telemetry TRACE TelemetryStorage::loadAbortedSessionPing - no such file
19:11:37 INFO - 1557429097270 Toolkit.Telemetry TRACE TelemetryController::checkAbortedSessionPing - found aborted-session ping: false
19:11:37 INFO - 1557429097270 Toolkit.Telemetry TRACE TelemetrySession::_saveAbortedSessionPing
19:11:37 INFO - 1557429097270 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - reason: aborted-session, clearSubsession: false
19:11:37 INFO - 1557429097272 Toolkit.Telemetry TRACE TelemetrySession::assemblePayloadWithMeasurements - reason: aborted-session, submitting subsession data: true
19:11:37 INFO - 1557429097275 Toolkit.Telemetry TRACE TelemetryController::saveAbortedSessionPing
19:11:37 INFO - 1557429097276 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true}
19:11:37 INFO - 1557429097281 Toolkit.Telemetry TRACE TelemetryStorage::saveAbortedSessionPing - ping path: Z:\task_1557426010\build\tmpja8oub.mozrunner\datareporting\aborted-session-ping
19:11:37 INFO - 1557429097282 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
19:11:37 INFO - 1557429097283 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: Z:\task_1557426010\build\tmpja8oub.mozrunner\datareporting\aborted-session-ping
19:11:37 INFO - 1557429097294 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange
19:11:37 INFO - 1557429097297 Toolkit.Telemetry TRACE TelemetryScheduler::init
19:11:37 INFO - 1557429097297 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - isUserIdle: false
19:11:37 INFO - 1557429097298 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Thu May 09 2019 19:16:37 GMT+0000 (Greenwich Mean Time)
19:11:37 INFO - 1557429097299 Toolkit.Telemetry TRACE TelemetryStorage::cleanArchiveTask
19:11:37 INFO - 1557429097299 Toolkit.Telemetry TRACE TelemetryStorage::removeFHRDatabase
19:11:37 INFO - 1557429097309 Toolkit.Telemetry TRACE TelemetryEventPing::::Starting up.
19:11:37 INFO - 1557429097310 Toolkit.Telemetry TRACE EcosystemTelemetry::Starting up.
19:11:37 INFO - 1557429097310 Toolkit.Telemetry TRACE TelemetryPrioPing::Extended collection disabled. Prio ping disabled.
19:11:37 INFO - 1557429097315 Toolkit.Telemetry TRACE TelemetryStorage::_purgeOldPings
19:11:37 INFO - 1557429097325 Toolkit.Telemetry TRACE TelemetryStorage::_scanArchive
19:11:37 INFO - 1557429097332 Toolkit.Telemetry TRACE TelemetryStorage::_scanArchive - checking in subdir: Z:\task_1557426010\build\tmpja8oub.mozrunner\datareporting\archived\2019-05
19:11:37 INFO - 1557429097346 Toolkit.Telemetry TRACE TelemetryStorage::_enforceArchiveQuota
19:11:37 INFO - 1557429097414 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
19:11:37 INFO - 1557429097432 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
19:11:37 INFO - 1557429097434 Toolkit.Telemetry TRACE TelemetryEnvironment::_startWatchingPrefs - [object Map]
19:11:37 INFO - 1557429097440 Marionette DEBUG Accepted connection 0 from 127.0.0.1:49590
19:11:37 INFO - 1557429097535 Marionette DEBUG Closed connection 0
19:11:37 INFO - 1557429097536 Marionette DEBUG Accepted connection 1 from 127.0.0.1:49597
19:11:37 INFO - 1557429097636 Marionette DEBUG Accepted connection 2 from 127.0.0.1:49598
19:11:37 INFO - 1557429097638 Marionette DEBUG Closed connection 2
19:11:37 INFO - 1557429097639 Marionette DEBUG Closed connection 1
19:11:37 INFO - 1557429097640 Marionette DEBUG Accepted connection 3 from 127.0.0.1:49599
19:11:37 INFO - 1557429097642 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
19:11:37 INFO - 1557429097652 Marionette TRACE [10] Frame script loaded
19:11:37 INFO - 1557429097652 Marionette TRACE [10] Frame script registered
19:11:37 INFO - 1557429097653 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: marionette.contentListener
19:11:37 INFO - 1557429097658 Marionette DEBUG 3 <- [1,1,null,{"sessionId":"5b989fbd-420a-4ce8-b24b-c78660d37c6d","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... d\tmpja8oub.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
19:11:37 INFO - 1557429097661 Marionette DEBUG 3 -> [0,2,"Marionette:SetContext",{"value":"content"}]
19:11:37 INFO - 1557429097662 Marionette DEBUG 3 <- [1,2,null,{"value":null}]
19:11:37 INFO - 1557429097664 Marionette DEBUG 3 -> [0,3,"WebDriver:GetChromeWindowHandles",{}]
19:11:37 INFO - 1557429097665 Marionette DEBUG 3 <- [1,3,null,["3"]]
19:11:37 INFO - 1557429097667 Marionette DEBUG 3 -> [0,4,"WebDriver:GetWindowHandles",{}]
19:11:37 INFO - 1557429097668 Marionette DEBUG 3 <- [1,4,null,["10"]]
[taskcluster:error] Aborting task...
[taskcluster 2019-05-09T19:11:37.776Z] SUCCESS: The process with PID 5908 (child process of PID 4020) has been terminated.
[taskcluster 2019-05-09T19:11:37.776Z] SUCCESS: The process with PID 4192 (child process of PID 4020) has been terminated.
[taskcluster 2019-05-09T19:11:37.776Z] SUCCESS: The process with PID 5292 (child process of PID 5768) has been terminated.
[taskcluster 2019-05-09T19:11:37.776Z] SUCCESS: The process with PID 4020 (child process of PID 5768) has been terminated.
[taskcluster 2019-05-09T19:11:37.776Z] SUCCESS: The process with PID 5768 (child process of PID 3248) has been terminated.
[taskcluster 2019-05-09T19:11:37.776Z] SUCCESS: The process with PID 3248 (child process of PID 5732) has been terminated.
[taskcluster 2019-05-09T19:11:37.776Z]
[taskcluster 2019-05-09T19:11:37.776Z] === Task Finished ===
[taskcluster 2019-05-09T19:11:37.776Z] Task Duration: 10m0.1830126s
[taskcluster 2019-05-09T19:11:38.108Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-05-08T17:44:42.441Z
[taskcluster 2019-05-09T19:11:38.751Z] Uploading artifact public/test_info/report.html from file build\blobber_upload_dir\report.html with content encoding "gzip", mime type "text/html; charset=utf-8" and expiry 2020-05-08T17:44:42.441Z
[taskcluster 2019-05-09T19:11:39.195Z] Uploading artifact public/test_info/report.xml from file build\blobber_upload_dir\report.xml with content encoding "gzip", mime type "text/xml; charset=utf-8" and expiry 2020-05-08T17:44:42.441Z
[taskcluster 2019-05-09T19:11:39.783Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/bw6XTZzhSy2SErfDQDuh9A/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2020-05-08T17:44:42.441Z
[taskcluster:error] Task aborted - max run time exceeded

Tasks are intermittently exceeding the 10 minute max-run-time, especially on windows ccov. Successful runs in the 9 to 10 minute range are fairly common on linux and windows.

max-run-time was reduced in bug 1531356...maybe a little too much!

Assignee: nobody → gbrown
See Also: → 1531356

Avoid intermittent failures by allowing the task to run a little longer.

Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bd4d0e2991ba
Increase telemetry-test-client max-run-time; r=jmaher
Status: NEW → RESOLVED
Closed: 4 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla69
You need to log in before you can comment on or make changes to this bug.