1694370 - Intermittent telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | application crashed [@ xul.dll + 0x567c78c]

Status: RESOLVED INCOMPLETE

(Toolkit :: Telemetry, defect, P4)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=330883267&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eSFCMENtR3WLs7msRD7r3A/runs/0/artifacts/public/logs/live_backing.log

---

...
[task 2021-02-23T10:51:48.725Z] 10:51:48     INFO - wait_for_pings running action 'restart_browser'.
[task 2021-02-23T10:51:48.725Z] 10:51:48     INFO -  1614077508715	Marionette	DEBUG	1 <- [1,35,null,{"value":true}]
[task 2021-02-23T10:51:48.725Z] 10:51:48     INFO -  1614077508717	Marionette	DEBUG	1 -> [0,36,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-23T10:51:48.725Z] 10:51:48     INFO -  1614077508718	Marionette	DEBUG	1 <- [1,36,null,{"value":null}]
[task 2021-02-23T10:51:48.725Z] 10:51:48     INFO -  1614077508719	Marionette	DEBUG	1 -> [0,37,"Marionette:GetContext",{}]
[task 2021-02-23T10:51:48.725Z] 10:51:48     INFO -  1614077508719	Marionette	DEBUG	1 <- [1,37,null,{"value":"content"}]
[task 2021-02-23T10:51:48.728Z] 10:51:48     INFO -  1614077508722	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.lastupdatetime
[task 2021-02-23T10:51:48.728Z] 10:51:48     INFO -  1614077508724	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.safebrowsing.provider.mozilla.nextupdatetime
[task 2021-02-23T10:51:48.728Z] 10:51:48     INFO -  1614077508725	Marionette	DEBUG	1 -> [0,38,"Marionette:AcceptConnections",{"value":false}]
[task 2021-02-23T10:51:48.728Z] 10:51:48     INFO -  1614077508725	Marionette	INFO	Stopped listening on port 2828
[task 2021-02-23T10:51:48.731Z] 10:51:48     INFO -  1614077508725	Marionette	DEBUG	1 <- [1,38,null,{"value":null}]
[task 2021-02-23T10:51:48.731Z] 10:51:48     INFO -  1614077508727	Marionette	DEBUG	1 -> [0,39,"Marionette:GetContext",{}]
[task 2021-02-23T10:51:48.731Z] 10:51:48     INFO -  1614077508728	Marionette	DEBUG	1 <- [1,39,null,{"value":"content"}]
[task 2021-02-23T10:51:48.734Z] 10:51:48     INFO -  1614077508729	Marionette	DEBUG	1 -> [0,40,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-02-23T10:51:48.734Z] 10:51:48     INFO -  1614077508730	Marionette	DEBUG	1 <- [1,40,null,{"value":null}]
[task 2021-02-23T10:51:48.741Z] 10:51:48     INFO -  1614077508732	Marionette	DEBUG	1 -> [0,41,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/Services.jsm\");\n                ... me":"Z:\\task_1614076511\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py","sandbox":"default","line":955}]
[task 2021-02-23T10:51:48.748Z] 10:51:48     INFO -  1614077508738	Marionette	DEBUG	1 <- [1,41,null,{"value":false}]
[task 2021-02-23T10:51:48.748Z] 10:51:48     INFO -  1614077508740	Marionette	DEBUG	1 -> [0,42,"Marionette:SetContext",{"value":"content"}]
[task 2021-02-23T10:51:48.748Z] 10:51:48     INFO -  1614077508740	Marionette	DEBUG	1 <- [1,42,null,{"value":null}]
[task 2021-02-23T10:51:48.748Z] 10:51:48     INFO -  1614077508741	Marionette	DEBUG	1 -> [0,43,"Marionette:Quit",{"flags":["eForceQuit","eRestart"]}]
[task 2021-02-23T10:51:48.776Z] 10:51:48     INFO -  [Child 3016, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:48.776Z] 10:51:48     INFO -  [Child 3016, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:48.795Z] 10:51:48     INFO -  [Child 3016, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:48.795Z] 10:51:48     INFO -  [Child 3016, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:48.795Z] 10:51:48     INFO -  [Child 3016, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:48.795Z] 10:51:48     INFO -  [Child 3016, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:48.795Z] 10:51:48     INFO -  [Child 3016, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:48.810Z] 10:51:48     INFO -  1614077508802	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.startup.last_success
[task 2021-02-23T10:51:48.811Z] 10:51:48     INFO -  1614077508807	Marionette	TRACE	Received observer notification quit-application
[task 2021-02-23T10:51:48.814Z] 10:51:48     INFO -  1614077508809	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.sessionstore.resume_session_once
[task 2021-02-23T10:51:48.829Z] 10:51:48     INFO -  1614077508816	Marionette	DEBUG	1 <- [1,43,null,{"cause":"restart"}]
[task 2021-02-23T10:51:48.924Z] 10:51:48     INFO -  [Parent 4844, URL Classifier] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp:250
...
[task 2021-02-23T10:51:48.945Z] 10:51:48     INFO -  [Parent 4844, URL Classifier] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp:250
[task 2021-02-23T10:51:48.959Z] 10:51:48     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-23T10:51:48.960Z] 10:51:48     INFO -  [Parent 4844, Main Thread] WARNIN
[task 2021-02-23T10:51:48.960Z] 10:51:48     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-23T10:51:48.960Z] 10:51:48     INFO -  G: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/dom/security/FramingChecker.cpp:210
[task 2021-02-23T10:51:48.961Z] 10:51:48     INFO -  [Parent 4844, Main Thread] WARNING: 'aOwner->IsDiscarded()', file /builds/worker/workspace/obj-build/dist/include/mozilla/dom/SyncedContextInlines.h:92
[task 2021-02-23T10:51:48.962Z] 10:51:48     INFO -  [Parent 4844, URL Classifier] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp:250
...
[task 2021-02-23T10:51:48.969Z] 10:51:48     INFO -  [Parent 4844, URL Classifier] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/netwerk/url-classifier/AsyncUrlChannelClassifier.cpp:250
[task 2021-02-23T10:51:48.969Z] 10:51:48     INFO -  [Parent 4844, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:224
[task 2021-02-23T10:51:48.969Z] 10:51:48     INFO -  [Parent 4844, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:497
[task 2021-02-23T10:51:48.970Z] 10:51:48     INFO -  [Parent 4844, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:497
[task 2021-02-23T10:51:48.970Z] 10:51:48     INFO -  [Parent 4844, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:497
[task 2021-02-23T10:51:48.970Z] 10:51:48     INFO -  [Parent 4844, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/dom/security/FramingChecker.cpp:210
[task 2021-02-23T10:51:48.970Z] 10:51:48     INFO -  [Child 920, Main Thread] WARNING: Scrolled rect smaller than scrollport?: file /builds/worker/checkouts/gecko/layout/generic/nsGfxScrollFrame.cpp:7053
[task 2021-02-23T10:51:48.971Z] 10:51:48     INFO -  1614077508965	Marionette	DEBUG	Closed connection 1
[task 2021-02-23T10:51:48.992Z] 10:51:48     INFO -  [Parent 4844, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/netwerk/cache/nsApplicationCacheService.cpp:161
[task 2021-02-23T10:51:48.999Z] 10:51:48     INFO -  1614077508992	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: privacy.sanitize.pending
[task 2021-02-23T10:51:49.006Z] 10:51:49     INFO -  [Parent 4844, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-23T10:51:49.006Z] 10:51:49     INFO -  [Parent 4844, Main Thread] WARNING: Error sending reply: file /builds/worker/workspace/obj-build/ipc/ipdl/PContentParent.cpp:12673
[task 2021-02-23T10:51:49.081Z] 10:51:49     INFO -  [2021-02-23T10:51:49Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2021-02-23T10:51:49.081Z] 10:51:49     INFO -  [2021-02-23T10:51:49Z WARN  xulstore::persist] tried to remove key that isn't in the store
[task 2021-02-23T10:51:49.121Z] 10:51:49     INFO -  [Child 3016, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-23T10:51:49.141Z] 10:51:49     INFO -  [Child 3016, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-23T10:51:49.288Z] 10:51:49     INFO -  [Parent 4844, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-23T10:51:49.288Z] 10:51:49     INFO -  [Parent 4844, Main Thread] WARNING: Error sending reply: file /builds/worker/workspace/obj-build/ipc/ipdl/PContentParent.cpp:12673
[task 2021-02-23T10:51:49.329Z] 10:51:49     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-23T10:51:49.345Z] 10:51:49     INFO -  [Child 4808, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-23T10:51:49.360Z] 10:51:49     INFO -  [Child 4808, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-23T10:51:49.383Z] 10:51:49     INFO -  [Child 4784, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-23T10:51:49.402Z] 10:51:49     INFO -  [Child 4784, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4380
[task 2021-02-23T10:51:49.449Z] 10:51:49     INFO -  [Child 920, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/checkouts/gecko/dom/base/WindowDestroyedEvent.cpp:113
[task 2021-02-23T10:51:49.584Z] 10:51:49     INFO -  1614077509575	Toolkit.Telemetry	TRACE	TelemetrySession::observe - user-interaction-active notified.
[task 2021-02-23T10:51:49.584Z] 10:51:49     INFO -  [Parent 4844, Main Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:224
[task 2021-02-23T10:51:49.591Z] 10:51:49     INFO -  [Child 920, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:40
[task 2021-02-23T10:51:49.594Z] 10:51:49     INFO -  [Parent 4844, Main Thread] WARNING: IPC message discardedJavaScript error: resource:///modules/FaviconLoader.jsm, :line 596: InvalidStateError: JSWin actor cannot send: file /builds/dowActorChwiold.sendAsyncMessage: JSWindorkweActorChild cannot send at the moment
[task 2021-02-23T10:51:49.594Z] 10:51:49     INFO -  r/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:512
[task 2021-02-23T10:51:49.595Z] 10:51:49     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-02-23T10:51:49.602Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.602Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: cache: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.602Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: sdb: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.603Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: ls: '0.000000s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.606Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.000000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.606Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.000000s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.609Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.000000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.609Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.000000s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.612Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.000000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.612Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.016000s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.615Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.016000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.615Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.016000s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.616Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.016000s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.616Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: idb: '0.016000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.616Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: cache: '0.016000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.619Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: sdb: '0.016000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.619Z] 10:51:49     INFO -  [Parent 4844, IPDL Background] WARNING: ls: '0.016000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3653
[task 2021-02-23T10:51:49.638Z] 10:51:49     INFO -  1614077509631	Toolkit.Telemetry	TRACE	TelemetryController::shutdown
[task 2021-02-23T10:51:49.638Z] 10:51:49     INFO -  1614077509632	Toolkit.Telemetry	TRACE	TelemetryController::sendNewProfilePing - shutting down: true
[task 2021-02-23T10:51:49.638Z] 10:51:49     INFO -  1614077509632	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: new-profile, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-02-23T10:51:49.638Z] 10:51:49     INFO -  1614077509633	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type new-profile, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-02-23T10:51:49.639Z] 10:51:49     INFO -  1614077509634	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: 6160911c-1f11-4f80-ada9-4524540ef001
[task 2021-02-23T10:51:49.642Z] 10:51:49     INFO -  1614077509636	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: 6160911c-1f11-4f80-ada9-4524540ef001, options: {"usePingSender":true}
[task 2021-02-23T10:51:49.642Z] 10:51:49     INFO -  1614077509637	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-23T10:51:49.729Z] 10:51:49     INFO -  [Child 920, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-02-23T10:51:49.749Z] 10:51:49     INFO -  [Child 920, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp1614077509741	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\datareporting\archived\2021-02\1614077509633.6160911c-1f11-4f80-ada9-4524540ef001.new-profile.jsonlz4
[task 2021-02-23T10:51:49.749Z] 10:51:49     INFO -  :4380
[task 2021-02-23T10:51:49.864Z] 10:51:49     INFO -  1614077509853	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\saved-telemetry-pings\6160911c-1f11-4f80-ada9-4524540ef001
[task 2021-02-23T10:51:49.871Z] 10:51:49     INFO -  1614077509863	Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id 6160911c-1f11-4f80-ada9-4524540ef001
[task 2021-02-23T10:51:49.871Z] 10:51:49     INFO -  1614077509863	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - sending 6160911c-1f11-4f80-ada9-4524540ef001 to http://localhost:8000/pings/submit/telemetry/6160911c-1f11-4f80-ada9-4524540ef001/new-profile/Firefox/88.0a1/default/20210223102422?v=4
[task 2021-02-23T10:51:49.871Z] 10:51:49     INFO -  1614077509863	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - too late to send. Batching.
[task 2021-02-23T10:51:49.871Z] 10:51:49     INFO -  1614077509863	Toolkit.Telemetry	TRACE	TelemetrySession::markNewProfilePingSent
[task 2021-02-23T10:51:49.871Z] 10:51:49     INFO -  1614077509864	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-23T10:51:49.954Z] 10:51:49     INFO -  1614077509948	Toolkit.Telemetry	TRACE	TelemetryEventPing::::Shutting down.
[task 2021-02-23T10:51:49.954Z] 10:51:49     INFO -  1614077509948	Toolkit.Telemetry	TRACE	TelemetryEventPing::::_submitPing
[task 2021-02-23T10:51:49.954Z] 10:51:49     INFO -  1614077509949	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: event, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-02-23T10:51:49.954Z] 10:51:49     INFO -  1614077509949	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type event, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-02-23T10:51:49.957Z] 10:51:49     INFO -  1614077509952	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: 826c6fda-e0e2-4087-967c-5dc4a6e7bca0
[task 2021-02-23T10:51:49.957Z] 10:51:49     INFO -  1614077509953	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: 826c6fda-e0e2-4087-967c-5dc4a6e7bca0, options: {"usePingSender":true}
[task 2021-02-23T10:51:49.957Z] 10:51:49     INFO -  1614077509953	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-23T10:51:49.957Z] 10:51:49     INFO -  1614077509953	Toolkit.Telemetry	TRACE	TelemetryPrioPing::Shutting down.
[task 2021-02-23T10:51:49.958Z] 10:51:49     INFO -  1614077509954	Toolkit.Telemetry	TRACE	TelemetryPrioPing::_submitPing
[task 2021-02-23T10:51:49.959Z] 10:51:49     INFO -  1614077509954	Toolkit.Telemetry	TRACE	TelemetryPrioPing::nothing to send
[task 2021-02-23T10:51:49.959Z] 10:51:49     INFO -  1614077509955	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::shutdown
[task 2021-02-23T10:51:49.959Z] 10:51:49     INFO -  1614077509955	Toolkit.Telemetry	TRACE	TelemetryEnvironment::shutdown
[task 2021-02-23T10:51:49.959Z] 10:51:49     INFO -  1614077509955	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::shutdown
[task 2021-02-23T10:51:49.959Z] 10:51:49     INFO -  1614077509955	Toolkit.Telemetry	TRACE	TelemetrySend::promisePendingPingActivity - Waiting for ping task
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509958	Toolkit.Telemetry	TRACE	TelemetryHealthPing::::shutdown()
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509958	Toolkit.Telemetry	TRACE	TelemetrySession::shutdownChromeProcess
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509958	Toolkit.Telemetry	TRACE	TelemetryEnvironment::unregisterChangeListener for TelemetrySession::onEnvironmentChange
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509958	Toolkit.Telemetry	WARN	TelemetryEnvironment::registerChangeListener - already shutdown
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509958	Toolkit.Telemetry	TRACE	TelemetryScheduler::shutdown
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509958	Toolkit.Telemetry	TRACE	TelemetrySession::saveShutdownPings
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509958	Toolkit.Telemetry	TRACE	TelemetrySession::getSessionPayload - reason: shutdown, clearSubsession: false
[task 2021-02-23T10:51:49.966Z] 10:51:49     INFO -  1614077509960	Toolkit.Telemetry	TRACE	TelemetrySession::assemblePayloadWithMeasurements - reason: shutdown, submitting subsession data: true
[task 2021-02-23T10:51:49.981Z] 10:51:49     INFO -  1614077509974	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: main, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":false}
[task 2021-02-23T10:51:49.981Z] 10:51:49     INFO -  1614077509974	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":false}
[task 2021-02-23T10:51:50.016Z] 10:51:50     INFO -  1614077510003	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: 0ee9af98-e95d-4134-91b1-e8e6fd4a8433
[task 2021-02-23T10:51:50.016Z] 10:51:50     INFO -  1614077510003	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: 0ee9af98-e95d-4134-91b1-e8e6fd4a8433, options: {"usePingSender":false}
[task 2021-02-23T10:51:50.016Z] 10:51:50     INFO -  1614077510003	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-23T10:51:50.016Z] 10:51:50     INFO -  1614077510004	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-23T10:51:50.016Z] 10:51:50     INFO -  1614077510004	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - can't send ping now, persisting to disk - canSendNow: false
[task 2021-02-23T10:51:50.016Z] 10:51:50     INFO -  1614077510004	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: first-shutdown, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-02-23T10:51:50.016Z] 10:51:50     INFO -  1614077510005	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type first-shutdown, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-02-23T10:51:50.037Z] 10:51:50     INFO -  1614077510032	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: f3daf82e-a77b-455f-91d0-3988a0e6ad94
[task 2021-02-23T10:51:50.037Z] 10:51:50     INFO -  1614077510032	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: f3daf82e-a77b-455f-91d0-3988a0e6ad94, options: {"usePingSender":true}
[task 2021-02-23T10:51:50.037Z] 10:51:50     INFO -  1614077510032	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-02-23T10:51:50.037Z] 10:51:50     INFO -  1614077510034	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\datareporting\archived\2021-02\1614077509950.826c6fda-e0e2-4087-967c-5dc4a6e7bca0.event.jsonlz4
[task 2021-02-23T10:51:50.076Z] 10:51:50     INFO -  1614077510063	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\saved-telemetry-pings\826c6fda-e0e2-4087-967c-5dc4a6e7bca0
[task 2021-02-23T10:51:50.091Z] 10:51:50     INFO -  1614077510083	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\datareporting\archived\2021-02\1614077510001.0ee9af98-e95d-4134-91b1-e8e6fd4a8433.main.jsonlz4
[task 2021-02-23T10:51:50.111Z] 10:51:50     INFO -  1614077510102	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\saved-telemetry-pings\0ee9af98-e95d-4134-91b1-e8e6fd4a8433
[task 2021-02-23T10:51:50.186Z] 10:51:50     INFO -  1614077510182	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\datareporting\archived\2021-02\1614077510030.f3daf82e-a77b-455f-91d0-3988a0e6ad94.first-shutdown.jsonlz4
[task 2021-02-23T10:51:50.201Z] 10:51:50     INFO -  1614077510194	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: Z:\task_1614076511\build\tmpi7msrz.mozrunner\saved-telemetry-pings\f3daf82e-a77b-455f-91d0-3988a0e6ad94
[task 2021-02-23T10:51:50.344Z] 10:51:50     INFO -  1614077510339	Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id 826c6fda-e0e2-4087-967c-5dc4a6e7bca0
[task 2021-02-23T10:51:50.344Z] 10:51:50     INFO -  1614077510339	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - sending 826c6fda-e0e2-4087-967c-5dc4a6e7bca0 to http://localhost:8000/pings/submit/telemetry/826c6fda-e0e2-4087-967c-5dc4a6e7bca0/event/Firefox/88.0a1/default/20210223102422?v=4
[task 2021-02-23T10:51:50.344Z] 10:51:50     INFO -  1614077510339	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - too late to send. Batching.
[task 2021-02-23T10:51:50.551Z] 10:51:50     INFO -  1614077510547	Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id 0ee9af98-e95d-4134-91b1-e8e6fd4a8433
[task 2021-02-23T10:51:50.611Z] 10:51:50     INFO -  1614077510605	Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id f3daf82e-a77b-455f-91d0-3988a0e6ad94
[task 2021-02-23T10:51:50.611Z] 10:51:50     INFO -  1614077510605	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - sending f3daf82e-a77b-455f-91d0-3988a0e6ad94 to http://localhost:8000/pings/submit/telemetry/f3daf82e-a77b-455f-91d0-3988a0e6ad94/first-shutdown/Firefox/88.0a1/default/20210223102422?v=4
[task 2021-02-23T10:51:50.611Z] 10:51:50     INFO -  1614077510605	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - too late to send. Batching.
[task 2021-02-23T10:51:50.611Z] 10:51:50     INFO -  1614077510606	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-23T10:51:50.618Z] 10:51:50     INFO -  1614077510611	Toolkit.Telemetry	TRACE	TelemetryStorage::removeAbortedSessionPing - success
[task 2021-02-23T10:51:50.618Z] 10:51:50     INFO -  1614077510613	Toolkit.Telemetry	TRACE	TelemetrySend::flushPingSenderBatch - Sending 3 pings.
[task 2021-02-23T10:51:50.621Z] 10:51:50     INFO -  1614077510615	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-02-23T10:51:50.621Z] 10:51:50     INFO -  1614077510616	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2021-02-23T10:51:50.621Z] 10:51:50     INFO -  1614077510616	Marionette	DEBUG	Marionette stopped listening
[task 2021-02-23T10:51:50.661Z] 10:51:50     INFO - pingserver pings_handler received 'new-profile' ping
[task 2021-02-23T10:51:50.668Z] 10:51:50     INFO - pingserver pings_handler received 'event' ping
[task 2021-02-23T10:51:50.683Z] 10:51:50     INFO - pingserver pings_handler received 'first-shutdown' ping
[task 2021-02-23T10:52:40.055Z] 10:52:40     INFO -  JavaScript error: resource://gre/modules/CrashManager.jsm, line 833: NotAllowedError: Shutting down and refusing additional I/O tasks
[task 2021-02-23T10:52:55.850Z] 10:52:55     INFO -  Hit MOZ_CRASH(Shutdown hanging after all known phases and workers finished.) at /builds/worker/checkouts/gecko/toolkit/components/terminator/nsTerminator.cpp:233
[task 2021-02-23T10:52:56.006Z] 10:52:56     INFO -  #01: PRP_TryLock[Z:\task_1614076511\build\application\firefox\nss3.dll +0x130fe7]
[task 2021-02-23T10:52:56.006Z] 10:52:56     INFO -  #02: PR_MD_UNLOCK[Z:\task_1614076511\build\application\firefox\nss3.dll +0x122a76]
[task 2021-02-23T10:52:56.006Z] 10:52:56     INFO -  #03: o____lc_collate_cp_func[Z:\task_1614076511\build\application\firefox\ucrtbase.DLL +0x3e16f]
[task 2021-02-23T10:52:56.006Z] 10:52:56     INFO -  #04: BaseThreadInitThunk[C:\windows\system32\kernel32.dll +0x4ef3c]
[task 2021-02-23T10:52:56.006Z] 10:52:56     INFO -  #05: RtlInitializeExceptionChain[C:\windows\SYSTEM32\ntdll.dll +0x63618]
[task 2021-02-23T10:52:56.006Z] 10:52:56     INFO -  #06: RtlInitializeExceptionChain[C:\windows\SYSTEM32\ntdll.dll +0x635eb]
[task 2021-02-23T10:54:59.177Z] 10:54:59     INFO - mozcrash Copy/paste: Z:/task_1614076511/fetches\minidump_stackwalk\minidump_stackwalk.exe Z:\task_1614076511\build\tmpi7msrz.mozrunner\minidumps\61511a65-2638-44ab-a626-e81f6ef78bd4.dmp c:\users\task_1614076511\appdata\local\temp\tmpvugp3x
[task 2021-02-23T10:55:06.398Z] 10:55:06     INFO - mozcrash Saved minidump as Z:\task_1614076511\build\blobber_upload_dir\61511a65-2638-44ab-a626-e81f6ef78bd4.dmp
[task 2021-02-23T10:55:06.398Z] 10:55:06     INFO - mozcrash Saved app info as Z:\task_1614076511\build\blobber_upload_dir\61511a65-2638-44ab-a626-e81f6ef78bd4.extra
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - PROCESS-CRASH | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | application crashed [@ xul.dll + 0x567c78c]
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - Mozilla crash reason: MOZ_CRASH(Shutdown hanging after all known phases and workers finished.)
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - Crash dump filename: Z:\task_1614076511\build\tmpi7msrz.mozrunner\minidumps\61511a65-2638-44ab-a626-e81f6ef78bd4.dmp
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - Operating system: Windows NT
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO -                   6.1.7601 Service Pack 1
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - CPU: x86
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO -      GenuineIntel family 6 model 63 stepping 2
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO -      8 CPUs
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - 
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - GPU: UNKNOWN
[task 2021-02-23T10:55:06.438Z] 10:55:06     INFO - 
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO - Crash reason:  EXCEPTION_BREAKPOINT
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO - Crash address: 0x59f4c78c
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO - Process uptime: 74 seconds
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO - 
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO - Thread 45 (crashed)
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -  0  xul.dll + 0x567c78c
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     eip = 0x59f4c78c   esp = 0x2791fbb4   ebp = 0x2791fbc8   ebx = 0x10a59428
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     esi = 0x0000003f   edi = 0x764bc446   eax = 0x6aece5f8   ecx = 0x000000e9
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     edx = 0x00000049   efl = 0x00000216
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     Found by: given as instruction pointer in context
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -  1  nss3.dll + 0x130fe7
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     eip = 0x696a0fe7   esp = 0x2791fbd0   ebp = 0x2791fbf0
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     Found by: previous frame's frame pointer
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -  2  nss3.dll + 0x122a76
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     eip = 0x69692a76   esp = 0x2791fbf8   ebp = 0x2791fc00
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     Found by: previous frame's frame pointer
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -  3  ucrtbase.dll!GetPrivateProfileStringA + 0x8e
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     eip = 0x6a8fe16f   esp = 0x2791fc08   ebp = 0x2791fc3c
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -     Found by: previous frame's frame pointer
[task 2021-02-23T10:55:06.439Z] 10:55:06     INFO -  4  kernel32.dll!BaseThreadInitThunk + 0x12
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -     eip = 0x764bef3c   esp = 0x2791fc44   ebp = 0x2791fc48
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -     Found by: call frame info
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -  5  ntdll.dll!BaseCheckVDMp + 0x8ff
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -     eip = 0x77743618   esp = 0x2791fc50   ebp = 0x2791fc88
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -     Found by: call frame info
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -  6  ntdll.dll!BaseCheckVDMp + 0x8d2
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -     eip = 0x777435eb   esp = 0x2791fc90   ebp = 0x2791fca0
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO -     Found by: call frame info
[task 2021-02-23T10:55:06.440Z] 10:55:06     INFO - 
...```

Comment 1

[Intermittent Failures Robot]

1 failures in 4327 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows7-32: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1694370&startday=2021-02-22&endday=2021-02-28&tree=all

Comment 2

[Intermittent Failures Robot]

1 failures in 2888 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-32: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1694370&startday=2021-06-14&endday=2021-06-20&tree=all

Comment 3

[Intermittent Failures Robot]

6 failures in 2873 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6

Platform and build breakdown:

• windows10-32-2004-qr: 3
  • opt: 3
• macosx1015-64-qr: 2
  • opt: 2
• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1694370&startday=2021-09-20&endday=2021-09-26&tree=all

Comment 4

[Chris H-C :chutten]

Not much I can do with this without symbolicated dumps. Investigation of which appeared to be happening in bug 1564019.

Comment 5

[Intermittent Failures Robot]

10 failures in 2845 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 8
• mozilla-central: 2

Platform and build breakdown:

• windows10-32-2004-qr: 4
  • opt: 4
• windows10-64-2004-qr: 4
  • opt: 4
• windows10-32-2004-shippable-qr: 1
  • opt: 1
• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1694370&startday=2021-10-25&endday=2021-10-31&tree=all

Comment 6

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.