Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=328801176&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Srg73khVSu6a1OL5m03n2A/runs/0/artifacts/public/logs/live_backing.log
[task 2021-02-04T06:36:33.489Z] 06:36:33 INFO - TEST-START | telemetry/marionette/tests/client/test_fog_user_activity.py TestClientActivity.test_user_activity
[task 2021-02-04T06:36:33.489Z] 06:36:33 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmpLsgKYL.mozrunner
[task 2021-02-04T06:36:33.859Z] 06:36:33 INFO - 1612420593858 Toolkit.Telemetry TRACE TelemetryController::observe - profile-after-change notified.
[task 2021-02-04T06:36:33.860Z] 06:36:33 INFO - 1612420593858 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry
[task 2021-02-04T06:36:33.864Z] 06:36:33 INFO - 1612420593859 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup
[task 2021-02-04T06:36:33.864Z] 06:36:33 INFO - 1612420593859 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:33.864Z] 06:36:33 INFO - 1612420593860 Toolkit.Telemetry TRACE TelemetrySession::earlyInit
[task 2021-02-04T06:36:33.872Z] 06:36:33 INFO - 1612420593866 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-04T06:36:33.872Z] 06:36:33 INFO - 1612420593866 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true
[task 2021-02-04T06:36:33.873Z] 06:36:33 INFO - 1612420593870 Toolkit.Telemetry TRACE TelemetryEnvironment::constructor
[task 2021-02-04T06:36:33.933Z] 06:36:33 INFO - 1612420593930 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2021-02-04T06:36:33.935Z] 06:36:33 INFO - 1612420593932 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2021-02-04T06:36:33.935Z] 06:36:33 INFO - 1612420593932 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2021-02-04T06:36:33.942Z] 06:36:33 INFO - 1612420593938 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2021-02-04T06:36:33.950Z] 06:36:33 INFO - 1612420593948 Marionette TRACE Marionette enabled
[task 2021-02-04T06:36:34.033Z] 06:36:34 INFO - 1612420594027 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-02-04T06:36:34.048Z] 06:36:34 INFO - 1612420594041 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
[task 2021-02-04T06:36:34.431Z] 06:36:34 INFO - 1612420594430 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2021-02-04T06:36:34.487Z] 06:36:34 INFO - 1612420594482 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2021-02-04T06:36:34.487Z] 06:36:34 INFO - 1612420594483 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:34.571Z] 06:36:34 INFO - 1612420594569 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2021-02-04T06:36:34.572Z] 06:36:34 INFO - 1612420594570 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:35.537Z] 06:36:35 INFO - 1612420595533 Toolkit.Telemetry TRACE TelemetrySession::observe - xul-window-visible notified.
[task 2021-02-04T06:36:35.739Z] 06:36:35 INFO - console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
[task 2021-02-04T06:36:35.776Z] 06:36:35 INFO - 1612420595765 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: sessionstore-windows-restored, aData: null
[task 2021-02-04T06:36:35.776Z] 06:36:35 INFO - 1612420595768 Toolkit.Telemetry TRACE TelemetrySession::observe - sessionstore-windows-restored notified.
[task 2021-02-04T06:36:35.778Z] 06:36:35 INFO - 1612420595768 Toolkit.Telemetry TRACE TelemetrySession::gatherStartup
[task 2021-02-04T06:36:35.779Z] 06:36:35 INFO - 1612420595768 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-04T06:36:35.779Z] 06:36:35 INFO - 1612420595768 Toolkit.Telemetry TRACE TelemetryReportingPolicy::_shouldNotify - User already notified or bypassing the policy.
[task 2021-02-04T06:36:35.961Z] 06:36:35 INFO - 1612420595957 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: settings-update-complete
[task 2021-02-04T06:36:36.201Z] 06:36:36 INFO - 1612420596191 Toolkit.Telemetry TRACE TelemetryEnvironment::_startWatchingPrefs - [object Map]
[task 2021-02-04T06:36:36.201Z] 06:36:36 INFO - 1612420596193 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:36.202Z] 06:36:36 INFO - 1612420596196 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.databaseSchema
[task 2021-02-04T06:36:36.224Z] 06:36:36 INFO - 1612420596222 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:36.268Z] 06:36:36 INFO - 1612420596266 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:36.291Z] 06:36:36 INFO - 1612420596285 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:36.307Z] 06:36:36 INFO - 1612420596303 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: init-complete
[task 2021-02-04T06:36:36.308Z] 06:36:36 INFO - 1612420596303 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - isInitialized: true
[task 2021-02-04T06:36:36.309Z] 06:36:36 INFO - 1612420596305 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.urlbar.placeholderName
[task 2021-02-04T06:36:36.310Z] 06:36:36 INFO - 1612420596307 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.storageVersion
[task 2021-02-04T06:36:36.317Z] 06:36:36 INFO - 1612420596312 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.pinned
[task 2021-02-04T06:36:36.317Z] 06:36:36 INFO - 1612420596313 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.improvesearch.topSiteSearchShortcuts.havePinned
[task 2021-02-04T06:36:36.333Z] 06:36:36 INFO - 1612420596329 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: distribution-customization-complete, aData: null
[task 2021-02-04T06:36:36.333Z] 06:36:36 INFO - 1612420596329 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.bookmarks.restore_default_bookmarks
[task 2021-02-04T06:36:36.352Z] 06:36:36 INFO - 1612420596342 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: network.trr.blocklist_cleanup_done
[task 2021-02-04T06:36:36.353Z] 06:36:36 INFO - 1612420596342 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.region-update-timer
[task 2021-02-04T06:36:36.359Z] 06:36:36 INFO - 1612420596356 Toolkit.Telemetry TRACE TelemetryEnvironment::_onEnvironmentChange for system-info
[task 2021-02-04T06:36:36.361Z] 06:36:36 INFO - 1612420596358 Toolkit.Telemetry DEBUG TelemetryEnvironment::_onEnvironmentChange - calling CrashAnnotator
[task 2021-02-04T06:36:36.361Z] 06:36:36 INFO - 1612420596359 Toolkit.Telemetry TRACE ClientID::_doLoadClientIDs
[task 2021-02-04T06:36:36.365Z] 06:36:36 INFO - 1612420596361 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.cachedClientID
[task 2021-02-04T06:36:36.365Z] 06:36:36 INFO - 1612420596362 Toolkit.Telemetry TRACE ClientID::_saveClientIDs
[task 2021-02-04T06:36:36.368Z] 06:36:36 INFO - 1612420596367 Toolkit.Telemetry TRACE ClientID::_doLoadClientIDs: New client IDs loaded and persisted.
[task 2021-02-04T06:36:36.370Z] 06:36:36 INFO - 1612420596367 Toolkit.Telemetry TRACE TelemetrySend::setup
[task 2021-02-04T06:36:36.370Z] 06:36:36 INFO - 1612420596368 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-04T06:36:36.390Z] 06:36:36 INFO - 1612420596377 Toolkit.Telemetry TRACE TelemetryStorage::_scanPendingPings
[task 2021-02-04T06:36:36.390Z] 06:36:36 INFO - 1612420596377 Toolkit.Telemetry TRACE TelemetryStorage::_migrateAppDataPings
[task 2021-02-04T06:36:36.390Z] 06:36:36 INFO - 1612420596377 Toolkit.Telemetry TRACE TelemetryStorage::_iterateAppDataPings
[task 2021-02-04T06:36:36.446Z] 06:36:36 INFO - 1612420596444 Toolkit.Telemetry INFO TelemetrySend::_checkPendingPings - pending ping count: 0
[task 2021-02-04T06:36:36.447Z] 06:36:36 INFO - 1612420596444 Toolkit.Telemetry TRACE TelemetrySend::_checkPendingPings - no pending pings
[task 2021-02-04T06:36:36.448Z] 06:36:36 INFO - 1612420596444 Toolkit.Telemetry TRACE TelemetryStorage::_enforcePendingPingsQuota
[task 2021-02-04T06:36:36.448Z] 06:36:36 INFO - 1612420596444 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true
[task 2021-02-04T06:36:36.449Z] 06:36:36 INFO - 1612420596444 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask iteration
[task 2021-02-04T06:36:36.450Z] 06:36:36 INFO - 1612420596445 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0
[task 2021-02-04T06:36:36.451Z] 06:36:36 INFO - 1612420596445 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0
[task 2021-02-04T06:36:36.451Z] 06:36:36 INFO - 1612420596445 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out
[task 2021-02-04T06:36:36.452Z] 06:36:36 INFO - 1612420596445 Toolkit.Telemetry TRACE TelemetrySession::delayedInit
[task 2021-02-04T06:36:36.452Z] 06:36:36 INFO - 1612420596445 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-04T06:36:36.455Z] 06:36:36 INFO - 1612420596453 Toolkit.Telemetry INFO TelemetryStorage::_loadSessionData - can not load session data file: {"operation":"open","path":"/builds/worker/workspace/build/tmpLsgKYL.mozrunner/datareporting/session-state.json","unixErrno":2}
[task 2021-02-04T06:36:36.456Z] 06:36:36 INFO - 1612420596453 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-04T06:36:36.553Z] 06:36:36 INFO - 1612420596547 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2021-02-04T06:36:36.554Z] 06:36:36 INFO - 1612420596549 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:36.554Z] 06:36:36 INFO - 1612420596549 Toolkit.Telemetry TRACE TelemetryStorage::loadPingfile - unreadable ping /builds/worker/workspace/build/tmpLsgKYL.mozrunner/datareporting/aborted-session-ping: {"operation":"open","path":"/builds/worker/workspace/build/tmpLsgKYL.mozrunner/datareporting/aborted-session-ping","unixErrno":2}
[task 2021-02-04T06:36:36.555Z] 06:36:36 INFO - 1612420596549 Toolkit.Telemetry TRACE TelemetryStorage::loadAbortedSessionPing - no such file
[task 2021-02-04T06:36:36.556Z] 06:36:36 INFO - 1612420596549 Toolkit.Telemetry TRACE TelemetryController::checkAbortedSessionPing - found aborted-session ping: false
[task 2021-02-04T06:36:36.557Z] 06:36:36 INFO - 1612420596550 Toolkit.Telemetry TRACE TelemetrySession::_saveAbortedSessionPing
[task 2021-02-04T06:36:36.557Z] 06:36:36 INFO - 1612420596550 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - reason: aborted-session, clearSubsession: false
[task 2021-02-04T06:36:36.558Z] 06:36:36 INFO - 1612420596550 Toolkit.Telemetry TRACE TelemetrySession::assemblePayloadWithMeasurements - reason: aborted-session, submitting subsession data: true
[task 2021-02-04T06:36:36.575Z] 06:36:36 INFO - 1612420596564 Toolkit.Telemetry TRACE TelemetryController::saveAbortedSessionPing
[task 2021-02-04T06:36:36.578Z] 06:36:36 INFO - 1612420596565 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true}
[task 2021-02-04T06:36:36.580Z] 06:36:36 INFO - 1612420596569 Toolkit.Telemetry TRACE TelemetryStorage::saveAbortedSessionPing - ping path: /builds/worker/workspace/build/tmpLsgKYL.mozrunner/datareporting/aborted-session-ping
[task 2021-02-04T06:36:36.589Z] 06:36:36 INFO - 1612420596583 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-04T06:36:36.592Z] 06:36:36 INFO - 1612420596583 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: /builds/worker/workspace/build/tmpLsgKYL.mozrunner/datareporting/aborted-session-ping
[task 2021-02-04T06:36:36.594Z] 06:36:36 INFO - 1612420596585 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange
[task 2021-02-04T06:36:36.610Z] 06:36:36 INFO - 1612420596599 Toolkit.Telemetry TRACE TelemetryScheduler::init
[task 2021-02-04T06:36:36.613Z] 06:36:36 INFO - 1612420596600 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - isUserIdle: false
[task 2021-02-04T06:36:36.615Z] 06:36:36 INFO - 1612420596600 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Thu Feb 04 2021 06:41:36 GMT+0000 (Coordinated Universal Time)
[task 2021-02-04T06:36:36.626Z] 06:36:36 INFO - 1612420596618 Toolkit.Telemetry TRACE TelemetryController::scheduleNewProfilePing
[task 2021-02-04T06:36:36.629Z] 06:36:36 INFO - 1612420596618 Toolkit.Telemetry TRACE TelemetryStorage::cleanArchiveTask
[task 2021-02-04T06:36:36.632Z] 06:36:36 INFO - 1612420596618 Toolkit.Telemetry TRACE TelemetryStorage::removeFHRDatabase
[task 2021-02-04T06:36:36.635Z] 06:36:36 INFO - 1612420596619 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.telemetry_modules_ping
[task 2021-02-04T06:36:36.647Z] 06:36:36 INFO - 1612420596644 Toolkit.Telemetry TRACE TelemetryEventPing::::Starting up.
[task 2021-02-04T06:36:36.650Z] 06:36:36 INFO - 1612420596645 Toolkit.Telemetry TRACE TelemetryPrioPing::Extended collection disabled. Prio ping disabled.
[task 2021-02-04T06:36:36.672Z] 06:36:36 INFO - 1612420596668 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.migrationVersion
[task 2021-02-04T06:36:36.682Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.cursorToolOnLoad
[task 2021-02-04T06:36:36.682Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.defaultZoomValue
[task 2021-02-04T06:36:36.683Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disablePageLabels
[task 2021-02-04T06:36:36.683Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enablePermissions
[task 2021-02-04T06:36:36.683Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enablePrintAutoRotate
[task 2021-02-04T06:36:36.684Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enableScripting
[task 2021-02-04T06:36:36.684Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enableWebGL
[task 2021-02-04T06:36:36.684Z] 06:36:36 INFO - 1612420596669 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.externalLinkTarget
[task 2021-02-04T06:36:36.688Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.historyUpdateUrl
[task 2021-02-04T06:36:36.688Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.ignoreDestinationZoom
[task 2021-02-04T06:36:36.688Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.pdfBugEnabled
[task 2021-02-04T06:36:36.689Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.renderer
[task 2021-02-04T06:36:36.689Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.sidebarViewOnLoad
[task 2021-02-04T06:36:36.689Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.scrollModeOnLoad
[task 2021-02-04T06:36:36.690Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.spreadModeOnLoad
[task 2021-02-04T06:36:36.690Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.textLayerMode
[task 2021-02-04T06:36:36.690Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.useOnlyCssZoom
[task 2021-02-04T06:36:36.690Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.viewerCssTheme
[task 2021-02-04T06:36:36.692Z] 06:36:36 INFO - 1612420596670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.viewOnLoad
[task 2021-02-04T06:36:36.692Z] 06:36:36 INFO - 1612420596671 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableAutoFetch
[task 2021-02-04T06:36:36.692Z] 06:36:36 INFO - 1612420596671 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableFontFace
[task 2021-02-04T06:36:36.693Z] 06:36:36 INFO - 1612420596671 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableRange
[task 2021-02-04T06:36:36.693Z] 06:36:36 INFO - 1612420596671 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableStream
[task 2021-02-04T06:36:36.707Z] 06:36:36 INFO - 1612420596672 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.xml
[task 2021-02-04T06:36:36.707Z] 06:36:36 INFO - 1612420596673 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.svg
[task 2021-02-04T06:36:36.708Z] 06:36:36 INFO - 1612420596674 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.webp
[task 2021-02-04T06:36:36.710Z] 06:36:36 INFO - 1612420596675 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.avif
[task 2021-02-04T06:36:36.712Z] 06:36:36 INFO - 1612420596692 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.uiCustomization.state
[task 2021-02-04T06:36:36.714Z] 06:36:36 INFO - 1612420596694 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.bookmarks.addedImportButton
[task 2021-02-04T06:36:36.764Z] 06:36:36 INFO - 1612420596752 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: gfx.blacklist.layers.opengl
[task 2021-02-04T06:36:36.766Z] 06:36:36 INFO - 1612420596753 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: gfx.blacklist.layers.opengl.failureid
[task 2021-02-04T06:36:36.783Z] 06:36:36 INFO - 1612420596773 Marionette TRACE Received observer notification marionette-startup-requested
[task 2021-02-04T06:36:36.783Z] 06:36:36 INFO - 1612420596773 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2021-02-04T06:36:36.871Z] 06:36:36 INFO - 1612420596862 Marionette TRACE All scripts recorded.
[task 2021-02-04T06:36:36.872Z] 06:36:36 INFO - 1612420596863 Marionette INFO Listening on port 2828
[task 2021-02-04T06:36:36.872Z] 06:36:36 INFO - 1612420596864 Marionette DEBUG Marionette is listening
[task 2021-02-04T06:36:37.374Z] 06:36:37 INFO - 1612420597369 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: write-settings-to-disk-complete
[task 2021-02-04T06:36:37.913Z] 06:36:37 INFO - 1612420597910 Marionette DEBUG Accepted connection 0 from 127.0.0.1:48184
[task 2021-02-04T06:36:37.929Z] 06:36:37 INFO - 1612420597920 Marionette DEBUG Closed connection 0
[task 2021-02-04T06:36:39.021Z] 06:36:39 INFO - 1612420599019 Toolkit.Telemetry TRACE TelemetrySession::observe - user-interaction-inactive notified.
[task 2021-02-04T06:36:39.932Z] 06:36:39 INFO - 1612420599928 Marionette DEBUG Accepted connection 1 from 127.0.0.1:48190
[task 2021-02-04T06:36:39.933Z] 06:36:39 INFO - 1612420599931 Marionette DEBUG Closed connection 1
[task 2021-02-04T06:36:40.946Z] 06:36:40 INFO - 1612420600941 Marionette DEBUG Accepted connection 2 from 127.0.0.1:48196
[task 2021-02-04T06:36:40.947Z] 06:36:40 INFO - 1612420600942 Marionette DEBUG Closed connection 2
[task 2021-02-04T06:36:41.956Z] 06:36:41 INFO - 1612420601954 Marionette DEBUG Accepted connection 3 from 127.0.0.1:48200
[task 2021-02-04T06:36:41.957Z] 06:36:41 INFO - 1612420601955 Marionette DEBUG Closed connection 3
[task 2021-02-04T06:36:42.057Z] 06:36:42 INFO - 1612420602055 Marionette DEBUG Accepted connection 4 from 127.0.0.1:48216
[task 2021-02-04T06:36:42.059Z] 06:36:42 INFO - 1612420602056 Marionette DEBUG Accepted connection 5 from 127.0.0.1:48218
[task 2021-02-04T06:36:42.063Z] 06:36:42 INFO - 1612420602061 Marionette DEBUG Closed connection 4
[task 2021-02-04T06:36:42.083Z] 06:36:42 INFO - 1612420602078 Marionette DEBUG 5 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-02-04T06:36:42.103Z] 06:36:42 INFO - 1612420602093 Marionette DEBUG 5 <- [1,1,null,{"sessionId":"8002cff1-3391-4826-950c-b06c33962bee","capabilities":{"browserName":"firefox","browserVersion":"87.0a ... ld/tmpLsgKYL.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2021-02-04T06:36:42.107Z] 06:36:42 INFO - 1612420602102 Marionette DEBUG 5 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-02-04T06:36:42.108Z] 06:36:42 INFO - 1612420602102 Marionette DEBUG 5 <- [1,2,null,{"value":null}]
[task 2021-02-04T06:36:42.115Z] 06:36:42 INFO - 1612420602111 Marionette DEBUG 5 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-02-04T06:36:42.116Z] 06:36:42 INFO - 1612420602112 Marionette DEBUG 5 <- [1,3,null,{"value":null}]
[task 2021-02-04T06:36:42.116Z] 06:36:42 INFO - 1612420602113 Marionette DEBUG 5 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-02-04T06:36:42.118Z] 06:36:42 INFO - 1612420602114 Marionette DEBUG 5 <- [1,4,null,{"value":null}]
[task 2021-02-04T06:36:42.118Z] 06:36:42 INFO - 1612420602114 Marionette DEBUG 5 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2021-02-04T06:36:42.118Z] 06:36:42 INFO - 1612420602115 Marionette DEBUG 5 <- [1,5,null,{"value":"6"}]
[task 2021-02-04T06:36:42.119Z] 06:36:42 INFO - 1612420602118 Marionette DEBUG 5 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2021-02-04T06:36:42.120Z] 06:36:42 INFO - 1612420602119 Marionette DEBUG 5 <- [1,6,null,["6"]]
[task 2021-02-04T06:36:42.124Z] 06:36:42 INFO - 1612420602121 Marionette DEBUG 5 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2021-02-04T06:36:42.124Z] 06:36:42 INFO - 1612420602121 Marionette DEBUG 5 <- [1,7,null,{"value":"17"}]
[task 2021-02-04T06:36:42.124Z] 06:36:42 INFO - 1612420602122 Marionette DEBUG 5 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2021-02-04T06:36:42.124Z] 06:36:42 INFO - 1612420602122 Marionette DEBUG 5 <- [1,8,null,["17"]]
[task 2021-02-04T06:36:42.124Z] 06:36:42 INFO - 1612420602122 Marionette DEBUG 5 -> [0,9,"Marionette:GetContext",{}]
[task 2021-02-04T06:36:42.124Z] 06:36:42 INFO - 1612420602122 Marionette DEBUG 5 <- [1,9,null,{"value":"content"}]
[task 2021-02-04T06:36:42.125Z] 06:36:42 INFO - 1612420602123 Marionette DEBUG 5 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:42.125Z] 06:36:42 INFO - 1612420602124 Marionette DEBUG 5 <- [1,10,null,{"value":null}]
[task 2021-02-04T06:36:42.130Z] 06:36:42 INFO - 1612420602126 Marionette DEBUG 5 -> [0,11,"WebDriver:Navigate",{"url":"about:about"}]
[task 2021-02-04T06:36:42.132Z] 06:36:42 INFO - 1612420602131 Marionette TRACE [17] MarionetteCommands actor created for window id 2147483649
[task 2021-02-04T06:36:42.135Z] 06:36:42 INFO - 1612420602133 Marionette TRACE [17] MarionetteEvents actor created for window id 2147483649
[task 2021-02-04T06:36:42.136Z] 06:36:42 INFO - 1612420602134 Marionette TRACE Received event beforeunload for about:blank
[task 2021-02-04T06:36:42.144Z] 06:36:42 INFO - 1612420602140 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 36
[task 2021-02-04T06:36:42.159Z] 06:36:42 INFO - 1612420602156 Marionette TRACE [36] MarionetteEvents actor created for window id 25
[task 2021-02-04T06:36:42.201Z] 06:36:42 INFO - 1612420602200 Marionette TRACE Received event beforeunload for about:blank
[task 2021-02-04T06:36:42.205Z] 06:36:42 INFO - 1612420602201 Marionette TRACE Received event pagehide for about:blank
[task 2021-02-04T06:36:42.229Z] 06:36:42 INFO - 1612420602227 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.lastupdatetime
[task 2021-02-04T06:36:42.234Z] 06:36:42 INFO - 1612420602228 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.nextupdatetime
[task 2021-02-04T06:36:42.253Z] 06:36:42 INFO - 1612420602241 Marionette TRACE [36] MarionetteEvents actor created for window id 26
[task 2021-02-04T06:36:42.255Z] 06:36:42 INFO - 1612420602241 Marionette TRACE Received event DOMContentLoaded for about:about
[task 2021-02-04T06:36:42.273Z] 06:36:42 INFO - 1612420602266 Marionette TRACE Received event pageshow for about:about
[task 2021-02-04T06:36:42.274Z] 06:36:42 INFO - 1612420602267 Marionette DEBUG 5 <- [1,11,null,{"value":null}]
[task 2021-02-04T06:36:42.290Z] 06:36:42 INFO - 1612420602282 Marionette DEBUG 5 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:42.292Z] 06:36:42 INFO - 1612420602285 Marionette DEBUG 5 <- [1,12,null,{"value":null}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602297 Marionette DEBUG 5 -> [0,13,"Marionette:GetContext",{}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602298 Marionette DEBUG 5 <- [1,13,null,{"value":"content"}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602298 Marionette DEBUG 5 -> [0,14,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602299 Marionette DEBUG 5 <- [1,14,null,{"value":null}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602301 Marionette DEBUG 5 -> [0,15,"WebDriver:ExecuteScript",{"script":"return AppConstants.MOZ_GLEAN;","newSandbox":true,"args":[],"filename":"venv/lib/python2.7/site-packages/telemetry_harness/fog_testcase.py","sandbox":"default","line":27}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602302 Marionette TRACE [6] MarionetteCommands actor created for window id 2
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602305 Marionette DEBUG 5 <- [1,15,null,{"value":true}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602306 Marionette DEBUG 5 -> [0,16,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:42.309Z] 06:36:42 INFO - 1612420602306 Marionette DEBUG 5 <- [1,16,null,{"value":null}]
[task 2021-02-04T06:36:42.311Z] 06:36:42 INFO - FOGTestCase Submitting to FOG ping server at http://localhost:38378/
[task 2021-02-04T06:36:42.312Z] 06:36:42 INFO - 1612420602311 Marionette DEBUG 5 -> [0,17,"Marionette:GetContext",{}]
[task 2021-02-04T06:36:42.313Z] 06:36:42 INFO - 1612420602311 Marionette DEBUG 5 <- [1,17,null,{"value":"content"}]
[task 2021-02-04T06:36:42.315Z] 06:36:42 INFO - 1612420602312 Marionette DEBUG 5 -> [0,18,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-04T06:36:42.316Z] 06:36:42 INFO - 1612420602312 Marionette DEBUG 5 <- [1,18,null,{"value":null}]
[task 2021-02-04T06:36:42.318Z] 06:36:42 INFO - 1612420602314 Marionette DEBUG 5 -> [0,19,"WebDriver:ExecuteScript",{"script":"let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n ... true,"args":[],"filename":"venv/lib/python2.7/site-packages/marionette_driver/marionette.py","sandbox":"default","line":895}]
[task 2021-02-04T06:36:42.322Z] 06:36:42 INFO - 1612420602318 Marionette DEBUG 5 <- [1,19,null,{"value":false}]
[task 2021-02-04T06:36:42.324Z] 06:36:42 INFO - 1612420602319 Marionette DEBUG 5 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:42.324Z] 06:36:42 INFO - 1612420602319 Marionette DEBUG 5 <- [1,20,null,{"value":null}]
[task 2021-02-04T06:36:42.324Z] 06:36:42 INFO - 1612420602320 Marionette DEBUG 5 -> [0,21,"Marionette:GetContext",{}]
[task 2021-02-04T06:36:42.324Z] 06:36:42 INFO - 1612420602320 Marionette DEBUG 5 <- [1,21,null,{"value":"content"}]
[task 2021-02-04T06:36:42.324Z] 06:36:42 INFO - 1612420602321 Marionette DEBUG 5 -> [0,22,"WebDriver:DeleteSession",{}]
[task 2021-02-04T06:36:42.324Z] 06:36:42 INFO - 1612420602322 Marionette DEBUG 5 <- [1,22,null,{"value":null}]
[task 2021-02-04T06:36:42.400Z] 06:36:42 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmp21enth.mozrunner
[task 2021-02-04T06:36:42.783Z] 06:36:42 INFO - 1612420602773 Toolkit.Telemetry TRACE TelemetryController::observe - profile-after-change notified.
[task 2021-02-04T06:36:42.783Z] 06:36:42 INFO - 1612420602773 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry
[task 2021-02-04T06:36:42.783Z] 06:36:42 INFO - 1612420602775 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup
[task 2021-02-04T06:36:42.783Z] 06:36:42 INFO - 1612420602775 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:42.783Z] 06:36:42 INFO - 1612420602775 Toolkit.Telemetry TRACE TelemetrySession::earlyInit
[task 2021-02-04T06:36:42.785Z] 06:36:42 INFO - 1612420602779 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-04T06:36:42.786Z] 06:36:42 INFO - 1612420602779 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true
[task 2021-02-04T06:36:42.788Z] 06:36:42 INFO - 1612420602784 Toolkit.Telemetry TRACE TelemetryEnvironment::constructor
[task 2021-02-04T06:36:42.829Z] 06:36:42 INFO - 1612420602828 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2021-02-04T06:36:42.833Z] 06:36:42 INFO - 1612420602829 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2021-02-04T06:36:42.834Z] 06:36:42 INFO - 1612420602830 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2021-02-04T06:36:42.836Z] 06:36:42 INFO - 1612420602835 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2021-02-04T06:36:42.852Z] 06:36:42 INFO - 1612420602845 Marionette TRACE Marionette enabled
[task 2021-02-04T06:36:42.928Z] 06:36:42 INFO - 1612420602924 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-02-04T06:36:42.944Z] 06:36:42 INFO - 1612420602932 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
[task 2021-02-04T06:36:43.322Z] 06:36:43 INFO - 1612420603318 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2021-02-04T06:36:43.359Z] 06:36:43 INFO - 1612420603353 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2021-02-04T06:36:43.361Z] 06:36:43 INFO - 1612420603355 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:43.482Z] 06:36:43 INFO - 1612420603480 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2021-02-04T06:36:43.483Z] 06:36:43 INFO - 1612420603481 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:44.428Z] 06:36:44 INFO - 1612420604426 Toolkit.Telemetry TRACE TelemetrySession::observe - xul-window-visible notified.
[task 2021-02-04T06:36:44.631Z] 06:36:44 INFO - 1612420604629 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: sessionstore-windows-restored, aData: null
[task 2021-02-04T06:36:44.639Z] 06:36:44 INFO - 1612420604634 Toolkit.Telemetry TRACE TelemetrySession::observe - sessionstore-windows-restored notified.
[task 2021-02-04T06:36:44.639Z] 06:36:44 INFO - 1612420604634 Toolkit.Telemetry TRACE TelemetrySession::gatherStartup
[task 2021-02-04T06:36:44.639Z] 06:36:44 INFO - 1612420604635 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-04T06:36:44.639Z] 06:36:44 INFO - 1612420604635 Toolkit.Telemetry TRACE TelemetryReportingPolicy::_shouldNotify - User already notified or bypassing the policy.
[task 2021-02-04T06:36:44.695Z] 06:36:44 INFO - console.warn: SearchSettings: "get: No settings file exists, new profile?" (new Error("", "(unknown module)"))
[task 2021-02-04T06:36:44.859Z] 06:36:44 INFO - 1612420604858 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: settings-update-complete
[task 2021-02-04T06:36:45.083Z] 06:36:45 INFO - 1612420605079 Toolkit.Telemetry TRACE TelemetryEnvironment::_startWatchingPrefs - [object Map]
[task 2021-02-04T06:36:45.084Z] 06:36:45 INFO - 1612420605081 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:45.090Z] 06:36:45 INFO - 1612420605084 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.normandy.first_run
[task 2021-02-04T06:36:45.133Z] 06:36:45 INFO - 1612420605132 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:45.181Z] 06:36:45 INFO - 1612420605176 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:45.202Z] 06:36:45 INFO - 1612420605196 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.webextensions.uuids
[task 2021-02-04T06:36:45.203Z] 06:36:45 INFO - 1612420605197 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.databaseSchema
[task 2021-02-04T06:36:45.219Z] 06:36:45 INFO - 1612420605210 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: init-complete
[task 2021-02-04T06:36:45.220Z] 06:36:45 INFO - 1612420605210 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - isInitialized: true
[task 2021-02-04T06:36:45.222Z] 06:36:45 INFO - 1612420605213 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.urlbar.placeholderName
[task 2021-02-04T06:36:45.222Z] 06:36:45 INFO - 1612420605214 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.storageVersion
[task 2021-02-04T06:36:45.224Z] 06:36:45 INFO - 1612420605218 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.pinned
[task 2021-02-04T06:36:45.225Z] 06:36:45 INFO - 1612420605218 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.improvesearch.topSiteSearchShortcuts.havePinned
[task 2021-02-04T06:36:45.240Z] 06:36:45 INFO - 1612420605235 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: distribution-customization-complete, aData: null
[task 2021-02-04T06:36:45.241Z] 06:36:45 INFO - 1612420605235 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.bookmarks.restore_default_bookmarks
[task 2021-02-04T06:36:45.261Z] 06:36:45 INFO - 1612420605249 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: network.trr.blocklist_cleanup_done
[task 2021-02-04T06:36:45.264Z] 06:36:45 INFO - 1612420605262 Toolkit.Telemetry TRACE TelemetryEnvironment::_onEnvironmentChange for system-info
[task 2021-02-04T06:36:45.265Z] 06:36:45 INFO - 1612420605263 Toolkit.Telemetry DEBUG TelemetryEnvironment::_onEnvironmentChange - calling CrashAnnotator
[task 2021-02-04T06:36:45.266Z] 06:36:45 INFO - 1612420605263 Toolkit.Telemetry TRACE ClientID::_doLoadClientIDs
[task 2021-02-04T06:36:45.270Z] 06:36:45 INFO - 1612420605265 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.cachedClientID
[task 2021-02-04T06:36:45.270Z] 06:36:45 INFO - 1612420605266 Toolkit.Telemetry TRACE ClientID::_saveClientIDs
[task 2021-02-04T06:36:45.273Z] 06:36:45 INFO - 1612420605271 Toolkit.Telemetry TRACE ClientID::_doLoadClientIDs: New client IDs loaded and persisted.
[task 2021-02-04T06:36:45.273Z] 06:36:45 INFO - 1612420605271 Toolkit.Telemetry TRACE TelemetrySend::setup
[task 2021-02-04T06:36:45.273Z] 06:36:45 INFO - 1612420605271 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-04T06:36:45.291Z] 06:36:45 INFO - 1612420605280 Toolkit.Telemetry TRACE TelemetryStorage::_scanPendingPings
[task 2021-02-04T06:36:45.291Z] 06:36:45 INFO - 1612420605280 Toolkit.Telemetry TRACE TelemetryStorage::_migrateAppDataPings
[task 2021-02-04T06:36:45.292Z] 06:36:45 INFO - 1612420605280 Toolkit.Telemetry TRACE TelemetryStorage::_iterateAppDataPings
[task 2021-02-04T06:36:45.292Z] 06:36:45 INFO - 1612420605285 Toolkit.Telemetry INFO TelemetrySend::_checkPendingPings - pending ping count: 0
[task 2021-02-04T06:36:45.292Z] 06:36:45 INFO - 1612420605285 Toolkit.Telemetry TRACE TelemetrySend::_checkPendingPings - no pending pings
[task 2021-02-04T06:36:45.293Z] 06:36:45 INFO - 1612420605285 Toolkit.Telemetry TRACE TelemetryStorage::_enforcePendingPingsQuota
[task 2021-02-04T06:36:45.293Z] 06:36:45 INFO - 1612420605286 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true
[task 2021-02-04T06:36:45.294Z] 06:36:45 INFO - 1612420605286 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask iteration
[task 2021-02-04T06:36:45.294Z] 06:36:45 INFO - 1612420605286 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0
[task 2021-02-04T06:36:45.294Z] 06:36:45 INFO - 1612420605286 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0
[task 2021-02-04T06:36:45.295Z] 06:36:45 INFO - 1612420605286 Toolkit.Telemetry TRACE TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out
[task 2021-02-04T06:36:45.295Z] 06:36:45 INFO - 1612420605286 Toolkit.Telemetry TRACE TelemetrySession::delayedInit
[task 2021-02-04T06:36:45.296Z] 06:36:45 INFO - 1612420605287 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-04T06:36:45.296Z] 06:36:45 INFO - 1612420605287 Toolkit.Telemetry INFO TelemetryStorage::_loadSessionData - can not load session data file: {"operation":"open","path":"/builds/worker/workspace/build/tmp21enth.mozrunner/datareporting/session-state.json","unixErrno":2}
[task 2021-02-04T06:36:45.296Z] 06:36:45 INFO - 1612420605287 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-04T06:36:45.331Z] 06:36:45 INFO - 1612420605324 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.region-update-timer
[task 2021-02-04T06:36:45.392Z] 06:36:45 INFO - 1612420605384 Toolkit.Telemetry TRACE TelemetryStorage::loadPingfile - unreadable ping /builds/worker/workspace/build/tmp21enth.mozrunner/datareporting/aborted-session-ping: {"operation":"open","path":"/builds/worker/workspace/build/tmp21enth.mozrunner/datareporting/aborted-session-ping","unixErrno":2}
[task 2021-02-04T06:36:45.393Z] 06:36:45 INFO - 1612420605386 Toolkit.Telemetry TRACE TelemetryStorage::loadAbortedSessionPing - no such file
[task 2021-02-04T06:36:45.394Z] 06:36:45 INFO - 1612420605386 Toolkit.Telemetry TRACE TelemetryController::checkAbortedSessionPing - found aborted-session ping: false
[task 2021-02-04T06:36:45.395Z] 06:36:45 INFO - 1612420605386 Toolkit.Telemetry TRACE TelemetrySession::_saveAbortedSessionPing
[task 2021-02-04T06:36:45.396Z] 06:36:45 INFO - 1612420605386 Toolkit.Telemetry TRACE TelemetrySession::getSessionPayload - reason: aborted-session, clearSubsession: false
[task 2021-02-04T06:36:45.396Z] 06:36:45 INFO - 1612420605387 Toolkit.Telemetry TRACE TelemetrySession::assemblePayloadWithMeasurements - reason: aborted-session, submitting subsession data: true
[task 2021-02-04T06:36:45.397Z] 06:36:45 INFO - 1612420605389 Toolkit.Telemetry TRACE TelemetryController::saveAbortedSessionPing
[task 2021-02-04T06:36:45.397Z] 06:36:45 INFO - 1612420605389 Toolkit.Telemetry TRACE TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true}
[task 2021-02-04T06:36:45.398Z] 06:36:45 INFO - 1612420605390 Toolkit.Telemetry TRACE TelemetryStorage::saveAbortedSessionPing - ping path: /builds/worker/workspace/build/tmp21enth.mozrunner/datareporting/aborted-session-ping
[task 2021-02-04T06:36:45.398Z] 06:36:45 INFO - 1612420605391 Toolkit.Telemetry TRACE TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-04T06:36:45.398Z] 06:36:45 INFO - 1612420605391 Toolkit.Telemetry TRACE TelemetryStorage::savePingToFile - path: /builds/worker/workspace/build/tmp21enth.mozrunner/datareporting/aborted-session-ping
[task 2021-02-04T06:36:45.400Z] 06:36:45 INFO - 1612420605392 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange
[task 2021-02-04T06:36:45.400Z] 06:36:45 INFO - 1612420605396 Toolkit.Telemetry TRACE TelemetryScheduler::init
[task 2021-02-04T06:36:45.400Z] 06:36:45 INFO - 1612420605396 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - isUserIdle: false
[task 2021-02-04T06:36:45.400Z] 06:36:45 INFO - 1612420605396 Toolkit.Telemetry TRACE TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Thu Feb 04 2021 06:41:45 GMT+0000 (Coordinated Universal Time)
[task 2021-02-04T06:36:45.417Z] 06:36:45 INFO - 1612420605406 Toolkit.Telemetry TRACE TelemetryController::scheduleNewProfilePing
[task 2021-02-04T06:36:45.417Z] 06:36:45 INFO - 1612420605406 Toolkit.Telemetry TRACE TelemetryStorage::cleanArchiveTask
[task 2021-02-04T06:36:45.417Z] 06:36:45 INFO - 1612420605406 Toolkit.Telemetry TRACE TelemetryStorage::removeFHRDatabase
[task 2021-02-04T06:36:45.417Z] 06:36:45 INFO - 1612420605408 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.telemetry_modules_ping
[task 2021-02-04T06:36:45.417Z] 06:36:45 INFO - 1612420605414 Toolkit.Telemetry TRACE TelemetryEventPing::::Starting up.
[task 2021-02-04T06:36:45.417Z] 06:36:45 INFO - 1612420605414 Toolkit.Telemetry TRACE TelemetryPrioPing::Extended collection disabled. Prio ping disabled.
[task 2021-02-04T06:36:45.494Z] 06:36:45 INFO - 1612420605488 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.migrationVersion
[task 2021-02-04T06:36:45.494Z] 06:36:45 INFO - 1612420605489 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.cursorToolOnLoad
[task 2021-02-04T06:36:45.494Z] 06:36:45 INFO - 1612420605489 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.defaultZoomValue
[task 2021-02-04T06:36:45.494Z] 06:36:45 INFO - 1612420605490 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disablePageLabels
[task 2021-02-04T06:36:45.494Z] 06:36:45 INFO - 1612420605490 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enablePermissions
[task 2021-02-04T06:36:45.494Z] 06:36:45 INFO - 1612420605491 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enablePrintAutoRotate
[task 2021-02-04T06:36:45.494Z] 06:36:45 INFO - 1612420605492 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enableScripting
[task 2021-02-04T06:36:45.495Z] 06:36:45 INFO - 1612420605493 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.enableWebGL
[task 2021-02-04T06:36:45.499Z] 06:36:45 INFO - 1612420605496 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.externalLinkTarget
[task 2021-02-04T06:36:45.499Z] 06:36:45 INFO - 1612420605496 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.historyUpdateUrl
[task 2021-02-04T06:36:45.501Z] 06:36:45 INFO - 1612420605497 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.ignoreDestinationZoom
[task 2021-02-04T06:36:45.501Z] 06:36:45 INFO - 1612420605498 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.pdfBugEnabled
[task 2021-02-04T06:36:45.504Z] 06:36:45 INFO - 1612420605500 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.renderer
[task 2021-02-04T06:36:45.504Z] 06:36:45 INFO - 1612420605502 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.sidebarViewOnLoad
[task 2021-02-04T06:36:45.505Z] 06:36:45 INFO - 1612420605503 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.scrollModeOnLoad
[task 2021-02-04T06:36:45.506Z] 06:36:45 INFO - 1612420605503 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.spreadModeOnLoad
[task 2021-02-04T06:36:45.509Z] 06:36:45 INFO - 1612420605504 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.textLayerMode
[task 2021-02-04T06:36:45.509Z] 06:36:45 INFO - 1612420605506 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.useOnlyCssZoom
[task 2021-02-04T06:36:45.510Z] 06:36:45 INFO - 1612420605507 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.viewerCssTheme
[task 2021-02-04T06:36:45.510Z] 06:36:45 INFO - 1612420605507 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.viewOnLoad
[task 2021-02-04T06:36:45.510Z] 06:36:45 INFO - 1612420605508 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableAutoFetch
[task 2021-02-04T06:36:45.513Z] 06:36:45 INFO - 1612420605511 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableFontFace
[task 2021-02-04T06:36:45.513Z] 06:36:45 INFO - 1612420605511 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableRange
[task 2021-02-04T06:36:45.514Z] 06:36:45 INFO - 1612420605512 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: pdfjs.disableStream
[task 2021-02-04T06:36:45.517Z] 06:36:45 INFO - 1612420605516 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.xml
[task 2021-02-04T06:36:45.519Z] 06:36:45 INFO - 1612420605517 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.svg
[task 2021-02-04T06:36:45.522Z] 06:36:45 INFO - 1612420605519 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.webp
[task 2021-02-04T06:36:45.523Z] 06:36:45 INFO - 1612420605520 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.download.viewableInternally.typeWasRegistered.avif
[task 2021-02-04T06:36:45.558Z] 06:36:45 INFO - 1612420605554 Toolkit.Telemetry TRACE TelemetryController::observe - app-startup notified.
[task 2021-02-04T06:36:45.558Z] 06:36:45 INFO - 1612420605555 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-02-04T06:36:45.660Z] 06:36:45 INFO - 1612420605658 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.uiCustomization.state
[task 2021-02-04T06:36:45.662Z] 06:36:45 INFO - 1612420605659 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.bookmarks.addedImportButton
[task 2021-02-04T06:36:45.680Z] 06:36:45 INFO - 1612420605677 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: gfx.blacklist.layers.opengl
[task 2021-02-04T06:36:45.680Z] 06:36:45 INFO - 1612420605677 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: gfx.blacklist.layers.opengl.failureid
[task 2021-02-04T06:36:45.723Z] 06:36:45 INFO - 1612420605721 Marionette TRACE Received observer notification marionette-startup-requested
[task 2021-02-04T06:36:45.723Z] 06:36:45 INFO - 1612420605721 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2021-02-04T06:36:45.805Z] 06:36:45 INFO - 1612420605802 Marionette TRACE All scripts recorded.
[task 2021-02-04T06:36:45.805Z] 06:36:45 INFO - 1612420605803 Marionette INFO Listening on port 2828
[task 2021-02-04T06:36:45.807Z] 06:36:45 INFO - 1612420605804 Marionette DEBUG Marionette is listening
[task 2021-02-04T06:36:45.832Z] 06:36:45 INFO - 1612420605829 Marionette DEBUG Accepted connection 0 from 127.0.0.1:48326
[task 2021-02-04T06:36:45.836Z] 06:36:45 INFO - 1612420605833 Marionette DEBUG Accepted connection 1 from 127.0.0.1:48328
[task 2021-02-04T06:36:45.845Z] 06:36:45 INFO - 1612420605839 Marionette DEBUG Closed connection 0
[task 2021-02-04T06:36:45.861Z] 06:36:45 INFO - 1612420605852 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-02-04T06:36:45.864Z] 06:36:45 INFO - 1612420605861 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"77539066-2f13-4edd-aedb-72d03a6168c5","capabilities":{"browserName":"firefox","browserVersion":"87.0a ... ld/tmp21enth.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2021-02-04T06:36:45.873Z] 06:36:45 INFO - 1612420605871 Marionette DEBUG 1 -> [0,2,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:45.874Z] 06:36:45 INFO - 1612420605871 Marionette DEBUG 1 <- [1,2,null,{"value":null}]
[task 2021-02-04T06:36:46.473Z] 06:36:46 INFO - 1612420606463 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: browser-search-service, aData: write-settings-to-disk-complete
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607882 Marionette DEBUG 1 -> [0,3,"Marionette:GetContext",{}]
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607882 Marionette DEBUG 1 <- [1,3,null,{"value":"content"}]
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607884 Marionette DEBUG 1 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607884 Marionette DEBUG 1 <- [1,4,null,{"value":null}]
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607887 Marionette DEBUG 1 -> [0,5,"WebDriver:ExecuteScript",{"script":"Services.prefs.setIntPref(\"telemetry.fog.test.inactivity_limit\", 0);\n ... true,"args":[],"filename":"tests/telemetry/marionette/tests/client/test_fog_user_activity.py","sandbox":"default","line":19}]
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607888 Marionette TRACE [6] MarionetteCommands actor created for window id 2
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607890 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: telemetry.fog.test.inactivity_limit
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607890 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: telemetry.fog.test.activity_limit
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - 1612420607890 Marionette DEBUG 1 <- [1,5,null,{"value":null}]
[task 2021-02-04T06:36:47.895Z] 06:36:47 INFO - wait_for_pings running action '<lambda>'.
[task 2021-02-04T06:36:47.896Z] 06:36:47 INFO - 1612420607893 Marionette DEBUG 1 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:47.898Z] 06:36:47 INFO - 1612420607893 Marionette DEBUG 1 <- [1,6,null,{"value":null}]
[task 2021-02-04T06:36:47.898Z] 06:36:47 INFO - 1612420607894 Marionette DEBUG 1 -> [0,7,"Marionette:GetContext",{}]
[task 2021-02-04T06:36:47.898Z] 06:36:47 INFO - 1612420607894 Marionette DEBUG 1 <- [1,7,null,{"value":"content"}]
[task 2021-02-04T06:36:47.904Z] 06:36:47 INFO - 1612420607899 Marionette DEBUG 1 -> [0,8,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-04T06:36:47.905Z] 06:36:47 INFO - 1612420607899 Marionette DEBUG 1 <- [1,8,null,{"value":null}]
[task 2021-02-04T06:36:47.905Z] 06:36:47 INFO - 1612420607900 Marionette DEBUG 1 -> [0,9,"WebDriver:ExecuteScript",{"script":"Services.obs.notifyObservers(null, 'user-interaction-active')","newSandbox":true,"args":[],"filename":"tests/telemetry/marionette/tests/client/test_fog_user_activity.py","sandbox":"default","line":26}]
[task 2021-02-04T06:36:47.906Z] 06:36:47 INFO - 1612420607902 Toolkit.Telemetry TRACE TelemetrySession::observe - user-interaction-active notified.
[task 2021-02-04T06:36:47.907Z] 06:36:47 INFO - 1612420607903 Marionette DEBUG 1 <- [1,9,null,{"value":null}]
[task 2021-02-04T06:36:47.907Z] 06:36:47 INFO - 1612420607904 Marionette DEBUG 1 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:47.908Z] 06:36:47 INFO - 1612420607904 Marionette DEBUG 1 <- [1,10,null,{"value":null}]
[task 2021-02-04T06:36:47.915Z] 06:36:47 INFO - fog_ping_server pings_handler received 'baseline' ping
[task 2021-02-04T06:36:47.922Z] 06:36:47 INFO - 1612420607917 Toolkit.Telemetry TRACE TelemetrySession::observe - user-interaction-inactive notified.
[task 2021-02-04T06:36:47.930Z] 06:36:47 INFO - fog_ping_server pings_handler received 'baseline' ping
[task 2021-02-04T06:36:48.006Z] 06:36:48 INFO - wait_for_pings running action '<lambda>'.
[task 2021-02-04T06:36:48.007Z] 06:36:48 INFO - 1612420608006 Marionette DEBUG 1 -> [0,11,"Marionette:GetContext",{}]
[task 2021-02-04T06:36:48.010Z] 06:36:48 INFO - 1612420608007 Marionette DEBUG 1 <- [1,11,null,{"value":"content"}]
[task 2021-02-04T06:36:48.011Z] 06:36:48 INFO - 1612420608008 Marionette DEBUG 1 -> [0,12,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-04T06:36:48.011Z] 06:36:48 INFO - 1612420608009 Marionette DEBUG 1 <- [1,12,null,{"value":null}]
[task 2021-02-04T06:36:48.014Z] 06:36:48 INFO - 1612420608011 Marionette DEBUG 1 -> [0,13,"WebDriver:ExecuteScript",{"script":"Services.obs.notifyObservers(null, 'user-interaction-inactive')","newSandbox":true,"args":[],"filename":"tests/telemetry/marionette/tests/client/test_fog_user_activity.py","sandbox":"default","line":26}]
[task 2021-02-04T06:36:48.015Z] 06:36:48 INFO - 1612420608013 Toolkit.Telemetry TRACE TelemetrySession::observe - user-interaction-inactive notified.
[task 2021-02-04T06:36:48.015Z] 06:36:48 INFO - 1612420608013 Marionette DEBUG 1 <- [1,13,null,{"value":null}]
[task 2021-02-04T06:36:48.018Z] 06:36:48 INFO - 1612420608014 Marionette DEBUG 1 -> [0,14,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:36:48.018Z] 06:36:48 INFO - 1612420608014 Marionette DEBUG 1 <- [1,14,null,{"value":null}]
[task 2021-02-04T06:36:48.122Z] 06:36:48 INFO - 1612420608119 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.lastupdatetime
[task 2021-02-04T06:36:48.122Z] 06:36:48 INFO - 1612420608120 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.nextupdatetime
[task 2021-02-04T06:37:04.672Z] 06:37:04 INFO - 1612420624670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: media.gmp-manager.buildID
[task 2021-02-04T06:37:04.673Z] 06:37:04 INFO - 1612420624670 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: media.gmp-manager.lastCheck
[task 2021-02-04T06:37:12.847Z] 06:37:12 INFO - 1612420632844 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.services-settings-poll-changes
[task 2021-02-04T06:37:12.849Z] 06:37:12 INFO - 1612420632845 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.addon-background-update-timer
[task 2021-02-04T06:37:12.850Z] 06:37:12 INFO - 1612420632845 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.search-engine-update-timer
[task 2021-02-04T06:37:12.851Z] 06:37:12 INFO - 1612420632845 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.background-update-timer
[task 2021-02-04T06:37:12.852Z] 06:37:12 INFO - 1612420632845 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.browser-cleanup-thumbnails
[task 2021-02-04T06:37:15.484Z] 06:37:15 INFO - 1612420635481 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.startup.last_success
[task 2021-02-04T06:37:44.644Z] 06:37:44 INFO - 1612420664635 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-04T06:37:44.644Z] 06:37:44 INFO - 1612420664635 Toolkit.Telemetry TRACE TelemetryReportingPolicy::_shouldNotify - User already notified or bypassing the policy.
[task 2021-02-04T06:37:48.094Z] 06:37:48 INFO - 1612420668088 Marionette DEBUG 1 -> [0,15,"Marionette:GetContext",{}]
[task 2021-02-04T06:37:48.096Z] 06:37:48 INFO - 1612420668088 Marionette DEBUG 1 <- [1,15,null,{"value":"content"}]
[task 2021-02-04T06:37:48.096Z] 06:37:48 INFO - 1612420668089 Marionette DEBUG 1 -> [0,16,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-04T06:37:48.096Z] 06:37:48 INFO - 1612420668089 Marionette DEBUG 1 <- [1,16,null,{"value":null}]
[task 2021-02-04T06:37:48.097Z] 06:37:48 INFO - 1612420668090 Marionette DEBUG 1 -> [0,17,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2021-02-04T06:37:48.141Z] 06:37:48 INFO - 1612420668136 Marionette DEBUG 1 <- [1,17,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzd3W/cB53v8f4V/BlcrfZmzw2rXuUmisqRQiu1UgsU0RYu ... AAAAAAjAlAAAAAABgTgAAAAAAwJgABAAAAYEwAAgAAAMCYAAQAAACAMQEIAAAAAGMCEAAAAADGBCAAAAAAjAlAAAAAABgLFm3pGy93XqIAAAAASUVORK5CYII="}]
[task 2021-02-04T06:37:48.141Z] 06:37:48 INFO - 1612420668137 Marionette DEBUG 1 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:37:48.141Z] 06:37:48 INFO - 1612420668137 Marionette DEBUG 1 <- [1,18,null,{"value":null}]
[task 2021-02-04T06:37:48.142Z] 06:37:48 INFO - 1612420668138 Marionette DEBUG 1 -> [0,19,"Marionette:GetContext",{}]
[task 2021-02-04T06:37:48.142Z] 06:37:48 INFO - 1612420668138 Marionette DEBUG 1 <- [1,19,null,{"value":"content"}]
[task 2021-02-04T06:37:48.143Z] 06:37:48 INFO - 1612420668139 Marionette DEBUG 1 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-04T06:37:48.143Z] 06:37:48 INFO - 1612420668140 Marionette DEBUG 1 <- [1,20,null,{"value":null}]
[task 2021-02-04T06:37:48.144Z] 06:37:48 INFO - 1612420668140 Marionette DEBUG 1 -> [0,21,"WebDriver:GetPageSource",{}]
[task 2021-02-04T06:37:48.154Z] 06:37:48 INFO - 1612420668148 Marionette TRACE [17] MarionetteCommands actor created for window id 2147483649
[task 2021-02-04T06:37:48.154Z] 06:37:48 INFO - 1612420668149 Marionette DEBUG 1 <- [1,21,null,{"value":"<html><head></head><body></body></html>"}]
[task 2021-02-04T06:37:48.168Z] 06:37:48 INFO - TEST-UNEXPECTED-FAIL | telemetry/marionette/tests/client/test_fog_user_activity.py TestClientActivity.test_user_activity | AssertionError: Error waiting for ping: Timed out after 60.1 seconds```
Description
•