1521799 - Intermittent toolkit/mozapps/update/tests/browser/browser_aboutDialog_bc_downloaded_staged.js | The active update state should equal applied - Got pending, expected applied

Status: RESOLVED DUPLICATE of bug 1520672

(Toolkit :: Application Update, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=223294511&repo=autoland

https://queue.taskcluster.net/v1/task/RWdDCyWcRn6_IygzZzkvPA/runs/0/artifacts/public/logs/live_backing.log

[task 2019-01-22T15:49:03.570Z] 15:49:03 INFO - TEST-START | toolkit/mozapps/update/tests/browser/browser_about_bc_downloaded_staged.js
[task 2019-01-22T15:49:03.608Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC shouldUseService - returning false
[task 2019-01-22T15:49:03.609Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-22T15:49:03.609Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-22T15:49:03.609Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-22T15:49:03.609Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/update.test
[task 2019-01-22T15:49:03.612Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC gCanStageUpdatesSession - able to stage updates
[task 2019-01-22T15:49:03.613Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:03.615Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:03.616Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com&invalidCompleteSize=1&appVersion=66.0a1
[task 2019-01-22T15:49:03.621Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-22T15:49:03.623Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Checker: checkForUpdates, force: false
[task 2019-01-22T15:49:03.625Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-22T15:49:03.626Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com&invalidCompleteSize=1&appVersion=66.0a1
[task 2019-01-22T15:49:03.635Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Checker:checkForUpdates - sending request to: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com&invalidCompleteSize=1&appVersion=66.0a1
[task 2019-01-22T15:49:03.656Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Checker:onLoad - request completed downloading document
[task 2019-01-22T15:49:03.657Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Checker:onLoad - Getting sslStatus failed.
[task 2019-01-22T15:49:03.660Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Checker:onLoad - number of updates available: 1
[task 2019-01-22T15:49:03.661Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC shouldUseService - returning false
[task 2019-01-22T15:49:03.662Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-22T15:49:03.667Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-22T15:49:03.668Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC UpdateService:_selectAndInstallUpdate - download the update
[task 2019-01-22T15:49:03.668Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Creating Downloader
[task 2019-01-22T15:49:03.670Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC UpdateService:_downloadUpdate
[task 2019-01-22T15:49:03.678Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:03.680Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:03.681Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:downloadUpdate - url: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, path: /builds/worker/workspace/build/application/firefox/updates/0/update.mar, interval: 0
[task 2019-01-22T15:49:03.700Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:onStartRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar
[task 2019-01-22T15:49:03.700Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-22T15:49:03.704Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-22T15:49:03.705Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:onStopRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, status: 0
[task 2019-01-22T15:49:03.706Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
[task 2019-01-22T15:49:03.708Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:_verifyDownload called
[task 2019-01-22T15:49:03.709Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
[task 2019-01-22T15:49:03.710Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC shouldUseService - returning false
[task 2019-01-22T15:49:03.710Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:onStopRequest - setting state to: pending
[task 2019-01-22T15:49:03.711Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC Downloader:onStopRequest - attempting to stage update: App Update Test
[task 2019-01-22T15:49:03.759Z] 15:49:03 INFO - GECKO(11431) | ExceptionHandler::GenerateDump cloned child 11716
[task 2019-01-22T15:49:03.760Z] 15:49:03 INFO - GECKO(11431) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2019-01-22T15:49:03.768Z] 15:49:03 INFO - GECKO(11431) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2019-01-22T15:49:03.908Z] 15:49:03 INFO - GECKO(11431) | *** AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /builds/worker/workspace/build/application/firefox/updates.xml
[task 2019-01-22T15:49:04.733Z] 15:49:04 INFO - GECKO(11431) | *** AUS:SVC readStatusFile - status: pending, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:04.734Z] 15:49:04 INFO - GECKO(11431) | *** AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-22T15:49:04.736Z] 15:49:04 INFO - GECKO(11431) | *** AUS:SVC readBinaryTransparencyResult - result: null, path: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-22T15:49:04.737Z] 15:49:04 INFO - GECKO(11431) | *** AUS:SVC UpdateManager:refreshUpdateStatus - Notifying observers that the update was staged. topic: update-staged, status: pending
[task 2019-01-22T15:49:04.737Z] 15:49:04 INFO - GECKO(11431) | *** AUS:SVC showUpdateDownloaded - Notifying observers that an update was downloaded. topic: update-downloaded, status: pending
[task 2019-01-22T15:49:04.883Z] 15:49:04 INFO - TEST-INFO | started process screentopng
[task 2019-01-22T15:49:05.407Z] 15:49:05 INFO - TEST-INFO | screentopng: exit 0
[task 2019-01-22T15:49:05.408Z] 15:49:05 INFO - Buffered messages logged at 15:49:03
[task 2019-01-22T15:49:05.409Z] 15:49:05 INFO - Entering test bound setDefaults
[task 2019-01-22T15:49:05.410Z] 15:49:05 INFO - Leaving test bound setDefaults
[task 2019-01-22T15:49:05.411Z] 15:49:05 INFO - Entering test bound aboutDialog_backgroundCheck_downloaded_staged
[task 2019-01-22T15:49:05.411Z] 15:49:05 INFO - 15:49:03:595 | TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/shared.js | [setUpdateURL : 182] setting app.update.url to http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com&invalidCompleteSize=1&appVersion=66.0a1
[task 2019-01-22T15:49:05.413Z] 15:49:05 INFO - 15:49:03:598 | TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js | [continueFileHandler : 67] creating continueStaging file for slow update staging
[task 2019-01-22T15:49:05.414Z] 15:49:05 INFO - Console message: AUS:SVC shouldUseService - returning false
[task 2019-01-22T15:49:05.416Z] 15:49:05 INFO - Console message: AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-22T15:49:05.417Z] 15:49:05 INFO - Console message: AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-22T15:49:05.419Z] 15:49:05 INFO - Console message: AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-22T15:49:05.420Z] 15:49:05 INFO - Console message: AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/update.test
[task 2019-01-22T15:49:05.422Z] 15:49:05 INFO - Console message: AUS:SVC gCanStageUpdatesSession - able to stage updates
[task 2019-01-22T15:49:05.423Z] 15:49:05 INFO - Console message: AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:05.429Z] 15:49:05 INFO - Console message: AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:05.431Z] 15:49:05 INFO - Console message: AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com&invalidCompleteSize=1&appVersion=66.0a1
[task 2019-01-22T15:49:05.432Z] 15:49:05 INFO - Console message: AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-22T15:49:05.436Z] 15:49:05 INFO - Console message: AUS:SVC Checker: checkForUpdates, force: false
[task 2019-01-22T15:49:05.437Z] 15:49:05 INFO - Console message: AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-22T15:49:05.438Z] 15:49:05 INFO - Console message: AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com&invalidCompleteSize=1&appVersion=66.0a1
[task 2019-01-22T15:49:05.439Z] 15:49:05 INFO - Console message: AUS:SVC Checker:checkForUpdates - sending request to: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com&invalidCompleteSize=1&appVersion=66.0a1
[task 2019-01-22T15:49:05.440Z] 15:49:05 INFO - Console message: AUS:SVC Checker:onLoad - request completed downloading document
[task 2019-01-22T15:49:05.441Z] 15:49:05 INFO - Console message: AUS:SVC Checker:onLoad - Getting sslStatus failed.
[task 2019-01-22T15:49:05.443Z] 15:49:05 INFO - Console message: AUS:SVC Checker:onLoad - number of updates available: 1
[task 2019-01-22T15:49:05.443Z] 15:49:05 INFO - Console message: AUS:SVC shouldUseService - returning false
[task 2019-01-22T15:49:05.443Z] 15:49:05 INFO - Console message: AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-22T15:49:05.444Z] 15:49:05 INFO - Console message: AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-22T15:49:05.448Z] 15:49:05 INFO - Console message: AUS:SVC UpdateService:_selectAndInstallUpdate - download the update
[task 2019-01-22T15:49:05.448Z] 15:49:05 INFO - Console message: AUS:SVC Creating Downloader
[task 2019-01-22T15:49:05.448Z] 15:49:05 INFO - Console message: AUS:SVC UpdateService:_downloadUpdate
[task 2019-01-22T15:49:05.448Z] 15:49:05 INFO - Console message: AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:05.453Z] 15:49:05 INFO - Console message: AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:05.454Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:downloadUpdate - url: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, path: /builds/worker/workspace/build/application/firefox/updates/0/update.mar, interval: 0
[task 2019-01-22T15:49:05.455Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:onStartRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar
[task 2019-01-22T15:49:05.456Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-22T15:49:05.457Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-22T15:49:05.458Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:onStopRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, status: 0
[task 2019-01-22T15:49:05.460Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
[task 2019-01-22T15:49:05.461Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:_verifyDownload called
[task 2019-01-22T15:49:05.462Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
[task 2019-01-22T15:49:05.463Z] 15:49:05 INFO - Console message: AUS:SVC shouldUseService - returning false
[task 2019-01-22T15:49:05.464Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:onStopRequest - setting state to: pending
[task 2019-01-22T15:49:05.465Z] 15:49:05 INFO - Console message: AUS:SVC Downloader:onStopRequest - attempting to stage update: App Update Test
[task 2019-01-22T15:49:05.466Z] 15:49:05 INFO - Console message: AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /builds/worker/workspace/build/application/firefox/updates.xml
[task 2019-01-22T15:49:05.467Z] 15:49:05 INFO - Buffered messages logged at 15:49:04
[task 2019-01-22T15:49:05.468Z] 15:49:05 INFO - 15:49:04:741 | TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js | [onOpenWindow : 519] About dialog shown...
[task 2019-01-22T15:49:05.469Z] 15:49:05 INFO - Console message: AUS:SVC readStatusFile - status: pending, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-22T15:49:05.470Z] 15:49:05 INFO - Console message: AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-22T15:49:05.472Z] 15:49:05 INFO - Console message: AUS:SVC readBinaryTransparencyResult - result: null, path: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-22T15:49:05.473Z] 15:49:05 INFO - Console message: AUS:SVC UpdateManager:refreshUpdateStatus - Notifying observers that the update was staged. topic: update-staged, status: pending
[task 2019-01-22T15:49:05.477Z] 15:49:05 INFO - Console message: AUS:SVC showUpdateDownloaded - Notifying observers that an update was downloaded. topic: update-downloaded, status: pending
[task 2019-01-22T15:49:05.478Z] 15:49:05 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-22T15:49:05.479Z] 15:49:05 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-22T15:49:05.480Z] 15:49:05 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-22T15:49:05.481Z] 15:49:05 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-22T15:49:05.482Z] 15:49:05 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_about_bc_downloaded_staged.js | About dialog appeared -
[task 2019-01-22T15:49:05.483Z] 15:49:05 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_about_bc_downloaded_staged.js | There should be an active update -
[task 2019-01-22T15:49:05.484Z] 15:49:05 INFO - Buffered messages finished
[task 2019-01-22T15:49:05.485Z] 15:49:05 INFO - TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/browser/browser_about_bc_downloaded_staged.js | The active update state should equal applied - Got pending, expected applied

Comment 1

[Robert Strong (they/them - no direct email)]

This is likely Linux only and related to bug 1520672

Comment 2

[Intermittent Failures Robot]

3 failures in 2383 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 2

Platform breakdown:

• linux64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1521799&startday=2019-01-21&endday=2019-01-27&tree=all

Comment 3

[Robert Strong (they/them - no direct email)]

This might be fixed by bug 1523430

Comment 4

[Robert Strong (they/them - no direct email)]

Fairly certain this is fixed by the landing of bug 1523430

Comment 5

[Cristian Brindusan [:cbrindusan]]

This failed again:
https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=224792533&revision=303a009b3ef9c7053c82be92d538a97e7c40f092
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=224792533&repo=autoland&lineNumber=19197

[task 2019-01-29T20:47:56.427Z] 20:47:56 INFO - TEST-START | toolkit/mozapps/update/tests/browser/browser_aboutDialog_bc_downloaded_staged.js
[task 2019-01-29T20:47:56.525Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC shouldUseService - returning false
[task 2019-01-29T20:47:56.525Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-29T20:47:56.525Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-29T20:47:56.533Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-29T20:47:56.535Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/update.test
[task 2019-01-29T20:47:56.536Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC gCanStageUpdatesSession - able to stage updates
[task 2019-01-29T20:47:56.541Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:56.543Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:56.551Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com/&invalidCompleteSize=1&appVersion=67.0a1
[task 2019-01-29T20:47:56.552Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-29T20:47:56.552Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Checker: checkForUpdates, force: false
[task 2019-01-29T20:47:56.560Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-29T20:47:56.560Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com/&invalidCompleteSize=1&appVersion=67.0a1
[task 2019-01-29T20:47:56.562Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Checker:checkForUpdates - sending request to: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com/&invalidCompleteSize=1&appVersion=67.0a1
[task 2019-01-29T20:47:56.601Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.601Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 125
[task 2019-01-29T20:47:56.602Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.602Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 125
[task 2019-01-29T20:47:56.602Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/UrlClassifierCommon.cpp, line 125
[task 2019-01-29T20:47:56.602Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp, line 751
[task 2019-01-29T20:47:56.603Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.605Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.605Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.634Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /builds/worker/workspace/build/application/firefox/active-update.xml
[task 2019-01-29T20:47:56.642Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /builds/worker/workspace/build/application/firefox/updates.xml
[task 2019-01-29T20:47:56.659Z] 20:47:56 INFO - GECKO(7278) | ++DOCSHELL 0x7f7a580cc800 == 1 [pid = 7508] [id = {3843183e-9d3f-4714-bd19-9806d28795dd}]
[task 2019-01-29T20:47:56.735Z] 20:47:56 INFO - GECKO(7278) | ++DOMWINDOW == 1 (0x7f7a58061c00) [pid = 7508] [serial = 1] [outer = (nil)]
[task 2019-01-29T20:47:56.824Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Checker:onLoad - request completed downloading document
[task 2019-01-29T20:47:56.825Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Checker:onLoad - Getting sslStatus failed.
[task 2019-01-29T20:47:56.844Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Checker:onLoad - number of updates available: 1
[task 2019-01-29T20:47:56.844Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC shouldUseService - returning false
[task 2019-01-29T20:47:56.844Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-29T20:47:56.844Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-29T20:47:56.844Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC UpdateService:_selectAndInstallUpdate - download the update
[task 2019-01-29T20:47:56.850Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Creating Downloader
[task 2019-01-29T20:47:56.850Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC UpdateService:_downloadUpdate
[task 2019-01-29T20:47:56.851Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:56.851Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:56.855Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:downloadUpdate - url: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, path: /builds/worker/workspace/build/application/firefox/updates/0/update.mar, interval: 0
[task 2019-01-29T20:47:56.937Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.937Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.937Z] 20:47:56 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Found a principal with no URI, assuming third-party request: file /builds/worker/workspace/build/src/dom/base/ThirdPartyUtil.cpp, line 226
[task 2019-01-29T20:47:56.945Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:onStartRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar
[task 2019-01-29T20:47:56.947Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-29T20:47:56.949Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-29T20:47:56.951Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:onStopRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, status: 0
[task 2019-01-29T20:47:56.960Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
[task 2019-01-29T20:47:56.961Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:_verifyDownload called
[task 2019-01-29T20:47:56.963Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
[task 2019-01-29T20:47:56.964Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC shouldUseService - returning false
[task 2019-01-29T20:47:56.981Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:onStopRequest - setting state to: pending
[task 2019-01-29T20:47:56.982Z] 20:47:56 INFO - GECKO(7278) | *** AUS:SVC Downloader:onStopRequest - attempting to stage update: App Update Test
[task 2019-01-29T20:47:57.019Z] 20:47:57 INFO - GECKO(7278) | ++DOMWINDOW == 2 (0x7f7a58788c00) [pid = 7508] [serial = 2] [outer = 0x7f7a58061c00]
[task 2019-01-29T20:47:57.020Z] 20:47:57 INFO - GECKO(7278) | Hit MOZ_CRASH(DOMEventTargetHelper not thread-safe) at /builds/worker/workspace/build/src/xpcom/base/nsISupportsImpl.cpp:40
[task 2019-01-29T20:47:57.020Z] 20:47:57 INFO - GECKO(7278) | #01: libxul.so + 0xc63fbe
[task 2019-01-29T20:47:57.020Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.020Z] 20:47:57 INFO - GECKO(7278) | #02: libxul.so + 0x2a1b225
[task 2019-01-29T20:47:57.020Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.020Z] 20:47:57 INFO - GECKO(7278) | #03: libxul.so + 0x4497e4b
[task 2019-01-29T20:47:57.021Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.025Z] 20:47:57 INFO - GECKO(7278) | #04: libxul.so + 0x449727f
[task 2019-01-29T20:47:57.025Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.026Z] 20:47:57 INFO - GECKO(7278) | #05: libc.so.6 + 0x39ff8
[task 2019-01-29T20:47:57.027Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.028Z] 20:47:57 INFO - GECKO(7278) | #06: libc.so.6 + 0x3a045
[task 2019-01-29T20:47:57.029Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.029Z] 20:47:57 INFO - GECKO(7278) | #07: libxul.so + 0x4641352
[task 2019-01-29T20:47:57.030Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.031Z] 20:47:57 INFO - GECKO(7278) | #08: libxul.so + 0x4640a7b
[task 2019-01-29T20:47:57.032Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.047Z] 20:47:57 INFO - GECKO(7278) | #09: libxul.so + 0x4641f1e
[task 2019-01-29T20:47:57.048Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.049Z] 20:47:57 INFO - GECKO(7278) | #10: libxul.so + 0x4643903
[task 2019-01-29T20:47:57.051Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.052Z] 20:47:57 INFO - GECKO(7278) | #11: libxul.so + 0xcf09c1
[task 2019-01-29T20:47:57.053Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.055Z] 20:47:57 INFO - GECKO(7278) | #12: libxul.so + 0xcf2d33
[task 2019-01-29T20:47:57.059Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.066Z] 20:47:57 INFO - GECKO(7278) | #13: libxul.so + 0x11fa95b
[task 2019-01-29T20:47:57.066Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.070Z] 20:47:57 INFO - GECKO(7278) | #14: libxul.so + 0x11b7c59
[task 2019-01-29T20:47:57.071Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.072Z] 20:47:57 INFO - GECKO(7278) | #15: libxul.so + 0x11b7bb4
[task 2019-01-29T20:47:57.073Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.073Z] 20:47:57 INFO - GECKO(7278) | #16: libxul.so + 0xcee39c
[task 2019-01-29T20:47:57.075Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.418Z] 20:47:57 INFO - GECKO(7278) | #17: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:204]
[task 2019-01-29T20:47:57.418Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.418Z] 20:47:57 INFO - GECKO(7278) | #18: libpthread.so.0 + 0x76ba
[task 2019-01-29T20:47:57.419Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.419Z] 20:47:57 INFO - GECKO(7278) | #19: libc.so.6 + 0x10741d
[task 2019-01-29T20:47:57.419Z] 20:47:57 INFO -
[task 2019-01-29T20:47:57.420Z] 20:47:57 INFO - GECKO(7278) | #20: ??? (???:???)
[task 2019-01-29T20:47:57.422Z] 20:47:57 INFO - GECKO(7278) | ExceptionHandler::GenerateDump cloned child 7531
[task 2019-01-29T20:47:57.424Z] 20:47:57 INFO - GECKO(7278) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2019-01-29T20:47:57.427Z] 20:47:57 INFO - GECKO(7278) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2019-01-29T20:47:57.428Z] 20:47:57 INFO - GECKO(7278) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpCVROe4.mozrunner/runtests_leaks_tab_pid7529.log
[task 2019-01-29T20:47:57.453Z] 20:47:57 INFO - GECKO(7278) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-01-29T20:47:58.005Z] 20:47:58 INFO - GECKO(7278) | *** AUS:SVC readStatusFile - status: pending, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:58.007Z] 20:47:58 INFO - GECKO(7278) | *** AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-29T20:47:58.009Z] 20:47:58 INFO - GECKO(7278) | *** AUS:SVC readBinaryTransparencyResult - result: null, path: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-29T20:47:58.012Z] 20:47:58 INFO - GECKO(7278) | *** AUS:SVC UpdateManager:refreshUpdateStatus - Notifying observers that the update was staged. topic: update-staged, status: pending
[task 2019-01-29T20:47:58.015Z] 20:47:58 INFO - GECKO(7278) | *** AUS:SVC showUpdateDownloaded - Notifying observers that an update was downloaded. topic: update-downloaded, status: pending
[task 2019-01-29T20:47:58.032Z] 20:47:58 INFO - GECKO(7278) | ++DOCSHELL 0x7f157a547000 == 7 [pid = 7278] [id = {ad419b1b-d9e4-46c8-ba44-b57f3b5bcee1}]
[task 2019-01-29T20:47:58.034Z] 20:47:58 INFO - GECKO(7278) | ++DOMWINDOW == 15 (0x7f157a151800) [pid = 7278] [serial = 15] [outer = (nil)]
[task 2019-01-29T20:47:58.035Z] 20:47:58 INFO - GECKO(7278) | ++DOMWINDOW == 16 (0x7f157a152400) [pid = 7278] [serial = 16] [outer = 0x7f157a151800]
[task 2019-01-29T20:47:58.054Z] 20:47:58 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: Attempting to get a displayport from a content with no primary frame!: file /builds/worker/workspace/build/src/layout/base/nsLayoutUtils.cpp, line 752
[task 2019-01-29T20:47:58.057Z] 20:47:58 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 1010
[task 2019-01-29T20:47:58.127Z] 20:47:58 INFO - GECKO(7278) | [Parent 7278, Main Thread] WARNING: NS_ENSURE_TRUE(root) failed: file /builds/worker/workspace/build/src/layout/base/nsDocumentViewer.cpp, line 3214
[task 2019-01-29T20:47:58.259Z] 20:47:58 INFO - TEST-INFO | started process screentopng
[task 2019-01-29T20:47:58.722Z] 20:47:58 INFO - TEST-INFO | screentopng: exit 0
[task 2019-01-29T20:47:58.725Z] 20:47:58 INFO - Buffered messages logged at 20:47:56
[task 2019-01-29T20:47:58.727Z] 20:47:58 INFO - Entering test bound setDefaults
[task 2019-01-29T20:47:58.729Z] 20:47:58 INFO - Leaving test bound setDefaults
[task 2019-01-29T20:47:58.731Z] 20:47:58 INFO - Entering test bound aboutDialog_backgroundCheck_downloaded_staged
[task 2019-01-29T20:47:58.733Z] 20:47:58 INFO - 20:47:56:508 | TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/shared.js | [setUpdateURL : 184] setting app.update.url to http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com/&invalidCompleteSize=1&appVersion=67.0a1
[task 2019-01-29T20:47:58.736Z] 20:47:58 INFO - Console message: AUS:SVC shouldUseService - returning false
[task 2019-01-29T20:47:58.738Z] 20:47:58 INFO - Console message: AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-29T20:47:58.739Z] 20:47:58 INFO - Console message: AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-29T20:47:58.743Z] 20:47:58 INFO - Console message: AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-29T20:47:58.745Z] 20:47:58 INFO - Console message: AUS:SVC gCanStageUpdatesSession - testing write access /builds/worker/workspace/build/application/update.test
[task 2019-01-29T20:47:58.749Z] 20:47:58 INFO - Console message: AUS:SVC gCanStageUpdatesSession - able to stage updates
[task 2019-01-29T20:47:58.751Z] 20:47:58 INFO - Console message: AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:58.755Z] 20:47:58 INFO - Console message: AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:58.757Z] 20:47:58 INFO - Console message: AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com/&invalidCompleteSize=1&appVersion=67.0a1
[task 2019-01-29T20:47:58.762Z] 20:47:58 INFO - Console message: AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-29T20:47:58.764Z] 20:47:58 INFO - Console message: AUS:SVC Checker: checkForUpdates, force: false
[task 2019-01-29T20:47:58.766Z] 20:47:58 INFO - Console message: AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2019-01-29T20:47:58.768Z] 20:47:58 INFO - Console message: AUS:SVC Checker:getUpdateURL - update URL: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com/&invalidCompleteSize=1&appVersion=67.0a1
[task 2019-01-29T20:47:58.769Z] 20:47:58 INFO - Console message: AUS:SVC Checker:checkForUpdates - sending request to: http://example.com/browser/toolkit/mozapps/update/tests/browser/app_update.sjs?detailsURL=http://example.com/&invalidCompleteSize=1&appVersion=67.0a1
[task 2019-01-29T20:47:58.771Z] 20:47:58 INFO - Console message: AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /builds/worker/workspace/build/application/firefox/active-update.xml
[task 2019-01-29T20:47:58.774Z] 20:47:58 INFO - Console message: AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /builds/worker/workspace/build/application/firefox/updates.xml
[task 2019-01-29T20:47:58.776Z] 20:47:58 INFO - Console message: AUS:SVC Checker:onLoad - request completed downloading document
[task 2019-01-29T20:47:58.777Z] 20:47:58 INFO - Console message: AUS:SVC Checker:onLoad - Getting sslStatus failed.
[task 2019-01-29T20:47:58.779Z] 20:47:58 INFO - Console message: AUS:SVC Checker:onLoad - number of updates available: 1
[task 2019-01-29T20:47:58.782Z] 20:47:58 INFO - Console message: AUS:SVC shouldUseService - returning false
[task 2019-01-29T20:47:58.785Z] 20:47:58 INFO - Console message: AUS:SVC getCanApplyUpdates - testing write access /builds/worker/workspace/build/application/firefox/update.test
[task 2019-01-29T20:47:58.786Z] 20:47:58 INFO - Console message: AUS:SVC getCanApplyUpdates - able to apply updates
[task 2019-01-29T20:47:58.790Z] 20:47:58 INFO - Console message: AUS:SVC UpdateService:_selectAndInstallUpdate - download the update
[task 2019-01-29T20:47:58.791Z] 20:47:58 INFO - Console message: AUS:SVC Creating Downloader
[task 2019-01-29T20:47:58.792Z] 20:47:58 INFO - Console message: AUS:SVC UpdateService:_downloadUpdate
[task 2019-01-29T20:47:58.793Z] 20:47:58 INFO - Console message: AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:58.799Z] 20:47:58 INFO - Console message: AUS:SVC readStatusFile - status: null, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:58.803Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:downloadUpdate - url: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, path: /builds/worker/workspace/build/application/firefox/updates/0/update.mar, interval: 0
[task 2019-01-29T20:47:58.807Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:onStartRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar
[task 2019-01-29T20:47:58.809Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-29T20:47:58.812Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:onProgress - progress: 1404/1404
[task 2019-01-29T20:47:58.814Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:onStopRequest - original URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, final URI spec: http://example.com/browser/toolkit/mozapps/update/tests/browser/simple.mar, status: 0
[task 2019-01-29T20:47:58.816Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
[task 2019-01-29T20:47:58.817Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:_verifyDownload called
[task 2019-01-29T20:47:58.819Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
[task 2019-01-29T20:47:58.822Z] 20:47:58 INFO - Console message: AUS:SVC shouldUseService - returning false
[task 2019-01-29T20:47:58.823Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:onStopRequest - setting state to: pending
[task 2019-01-29T20:47:58.824Z] 20:47:58 INFO - Console message: AUS:SVC Downloader:onStopRequest - attempting to stage update: App Update Test
[task 2019-01-29T20:47:58.826Z] 20:47:58 INFO - Buffered messages logged at 20:47:58
[task 2019-01-29T20:47:58.827Z] 20:47:58 INFO - 20:47:58:039 | TEST-INFO | chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js | [onOpenWindow : 530] About dialog shown...
[task 2019-01-29T20:47:58.829Z] 20:47:58 INFO - Console message: AUS:SVC readStatusFile - status: pending, path: /builds/worker/workspace/build/application/firefox/updates/0/update.status
[task 2019-01-29T20:47:58.831Z] 20:47:58 INFO - Console message: AUS:SVC readStringFromFile - file doesn't exist: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-29T20:47:58.833Z] 20:47:58 INFO - Console message: AUS:SVC readBinaryTransparencyResult - result: null, path: /builds/worker/workspace/build/application/firefox/updates/0/bt.result
[task 2019-01-29T20:47:58.837Z] 20:47:58 INFO - Console message: AUS:SVC UpdateManager:refreshUpdateStatus - Notifying observers that the update was staged. topic: update-staged, status: pending
[task 2019-01-29T20:47:58.838Z] 20:47:58 INFO - Console message: AUS:SVC showUpdateDownloaded - Notifying observers that an update was downloaded. topic: update-downloaded, status: pending
[task 2019-01-29T20:47:58.840Z] 20:47:58 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-29T20:47:58.841Z] 20:47:58 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-29T20:47:58.843Z] 20:47:58 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-29T20:47:58.844Z] 20:47:58 INFO - Console message: [JavaScript Warning: "XUL box for hbox element contained an inline #text child, forcing all its children to be wrapped in a block." {file: "chrome://browser/content/aboutDialog.xul" line: 0}]
[task 2019-01-29T20:47:58.845Z] 20:47:58 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutDialog_bc_downloaded_staged.js | About dialog appeared -
[task 2019-01-29T20:47:58.847Z] 20:47:58 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutDialog_bc_downloaded_staged.js | The panel ID should equal apply -
[task 2019-01-29T20:47:58.849Z] 20:47:58 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutDialog_bc_downloaded_staged.js | There should be an active update -
[task 2019-01-29T20:47:58.850Z] 20:47:58 INFO - Buffered messages finished
[task 2019-01-29T20:47:58.852Z] 20:47:58 INFO - TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/browser/browser_aboutDialog_bc_downloaded_staged.js | The active update state should equal applied - Got pending, expected applied

Comment 6

[Robert Strong (they/them - no direct email)]

This is also a crash

[task 2019-01-22T15:49:43.404Z] 15:49:43 INFO - Thread 0 (crashed)
[task 2019-01-22T15:49:43.405Z] 15:49:43 INFO - 0 libxul.so!mozilla::ipc::MessageChannel::Close() [MessageChannel.h:f71ebb7632fb7e9e8f8514f377c12e9a52430da1 : 538 + 0x0]
[task 2019-01-22T15:49:43.405Z] 15:49:43 INFO - rax = 0x00007f43f34e8a94 rdx = 0x00007f43d6b53a30
[task 2019-01-22T15:49:43.406Z] 15:49:43 INFO - rcx = 0x000056236dc61958 rbx = 0x00007f43fde864c0
[task 2019-01-22T15:49:43.406Z] 15:49:43 INFO - rsi = 0x0000000000000001 rdi = 0x0000000000000020
[task 2019-01-22T15:49:43.406Z] 15:49:43 INFO - rbp = 0x00007f43d6b51400 rsp = 0x00007f43d6b513d0
[task 2019-01-22T15:49:43.407Z] 15:49:43 INFO - r8 = 0x0000000000000000 r9 = 0x0000000000000000
[task 2019-01-22T15:49:43.407Z] 15:49:43 INFO - r10 = 0x0000000000005008 r11 = 0x00007f43fe248390
[task 2019-01-22T15:49:43.408Z] 15:49:43 INFO - r12 = 0x0000000000000006 r13 = 0x00007f43de6ef0d8
[task 2019-01-22T15:49:43.408Z] 15:49:43 INFO - r14 = 0x00007f43e76dfa90 r15 = 0x00007f43dfafd740
[task 2019-01-22T15:49:43.409Z] 15:49:43 INFO - rip = 0x00007f43ee5c3b87
[task 2019-01-22T15:49:43.409Z] 15:49:43 INFO - Found by: given as instruction pointer in context
[task 2019-01-22T15:49:43.410Z] 15:49:43 INFO - 1 libxul.so!mozilla::ProfilerParentTracker::~ProfilerParentTracker() [ProfilerParent.cpp:f71ebb7632fb7e9e8f8514f377c12e9a52430da1 : 80 + 0x8]
[task 2019-01-22T15:49:43.410Z] 15:49:43 INFO - rbx = 0x0000000000000000 rbp = 0x00007f43d6b51450
[task 2019-01-22T15:49:43.411Z] 15:49:43 INFO - rsp = 0x00007f43d6b51410 r12 = 0x0000000000000006
[task 2019-01-22T15:49:43.411Z] 15:49:43 INFO - r13 = 0x00007f43d9c571c0 r14 = 0x00007f43e76dfa90
[task 2019-01-22T15:49:43.412Z] 15:49:43 INFO - r15 = 0x00007f43dfafd740 rip = 0x00007f43f153d792
[task 2019-01-22T15:49:43.412Z] 15:49:43 INFO - Found by: call frame info
[task 2019-01-22T15:49:43.413Z] 15:49:43 INFO - 2 libxul.so!mozilla::UniquePtr<mozilla::ProfilerParentTracker, mozilla::DefaultDelete<mozilla::ProfilerParentTracker> >::~UniquePtr() [UniquePtr.h:f71ebb7632fb7e9e8f8514f377c12e9a52430da1 : 486 + 0x8]
[task 2019-01-22T15:49:43.413Z] 15:49:43 INFO - rbx = 0x00007f43e76dfa90 rbp = 0x00007f43d6b51470
[task 2019-01-22T15:49:43.414Z] 15:49:43 INFO - rsp = 0x00007f43d6b51460 r12 = 0x0000000000000001
[task 2019-01-22T15:49:43.414Z] 15:49:43 INFO - r13 = 0x00007f43fde75000 r14 = 0x0000000000000000
[task 2019-01-22T15:49:43.415Z] 15:49:43 INFO - r15 = 0x00007f43d8216040 rip = 0x00007f43f153d4dd
[task 2019-01-22T15:49:43.415Z] 15:49:43 INFO - Found by: call frame info
[task 2019-01-22T15:49:43.416Z] 15:49:43 INFO - 3 libc-2.23.so + 0x39ff8
[task 2019-01-22T15:49:43.416Z] 15:49:43 INFO - rbx = 0x00000000ffffffff rbp = 0x00007f43fe4765f8
[task 2019-01-22T15:49:43.417Z] 15:49:43 INFO - rsp = 0x00007f43d6b51480 r12 = 0x0000000000000001
[task 2019-01-22T15:49:43.418Z] 15:49:43 INFO - r13 = 0x00007f43fde75000 r14 = 0x0000000000000000
[task 2019-01-22T15:49:43.418Z] 15:49:43 INFO - r15 = 0x00007f43d8216040 rip = 0x00007f43fe0ebff8
[task 2019-01-22T15:49:43.419Z] 15:49:43 INFO - Found by: call frame info
[task 2019-01-22T15:49:43.419Z] 15:49:43 INFO - 4 libc-2.23.so + 0x3a045
[task 2019-01-22T15:49:43.419Z] 15:49:43 INFO - rbp = 0x00007f43fe4765f8 rsp = 0x00007f43d6b514b0
[task 2019-01-22T15:49:43.420Z] 15:49:43 INFO - rip = 0x00007f43fe0ec045
[task 2019-01-22T15:49:43.420Z] 15:49:43 INFO - Found by: stack scanning
[task 2019-01-22T15:49:43.421Z] 15:49:43 INFO - 5 libxul.so!ApplyUpdate(nsIFile*, nsIFile*, nsIFile*, int, char**, bool, bool, int*) [nsTString.h:f71ebb7632fb7e9e8f8514f377c12e9a52430da1 : 159 + 0x16]
[task 2019-01-22T15:49:43.421Z] 15:49:43 INFO - rbp = 0x00007f43fe4765f8 rsp = 0x00007f43d6b514c0
[task 2019-01-22T15:49:43.422Z] 15:49:43 INFO - rip = 0x00007f43f17b8ac0
[task 2019-01-22T15:49:43.422Z] 15:49:43 INFO - Found by: stack scanning
[task 2019-01-22T15:49:43.422Z] 15:49:43 INFO - 6 libxul.so!_fini + 0x10ac860
[task 2019-01-22T15:49:43.423Z] 15:49:43 INFO - rbp = 0x00007f43fe4765f8 rsp = 0x00007f43d6b51500
[task 2019-01-22T15:49:43.423Z] 15:49:43 INFO - rip = 0x00007f43f38cf3d0
[task 2019-01-22T15:49:43.424Z] 15:49:43 INFO - Found by: stack scanning

Comment 7

[Intermittent Failures Robot]

8 failures in 2628 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4
• try: 2
• mozilla-beta: 2

Platform breakdown:

• linux32: 2
• linux64-nightly: 1
• linux32-nightly: 1
• linux64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1521799&startday=2019-01-28&endday=2019-02-03&tree=all

Comment 8

[Intermittent Failures Robot]

3 failures in 2658 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-beta: 1
• try: 1

Platform breakdown:

• linux32-devedition: 1
• linux64: 1
• linux64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1521799&startday=2019-02-04&endday=2019-02-10&tree=all

Comment 9

[Robert Strong (they/them - no direct email)]

The patch for bug 1520672 fixes this bug

Comment 10

[Intermittent Failures Robot]

2 failures in 2832 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-inbound: 1

Platform breakdown:

• linux32: 1
• linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1521799&startday=2019-02-11&endday=2019-02-17&tree=all

Comment 11

[Robert Strong (they/them - no direct email)]

This is likely fixed by the patch in bug 1434033 which also fixed bug 1520672.