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)
Toolkit
Telemetry
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
Comment hidden (Intermittent Failures Robot) |
Comment 2•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Reporter | ||
Comment 3•1 year ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=443030701&repo=mozilla-beta
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 6•1 year ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: REOPENED → RESOLVED
Closed: 2 years ago → 1 year ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•