Closed
Bug 1807640
Opened 2 years ago
Closed 2 years ago
Intermittent telemetry/marionette/tests/client/test_fog_custom_ping.py TestDeletionRequestPing.test_one_ping_only_ping | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for
Categories
(Toolkit :: Telemetry, defect, P5)
Toolkit
Telemetry
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=400793234&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/cAJgANERRnua9z1GEKm_zw/runs/0/artifacts/public/logs/live_backing.log
[task 2022-12-27T06:03:22.886Z] 06:03:22 INFO - TEST-START | telemetry/marionette/tests/client/test_fog_custom_ping.py TestDeletionRequestPing.test_one_ping_only_ping
[task 2022-12-27T06:03:22.890Z] 06:03:22 INFO - Application command: Z:\task_167212031466973\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_167212031466973\build\tmpqg2ti4yn.mozrunner
[task 2022-12-27T06:03:23.231Z] 06:03:23 INFO - 1672121003242 Toolkit.Telemetry TRACE TelemetryController::observe - profile-after-change notified.
[task 2022-12-27T06:03:23.243Z] 06:03:23 INFO - 1672121003242 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry
[task 2022-12-27T06:03:23.244Z] 06:03:23 INFO - 1672121003243 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup
[task 2022-12-27T06:03:23.244Z] 06:03:23 INFO - 1672121003244 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2022-12-27T06:03:23.244Z] 06:03:23 INFO - 1672121003244 Toolkit.Telemetry TRACE TelemetrySession::earlyInit
[task 2022-12-27T06:03:23.248Z] 06:03:23 INFO - 1672121003248 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2022-12-27T06:03:23.248Z] 06:03:23 INFO - 1672121003248 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true
[task 2022-12-27T06:03:23.254Z] 06:03:23 INFO - 1672121003254 Toolkit.Telemetry TRACE TelemetryEnvironment::constructor
[task 2022-12-27T06:03:23.281Z] 06:03:23 INFO - 1672121003288 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2022-12-27T06:03:23.292Z] 06:03:23 INFO - 1672121003291 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2022-12-27T06:03:23.292Z] 06:03:23 INFO - 1672121003291 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2022-12-27T06:03:23.293Z] 06:03:23 INFO - 1672121003293 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2022-12-27T06:03:23.300Z] 06:03:23 INFO - 1672121003300 Marionette INFO Marionette enabled
[task 2022-12-27T06:03:23.302Z] 06:03:23 INFO - 1672121003302 Marionette TRACE Received observer notification final-ui-startup
[task 2022-12-27T06:03:23.303Z] 06:03:23 INFO - 1672121003303 Marionette INFO Listening on port 2828
[task 2022-12-27T06:03:23.304Z] 06:03:23 INFO - 1672121003303 Marionette DEBUG Marionette is listening
[task 2022-12-27T06:03:23.377Z] 06:03:23 INFO - 1672121003386 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
[task 2022-12-27T06:03:23.414Z] 06:03:23 INFO - 1672121003418 Marionette DEBUG Accepted connection 0 from 127.0.0.1:49929
[task 2022-12-27T06:03:23.509Z] 06:03:23 INFO - 1672121003510 Marionette DEBUG Closed connection 0
[task 2022-12-27T06:03:23.510Z] 06:03:23 INFO - 1672121003510 Marionette DEBUG Accepted connection 1 from 127.0.0.1:49932
[task 2022-12-27T06:03:23.662Z] 06:03:23 INFO - 1672121003675 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-12-27T06:03:23.679Z] 06:03:23 INFO - 1672121003678 Marionette DEBUG Waiting for initial application window
[task 2022-12-27T06:03:23.714Z] 06:03:23 INFO - 1672121003719 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - Topic gmp-provider-registered
[task 2022-12-27T06:03:23.762Z] 06:03:23 INFO - 1672121003768 Toolkit.Telemetry TRACE TelemetryController::observe - content-process-ready-for-script notified.
[task 2022-12-27T06:03:23.769Z] 06:03:23 INFO - 1672121003768 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2022-12-27T06:03:23.853Z] 06:03:23 INFO - 1672121003861 Toolkit.Telemetry TRACE TelemetryController::observe - content-process-ready-for-script notified.
[task 2022-12-27T06:03:23.862Z] 06:03:23 INFO - 1672121003861 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2022-12-27T06:03:23.904Z] 06:03:23 INFO - 1672121003914 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2022-12-27T06:03:23.954Z] 06:03:23 INFO - 1672121003961 Toolkit.Telemetry TRACE TelemetrySession::observe - user-interaction-active notified.
[task 2022-12-27T06:03:23.973Z] 06:03:23 INFO - 1672121003988 Toolkit.Telemetry TRACE TelemetrySession::observe - xul-window-visible notified.
[task 2022-12-27T06:03:24.000Z] 06:03:24 INFO - console.error: (new SyntaxError("The URI is malformed.", (void 0), 133))
[task 2022-12-27T06:03:24.270Z] 06:03:24 INFO - 1672121004273 Toolkit.Telemetry TRACE ClientID::_doLoadClientID
[task 2022-12-27T06:03:24.275Z] 06:03:24 INFO - 1672121004275 Toolkit.Telemetry TRACE ClientID::_saveClientID
[task 2022-12-27T06:03:24.277Z] 06:03:24 INFO - 1672121004276 Toolkit.Telemetry TRACE ClientID::_doLoadClientID: New client ID loaded and persisted.
[task 2022-12-27T06:03:24.277Z] 06:03:24 INFO - 1672121004276 Toolkit.Telemetry TRACE TelemetrySend::setup
[task 2022-12-27T06:03:24.277Z] 06:03:24 INFO - 1672121004276 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
<...>
[task 2022-12-27T06:03:26.007Z] 06:03:26 INFO - 1672121006007 Marionette DEBUG 1 <- [1,27,null,{"value":false}]
[task 2022-12-27T06:03:26.008Z] 06:03:26 INFO - console.error: (new SyntaxError("The URI is malformed.", (void 0), 133))
[task 2022-12-27T06:03:26.012Z] 06:03:26 INFO - 1672121006011 Marionette DEBUG 1 -> [0,28,"Marionette:SetContext",{"value":"content"}]
[task 2022-12-27T06:03:26.012Z] 06:03:26 INFO - 1672121006011 Marionette DEBUG 1 <- [1,28,null,{"value":null}]
[task 2022-12-27T06:03:26.017Z] 06:03:26 INFO - FOGTestCase Submitting to FOG ping server at http://localhost:49935/
[task 2022-12-27T06:03:26.018Z] 06:03:26 INFO - 1672121006017 Marionette DEBUG 1 -> [0,29,"Marionette:GetContext",{}]
[task 2022-12-27T06:03:26.018Z] 06:03:26 INFO - 1672121006017 Marionette DEBUG 1 <- [1,29,null,{"value":"content"}]
[task 2022-12-27T06:03:26.018Z] 06:03:26 INFO - 1672121006018 Marionette DEBUG 1 -> [0,30,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-12-27T06:03:26.018Z] 06:03:26 INFO - 1672121006018 Marionette DEBUG 1 <- [1,30,null,{"value":null}]
[task 2022-12-27T06:03:26.020Z] 06:03:26 INFO - 1672121006019 Marionette DEBUG 1 -> [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":908,"filename":"Z:\\task_167212031466973\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py"}]
[task 2022-12-27T06:03:26.021Z] 06:03:26 INFO - 1672121006021 Marionette DEBUG 1 <- [1,31,null,{"value":false}]
[task 2022-12-27T06:03:26.021Z] 06:03:26 INFO - 1672121006022 Marionette DEBUG 1 -> [0,32,"Marionette:SetContext",{"value":"content"}]
[task 2022-12-27T06:03:26.022Z] 06:03:26 INFO - 1672121006022 Marionette DEBUG 1 <- [1,32,null,{"value":null}]
[task 2022-12-27T06:03:26.023Z] 06:03:26 INFO - 1672121006022 Marionette DEBUG 1 -> [0,33,"Marionette:GetContext",{}]
[task 2022-12-27T06:03:26.023Z] 06:03:26 INFO - 1672121006022 Marionette DEBUG 1 <- [1,33,null,{"value":"content"}]
[task 2022-12-27T06:03:26.023Z] 06:03:26 INFO - 1672121006023 Marionette DEBUG 1 -> [0,34,"WebDriver:DeleteSession",{}]
[task 2022-12-27T06:03:26.027Z] 06:03:26 INFO - 1672121006026 Marionette DEBUG 1 <- [1,34,null,{"value":null}]
[task 2022-12-27T06:03:26.030Z] 06:03:26 INFO - 1672121006030 Marionette DEBUG Closed connection 1
[task 2022-12-27T06:03:26.085Z] 06:03:26 INFO - Application command: Z:\task_167212031466973\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_167212031466973\build\tmp1mkhedlk.mozrunner
[task 2022-12-27T06:03:26.405Z] 06:03:26 INFO - 1672121006412 Toolkit.Telemetry TRACE TelemetryController::observe - profile-after-change notified.
[task 2022-12-27T06:03:26.413Z] 06:03:26 INFO - 1672121006412 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry
[task 2022-12-27T06:03:26.414Z] 06:03:26 INFO - 1672121006414 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup
[task 2022-12-27T06:03:26.414Z] 06:03:26 INFO - 1672121006414 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2022-12-27T06:03:26.415Z] 06:03:26 INFO - 1672121006414 Toolkit.Telemetry TRACE TelemetrySession::earlyInit
[task 2022-12-27T06:03:26.418Z] 06:03:26 INFO - 1672121006417 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2022-12-27T06:03:26.418Z] 06:03:26 INFO - 1672121006418 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true
[task 2022-12-27T06:03:26.424Z] 06:03:26 INFO - 1672121006424 Toolkit.Telemetry TRACE TelemetryEnvironment::constructor
[task 2022-12-27T06:03:26.451Z] 06:03:26 INFO - 1672121006454 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2022-12-27T06:03:26.457Z] 06:03:26 INFO - 1672121006457 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2022-12-27T06:03:26.457Z] 06:03:26 INFO - 1672121006457 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2022-12-27T06:03:26.458Z] 06:03:26 INFO - 1672121006458 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2022-12-27T06:03:26.465Z] 06:03:26 INFO - 1672121006465 Marionette INFO Marionette enabled
[task 2022-12-27T06:03:26.467Z] 06:03:26 INFO - 1672121006467 Marionette TRACE Received observer notification final-ui-startup
[task 2022-12-27T06:03:26.468Z] 06:03:26 INFO - 1672121006468 Marionette INFO Listening on port 2828
[task 2022-12-27T06:03:26.468Z] 06:03:26 INFO - 1672121006468 Marionette DEBUG Marionette is listening
[task 2022-12-27T06:06:38.219Z] 06:06:38 INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_fog_custom_ping.py TestDeletionRequestPing.test_one_ping_only_ping | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
[task 2022-12-27T06:06:38.219Z] 06:06:38 INFO - Traceback (most recent call last):
[task 2022-12-27T06:06:38.219Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 179, in run
[task 2022-12-27T06:06:38.219Z] 06:06:38 INFO - self.setUp()
[task 2022-12-27T06:06:38.219Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\telemetry_harness\fog_testcase.py", line 45, in setUp
[task 2022-12-27T06:06:38.219Z] 06:06:38 INFO - self.marionette.enforce_gecko_prefs(
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\marionette_driver\decorators.py", line 34, in _
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - m._handle_socket_failure()
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\marionette_driver\marionette.py", line 740, in _handle_socket_failure
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - reraise(
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - raise value.with_traceback(tb)
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - return func(*args, **kwargs)
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\marionette_driver\marionette.py", line 936, in enforce_gecko_prefs
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - self.raise_for_port()
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - File "Z:\task_167212031466973\build\venv\lib\site-packages\marionette_driver\marionette.py", line 631, in raise_for_port
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - raise socket.timeout(
[task 2022-12-27T06:06:38.231Z] 06:06:38 INFO - TEST-INFO took 195333ms
[task 2022-12-27T06:06:38.232Z] 06:06:38 INFO - TEST-START | telemetry/marionette/tests/client/test_fog_user_activity.py TestClientActivity.test_user_activity
| 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 auto_nag documentation.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
|
Reporter | |
Comment 3•2 years ago
|
||
| treeherder | ||
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=405003079&repo=autoland
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 6•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•