Closed
Bug 1842219
Opened 2 years ago
Closed 2 years ago
Intermittent telemetry/marionette/tests/client/test_shutdown_pings_succeed.py TestShutdownPingsSucced.test_shutdown_pings_succeed_pingsender1 | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Process unexpectedly quit
Categories
(Toolkit :: Telemetry, defect, P5)
Toolkit
Telemetry
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=421894149&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NCF_zrBfRmCRY8XasYTvHw/runs/0/artifacts/public/logs/live_backing.log
[task 2023-07-07T14:51:45.256Z] 14:51:45 INFO - TEST-START | telemetry/marionette/tests/client/test_shutdown_pings_succeed.py TestShutdownPingsSucced.test_shutdown_pings_succeed_pingsender1
[task 2023-07-07T14:51:45.277Z] 14:51:45 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmp83xajvo4.mozrunner
[task 2023-07-07T14:51:47.702Z] 14:51:47 INFO - 1688741507700 Toolkit.Telemetry TRACE TelemetryController::observe - profile-after-change notified.
[task 2023-07-07T14:51:47.703Z] 14:51:47 INFO - 1688741507701 Toolkit.Telemetry TRACE TelemetryController::setupTelemetry
[task 2023-07-07T14:51:47.705Z] 14:51:47 INFO - 1688741507702 Toolkit.Telemetry TRACE TelemetryController::registerJsProbes - registering builtin JS probes
[task 2023-07-07T14:51:47.706Z] 14:51:47 INFO - 1688741507702 Toolkit.Telemetry TRACE TelemetryController::registerScalarProbes - registering scalar builtin JS probes
[task 2023-07-07T14:51:47.707Z] 14:51:47 INFO - 1688741507703 Toolkit.Telemetry TRACE TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json
[task 2023-07-07T14:51:47.724Z] 14:51:47 INFO - 1688741507723 Toolkit.Telemetry TRACE TelemetryReportingPolicy::setup
[task 2023-07-07T14:51:47.726Z] 14:51:47 INFO - 1688741507724 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2023-07-07T14:51:47.727Z] 14:51:47 INFO - 1688741507726 Toolkit.Telemetry TRACE TelemetrySession::earlyInit
[task 2023-07-07T14:51:47.773Z] 14:51:47 INFO - 1688741507773 Toolkit.Telemetry TRACE UpdatePing::init - enabled: true
[task 2023-07-07T14:51:47.836Z] 14:51:47 INFO - 1688741507834 Toolkit.Telemetry TRACE TelemetryEnvironment::constructor
[task 2023-07-07T14:51:48.488Z] 14:51:48 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-07-07T14:51:48.527Z] 14:51:48 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-07-07T14:51:48.626Z] 14:51:48 INFO - 1688741508625 Toolkit.Telemetry TRACE TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2023-07-07T14:51:48.647Z] 14:51:48 INFO - 1688741508646 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2023-07-07T14:51:48.648Z] 14:51:48 INFO - 1688741508647 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons
[task 2023-07-07T14:51:48.660Z] 14:51:48 INFO - 1688741508659 Toolkit.Telemetry TRACE TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2023-07-07T14:51:48.731Z] 14:51:48 INFO - 1688741508730 Marionette INFO Marionette enabled
[task 2023-07-07T14:51:48.742Z] 14:51:48 INFO - 1688741508741 Marionette TRACE Received observer notification final-ui-startup
[task 2023-07-07T14:51:49.407Z] 14:51:49 INFO - 1688741509406 Toolkit.Telemetry TRACE TelemetryController::registerEventProbes - registering builtin JS Event probes
[task 2023-07-07T14:51:49.409Z] 14:51:49 INFO - 1688741509407 Toolkit.Telemetry TRACE TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json
[task 2023-07-07T14:51:49.421Z] 14:51:49 INFO - 1688741509420 Marionette INFO Listening on port 2828
[task 2023-07-07T14:51:49.435Z] 14:51:49 INFO - 1688741509434 Marionette DEBUG Marionette is listening
[task 2023-07-07T14:51:49.450Z] 14:51:49 INFO - 1688741509449 Toolkit.Telemetry TRACE TelemetryEnvironment::_updateAddons: addons differ
[task 2023-07-07T14:51:49.551Z] 14:51:49 INFO - 1688741509551 Marionette DEBUG Accepted connection 0 from 127.0.0.1:45146
[task 2023-07-07T14:51:49.703Z] 14:51:49 INFO - 1688741509702 Marionette DEBUG Closed connection 0
[task 2023-07-07T14:51:49.932Z] 14:51:49 INFO - 1688741509931 Marionette DEBUG Accepted connection 1 from 127.0.0.1:45148
[task 2023-07-07T14:51:51.353Z] 14:51:51 INFO - 1688741511353 Marionette DEBUG Closed connection 1
[task 2023-07-07T14:51:51.576Z] 14:51:51 INFO - 1688741511575 Marionette DEBUG Accepted connection 2 from 127.0.0.1:45150
[task 2023-07-07T14:51:51.661Z] 14:51:51 INFO - 1688741511660 Marionette DEBUG Accepted connection 3 from 127.0.0.1:45152
[task 2023-07-07T14:51:51.665Z] 14:51:51 INFO - 1688741511663 Marionette DEBUG Closed connection 2
[task 2023-07-07T14:51:51.866Z] 14:51:51 INFO - 1688741511865 Marionette DEBUG 3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-07-07T14:51:51.902Z] 14:51:51 INFO - 1688741511901 Marionette DEBUG Waiting for initial application window
[task 2023-07-07T14:51:52.067Z] 14:51:52 INFO - 1688741512066 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - Topic gmp-provider-registered
[task 2023-07-07T14:51:52.385Z] 14:51:52 INFO - 1688741512383 Toolkit.Telemetry TRACE TelemetryController::observe - content-process-ready-for-script notified.
[task 2023-07-07T14:51:52.390Z] 14:51:52 INFO - 1688741512386 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2023-07-07T14:51:53.307Z] 14:51:53 INFO - 1688741513305 Toolkit.Telemetry TRACE TelemetryController::observe - content-process-ready-for-script notified.
[task 2023-07-07T14:51:53.314Z] 14:51:53 INFO - 1688741513313 Toolkit.Telemetry CONFIG TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2023-07-07T14:51:54.005Z] 14:51:54 INFO - 1688741514004 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2023-07-07T14:51:54.041Z] 14:51:54 INFO - console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-07-07T14:51:55.524Z] 14:51:55 INFO - 1688741515523 Toolkit.Telemetry TRACE TelemetrySession::observe - xul-window-visible notified.
[task 2023-07-07T14:51:59.826Z] 14:51:59 INFO - console.error: ({})
[task 2023-07-07T14:51:59.885Z] 14:51:59 INFO - 1688741519885 Toolkit.Telemetry TRACE TelemetryEnvironment::observe - aTopic: sessionstore-windows-restored, aData: null
[task 2023-07-07T14:51:59.901Z] 14:51:59 INFO - 1688741519900 Toolkit.Telemetry TRACE TelemetrySession::observe - sessionstore-windows-restored notified.
[task 2023-07-07T14:51:59.902Z] 14:51:59 INFO - 1688741519901 Toolkit.Telemetry TRACE TelemetrySession::gatherStartup
[task 2023-07-07T14:51:59.907Z] 14:51:59 INFO - 1688741519904 Toolkit.Telemetry INFO TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2023-07-07T14:51:59.910Z] 14:51:59 INFO - 1688741519904 Toolkit.Telemetry TRACE TelemetryReportingPolicy::_shouldNotify - User already notified or bypassing the policy.
[task 2023-07-07T14:52:00.082Z] 14:52:00 INFO - 1688741520082 Toolkit.Telemetry TRACE TelemetryEnvironment::_startWatchingPrefs - [object Map]
[task 2023-07-07T14:52:00.155Z] 14:52:00 INFO - 1688741520155 Toolkit.Telemetry TRACE TelemetrySession::observe - user-interaction-inactive notified.
<...>
[task 2023-07-07T14:52:18.137Z] 14:52:18 INFO - [Parent 4996: StreamTrans #5,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.137Z] 14:52:18 INFO - [Parent 4996: StreamTrans #5,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.138Z] 14:52:18 INFO - [Parent 4996: StreamTrans #3,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.138Z] 14:52:18 INFO - [Parent 4996: StreamTrans #4,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.140Z] 14:52:18 INFO - [Parent 4996: StreamTrans #4,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.140Z] 14:52:18 INFO - [Parent 4996: StreamTrans #1,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.143Z] 14:52:18 INFO - [Parent 4996: StreamTrans #1,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.143Z] 14:52:18 INFO - [Parent 4996: StreamTrans #3,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.143Z] 14:52:18 INFO - [Parent 4996: HTML5 Parser,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.143Z] 14:52:18 INFO - [Parent 4996: HTML5 Parser,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.145Z] 14:52:18 INFO - [Parent 4996: IPDL Background,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.145Z] 14:52:18 INFO - [Parent 4996: IPDL Background,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.146Z] 14:52:18 INFO - [Parent 4996: Netlink Monitor,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.146Z] 14:52:18 INFO - [Parent 4996: Timer]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.148Z] 14:52:18 INFO - [Parent 4996: Timer,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.148Z] 14:52:18 INFO - [Parent 4996: Timer,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.151Z] 14:52:18 INFO - [Parent 4996: BackgroundThreadPool #1,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.152Z] 14:52:18 INFO - [Parent 4996: BackgroundThreadPool #1,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.153Z] 14:52:18 INFO - [Parent 4996: BgIOThreadPool #2,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.153Z] 14:52:18 INFO - [Parent 4996: BgIOThreadPool #2,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.154Z] 14:52:18 INFO - [Parent 4996: Compositor,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.154Z] 14:52:18 INFO - [Parent 4996: Compositor,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.155Z] 14:52:18 INFO - [Parent 4996: Permission,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:18.155Z] 14:52:18 INFO - [Parent 4996: Permission,SHDRCV]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.518Z] 14:52:19 INFO - [Parent 4996: AudioIPC Server RPC]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.525Z] 14:52:19 INFO - [Parent 4996: SoftwareVsyncThread]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.526Z] 14:52:19 INFO - [Parent 4996: SoftwareVsyncThread]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.562Z] 14:52:19 INFO - [Parent 4996: JS Watchdog]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.562Z] 14:52:19 INFO - [Parent 4996: JS Watchdog]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.590Z] 14:52:19 INFO - [Parent 4996: IPC I/O Parent]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.591Z] 14:52:19 INFO - [Parent 4996: IPC I/O Parent]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.593Z] 14:52:19 INFO - [Parent 4996: TaskController #1]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.593Z] 14:52:19 INFO - [Parent 4996: TaskController #1]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.594Z] 14:52:19 INFO - [Parent 4996: TaskController #0]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.595Z] 14:52:19 INFO - [Parent 4996: TaskController #0]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.618Z] 14:52:19 INFO - [Parent 4996: Main Thread]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:19.619Z] 14:52:19 INFO - [Parent 4996: Main Thread]: I/glean_core::* [glean_core::dispatcher::global] Failed to launch a task on the queue. Discarding task.
[task 2023-07-07T14:52:21.388Z] 14:52:21 INFO - ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-07-07T14:52:21.408Z] 14:52:21 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-07-07T15:00:27.180Z] 15:00:27 INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_shutdown_pings_succeed.py TestShutdownPingsSucced.test_shutdown_pings_succeed_pingsender1 | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: Process unexpectedly quit without restarting (exit code: 0))
[task 2023-07-07T15:00:27.180Z] 15:00:27 INFO - Traceback (most recent call last):
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 198, in run
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - testMethod()
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 48, in wrapper
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - return func(self, *args, **kwargs)
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - File "/builds/worker/workspace/build/tests/telemetry/marionette/tests/client/test_shutdown_pings_succeed.py", line 47, in test_shutdown_pings_succeed
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - len(ping_types),
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py", line 124, in wait_for_pings
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - action_func()
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py", line 144, in restart_browser
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - return self.marionette.restart(clean=False, in_app=True)
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 34, in _
[task 2023-07-07T15:00:27.181Z] 15:00:27 INFO - m._handle_socket_failure()
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 770, in _handle_socket_failure
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/six.py", line 702, in reraise
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - raise value.with_traceback(tb)
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - return func(*args, **kwargs)
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1217, in restart
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - tb,
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/six.py", line 702, in reraise
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - raise value.with_traceback(tb)
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1197, in restart
[task 2023-07-07T15:00:27.182Z] 15:00:27 INFO - self.raise_for_port(timeout=timeout_restart, check_process_status=False)
[task 2023-07-07T15:00:27.183Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 662, in raise_for_port
[task 2023-07-07T15:00:27.183Z] 15:00:27 INFO - self.host, self.port
[task 2023-07-07T15:00:27.184Z] 15:00:27 INFO - TEST-INFO took 521922ms
[task 2023-07-07T15:00:27.188Z] 15:00:27 ERROR - test_end for telemetry/marionette/tests/client/test_shutdown_pings_succeed.py TestShutdownPingsSucced.test_shutdown_pings_succeed_pingsender1 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 \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py\", line 231, in run\n self.tearDown()\n File \"/builds/worker/workspace/build/tests/telemetry/marionette/tests/client/test_shutdown_pings_succeed.py\", line 13, in tearDown\n super(TestShutdownPingsSucced, self).tearDown()\n File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py\", line 231, in tearDown\n super(TelemetryTestCase, self).tearDown()\n File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/mixins/window_manager.py\", line 22, in tearDown\n if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 1452, in chrome_window_handles\n with self.using_context(\"chrome\"):\n File \"/usr/lib/python3.7/contextlib.py\", line 112, in __enter__\n return next(self.gen)\n File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 1521, in using_context\n scope = self._send_message(\"Marionette:GetContext\", key=\"value\")\n File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py\", line 24, in _\n return func(*args, **kwargs)\n File \"/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py\", line 682, in _send_message\n raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_shutdown_pings_succeed.TestShutdownPingsSucced", "method_name": "test_shutdown_pings_succeed_pingsender1"}, "test": "telemetry/marionette/tests/client/test_shutdown_pings_succeed.py TestShutdownPingsSucced.test_shutdown_pings_succeed_pingsender1", "status": "ERROR"}
[task 2023-07-07T15:00:27.189Z] 15:00:27 INFO - TEST-START | telemetry/marionette/tests/client/test_shutdown_pings_succeed.py TestShutdownPingsSucced.test_shutdown_pings_succeed_pingsender2
[task 2023-07-07T15:00:27.190Z] 15:00:27 INFO - Failed to start HTTP server on port 8000; is something already using that port?
[task 2023-07-07T15:00:27.192Z] 15:00:27 INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_shutdown_pings_succeed.py TestShutdownPingsSucced.test_shutdown_pings_succeed_pingsender2 | OSError: [Errno 98] Address already in use
[task 2023-07-07T15:00:27.192Z] 15:00:27 INFO - Traceback (most recent call last):
[task 2023-07-07T15:00:27.193Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 179, in run
[task 2023-07-07T15:00:27.193Z] 15:00:27 INFO - self.setUp()
[task 2023-07-07T15:00:27.193Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/telemetry_harness/testcase.py", line 33, in setUp
[task 2023-07-07T15:00:27.193Z] 15:00:27 INFO - self.testvars["server_root"], self.testvars["server_url"]
[task 2023-07-07T15:00:27.193Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/telemetry_harness/ping_server.py", line 64, in __init__
[task 2023-07-07T15:00:27.193Z] 15:00:27 INFO - self._httpd = httpd.FixtureServer(server_root, url=url)
[task 2023-07-07T15:00:27.193Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/httpd.py", line 162, in __init__
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - key_file=ssl_key,
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/wptserve/server.py", line 838, in __init__
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - http2=http2)
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/wptserve/server.py", line 192, in __init__
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - super().__init__(hostname_port, request_handler_cls)
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - File "/usr/lib/python3.7/socketserver.py", line 452, in __init__
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - self.server_bind()
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - File "/usr/lib/python3.7/http/server.py", line 137, in server_bind
[task 2023-07-07T15:00:27.194Z] 15:00:27 INFO - socketserver.TCPServer.server_bind(self)
[task 2023-07-07T15:00:27.195Z] 15:00:27 INFO - File "/usr/lib/python3.7/socketserver.py", line 466, in server_bind
[task 2023-07-07T15:00:27.195Z] 15:00:27 INFO - self.socket.bind(self.server_address)
[task 2023-07-07T15:00:27.195Z] 15:00:27 INFO - TEST-INFO took 8ms
[task 2023-07-07T15:00:27.562Z] 15:00:27 ERROR - 'TestShutdownPingsSucced' object has no attribute 'marionette'
[task 2023-07-07T15:00:27.563Z] 15:00:27 ERROR - Traceback (most recent call last):
[task 2023-07-07T15:00:27.563Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.563Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runtests.py", line 105, in cli
[task 2023-07-07T15:00:27.563Z] 15:00:27 ERROR - failed = harness_instance.run()
[task 2023-07-07T15:00:27.563Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.564Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runtests.py", line 79, in run
[task 2023-07-07T15:00:27.564Z] 15:00:27 ERROR - runner.run_tests(tests)
[task 2023-07-07T15:00:27.564Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.564Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1019, in run_tests
[task 2023-07-07T15:00:27.564Z] 15:00:27 ERROR - self.run_test_sets()
[task 2023-07-07T15:00:27.565Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.565Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1245, in run_test_sets
[task 2023-07-07T15:00:27.565Z] 15:00:27 ERROR - self.run_test_set(self.tests)
[task 2023-07-07T15:00:27.565Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.565Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1215, in run_test_set
[task 2023-07-07T15:00:27.566Z] 15:00:27 ERROR - self.run_test(test["filepath"], test["expected"])
[task 2023-07-07T15:00:27.566Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.566Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 1179, in run_test
[task 2023-07-07T15:00:27.566Z] 15:00:27 ERROR - results = runner.run(suite)
[task 2023-07-07T15:00:27.566Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.567Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/runner/base.py", line 256, in run
[task 2023-07-07T15:00:27.567Z] 15:00:27 ERROR - result = super(MarionetteTextTestRunner, self).run(test)
[task 2023-07-07T15:00:27.567Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.567Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/moztest/adapters/unit.py", line 208, in run
[task 2023-07-07T15:00:27.567Z] 15:00:27 ERROR - test(result)
[task 2023-07-07T15:00:27.568Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.568Z] 15:00:27 ERROR - File "/usr/lib/python3.7/unittest/suite.py", line 84, in __call__
[task 2023-07-07T15:00:27.568Z] 15:00:27 ERROR - return self.run(*args, **kwds)
[task 2023-07-07T15:00:27.568Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.568Z] 15:00:27 ERROR - File "/usr/lib/python3.7/unittest/suite.py", line 122, in run
[task 2023-07-07T15:00:27.569Z] 15:00:27 ERROR - test(result)
[task 2023-07-07T15:00:27.569Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.569Z] 15:00:27 ERROR - File "/usr/lib/python3.7/unittest/case.py", line 676, in __call__
[task 2023-07-07T15:00:27.569Z] 15:00:27 ERROR - return self.run(*args, **kwds)
[task 2023-07-07T15:00:27.570Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.570Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 241, in run
[task 2023-07-07T15:00:27.570Z] 15:00:27 ERROR - self.cleanTest()
[task 2023-07-07T15:00:27.570Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.571Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 310, in cleanTest
[task 2023-07-07T15:00:27.571Z] 15:00:27 ERROR - self._delete_session()
[task 2023-07-07T15:00:27.571Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.571Z] 15:00:27 ERROR - File "/builds/worker/workspace/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 315, in _delete_session
[task 2023-07-07T15:00:27.572Z] 15:00:27 ERROR - if self.marionette.session is not None:
[task 2023-07-07T15:00:27.572Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.572Z] 15:00:27 ERROR - AttributeError: 'TestShutdownPingsSucced' object has no attribute 'marionette'
[task 2023-07-07T15:00:27.572Z] 15:00:27 ERROR -
[task 2023-07-07T15:00:27.614Z] 15:00:27 INFO - Return code: 1
[task 2023-07-07T15:00:27.615Z] 15:00:27 WARNING - Got 2 unexpected statuses
[task 2023-07-07T15:00:27.616Z] 15:00:27 ERROR - No suite end message was emitted by this harness.
[task 2023-07-07T15:00:27.616Z] 15:00:27 WARNING - setting return code to 2
[task 2023-07-07T15:00:27.616Z] 15:00:27 INFO - Running post-action listener: _package_coverage_data
[task 2023-07-07T15:00:27.617Z] 15:00:27 INFO - Running post-action listener: _resource_record_post_action
[task 2023-07-07T15:00:27.617Z] 15:00:27 INFO - Running post-action listener: process_java_coverage_data
[task 2023-07-07T15:00:27.617Z] 15:00:27 INFO - [mozharness: 2023-07-07 15:00:27.616885Z] Finished run-tests step (success)
[task 2023-07-07T15:00:27.617Z] 15:00:27 INFO - [mozharness: 2023-07-07 15:00:27.617220Z] Running uninstall step.
[task 2023-07-07T15:00:27.617Z] 15:00:27 INFO - Running pre-action listener: _resource_record_pre_action
[task 2023-07-07T15:00:27.617Z] 15:00:27 INFO - Running main action method: uninstall
[task 2023-07-07T15:00:27.618Z] 15:00:27 INFO - Getting output from command: ['/builds/worker/workspace/build/venv/bin/mozuninstall', '/builds/worker/workspace/build/application']
[task 2023-07-07T15:00:27.618Z] 15:00:27 INFO - Copy/paste: /builds/worker/workspace/build/venv/bin/mozuninstall /builds/worker/workspace/build/application
[task 2023-07-07T15:00:28.019Z] 15:00:28 INFO - Return code: 0
[task 2023-07-07T15:00:28.019Z] 15:00:28 INFO - Running post-action listener: _resource_record_post_action
[task 2023-07-07T15:00:28.020Z] 15:00:28 INFO - [mozharness: 2023-07-07 15:00:28.020606Z] Finished uninstall step (success)
[task 2023-07-07T15:00:28.021Z] 15:00:28 INFO - Running post-run listener: _resource_record_post_run
[task 2023-07-07T15:00:28.098Z] 15:00:28 INFO - Total resource usage - Wall time: 1044s; CPU: 38%; Read bytes: 46100480; Write bytes: 2891628544; Read time: 316; Write time: 1412528
[task 2023-07-07T15:00:28.099Z] 15:00:28 INFO - TinderboxPrint: CPU usage<br/>37.8%
[task 2023-07-07T15:00:28.100Z] 15:00:28 INFO - TinderboxPrint: I/O read bytes / time<br/>46,100,480 / 316
[task 2023-07-07T15:00:28.100Z] 15:00:28 INFO - TinderboxPrint: I/O write bytes / time<br/>2,891,628,544 / 1,412,528
[task 2023-07-07T15:00:28.101Z] 15:00:28 INFO - TinderboxPrint: CPU idle<br/>1,294.1 (62.1%)
[task 2023-07-07T15:00:28.101Z] 15:00:28 INFO - TinderboxPrint: CPU system<br/>81.8 (3.9%)
[task 2023-07-07T15:00:28.102Z] 15:00:28 INFO - TinderboxPrint: CPU user<br/>703.8 (33.8%)
[task 2023-07-07T15:00:28.102Z] 15:00:28 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2023-07-07T15:00:28.103Z] 15:00:28 INFO - install - Wall time: 40s; CPU: 51%; Read bytes: 8192; Write bytes: 1865990144; Read time: 8; Write time: 1331604
[task 2023-07-07T15:00:28.106Z] 15:00:28 INFO - run-tests - Wall time: 1005s; CPU: 37%; Read bytes: 44978176; Write bytes: 1023475712; Read time: 292; Write time: 79904
[task 2023-07-07T15:00:28.107Z] 15:00:28 INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-07-07T15:00:28.209Z] 15:00:28 WARNING - returning nonzero exit status 2
| 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•2 years ago
|
||
| treeherder | ||
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=429658458&repo=try
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 BugBot 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
•