Closed Bug 1690728 Opened 4 years ago Closed 7 months ago

Intermittent telemetry/marionette/tests/client/test_fog_user_activity.py TestClientActivity.test_user_activity | AssertionError: Error waiting for ping: Timed out after 60.1 seconds

Categories

(Toolkit :: Telemetry, defect, P1)

defect

Tracking

()

RESOLVED FIXED
127 Branch
Tracking Status
firefox-esr115 --- fixed
firefox125 --- wontfix
firefox126 --- fixed
firefox127 --- fixed

People

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

References

Details

(Keywords: assertion, intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(2 files)

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```

Hm. Having the Telemetry Log be so verbose in a FOG Test isn't so useful. FOG has its own logging which would be more likely to be helpful. Lemme file a bug to augment that.

Depends on: 1690860
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

There have been 44 total failures in the last 7 days.
There are:

  • 1 failure on linux1804-64-ccov-qr opt
  • 43 failures on windows11-64-2009-asan-qr opt

Recent failure log.

Chris, as the owner of this component, can you help us assign the bug to someone? Thank you.

Flags: needinfo?(chutten)
Whiteboard: [stockwell needswork:owner]

Odd, I wonder what would cause this to increase in frequency since the end of March. I'll take a look.

Assignee: nobody → chutten
Status: REOPENED → ASSIGNED
Flags: needinfo?(chutten)
Priority: P5 → P2

Alrighty, so we went from .008 - 0.02. It's mostly windows-11 asan. Tests are timing out all on line 39 after waiting a full minute for a second "baseline" ping.

Huh, the second ping's never sent because FOG thinks the user's already inactive (e.g. this line [fog_control::init::user_activity] User triggers core inactivity after 5s!). Five seconds, huh, that sounds like the right length of time for the core user interaction timer to have fired due to inactivity.

Yeah, it looks as though we're getting scooped by the real EventStateManager's real UITimerCallback notifying a real user-interaction-inactive when we were hoping for our synthetics to happen within the 5s before its timer callback fires. I think we should be able to stabilize this test by setting dom.events.user_interaction_interval to, say, 60000ms since that's the ping wait timeout.

Priority: P2 → P1
Pushed by chutten@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ae3a0c9bfa77 Slow down UI inactivity timer for FOG user activity tests r=TravisLong
Status: ASSIGNED → RESOLVED
Closed: 3 years ago7 months ago
Resolution: --- → FIXED
Target Milestone: --- → 127 Branch

The patch landed in nightly and beta is affected.
:chutten, is this bug important enough to require an uplift?

  • If yes, please nominate the patch for beta approval.
  • If no, please set status-firefox126 to wontfix.

For more information, please visit BugBot documentation.

Flags: needinfo?(chutten)

Normally I'd not bother since only so many testruns are conducted against beta anyway... but we're still in early beta, and RyanVM didn't just wontfix 126, so I'm game.

Flags: needinfo?(chutten)
Attachment #9398207 - Flags: approval-mozilla-beta?

beta Uplift Approval Request

  • User impact if declined: none
  • Code covered by automated testing: yes
  • Fix verified in Nightly: yes
  • Needs manual QE test: no
  • Steps to reproduce for manual QE testing: n/a
  • Risk associated with taking this patch: low/none
  • Explanation of risk level: test-only change for a test-only fix
  • String changes made/needed: none
  • Is Android affected?: no
Attachment #9398207 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
See Also: → 1900085
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: