Closed Bug 1827029 Opened 2 years ago Closed 1 year ago

Intermittent telemetry/marionette/tests/client/test_fog_deletion_request_ping.py TestDeletionRequestPing.test_deletion_request_ping_across_sessions | OSError: Process has been unexpectedly closed (Exit code: 127) (Reason: Timed out waiting for connection

Categories

(Toolkit :: Telemetry, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


[task 2023-04-07T22:03:18.207Z] 22:03:18     INFO - TEST-START | telemetry/marionette/tests/client/test_fog_deletion_request_ping.py TestDeletionRequestPing.test_deletion_request_ping_across_sessions
[task 2023-04-07T22:03:18.214Z] 22:03:18     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmp2fqs0h29.mozrunner
[task 2023-04-07T22:03:21.081Z] 22:03:21     INFO -  1680905001079	Toolkit.Telemetry	TRACE	TelemetryController::observe - profile-after-change notified.
[task 2023-04-07T22:03:21.082Z] 22:03:21     INFO -  1680905001080	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry
[task 2023-04-07T22:03:21.083Z] 22:03:21     INFO -  1680905001081	Toolkit.Telemetry	TRACE	TelemetryController::registerJsProbes - registering builtin JS probes
[task 2023-04-07T22:03:21.085Z] 22:03:21     INFO -  1680905001083	Toolkit.Telemetry	TRACE	TelemetryController::registerScalarProbes - registering scalar builtin JS probes
[task 2023-04-07T22:03:21.086Z] 22:03:21     INFO -  1680905001084	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json
[task 2023-04-07T22:03:21.111Z] 22:03:21     INFO -  1680905001109	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup
[task 2023-04-07T22:03:21.113Z] 22:03:21     INFO -  1680905001111	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2023-04-07T22:03:21.115Z] 22:03:21     INFO -  1680905001114	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit
[task 2023-04-07T22:03:21.164Z] 22:03:21     INFO -  1680905001163	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true
[task 2023-04-07T22:03:21.228Z] 22:03:21     INFO -  1680905001227	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor
[task 2023-04-07T22:03:21.984Z] 22:03:21     INFO -  ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-04-07T22:03:22.028Z] 22:03:22     INFO -  ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-04-07T22:03:22.124Z] 22:03:22     INFO -  1680905002122	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2023-04-07T22:03:22.146Z] 22:03:22     INFO -  1680905002145	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2023-04-07T22:03:22.148Z] 22:03:22     INFO -  1680905002147	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons
[task 2023-04-07T22:03:22.161Z] 22:03:22     INFO -  1680905002161	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2023-04-07T22:03:22.243Z] 22:03:22     INFO -  1680905002242	Marionette	INFO	Marionette enabled
[task 2023-04-07T22:03:22.258Z] 22:03:22     INFO -  1680905002257	Marionette	TRACE	Received observer notification final-ui-startup
[task 2023-04-07T22:03:22.272Z] 22:03:22     INFO -  1680905002271	Marionette	INFO	Listening on port 2828
[task 2023-04-07T22:03:22.275Z] 22:03:22     INFO -  1680905002273	Marionette	DEBUG	Marionette is listening
[task 2023-04-07T22:03:22.974Z] 22:03:22     INFO -  1680905002973	Toolkit.Telemetry	TRACE	TelemetryController::registerEventProbes - registering builtin JS Event probes
[task 2023-04-07T22:03:22.976Z] 22:03:22     INFO -  1680905002973	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json
[task 2023-04-07T22:03:23.011Z] 22:03:23     INFO -  1680905003010	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ
[task 2023-04-07T22:03:23.141Z] 22:03:23     INFO -  1680905003141	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:50212
[task 2023-04-07T22:03:23.332Z] 22:03:23     INFO -  1680905003331	Marionette	DEBUG	Closed connection 0
[task 2023-04-07T22:03:23.342Z] 22:03:23     INFO -  1680905003342	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:50214
[task 2023-04-07T22:03:23.647Z] 22:03:23     INFO -  1680905003647	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:50216
[task 2023-04-07T22:03:23.651Z] 22:03:23     INFO -  1680905003650	Marionette	DEBUG	Closed connection 1
[task 2023-04-07T22:03:25.294Z] 22:03:25     INFO -  1680905005293	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-04-07T22:03:25.329Z] 22:03:25     INFO -  1680905005329	Marionette	DEBUG	Waiting for initial application window
[task 2023-04-07T22:03:25.724Z] 22:03:25     INFO -  1680905005723	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - Topic gmp-provider-registered
[task 2023-04-07T22:03:26.098Z] 22:03:26     INFO -  1680905006097	Toolkit.Telemetry	TRACE	TelemetryController::observe - content-process-ready-for-script notified.
[task 2023-04-07T22:03:26.103Z] 22:03:26     INFO -  1680905006102	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2023-04-07T22:03:26.236Z] 22:03:26     INFO -  console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-07T22:03:27.238Z] 22:03:27     INFO -  1680905007236	Toolkit.Telemetry	TRACE	TelemetryController::observe - content-process-ready-for-script notified.
[task 2023-04-07T22:03:27.243Z] 22:03:27     INFO -  1680905007241	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2023-04-07T22:03:28.028Z] 22:03:28     INFO -  1680905008027	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2023-04-07T22:03:28.065Z] 22:03:28     INFO -  1680905008064	Toolkit.Telemetry	TRACE	TelemetrySession::observe - user-interaction-inactive notified.
[task 2023-04-07T22:03:29.547Z] 22:03:29     INFO -  1680905009546	Toolkit.Telemetry	TRACE	TelemetrySession::observe - xul-window-visible notified.
[task 2023-04-07T22:03:34.029Z] 22:03:34     INFO -  console.error: ({})
[task 2023-04-07T22:03:34.120Z] 22:03:34     INFO -  1680905014119	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: sessionstore-windows-restored, aData: null
[task 2023-04-07T22:03:34.136Z] 22:03:34     INFO -  1680905014135	Toolkit.Telemetry	TRACE	TelemetrySession::observe - sessionstore-windows-restored notified.
[task 2023-04-07T22:03:34.138Z] 22:03:34     INFO -  1680905014136	Toolkit.Telemetry	TRACE	TelemetrySession::gatherStartup
[task 2023-04-07T22:03:34.141Z] 22:03:34     INFO -  1680905014139	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2023-04-07T22:03:34.142Z] 22:03:34     INFO -  1680905014139	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_shouldNotify - User already notified or bypassing the policy.
[task 2023-04-07T22:03:34.276Z] 22:03:34     INFO -  1680905014275	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]
[task 2023-04-07T22:03:34.687Z] 22:03:34     INFO -  1680905014685	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.default.sites
[task 2023-04-07T22:03:34.690Z] 22:03:34     INFO -  1680905014686	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.feeds.section.topstories.options
[task 2023-04-07T22:03:34.693Z] 22:03:34     INFO -  1680905014689	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.feeds.topsites
[task 2023-04-07T22:03:34.695Z] 22:03:34     INFO -  1680905014691	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.hideTopSitesTitle
[task 2023-04-07T22:03:34.696Z] 22:03:34     INFO -  1680905014693	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.showSponsored
[task 2023-04-07T22:03:34.697Z] 22:03:34     INFO -  1680905014697	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.showSponsoredTopSites
[task 2023-04-07T22:03:34.701Z] 22:03:34     INFO -  1680905014699	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.pocketCta
[task 2023-04-07T22:03:34.703Z] 22:03:34     INFO -  1680905014702	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.showSearch
[task 2023-04-07T22:03:34.706Z] 22:03:34     INFO -  1680905014705	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.feeds.snippets
[task 2023-04-07T22:03:34.709Z] 22:03:34     INFO -  1680905014707	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.topSitesRows
[task 2023-04-07T22:03:34.712Z] 22:03:34     INFO -  1680905014711	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.telemetry.ut.events
[task 2023-04-07T22:03:34.714Z] 22:03:34     INFO -  1680905014713	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.telemetry.structuredIngestion.endpoint
[task 2023-04-07T22:03:34.716Z] 22:03:34     INFO -  1680905014715	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.section.highlights.includeVisited
[task 2023-04-07T22:03:34.719Z] 22:03:34     INFO -  1680905014718	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.section.highlights.includeBookmarks
[task 2023-04-07T22:03:34.724Z] 22:03:34     INFO -  1680905014720	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.section.highlights.includePocket
[task 2023-04-07T22:03:34.728Z] 22:03:34     INFO -  1680905014723	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.section.highlights.includeDownloads
[task 2023-04-07T22:03:34.730Z] 22:03:34     INFO -  1680905014725	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.section.highlights.rows
[task 2023-04-07T22:03:34.731Z] 22:03:34     INFO -  1680905014728	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.section.topstories.rows
[task 2023-04-07T22:03:34.734Z] 22:03:34     INFO -  1680905014733	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.sectionOrder
<...>
[task 2023-04-07T22:03:49.399Z] 22:03:49     INFO -  1680905029399	Marionette	DEBUG	2 <- [1,28,null,{"value":null}]
[task 2023-04-07T22:03:49.407Z] 22:03:49     INFO - FOGTestCase Submitting to FOG ping server at http://localhost:41896/
[task 2023-04-07T22:03:49.411Z] 22:03:49     INFO -  1680905029410	Marionette	DEBUG	2 -> [0,29,"Marionette:GetContext",{}]
[task 2023-04-07T22:03:49.414Z] 22:03:49     INFO -  1680905029413	Marionette	DEBUG	2 <- [1,29,null,{"value":"content"}]
[task 2023-04-07T22:03:49.419Z] 22:03:49     INFO -  1680905029419	Marionette	DEBUG	2 -> [0,30,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-04-07T22:03:49.422Z] 22:03:49     INFO -  1680905029422	Marionette	DEBUG	2 <- [1,30,null,{"value":null}]
[task 2023-04-07T22:03:49.430Z] 22:03:49     INFO -  1680905029428	Marionette	DEBUG	2 -> [0,31,"WebDriver:ExecuteScript",{"script":"let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n                                              .g ... ref).toString();\n                    case prefInterface.PREF_INVALID:\n                        return false;\n                }","args":[],"newSandbox":true,"sandbox":"default","line":966,"filename":"venv/lib/python3.7/site-packages/marionette_driver/marionette.py"}]
[task 2023-04-07T22:03:49.452Z] 22:03:49     INFO -  1680905029451	Marionette	DEBUG	2 <- [1,31,null,{"value":false}]
[task 2023-04-07T22:03:49.458Z] 22:03:49     INFO -  1680905029457	Marionette	DEBUG	2 -> [0,32,"Marionette:SetContext",{"value":"content"}]
[task 2023-04-07T22:03:49.461Z] 22:03:49     INFO -  1680905029460	Marionette	DEBUG	2 <- [1,32,null,{"value":null}]
[task 2023-04-07T22:03:49.467Z] 22:03:49     INFO -  1680905029466	Marionette	DEBUG	2 -> [0,33,"Marionette:GetContext",{}]
[task 2023-04-07T22:03:49.470Z] 22:03:49     INFO -  1680905029469	Marionette	DEBUG	2 <- [1,33,null,{"value":"content"}]
[task 2023-04-07T22:03:49.476Z] 22:03:49     INFO -  1680905029475	Marionette	DEBUG	2 -> [0,34,"WebDriver:DeleteSession",{}]
[task 2023-04-07T22:03:49.483Z] 22:03:49     INFO -  1680905029482	Marionette	TRACE	[1] MarionetteCommands actor destroyed for window id 2
[task 2023-04-07T22:03:49.534Z] 22:03:49     INFO -  1680905029533	Marionette	DEBUG	2 <- [1,34,null,{"value":null}]
[task 2023-04-07T22:03:49.670Z] 22:03:49     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmp_0gm58h6.mozrunner
[task 2023-04-07T22:03:52.643Z] 22:03:52     INFO -  1680905032642	Toolkit.Telemetry	TRACE	TelemetryController::observe - profile-after-change notified.
[task 2023-04-07T22:03:52.646Z] 22:03:52     INFO -  1680905032643	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry
[task 2023-04-07T22:03:52.648Z] 22:03:52     INFO -  1680905032643	Toolkit.Telemetry	TRACE	TelemetryController::registerJsProbes - registering builtin JS probes
[task 2023-04-07T22:03:52.650Z] 22:03:52     INFO -  1680905032644	Toolkit.Telemetry	TRACE	TelemetryController::registerScalarProbes - registering scalar builtin JS probes
[task 2023-04-07T22:03:52.651Z] 22:03:52     INFO -  1680905032645	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json
[task 2023-04-07T22:03:52.670Z] 22:03:52     INFO -  1680905032668	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup
[task 2023-04-07T22:03:52.671Z] 22:03:52     INFO -  1680905032670	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2023-04-07T22:03:52.674Z] 22:03:52     INFO -  1680905032673	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit
[task 2023-04-07T22:03:52.723Z] 22:03:52     INFO -  1680905032722	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true
[task 2023-04-07T22:03:52.794Z] 22:03:52     INFO -  1680905032792	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor
[task 2023-04-07T22:03:53.561Z] 22:03:53     INFO -  ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-04-07T22:03:53.581Z] 22:03:53     INFO -  Inconsistency detected by ld.so: ../elf/dl-tls.c: 481: _dl_allocate_tls_init: Assertion `listp->slotinfo[cnt].gen <= GL(dl_tls_generation)' failed!
[task 2023-04-07T22:03:53.711Z] 22:03:53     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_fog_deletion_request_ping.py TestDeletionRequestPing.test_deletion_request_ping_across_sessions | OSError: Process has been unexpectedly closed (Exit code: 127) (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
[task 2023-04-07T22:03:53.711Z] 22:03:53     INFO - Traceback (most recent call last):
[task 2023-04-07T22:03:53.711Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 179, in run
[task 2023-04-07T22:03:53.712Z] 22:03:53     INFO -     self.setUp()
[task 2023-04-07T22:03:53.712Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/telemetry_harness/fog_testcase.py", line 57, in setUp
[task 2023-04-07T22:03:53.712Z] 22:03:53     INFO -     "logging.glean_core::*": 5,
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -     m._handle_socket_failure()
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 781, in _handle_socket_failure
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -     IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/six.py", line 702, in reraise
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -     raise value.with_traceback(tb)
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -     return func(*args, **kwargs)
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 976, in enforce_gecko_prefs
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -     self.raise_for_port()
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 673, in raise_for_port
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO -     self.host, self.port
[task 2023-04-07T22:03:53.713Z] 22:03:53     INFO - TEST-INFO took 35503ms
[task 2023-04-07T22:03:53.715Z] 22:03:53     INFO - TEST-START | telemetry/marionette/tests/client/test_fog_custom_ping.py TestDeletionRequestPing.test_one_ping_only_ping
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.