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)
Toolkit
Telemetry
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
| Comment hidden (Intermittent Failures Robot) |
Comment 2•4 years ago
|
||
With bug 1739008 fixed this should no longer happen.
Assignee: nobody → jdescottes
Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox94:
--- → unaffected
status-firefox95:
--- → affected
status-firefox96:
--- → fixed
status-firefox-esr91:
--- → unaffected
Resolution: --- → FIXED
Target Milestone: --- → 96 Branch
Comment 3•4 years ago
|
||
The fix from bug 1739008 got uplifted to beta as:
https://hg.mozilla.org/releases/mozilla-beta/rev/7cb8324e9f4d
| Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•