Closed Bug 1739066 Opened 4 years ago Closed 4 years ago

Intermittent telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | marionette_driver.errors.SessionNotCreatedException: TimeoutError: TimedPromise timed out after 300000 ms

Categories

(Toolkit :: Telemetry, defect, P5)

defect

Tracking

()

RESOLVED FIXED
96 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox94 --- unaffected
firefox95 --- fixed
firefox96 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: jdescottes)

References

Details

(Keywords: intermittent-failure)

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


[task 2021-11-03T08:00:56.289Z] 08:00:56     INFO - TEST-START | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping
[task 2021-11-03T08:00:56.290Z] 08:00:56     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmp8lvr34pk.mozrunner
[task 2021-11-03T08:00:56.968Z] 08:00:56     INFO -  [2021-11-03T08:00:56Z WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2021-11-03T08:00:57.147Z] 08:00:57     INFO -  1635926457146	Toolkit.Telemetry	TRACE	TelemetryController::observe - profile-after-change notified.
[task 2021-11-03T08:00:57.148Z] 08:00:57     INFO -  1635926457146	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry
[task 2021-11-03T08:00:57.152Z] 08:00:57     INFO -  1635926457151	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup
[task 2021-11-03T08:00:57.153Z] 08:00:57     INFO -  1635926457152	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-11-03T08:00:57.154Z] 08:00:57     INFO -  1635926457153	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit
[task 2021-11-03T08:00:57.164Z] 08:00:57     INFO -  1635926457163	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-11-03T08:00:57.166Z] 08:00:57     INFO -  1635926457165	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true
[task 2021-11-03T08:00:57.180Z] 08:00:57     INFO -  1635926457179	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor
[task 2021-11-03T08:00:57.352Z] 08:00:57     INFO -  [Parent 1711, Main Thread] WARNING: GLX_swap_control unsupported, ASAP mode may still block on buffer swaps.: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderGLX.cpp:214
[task 2021-11-03T08:00:57.373Z] 08:00:57     INFO -  1635926457372	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Two display adapters detected.
[task 2021-11-03T08:00:57.381Z] 08:00:57     INFO -  1635926457381	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2021-11-03T08:00:57.382Z] 08:00:57     INFO -  1635926457382	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons
[task 2021-11-03T08:00:57.391Z] 08:00:57     INFO -  1635926457390	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2021-11-03T08:00:57.419Z] 08:00:57     INFO -  1635926457418	Marionette	INFO	Marionette enabled
[task 2021-11-03T08:00:57.566Z] 08:00:57     INFO -  1635926457566	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-11-03T08:00:57.593Z] 08:00:57     INFO -  1635926457592	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ
[task 2021-11-03T08:00:57.607Z] 08:00:57     INFO -  [Parent 1711, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4225
[task 2021-11-03T08:00:58.204Z] 08:00:58     INFO -  [Parent 1711, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4223
[task 2021-11-03T08:00:58.366Z] 08:00:58     INFO -  [GLX] window 220002c has VisualID 0x41
[task 2021-11-03T08:00:58.374Z] 08:00:58     INFO -  [Parent 1711, Renderer] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2021-11-03T08:00:58.375Z] 08:00:58     INFO -  [Parent 1711, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/checkouts/gecko/gfx/gl/GLContext.cpp:988
[task 2021-11-03T08:00:58.375Z] 08:00:58     INFO -  [Parent 1711, Renderer] WARNING: robustness marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:632
[task 2021-11-03T08:00:58.377Z] 08:00:58     INFO -  [2021-11-03T08:00:58Z WARN  webrender::device::gl] Missing optimized shader source for gpu_cache_update
[task 2021-11-03T08:00:58.411Z] 08:00:58     INFO -  [Parent 1711, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp:1626
[task 2021-11-03T08:00:58.466Z] 08:00:58     INFO -  [Child 1779, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:644
[task 2021-11-03T08:00:58.500Z] 08:00:58     INFO -  1635926458498	Toolkit.Telemetry	TRACE	TelemetryController::observe - app-startup notified.
[task 2021-11-03T08:00:58.504Z] 08:00:58     INFO -  1635926458503	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-11-03T08:00:58.722Z] 08:00:58     INFO -  [Parent 1711, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4223
[task 2021-11-03T08:00:58.727Z] 08:00:58     INFO -  1635926458726	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2021-11-03T08:00:58.732Z] 08:00:58     INFO -  [Child 1798, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:644
[task 2021-11-03T08:00:58.771Z] 08:00:58     INFO -  1635926458769	Toolkit.Telemetry	TRACE	TelemetryController::observe - app-startup notified.
[task 2021-11-03T08:00:58.778Z] 08:00:58     INFO -  1635926458775	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-11-03T08:00:58.847Z] 08:00:58     INFO -  [Child 1798, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2865
[task 2021-11-03T08:00:58.863Z] 08:00:58     INFO -  [Child 1798, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2865
[task 2021-11-03T08:00:58.876Z] 08:00:58     INFO -  [Child 1798, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2865
[task 2021-11-03T08:00:58.885Z] 08:00:58     INFO -  [Child 1798, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2865
[task 2021-11-03T08:00:58.897Z] 08:00:58     INFO -  [Child 1798, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2865
[task 2021-11-03T08:00:59.943Z] 08:00:59     INFO -  1635926459942	Toolkit.Telemetry	TRACE	TelemetrySession::observe - xul-window-visible notified.
[task 2021-11-03T08:01:00.136Z] 08:01:00     INFO -  1635926460135	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientID
[task 2021-11-03T08:01:00.147Z] 08:01:00     INFO -  1635926460146	Toolkit.Telemetry	TRACE	ClientID::_saveClientID
[task 2021-11-03T08:01:00.151Z] 08:01:00     INFO -  1635926460151	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientID: New client ID loaded and persisted.
[task 2021-11-03T08:01:00.154Z] 08:01:00     INFO -  1635926460154	Toolkit.Telemetry	TRACE	TelemetrySend::setup
[task 2021-11-03T08:01:00.158Z] 08:01:00     INFO -  1635926460158	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-11-03T08:01:00.186Z] 08:01:00     INFO -  1635926460185	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanPendingPings
[task 2021-11-03T08:01:00.186Z] 08:01:00     INFO -  1635926460185	Toolkit.Telemetry	TRACE	TelemetryStorage::_migrateAppDataPings
[task 2021-11-03T08:01:00.187Z] 08:01:00     INFO -  1635926460185	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings
[task 2021-11-03T08:01:00.279Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_TL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 8, found at -1
[task 2021-11-03T08:01:00.280Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_TR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 10, found at -1
[task 2021-11-03T08:01:00.281Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_BL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 12, found at -1
[task 2021-11-03T08:01:00.282Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_BR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 14, found at -1
[task 2021-11-03T08:01:00.302Z] 08:01:00     INFO -  [Parent 1711, Main Thread] WARNING: '!mLastFocusedWindow', file /builds/worker/checkouts/gecko/widget/gtk/IMContextWrapper.cpp:3143
[task 2021-11-03T08:01:00.358Z] 08:01:00     INFO -  [Child 1826, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:644
[task 2021-11-03T08:01:00.394Z] 08:01:00     INFO -  1635926460391	Toolkit.Telemetry	TRACE	TelemetryController::observe - app-startup notified.
[task 2021-11-03T08:01:00.396Z] 08:01:00     INFO -  1635926460396	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-11-03T08:01:00.701Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_TL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 8, found at -1
[task 2021-11-03T08:01:00.703Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_TR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 10, found at -1
[task 2021-11-03T08:01:00.703Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRadii_TR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 11, found at -1
[task 2021-11-03T08:01:00.704Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_BL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 12, found at -1
[task 2021-11-03T08:01:00.705Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRadii_BL", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 13, found at -1
[task 2021-11-03T08:01:00.706Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRect_BR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 14, found at -1
[task 2021-11-03T08:01:00.706Z] 08:01:00     INFO -  [2021-11-03T08:01:00Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aClipRadii_BR", count: 4, kind: F32 } is not found in the shader cs_clip_rectangle. Expected at 15, found at -1
[task 2021-11-03T08:01:01.884Z] 08:01:01     INFO -  [2021-11-03T08:01:01Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect1", count: 4, kind: F32 } is not found in the shader composite. Expected at 6, found at -1
[task 2021-11-03T08:01:01.885Z] 08:01:01     INFO -  [2021-11-03T08:01:01Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect2", count: 4, kind: F32 } is not found in the shader composite. Expected at 7, found at -1
[task 2021-11-03T08:01:01.888Z] 08:01:01     INFO -  [2021-11-03T08:01:01Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aColor", count: 4, kind: F32 } is not found in the shader composite. Expected at 3, found at -1
[task 2021-11-03T08:01:01.889Z] 08:01:01     INFO -  [2021-11-03T08:01:01Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect1", count: 4, kind: F32 } is not found in the shader composite. Expected at 6, found at -1
[task 2021-11-03T08:01:01.889Z] 08:01:01     INFO -  [2021-11-03T08:01:01Z WARN  webrender::device::gl] Attribute VertexAttribute { name: "aUvRect2", count: 4, kind: F32 } is not found in the shader composite. Expected at 7, found at -1
[task 2021-11-03T08:01:02.286Z] 08:01:02     INFO -  1635926462285	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: sessionstore-windows-restored, aData: null
[task 2021-11-03T08:01:02.302Z] 08:01:02     INFO -  1635926462301	Toolkit.Telemetry	TRACE	TelemetrySession::observe - sessionstore-windows-restored notified.
[task 2021-11-03T08:01:02.305Z] 08:01:02     INFO -  1635926462301	Toolkit.Telemetry	TRACE	TelemetrySession::gatherStartup
[task 2021-11-03T08:01:02.307Z] 08:01:02     INFO -  1635926462306	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-11-03T08:01:02.308Z] 08:01:02     INFO -  1635926462306	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_shouldNotify - User already notified or bypassing the policy.
[task 2021-11-03T08:01:02.349Z] 08:01:02     INFO -  1635926462348	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]
[task 2021-11-03T08:01:02.374Z] 08:01:02     INFO -  [2021-11-03T08:01:02Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2021-11-03T08:01:02.375Z] 08:01:02     INFO -  [2021-11-03T08:01:02Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
[task 2021-11-03T08:01:02.375Z] 08:01:02     INFO -  [2021-11-03T08:01:02Z WARN  webrender::device::gl] Cropping texture upload Box2D((0, 0), (0, 1)) to None
<...>
[task 2021-11-03T08:06:16.747Z] 08:06:16     INFO -  1635926776744	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type main, aOptions {"addClientId":true,"addEnvironment":true}
[task 2021-11-03T08:06:16.773Z] 08:06:16     INFO -  1635926776772	Toolkit.Telemetry	TRACE	TelemetryStorage::saveAbortedSessionPing - ping path: /builds/worker/workspace/build/tmp8lvr34pk.mozrunner/datareporting/aborted-session-ping
[task 2021-11-03T08:06:16.777Z] 08:06:16     INFO -  1635926776772	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - isUserIdle: false
[task 2021-11-03T08:06:16.777Z] 08:06:16     INFO -  1635926776773	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Wed Nov 03 2021 08:11:16 GMT+0000 (Coordinated Universal Time)
[task 2021-11-03T08:06:16.778Z] 08:06:16     INFO -  1635926776777	Toolkit.Telemetry	TRACE	TelemetryScheduler::observe - aTopic: idle
[task 2021-11-03T08:06:16.778Z] 08:06:16     INFO -  1635926776778	Toolkit.Telemetry	TRACE	TelemetryScheduler::_onSchedulerTick - dispatchOnIdle: false
[task 2021-11-03T08:06:16.780Z] 08:06:16     INFO -  1635926776778	Toolkit.Telemetry	TRACE	TelemetryScheduler::_schedulerTickLogic
[task 2021-11-03T08:06:16.780Z] 08:06:16     INFO -  1635926776779	Toolkit.Telemetry	TRACE	TelemetryScheduler::_isDailyPingDue - already sent one today
[task 2021-11-03T08:06:16.780Z] 08:06:16     INFO -  1635926776779	Toolkit.Telemetry	TRACE	TelemetryScheduler::_isPeriodicPingDue - already sent one today
[task 2021-11-03T08:06:16.781Z] 08:06:16     INFO -  1635926776779	Toolkit.Telemetry	TRACE	TelemetryScheduler::_schedulerTickLogic - No ping due.
[task 2021-11-03T08:06:16.781Z] 08:06:16     INFO -  1635926776780	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - isUserIdle: true
[task 2021-11-03T08:06:16.782Z] 08:06:16     INFO -  1635926776782	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Wed Nov 03 2021 09:06:16 GMT+0000 (Coordinated Universal Time)
[task 2021-11-03T08:06:16.784Z] 08:06:16     INFO -  1635926776783	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2021-11-03T08:06:16.785Z] 08:06:16     INFO -  1635926776784	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /builds/worker/workspace/build/tmp8lvr34pk.mozrunner/datareporting/aborted-session-ping
[task 2021-11-03T08:06:21.287Z] 08:06:21     INFO -  1635926781286	Marionette	DEBUG	1 <- [1,1,{"error":"session not created","message":"TimeoutError: TimedPromise timed out after 300000 ms","stacktrace":"WebDriverE ... r@chrome://remote/content/shared/webdriver/Errors.jsm:450:5\nbail@chrome://remote/content/marionette/sync.js:230:19\n"},null]
[task 2021-11-03T08:06:21.292Z] 08:06:21     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | marionette_driver.errors.SessionNotCreatedException: TimeoutError: TimedPromise timed out after 300000 ms
[task 2021-11-03T08:06:21.293Z] 08:06:21     INFO - stacktrace:
[task 2021-11-03T08:06:21.293Z] 08:06:21     INFO - 	WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:181:5
[task 2021-11-03T08:06:21.293Z] 08:06:21     INFO - 	TimeoutError@chrome://remote/content/shared/webdriver/Errors.jsm:450:5
[task 2021-11-03T08:06:21.294Z] 08:06:21     INFO - 	bail@chrome://remote/content/marionette/sync.js:230:19
[task 2021-11-03T08:06:21.294Z] 08:06:21     INFO - Traceback (most recent call last):
[task 2021-11-03T08:06:21.294Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2021-11-03T08:06:21.294Z] 08:06:21     INFO -     testMethod()
[task 2021-11-03T08:06:21.295Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/tests/telemetry/marionette/tests/client/test_event_ping.py", line 51, in test_event_ping
[task 2021-11-03T08:06:21.295Z] 08:06:21     INFO -     payload = self.wait_for_ping(self.restart_browser, EVENT_PING)["payload"]
[task 2021-11-03T08:06:21.295Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/telemetry_harness/testcase.py", line 170, in wait_for_ping
[task 2021-11-03T08:06:21.298Z] 08:06:21     INFO -     action_func, ping_filter, 1, ping_server=ping_server
[task 2021-11-03T08:06:21.299Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/telemetry_harness/testcase.py", line 156, in wait_for_pings
[task 2021-11-03T08:06:21.299Z] 08:06:21     INFO -     action_func()
[task 2021-11-03T08:06:21.299Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/telemetry_harness/testcase.py", line 176, in restart_browser
[task 2021-11-03T08:06:21.300Z] 08:06:21     INFO -     return self.marionette.restart(clean=False, in_app=True)
[task 2021-11-03T08:06:21.300Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-11-03T08:06:21.301Z] 08:06:21     INFO -     return func(*args, **kwargs)
[task 2021-11-03T08:06:21.301Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1129, in restart
[task 2021-11-03T08:06:21.301Z] 08:06:21     INFO -     self.start_session()
[task 2021-11-03T08:06:21.301Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -     return func(*args, **kwargs)
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1187, in start_session
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -     resp = self._send_message("WebDriver:NewSession", capabilities)
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -     return func(*args, **kwargs)
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 630, in _send_message
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -     self._handle_error(err)
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 652, in _handle_error
[task 2021-11-03T08:06:21.302Z] 08:06:21     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2021-11-03T08:06:21.303Z] 08:06:21     INFO - TEST-INFO took 325001ms
[task 2021-11-03T08:06:21.303Z] 08:06:21    ERROR - test_end for telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping 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.6/site-packages/marionette_harness/marionette_test/testcases.py\", line 235, in run\n    self.tearDown()\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/telemetry_harness/testcase.py\", line 253, in tearDown\n    super(TelemetryTestCase, self).tearDown()\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/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 \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 1342, in chrome_window_handles\n    with self.using_context(\"chrome\"):\n  File \"/usr/lib/python3.6/contextlib.py\", line 81, in __enter__\n    return next(self.gen)\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 1411, in using_context\n    scope = self._send_message(\"Marionette:GetContext\", key=\"value\")\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 620, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_event_ping.TestEventPing", "method_name": "test_event_ping"}, "test": "telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping", "status": "ERROR"}
[task 2021-11-03T08:06:21.303Z] 08:06:21     INFO -  Failed to start HTTP server on port 8000; is something already using that port?
[task 2021-11-03T08:06:21.497Z] 08:06:21     INFO -  JavaScript error: chrome://remote/content/marionette/driver.js, line 2113: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIObserverService.removeObserver]
[task 2021-11-03T08:06:21.499Z] 08:06:21     INFO -  1635926781498	Marionette	WARN	Connection attempt denied because an active session has been found
[task 2021-11-03T08:07:32.596Z] 08:07:32    ERROR - Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: No data received over socket)
[task 2021-11-03T08:07:32.596Z] 08:07:32    ERROR - Traceback (most recent call last):
[task 2021-11-03T08:07:32.596Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.596Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/base.py", line 1048, in run_tests
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     self.run_test_sets()
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/base.py", line 1275, in run_test_sets
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     self.run_test_set(self.tests)
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/base.py", line 1245, in run_test_set
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     self.run_test(test["filepath"], test["expected"])
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/base.py", line 1197, in run_test
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     **self.test_kwargs
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 400, in add_tests_to_suite
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     **kwargs
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/telemetry_harness/testcase.py", line 32, in __init__
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     self.testvars["server_root"], self.testvars["server_url"]
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/telemetry_harness/ping_server.py", line 60, in __init__
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     self._httpd = httpd.FixtureServer(server_root, url=url)
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/httpd.py", line 123, in __init__
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     key_file=ssl_key,
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/wptserve/server.py", line 826, in __init__
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     http2=http2)
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/wptserve/server.py", line 190, in __init__
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     http.server.HTTPServer.__init__(self, hostname_port, request_handler_cls, **kwargs)
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/usr/lib/python3.6/socketserver.py", line 456, in __init__
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     self.server_bind()
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/usr/lib/python3.6/http/server.py", line 136, in server_bind
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     socketserver.TCPServer.server_bind(self)
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -   File "/usr/lib/python3.6/socketserver.py", line 470, in server_bind
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR -     self.socket.bind(self.server_address)
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - OSError: [Errno 98] Address already in use
[task 2021-11-03T08:07:32.597Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR - During handling of the above exception, another exception occurred:
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR - Traceback (most recent call last):
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-11-03T08:07:32.598Z] 08:07:32    ERROR -     return func(*args, **kwargs)
[task 2021-11-03T08:07:32.599Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.601Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1184, in start_session
[task 2021-11-03T08:07:32.601Z] 08:07:32    ERROR -     self.protocol, _ = self.client.connect()
[task 2021-11-03T08:07:32.602Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.602Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 310, in connect
[task 2021-11-03T08:07:32.603Z] 08:07:32    ERROR -     raw = self.receive(unmarshal=False)
[task 2021-11-03T08:07:32.603Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.603Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 230, in receive
[task 2021-11-03T08:07:32.604Z] 08:07:32    ERROR -     raise socket.error("No data received over socket")
[task 2021-11-03T08:07:32.604Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.605Z] 08:07:32    ERROR - OSError: No data received over socket
[task 2021-11-03T08:07:32.605Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.606Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.606Z] 08:07:32    ERROR - During handling of the above exception, another exception occurred:
[task 2021-11-03T08:07:32.606Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.607Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.607Z] 08:07:32    ERROR - Traceback (most recent call last):
[task 2021-11-03T08:07:32.607Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.607Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runtests.py", line 108, in cli
[task 2021-11-03T08:07:32.607Z] 08:07:32    ERROR -     failed = harness_instance.run()
[task 2021-11-03T08:07:32.607Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.607Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runtests.py", line 82, in run
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -     runner.run_tests(tests)
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/base.py", line 1062, in run_tests
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -     self.cleanup()
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/base.py", line 1289, in cleanup
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -     self.marionette.start_session()
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -     m._handle_socket_failure()
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 717, in _handle_socket_failure
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -     IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 702, in reraise
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -     raise value.with_traceback(tb)
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.608Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR -     return func(*args, **kwargs)
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1184, in start_session
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR -     self.protocol, _ = self.client.connect()
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 310, in connect
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR -     raw = self.receive(unmarshal=False)
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 230, in receive
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR -     raise socket.error("No data received over socket")
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR - OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: No data received over socket)
[task 2021-11-03T08:07:32.609Z] 08:07:32    ERROR - 
[task 2021-11-03T08:07:32.642Z] 08:07:32    ERROR - Return code: 1
[task 2021-11-03T08:07:32.643Z] 08:07:32    ERROR - Got 1 unexpected statuses
[task 2021-11-03T08:07:32.643Z] 08:07:32    ERROR - No suite end message was emitted by this harness.
[task 2021-11-03T08:07:32.644Z] 08:07:32    ERROR - # TBPL FAILURE #
[task 2021-11-03T08:07:32.644Z] 08:07:32  WARNING - setting return code to 2
[task 2021-11-03T08:07:32.644Z] 08:07:32     INFO - Running post-action listener: _package_coverage_data
[task 2021-11-03T08:07:32.645Z] 08:07:32     INFO - Running post-action listener: _resource_record_post_action
[task 2021-11-03T08:07:32.645Z] 08:07:32     INFO - Running post-action listener: process_java_coverage_data
[task 2021-11-03T08:07:32.645Z] 08:07:32     INFO - [mozharness: 2021-11-03 08:07:32.645571Z] Finished run-tests step (success)
[task 2021-11-03T08:07:32.646Z] 08:07:32     INFO - [mozharness: 2021-11-03 08:07:32.645842Z] Running uninstall step.
[task 2021-11-03T08:07:32.646Z] 08:07:32     INFO - Running pre-action listener: _resource_record_pre_action
[task 2021-11-03T08:07:32.646Z] 08:07:32     INFO - Running main action method: uninstall
[task 2021-11-03T08:07:32.646Z] 08:07:32     INFO - Getting output from command: ['/builds/worker/workspace/build/venv/bin/mozuninstall', '/builds/worker/workspace/build/application']
[task 2021-11-03T08:07:32.646Z] 08:07:32     INFO - Copy/paste: /builds/worker/workspace/build/venv/bin/mozuninstall /builds/worker/workspace/build/application
[task 2021-11-03T08:07:32.901Z] 08:07:32     INFO - Running post-action listener: _resource_record_post_action
[task 2021-11-03T08:07:32.902Z] 08:07:32     INFO - [mozharness: 2021-11-03 08:07:32.901712Z] Finished uninstall step (success)
[task 2021-11-03T08:07:32.902Z] 08:07:32     INFO - Running post-run listener: _resource_record_post_run
[task 2021-11-03T08:07:32.965Z] 08:07:32     INFO - Total resource usage - Wall time: 444s; CPU: 13%; Read bytes: 10027008; Write bytes: 883445760; Read time: 144; Write time: 65676
[task 2021-11-03T08:07:32.966Z] 08:07:32     INFO - TinderboxPrint: CPU usage<br/>12.8%
[task 2021-11-03T08:07:32.966Z] 08:07:32     INFO - TinderboxPrint: I/O read bytes / time<br/>10,027,008 / 144
[task 2021-11-03T08:07:32.966Z] 08:07:32     INFO - TinderboxPrint: I/O write bytes / time<br/>883,445,760 / 65,676
[task 2021-11-03T08:07:32.967Z] 08:07:32     INFO - TinderboxPrint: CPU idle<br/>771.6 (87.1%)
[task 2021-11-03T08:07:32.967Z] 08:07:32     INFO - TinderboxPrint: CPU user<br/>103.8 (11.7%)
[task 2021-11-03T08:07:32.968Z] 08:07:32     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-11-03T08:07:32.968Z] 08:07:32     INFO - install - Wall time: 14s; CPU: 50%; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-11-03T08:07:32.970Z] 08:07:32     INFO - run-tests - Wall time: 430s; CPU: 12%; Read bytes: 9019392; Write bytes: 883019776; Read time: 120; Write time: 65596
[task 2021-11-03T08:07:32.970Z] 08:07:32     INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-11-03T08:07:33.018Z] 08:07:33  WARNING - returning nonzero exit status 2
[task 2021-11-03T08:07:33.042Z] cleanup
[task 2021-11-03T08:07:33.042Z] + cleanup
[task 2021-11-03T08:07:33.042Z] + local rv=2
[task 2021-11-03T08:07:33.043Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-11-03T08:07:33.043Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-11-03T08:07:33.046Z] + '[' ']'
[task 2021-11-03T08:07:33.046Z] + true
[task 2021-11-03T08:07:33.046Z] + cleanup_xvfb
[task 2021-11-03T08:07:33.046Z] ++ pidof Xvfb
[task 2021-11-03T08:07:33.051Z] + local xvfb_pid=48
[task 2021-11-03T08:07:33.051Z] + local vnc=false
[task 2021-11-03T08:07:33.052Z] + local interactive=false
[task 2021-11-03T08:07:33.052Z] + '[' -n 48 ']'
[task 2021-11-03T08:07:33.053Z] + [[ false == false ]]
[task 2021-11-03T08:07:33.053Z] + [[ false == false ]]
[task 2021-11-03T08:07:33.053Z] + kill 48
[task 2021-11-03T08:07:33.054Z] + screen -XS xvfb quit
[task 2021-11-03T08:07:33.064Z] No screen session found.
[task 2021-11-03T08:07:33.065Z] + true
[task 2021-11-03T08:07:33.065Z] + exit 2
[taskcluster 2021-11-03 08:07:33.539Z] === Task Finished ===
[taskcluster 2021-11-03 08:07:34.277Z] Unsuccessful task run with exit code: 2 completed in 730.737 seconds

With bug 1739008 fixed this should no longer happen.

Assignee: nobody → jdescottes
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 96 Branch
You need to log in before you can comment on or make changes to this bug.