Closed Bug 1704344 Opened 3 years ago Closed 1 year ago

Intermittent telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management | application crashed [@ XUL + 0x2887d43]

Categories

(Toolkit :: Telemetry, defect, P4)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: crash, intermittent-failure)

Crash Data

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


[task 2021-04-11T03:47:08.275Z] 03:47:08     INFO -  1618112828261	Toolkit.Telemetry	TRACE	TelemetrySend::_doPing - server: http://localhost:8000/pings, persisted: false, id: af636890-af7e-d34a-bd1d-24203c2e0787
[task 2021-04-11T03:47:08.276Z] 03:47:08     INFO - pingserver pings_handler received 'main' ping with reason 'environment-change'
[task 2021-04-11T03:47:08.277Z] 03:47:08     INFO - wait_for_pings running action 'restart_browser'.
[task 2021-04-11T03:47:08.277Z] 03:47:08     INFO -  1618112828266	Toolkit.Telemetry	INFO	TelemetrySend::_doPing - successfully loaded, status: 200
[task 2021-04-11T03:47:08.277Z] 03:47:08     INFO -  1618112828267	Toolkit.Telemetry	TRACE	TelemetrySend::_onPingRequestFinished - success: true, persisted: false
[task 2021-04-11T03:47:08.278Z] 03:47:08     INFO -  1618112828267	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - bailing out after sending, shutdown: false, pendingPingCount: 0
[task 2021-04-11T03:47:08.278Z] 03:47:08     INFO -  1618112828268	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-04-11T03:47:08.278Z] 03:47:08     INFO -  1618112828268	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/datareporting/aborted-session-ping
[task 2021-04-11T03:47:08.278Z] 03:47:08     INFO -  1618112828268	Marionette	DEBUG	1 -> [0,8,"Marionette:GetContext",{}]
[task 2021-04-11T03:47:08.278Z] 03:47:08     INFO -  1618112828268	Marionette	DEBUG	1 <- [1,8,null,{"value":"content"}]
[task 2021-04-11T03:47:08.279Z] 03:47:08     INFO -  1618112828269	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/datareporting/archived/2021-04/1618112828260.af636890-af7e-d34a-bd1d-24203c2e0787.main.jsonlz4
[task 2021-04-11T03:47:08.279Z] 03:47:08     INFO -  1618112828271	Marionette	DEBUG	1 -> [0,9,"Marionette:AcceptConnections",{"value":false}]
[task 2021-04-11T03:47:08.279Z] 03:47:08     INFO -  1618112828271	Marionette	INFO	Stopped listening on port 2828
[task 2021-04-11T03:47:08.280Z] 03:47:08     INFO -  1618112828271	Marionette	DEBUG	1 <- [1,9,null,{"value":null}]
[task 2021-04-11T03:47:08.280Z] 03:47:08     INFO -  1618112828272	Marionette	DEBUG	1 -> [0,10,"Marionette:Quit",{"flags":["eRestart","eForceQuit"]}]
[task 2021-04-11T03:47:08.292Z] 03:47:08     INFO -  1618112828292	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.startup.last_success
[task 2021-04-11T03:47:08.294Z] 03:47:08     INFO -  1618112828294	Marionette	TRACE	Received observer notification quit-application
[task 2021-04-11T03:47:08.295Z] 03:47:08     INFO -  1618112828294	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.sessionstore.resume_session_once
[task 2021-04-11T03:47:08.297Z] 03:47:08     INFO -  1618112828297	Marionette	DEBUG	1 <- [1,10,null,{"cause":"restart","forced":false}]
[task 2021-04-11T03:47:08.317Z] 03:47:08     INFO -  1618112828317	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.sessionstore.upgradeBackup.latestBuildID
[task 2021-04-11T03:47:08.325Z] 03:47:08     INFO -  1618112828325	Marionette	DEBUG	Closed connection 1
[task 2021-04-11T03:47:08.329Z] 03:47:08     INFO -  1618112828329	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: privacy.sanitize.pending
[task 2021-04-11T03:47:08.336Z] 03:47:08     INFO -  WARNING: A blocker encountered an error while we were waiting.
[task 2021-04-11T03:47:08.337Z] 03:47:08     INFO -            Blocker:  Flush WebExtension StartupCache
[task 2021-04-11T03:47:08.337Z] 03:47:08     INFO -            Phase: IOUtils: waiting for profileBeforeChange IO to complete
[task 2021-04-11T03:47:08.337Z] 03:47:08     INFO -            State: (none)
[task 2021-04-11T03:47:08.337Z] 03:47:08     INFO -  WARNING: Error: The object has been already finalized.
[task 2021-04-11T03:47:08.337Z] 03:47:08     INFO -  WARNING: finalize@resource://gre/modules/DeferredTask.jsm:267:13
[task 2021-04-11T03:47:08.338Z] 03:47:08     INFO -  save/<@resource://gre/modules/ExtensionParent.jsm:1725:32
[task 2021-04-11T03:47:08.338Z] 03:47:08     INFO -  trigger@resource://gre/modules/AsyncShutdown.jsm:747:23
[task 2021-04-11T03:47:08.338Z] 03:47:08     INFO -  _wait@resource://gre/modules/AsyncShutdown.jsm:899:15
[task 2021-04-11T03:47:08.338Z] 03:47:08     INFO -  wait@resource://gre/modules/AsyncShutdown.jsm:880:34
[task 2021-04-11T03:47:08.339Z] 03:47:08     INFO -  wait@resource://gre/modules/nsAsyncShutdown.jsm:209:25
[task 2021-04-11T03:47:08.339Z] 03:47:08     INFO -  addBlocker/moduleBlocker/<@resource://gre/modules/nsAsyncShutdown.jsm:156:30
[task 2021-04-11T03:47:08.339Z] 03:47:08     INFO -  moduleBlocker@resource://gre/modules/nsAsyncShutdown.jsm:152:9
[task 2021-04-11T03:47:08.340Z] 03:47:08     INFO -  trigger@resource://gre/modules/AsyncShutdown.jsm:747:23
[task 2021-04-11T03:47:08.340Z] 03:47:08     INFO -  _wait@resource://gre/modules/AsyncShutdown.jsm:899:15
[task 2021-04-11T03:47:08.340Z] 03:47:08     INFO -  wait@resource://gre/modules/AsyncShutdown.jsm:880:34
[task 2021-04-11T03:47:08.340Z] 03:47:08     INFO -  observe@resource://gre/modules/AsyncShutdown.jsm:557:10
[task 2021-04-11T03:47:08.341Z] 03:47:08     INFO -  1618112828339	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: browser-search-service, aData: write-settings-to-disk-complete
[task 2021-04-11T03:47:08.341Z] 03:47:08     INFO -  JavaScript error: resource://gre/modules/DeferredTask.jsm, line 267: Error: The object has been already finalized.
[task 2021-04-11T03:47:08.345Z] 03:47:08     INFO -  1618112828344	Toolkit.Telemetry	TRACE	TelemetryController::shutdown
[task 2021-04-11T03:47:08.345Z] 03:47:08     INFO -  1618112828344	Toolkit.Telemetry	TRACE	TelemetryEventPing::::Shutting down.
[task 2021-04-11T03:47:08.345Z] 03:47:08     INFO -  1618112828344	Toolkit.Telemetry	TRACE	TelemetryEventPing::::_submitPing
[task 2021-04-11T03:47:08.345Z] 03:47:08     INFO -  1618112828345	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: event, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-04-11T03:47:08.346Z] 03:47:08     INFO -  1618112828345	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type event, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-04-11T03:47:08.346Z] 03:47:08     INFO -  1618112828345	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: e4511c8f-bce2-194d-8140-351a9315a5de
[task 2021-04-11T03:47:08.346Z] 03:47:08     INFO -  1618112828345	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: e4511c8f-bce2-194d-8140-351a9315a5de, options: {"usePingSender":true}
[task 2021-04-11T03:47:08.347Z] 03:47:08     INFO -  1618112828345	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-04-11T03:47:08.347Z] 03:47:08     INFO -  1618112828345	Toolkit.Telemetry	TRACE	TelemetryPrioPing::Shutting down.
[task 2021-04-11T03:47:08.347Z] 03:47:08     INFO -  1618112828345	Toolkit.Telemetry	TRACE	TelemetryPrioPing::_submitPing
[task 2021-04-11T03:47:08.347Z] 03:47:08     INFO -  1618112828346	Toolkit.Telemetry	TRACE	TelemetryPrioPing::nothing to send
[task 2021-04-11T03:47:08.348Z] 03:47:08     INFO -  1618112828346	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::shutdown
[task 2021-04-11T03:47:08.348Z] 03:47:08     INFO -  1618112828346	Toolkit.Telemetry	TRACE	TelemetryEnvironment::shutdown
[task 2021-04-11T03:47:08.348Z] 03:47:08     INFO -  1618112828346	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::shutdown
[task 2021-04-11T03:47:08.349Z] 03:47:08     INFO -  1618112828346	Toolkit.Telemetry	TRACE	TelemetrySend::promisePendingPingActivity - Waiting for ping task
[task 2021-04-11T03:47:08.349Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	TRACE	TelemetryHealthPing::::shutdown()
[task 2021-04-11T03:47:08.349Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	TRACE	TelemetrySession::shutdownChromeProcess
[task 2021-04-11T03:47:08.349Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	TRACE	TelemetryEnvironment::unregisterChangeListener for TelemetrySession::onEnvironmentChange
[task 2021-04-11T03:47:08.350Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	WARN	TelemetryEnvironment::registerChangeListener - already shutdown
[task 2021-04-11T03:47:08.350Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	TRACE	TelemetryScheduler::shutdown
[task 2021-04-11T03:47:08.350Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	TRACE	TelemetrySession::saveShutdownPings
[task 2021-04-11T03:47:08.350Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	TRACE	TelemetrySession::getSessionPayload - reason: shutdown, clearSubsession: false
[task 2021-04-11T03:47:08.351Z] 03:47:08     INFO -  1618112828347	Toolkit.Telemetry	TRACE	TelemetrySession::assemblePayloadWithMeasurements - reason: shutdown, submitting subsession data: true
[task 2021-04-11T03:47:08.351Z] 03:47:08     INFO -  1618112828349	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: main, aOptions: {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-04-11T03:47:08.352Z] 03:47:08     INFO -  1618112828349	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true,"usePingSender":true}
[task 2021-04-11T03:47:08.352Z] 03:47:08     INFO -  1618112828351	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: 90074bad-7d1d-724e-b729-2348fc488b14
[task 2021-04-11T03:47:08.352Z] 03:47:08     INFO -  1618112828351	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: 90074bad-7d1d-724e-b729-2348fc488b14, options: {"usePingSender":true}
[task 2021-04-11T03:47:08.352Z] 03:47:08     INFO -  1618112828351	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-04-11T03:47:08.353Z] 03:47:08     INFO -  1618112828351	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/datareporting/archived/2021-04/1618112828345.e4511c8f-bce2-194d-8140-351a9315a5de.event.jsonlz4
[task 2021-04-11T03:47:08.353Z] 03:47:08     INFO -  1618112828352	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/saved-telemetry-pings/e4511c8f-bce2-194d-8140-351a9315a5de
[task 2021-04-11T03:47:08.354Z] 03:47:08     INFO -  1618112828352	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/datareporting/archived/2021-04/1618112828350.90074bad-7d1d-724e-b729-2348fc488b14.main.jsonlz4
[task 2021-04-11T03:47:08.354Z] 03:47:08     INFO -  1618112828353	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/saved-telemetry-pings/90074bad-7d1d-724e-b729-2348fc488b14
[task 2021-04-11T03:47:08.356Z] 03:47:08     INFO -  1618112828355	Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id e4511c8f-bce2-194d-8140-351a9315a5de
[task 2021-04-11T03:47:08.356Z] 03:47:08     INFO -  1618112828356	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - sending e4511c8f-bce2-194d-8140-351a9315a5de to http://localhost:8000/pings/submit/telemetry/e4511c8f-bce2-194d-8140-351a9315a5de/event/Firefox/89.0a1/default/20210411031624?v=4
[task 2021-04-11T03:47:08.357Z] 03:47:08     INFO -  1618112828356	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - too late to send. Batching.
[task 2021-04-11T03:47:08.357Z] 03:47:08     INFO -  1618112828357	Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id 90074bad-7d1d-724e-b729-2348fc488b14
[task 2021-04-11T03:47:08.358Z] 03:47:08     INFO -  1618112828357	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - sending 90074bad-7d1d-724e-b729-2348fc488b14 to http://localhost:8000/pings/submit/telemetry/90074bad-7d1d-724e-b729-2348fc488b14/main/Firefox/89.0a1/default/20210411031624?v=4
[task 2021-04-11T03:47:08.358Z] 03:47:08     INFO -  1618112828357	Toolkit.Telemetry	TRACE	TelemetrySend::_sendWithPingSender - too late to send. Batching.
[task 2021-04-11T03:47:08.358Z] 03:47:08     INFO -  1618112828357	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-04-11T03:47:08.359Z] 03:47:08     INFO -  1618112828357	Toolkit.Telemetry	TRACE	TelemetryStorage::removeAbortedSessionPing - success
[task 2021-04-11T03:47:08.359Z] 03:47:08     INFO -  1618112828358	Toolkit.Telemetry	TRACE	TelemetrySend::flushPingSenderBatch - Sending 2 pings.
[task 2021-04-11T03:47:08.359Z] 03:47:08     INFO -  1618112828359	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-04-11T03:47:08.360Z] 03:47:08     INFO -  1618112828359	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2021-04-11T03:47:08.360Z] 03:47:08     INFO -  1618112828360	Marionette	DEBUG	Marionette stopped listening
[task 2021-04-11T03:47:08.374Z] 03:47:08     INFO - pingserver pings_handler received 'event' ping
[task 2021-04-11T03:47:08.377Z] 03:47:08     INFO - pingserver pings_handler received 'main' ping with reason 'shutdown'
[task 2021-04-11T03:47:08.392Z] 03:47:08     INFO -  ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-11T03:47:08.425Z] 03:47:08     INFO -  1618112828424	Toolkit.Telemetry	TRACE	TelemetryController::observe - app-startup notified.
[task 2021-04-11T03:47:08.425Z] 03:47:08     INFO -  1618112828425	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-04-11T03:50:18.370Z] 03:50:18     INFO - mozcrash Copy/paste: /opt/worker/tasks/task_161810240929161/fetches/minidump_stackwalk/minidump_stackwalk /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/minidumps/58F6555C-2C5C-4FFB-802D-B13DAC9789F9.dmp /var/folders/ds/9_p3r7s95p7_1rx9lt0_5wg0000014/T/tmpa1grnij4
[task 2021-04-11T03:50:20.483Z] 03:50:20     INFO - mozcrash Saved minidump as /opt/worker/tasks/task_161810240929161/build/blobber_upload_dir/58F6555C-2C5C-4FFB-802D-B13DAC9789F9.dmp
[task 2021-04-11T03:50:20.483Z] 03:50:20     INFO - mozcrash Saved app info as /opt/worker/tasks/task_161810240929161/build/blobber_upload_dir/58F6555C-2C5C-4FFB-802D-B13DAC9789F9.extra
[task 2021-04-11T03:50:20.632Z] 03:50:20     INFO - PROCESS-CRASH | telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management | application crashed [@ XUL + 0x2887d43]
[task 2021-04-11T03:50:20.632Z] 03:50:20     INFO - Crash dump filename: /opt/worker/tasks/task_161810240929161/build/tmp9mbadst3.mozrunner/minidumps/58F6555C-2C5C-4FFB-802D-B13DAC9789F9.dmp
[task 2021-04-11T03:50:20.632Z] 03:50:20     INFO - Operating system: Mac OS X
[task 2021-04-11T03:50:20.632Z] 03:50:20     INFO -                   10.15.7 19H524
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - CPU: amd64
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -      family 6 model 158 stepping 10
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -      12 CPUs
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - GPU: UNKNOWN
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - Crash reason:  EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - Crash address: 0x0
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - Process uptime: 2 seconds
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO - Thread 0 (crashed)
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -  0  XUL + 0x2887d43
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     rax = 0x0000000000000001   rdx = 0x0000000008220045
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     rcx = 0x0000000000000008   rbx = 0x000000010a0ac5d8
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     rsi = 0x0000000000020000   rdi = 0x0000000000000000
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     rbp = 0x00007ffee5dd8360   rsp = 0x00007ffee5dd8220
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -      r8 = 0x00000000000185b9    r9 = 0xffffffff00000000
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     r10 = 0x000000011d3da600   r11 = 0x000000000000001d
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     r12 = 0x0000000000000003   r13 = 0x0000000000000003
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     r14 = 0x0000000000000003   r15 = 0x000000010a0ac000
[task 2021-04-11T03:50:20.633Z] 03:50:20     INFO -     rip = 0x000000010cc36d43
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -  1  XUL + 0x7405ad
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     rbp = 0x00007ffee5dd83b0   rsp = 0x00007ffee5dd8370
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     rip = 0x000000010aaef5ad
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -  2  XUL + 0x8332b3
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     rbp = 0x00007ffee5dd83d0   rsp = 0x00007ffee5dd83c0
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     rip = 0x000000010abe22b3
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -  3  XUL + 0x73c559
[task 2021-04-11T03:50:20.634Z] 03:50:20     INFO -     rbp = 0x00007ffee5dd8410   rsp = 0x00007ffee5dd83e0
<...>
[task 2021-04-11T03:50:20.638Z] 03:50:20     INFO - Thread 1
[task 2021-04-11T03:50:20.638Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!__workq_kernreturn + 0xa
[task 2021-04-11T03:50:20.638Z] 03:50:20     INFO -     rax = 0x0000000002000170   rdx = 0x0000000000000000
[task 2021-04-11T03:50:20.638Z] 03:50:20     INFO -     rcx = 0x000070000b4fbfa8   rbx = 0x0000000000064003
[task 2021-04-11T03:50:20.638Z] 03:50:20     INFO -     rsi = 0x0000000000000000   rdi = 0x0000000000000004
[task 2021-04-11T03:50:20.638Z] 03:50:20     INFO -     rbp = 0x000070000b4fbfd0   rsp = 0x000070000b4fbfa8
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -      r8 = 0x0000000000064003    r9 = 0x0000000000000000
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000246
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     r12 = 0x000070000b4fc000   r13 = 0x0000000000000000
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     r14 = 0x0000000000000000   r15 = 0x0000000000000000
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rip = 0x00007fff6f72f4ce
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -  1  libsystem_pthread.dylib!start_wqthread + 0xf
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rbp = 0x000070000b4fbff0   rsp = 0x000070000b4fbfe0
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rip = 0x00007fff6f7ecb77
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -  2  libdispatch.dylib!_dispatch_root_queues_init_once + 0xd8
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rsp = 0x000070000b4fc098   rip = 0x00007fff6f5a203b
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     Found by: stack scanning
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO - Thread 2
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!__workq_kernreturn + 0xa
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rax = 0x0000000002000170   rdx = 0x0000000000000000
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rcx = 0x000070000b57efa8   rbx = 0x0000000000064003
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rsi = 0x0000000000000000   rdi = 0x0000000000000004
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rbp = 0x000070000b57efd0   rsp = 0x000070000b57efa8
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -      r8 = 0x0000000000000001    r9 = 0x000000012bbb0a00
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000246
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     r12 = 0x000070000b57f000   r13 = 0x0000000000000000
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     r14 = 0x0000000000000000   r15 = 0x0000000000000000
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rip = 0x00007fff6f72f4ce
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -  1  libsystem_pthread.dylib!start_wqthread + 0xf
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rbp = 0x000070000b57eff0   rsp = 0x000070000b57efe0
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rip = 0x00007fff6f7ecb77
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -  2  libdispatch.dylib!_dispatch_root_queues_init_once + 0xd8
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     rsp = 0x000070000b57f098   rip = 0x00007fff6f5a203b
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -     Found by: stack scanning
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO - Thread 3
[task 2021-04-11T03:50:20.639Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!__workq_kernreturn + 0xa
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rax = 0x0000000002000170   rdx = 0x0000000000000000
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rcx = 0x000070000b684fa8   rbx = 0x0000000000064005
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rsi = 0x0000000000000000   rdi = 0x0000000000000004
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rbp = 0x000070000b684fd0   rsp = 0x000070000b684fa8
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -      r8 = 0x0000000120b012a8    r9 = 0x0000000000000001
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000246
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     r12 = 0x000070000b685000   r13 = 0x0000000000000000
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     r14 = 0x0000000000000000   r15 = 0x0000000000000000
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rip = 0x00007fff6f72f4ce
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -  1  libsystem_pthread.dylib!start_wqthread + 0xf
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rbp = 0x000070000b684ff0   rsp = 0x000070000b684fe0
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rip = 0x00007fff6f7ecb77
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -  2  libdispatch.dylib!_dispatch_root_queues_init_once + 0xd8
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rsp = 0x000070000b685098   rip = 0x00007fff6f5a203b
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     Found by: stack scanning
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO - Thread 4
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!__workq_kernreturn + 0xa
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rax = 0x0000000002000170   rdx = 0x0000000000000000
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rcx = 0x000070000b707fa8   rbx = 0x0000000000064003
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rsi = 0x0000000000000000   rdi = 0x0000000000000004
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rbp = 0x000070000b707fd0   rsp = 0x000070000b707fa8
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -      r8 = 0x000000012b800180    r9 = 0x000000012bb01001
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000246
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     r12 = 0x000070000b708000   r13 = 0x0000000000000000
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     r14 = 0x0000000000000000   r15 = 0x0000000000000000
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rip = 0x00007fff6f72f4ce
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -  1  libsystem_pthread.dylib!start_wqthread + 0xf
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rbp = 0x000070000b707ff0   rsp = 0x000070000b707fe0
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     rip = 0x00007fff6f7ecb77
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.640Z] 03:50:20     INFO -  2  libdispatch.dylib!_dispatch_root_queues_init_once + 0xd8
[task 2021-04-11T03:50:20.641Z] 03:50:20     INFO -     rsp = 0x000070000b708098   rip = 0x00007fff6f5a203b
[task 2021-04-11T03:50:20.641Z] 03:50:20     INFO -     Found by: stack scanning
[task 2021-04-11T03:50:20.641Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.641Z] 03:50:20     INFO - Thread 5
[task 2021-04-11T03:50:20.641Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!kevent + 0xa
<...>
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO - Thread 6
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!__psynch_cvwait + 0xa
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rax = 0x0000000002000131   rdx = 0x0000000000000200
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rcx = 0x000070000b91ca98   rbx = 0x0000000000000002
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rsi = 0x0000020100000300   rdi = 0x000000011cc29b38
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rbp = 0x000070000b91cb30   rsp = 0x000070000b91ca98
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -      r8 = 0x0000000000000000    r9 = 0x00000000000000a0
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000202
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     r12 = 0x000000011cc29b38   r13 = 0x0000000000000016
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     r14 = 0x0000020100000300   r15 = 0x000070000b91d000
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rip = 0x00007fff6f730882
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -  1  libmozglue.dylib!mozilla::detail::ConditionVariableImpl::wait(mozilla::detail::MutexImpl&) [ConditionVariable_posix.cpp:0ea49daf534fcd9a49708717b3864a4ebc73c20d : 108 + 0xb]
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rbp = 0x000070000b91cb50   rsp = 0x000070000b91cb40
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rip = 0x0000000109e7486c
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -  2  XUL + 0x11c3c9
[task 2021-04-11T03:50:20.642Z] 03:50:20     INFO -     rbp = 0x000070000b91cbb0   rsp = 0x000070000b91cb60
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x000000010a4cb3c9
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -  3  XUL + 0x124d40
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rbp = 0x000070000b91ccf0   rsp = 0x000070000b91cbc0
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x000000010a4d3d40
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -  4  XUL + 0x129ac9
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rbp = 0x000070000b91cd20   rsp = 0x000070000b91cd00
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x000000010a4d8ac9
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -  5  XUL + 0x73e064
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rbp = 0x000070000b91cd70   rsp = 0x000070000b91cd30
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x000000010aaed064
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -  6  XUL + 0x6f4b66
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rbp = 0x000070000b91cda0   rsp = 0x000070000b91cd80
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x000000010aaa3b66
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -  7  XUL + 0x122ca9
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rbp = 0x000070000b91cf60   rsp = 0x000070000b91cdb0
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x000000010a4d1ca9
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -  8  libnss3.dylib!_pt_root [ptthread.c:0ea49daf534fcd9a49708717b3864a4ebc73c20d : 201 + 0x8]
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rbp = 0x000070000b91cfb0   rsp = 0x000070000b91cf70
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x000000010a258125
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -  9  libsystem_pthread.dylib!_pthread_start + 0x94
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rbp = 0x000070000b91cfd0   rsp = 0x000070000b91cfc0
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     rip = 0x00007fff6f7f1109
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.643Z] 03:50:20     INFO - 10  libsystem_pthread.dylib!thread_start + 0xf
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rbp = 0x000070000b91cff0   rsp = 0x000070000b91cfe0
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rip = 0x00007fff6f7ecb8b
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO - 11  libnss3.dylib + 0x157fc0
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rsp = 0x000070000b91d098   rip = 0x000000010a257fc0
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: stack scanning
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO - Thread 7
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!__psynch_cvwait + 0xa
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rax = 0x0000000002000131   rdx = 0x0000000000000500
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rcx = 0x000070000b9a29a8   rbx = 0x0000000000000002
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rsi = 0x0000050100000600   rdi = 0x000000011745db18
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rbp = 0x000070000b9a2a40   rsp = 0x000070000b9a29a8
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -      r8 = 0x0000000000000000    r9 = 0x00000000000000a0
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000202
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     r12 = 0x000000011745db18   r13 = 0x0000000000000016
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     r14 = 0x0000050100000600   r15 = 0x000070000b9a3000
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rip = 0x00007fff6f730882
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -  1  libmozglue.dylib!mozilla::detail::ConditionVariableImpl::wait_for(mozilla::detail::MutexImpl&, mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> const&) [ConditionVariable_posix.cpp:0ea49daf534fcd9a49708717b3864a4ebc73c20d : 115 + 0xb]
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rbp = 0x000070000b9a2a90   rsp = 0x000070000b9a2a50
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rip = 0x0000000109e748ed
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -  2  XUL + 0x3e517c7
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rbp = 0x000070000b9a2f30   rsp = 0x000070000b9a2aa0
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rip = 0x000000010e2007c7
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -  3  XUL + 0x3e5156e
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rbp = 0x000070000b9a2f60   rsp = 0x000070000b9a2f40
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rip = 0x000000010e20056e
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -  4  libnss3.dylib!_pt_root [ptthread.c:0ea49daf534fcd9a49708717b3864a4ebc73c20d : 201 + 0x8]
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rbp = 0x000070000b9a2fb0   rsp = 0x000070000b9a2f70
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rip = 0x000000010a258125
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -  5  libsystem_pthread.dylib!_pthread_start + 0x94
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rbp = 0x000070000b9a2fd0   rsp = 0x000070000b9a2fc0
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     rip = 0x00007fff6f7f1109
[task 2021-04-11T03:50:20.644Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -  6  libsystem_pthread.dylib!thread_start + 0xf
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rbp = 0x000070000b9a2ff0   rsp = 0x000070000b9a2fe0
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rip = 0x00007fff6f7ecb8b
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     Found by: previous frame's frame pointer
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -  7  libnss3.dylib + 0x157fc0
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rsp = 0x000070000b9a3098   rip = 0x000000010a257fc0
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     Found by: stack scanning
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO - 
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO - Thread 8
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -  0  libsystem_kernel.dylib!__psynch_cvwait + 0xa
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rax = 0x0000000002000131   rdx = 0x0000000000000100
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rcx = 0x000070000b9e5a98   rbx = 0x0000000000000002
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rsi = 0x0000010100000200   rdi = 0x000000011cc290b8
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rbp = 0x000070000b9e5b30   rsp = 0x000070000b9e5a98
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -      r8 = 0x0000000000000000    r9 = 0x00000000000000a0
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000202
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     r12 = 0x000000011cc290b8   r13 = 0x0000000000000016
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     r14 = 0x0000010100000200   r15 = 0x000070000b9e6000
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     rip = 0x00007fff6f730882
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -     Found by: given as instruction pointer in context
[task 2021-04-11T03:50:20.645Z] 03:50:20     INFO -  1  libmozglue.dylib!mozilla::detail::ConditionVariableImpl::wait(mozilla::detail::MutexImpl&) [ConditionVariable_posix.cpp:0ea49daf534fcd9a49708717b3864a4ebc73c20d : 108 + 0xb]
<...>
[task 2021-04-11T03:50:20.780Z] 03:50:20     INFO - 0x7fff6f824000 - 0x7fff6f859fff  libxpc.dylib  ???
[task 2021-04-11T03:50:20.782Z] 03:50:20     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Process crashed (Exit code: 0))
[task 2021-04-11T03:50:20.782Z] 03:50:20     INFO - Traceback (most recent call last):
[task 2021-04-11T03:50:20.782Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 214, in run
[task 2021-04-11T03:50:20.782Z] 03:50:20     INFO -     testMethod()
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/tests/telemetry/marionette/tests/client/test_subsession_management.py", line 110, in test_subsession_management
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     ping3 = self.wait_for_ping(self.restart_browser, MAIN_SHUTDOWN_PING)
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py", line 170, in wait_for_ping
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     action_func, ping_filter, 1, ping_server=ping_server
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py", line 156, in wait_for_pings
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     action_func()
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py", line 176, in restart_browser
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     return self.marionette.restart(clean=False, in_app=True)
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     m._handle_socket_failure()
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 716, in _handle_socket_failure
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/six.py", line 702, in reraise
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     raise value.with_traceback(tb)
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     return func(*args, **kwargs)
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1087, in restart
[task 2021-04-11T03:50:20.783Z] 03:50:20     INFO -     self.raise_for_port(timeout=timeout_restart, check_process_status=False)
[task 2021-04-11T03:50:20.784Z] 03:50:20     INFO -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 594, in raise_for_port
[task 2021-04-11T03:50:20.784Z] 03:50:20     INFO -     raise IOError("Process crashed (Exit code: {})".format(runner.wait(0)))
[task 2021-04-11T03:50:20.784Z] 03:50:20     INFO - TEST-INFO took 196509ms
[task 2021-04-11T03:50:20.786Z] 03:50:20    ERROR - test_end for telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n  File \"/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py\", line 247, in run\n    self.tearDown()\n  File \"/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py\", line 240, in tearDown\n    super(TelemetryTestCase, self).tearDown()\n  File \"/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runner/mixins/window_manager.py\", line 24, in tearDown\n    if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n  File \"/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 1338, in chrome_window_handles\n    return self._send_message(\"WebDriver:GetChromeWindowHandles\")\n  File \"/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 618, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_subsession_management.TestSubsessionManagement", "method_name": "test_subsession_management"}, "test": "telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management", "status": "ERROR"}
[task 2021-04-11T03:50:20.788Z] 03:50:20 CRITICAL - pingserver Failed to start HTTP server on port 8000; is something already using that port?
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR - [Errno 48] Address already in use
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR - Traceback (most recent call last):
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runtests.py", line 108, in cli
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -     failed = harness_instance.run()
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runtests.py", line 82, in run
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -     runner.run_tests(tests)
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1042, in run_tests
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -     self.run_test_sets()
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1269, in run_test_sets
[task 2021-04-11T03:50:20.791Z] 03:50:20    ERROR -     self.run_test_set(self.tests)
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1239, in run_test_set
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -     self.run_test(test["filepath"], test["expected"])
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1191, in run_test
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -     **self.test_kwargs
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 412, in add_tests_to_suite
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -     **kwargs
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/telemetry_harness/fog_testcase.py", line 15, in __init__
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -     super(FOGTestCase, self).__init__(*args, **kwargs)
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py", line 32, in __init__
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -     self.testvars["server_root"], self.testvars["server_url"]
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/telemetry_harness/ping_server.py", line 60, in __init__
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -     self._httpd = httpd.FixtureServer(server_root, url=url)
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/marionette_harness/runner/httpd.py", line 123, in __init__
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR -     key_file=ssl_key,
[task 2021-04-11T03:50:20.792Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/wptserve/server.py", line 820, in __init__
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -     http2=http2)
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -   File "/opt/worker/tasks/task_161810240929161/build/venv/lib/python3.7/site-packages/wptserve/server.py", line 190, in __init__
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -     http.server.HTTPServer.__init__(self, hostname_port, request_handler_cls, **kwargs)
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/socketserver.py", line 452, in __init__
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -     self.server_bind()
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/http/server.py", line 137, in server_bind
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -     socketserver.TCPServer.server_bind(self)
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -   File "/Library/Frameworks/Python.framework/Versions/3.7/lib/python3.7/socketserver.py", line 466, in server_bind
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR -     self.socket.bind(self.server_address)
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - OSError: [Errno 48] Address already in use
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - 
[task 2021-04-11T03:50:20.793Z] 03:50:20    ERROR - Return code: 1
[task 2021-04-11T03:50:20.794Z] 03:50:20    ERROR - Got 1 unexpected statuses
[task 2021-04-11T03:50:20.794Z] 03:50:20    ERROR - Got 1 unexpected crashes
[task 2021-04-11T03:50:20.794Z] 03:50:20    ERROR - No suite end message was emitted by this harness.
[task 2021-04-11T03:50:20.794Z] 03:50:20 CRITICAL - # TBPL FAILURE #
[task 2021-04-11T03:50:20.794Z] 03:50:20  WARNING - setting return code to 2
[task 2021-04-11T03:50:20.794Z] 03:50:20     INFO - Running post-action listener: _package_coverage_data
[task 2021-04-11T03:50:20.794Z] 03:50:20     INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-11T03:50:20.794Z] 03:50:20     INFO - Running post-action listener: process_java_coverage_data
[task 2021-04-11T03:50:20.794Z] 03:50:20     INFO - [mozharness: 2021-04-11 03:50:20.794866Z] Finished run-tests step (success)
[task 2021-04-11T03:50:20.794Z] 03:50:20     INFO - [mozharness: 2021-04-11 03:50:20.794919Z] Running uninstall step.
[task 2021-04-11T03:50:20.795Z] 03:50:20     INFO - Running pre-action listener: _resource_record_pre_action
[task 2021-04-11T03:50:20.795Z] 03:50:20     INFO - Running main action method: uninstall
[task 2021-04-11T03:50:20.795Z] 03:50:20     INFO - Getting output from command: ['/opt/worker/tasks/task_161810240929161/build/venv/bin/mozuninstall', '/opt/worker/tasks/task_161810240929161/build/application']
[task 2021-04-11T03:50:20.795Z] 03:50:20     INFO - Copy/paste: /opt/worker/tasks/task_161810240929161/build/venv/bin/mozuninstall /opt/worker/tasks/task_161810240929161/build/application
[task 2021-04-11T03:50:21.077Z] 03:50:21     INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-11T03:50:21.077Z] 03:50:21     INFO - [mozharness: 2021-04-11 03:50:21.077429Z] Finished uninstall step (success)
[task 2021-04-11T03:50:21.077Z] 03:50:21     INFO - Running post-run listener: _resource_record_post_run
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - Total resource usage - Wall time: 241s; CPU: 5%; Read bytes: 43995136; Write bytes: 792170496; Read time: 690; Write time: 1492
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - TinderboxPrint: CPU usage<br/>5.3%
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - TinderboxPrint: I/O read bytes / time<br/>43,995,136 / 690
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - TinderboxPrint: I/O write bytes / time<br/>792,170,496 / 1,492
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - TinderboxPrint: CPU idle<br/>2,727.2 (94.4%)
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - TinderboxPrint: CPU system<br/>43.6 (1.5%)
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - TinderboxPrint: CPU user<br/>118.5 (4.1%)
[task 2021-04-11T03:50:21.146Z] 03:50:21     INFO - TinderboxPrint: Swap in / out<br/>277,446,656 / 0
[task 2021-04-11T03:50:21.147Z] 03:50:21     INFO - install - Wall time: 19s; CPU: 14%; Read bytes: 253019648; Write bytes: 273154048; Read time: 16456; Write time: 422
[task 2021-04-11T03:50:21.150Z] 03:50:21     INFO - run-tests - Wall time: 223s; CPU: 4%; Read bytes: 38580224; Write bytes: 514179072; Read time: 557; Write time: 1065
[task 2021-04-11T03:50:21.150Z] 03:50:21     INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-04-11T03:50:21.206Z] 03:50:21  WARNING - returning nonzero exit status 2
[taskcluster 2021-04-11T03:50:21.234Z]    Exit Code: 2
[taskcluster 2021-04-11T03:50:21.234Z]    User Time: 1m8.620725s
[taskcluster 2021-04-11T03:50:21.234Z]  Kernel Time: 14.115368s
[taskcluster 2021-04-11T03:50:21.234Z]    Wall Time: 4m50.855934s
[taskcluster 2021-04-11T03:50:21.234Z]       Result: FAILED```

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

Depends on: 1698708
Priority: -- → P4

Got the wrong depends on link : |

On the plus side we appear to be getting some partial symbolication on these latest crashes.

On the negative side, it's pretty hard to pin down what's wrong. The crash line suggests that it's crashing at some unsymbol'd offset into libxul, but I'm not sure if thread 0 is actually the crashing thread or not.

Depends on: 1594515
No longer depends on: 1698708
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.