1673530 - Intermittent dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | Test timed out.

Status: RESOLVED FIXED

(Core :: DOM: UI Events & Focus Handling, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-10-27T03:38:06.206Z] 03:38:06     INFO - TEST-START | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html
[task 2020-10-27T03:38:06.531Z] 03:38:06     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4282
[task 2020-10-27T03:38:06.773Z] 03:38:06     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: 'NS_FAILED(targetPrincipal->GetAsciiOrigin(targetOrigin))', file /builds/worker/checkouts/gecko/toolkit/components/antitracking/AntiTrackingUtils.cpp:347
[task 2020-10-27T03:38:06.850Z] 03:38:06     INFO - GECKO(1947) | [GLX] window 2200029 has VisualID 0x41
[task 2020-10-27T03:38:06.850Z] 03:38:06     INFO - GECKO(1947) | [Parent 1947, Renderer] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:628
[task 2020-10-27T03:38:06.850Z] 03:38:06     INFO - GECKO(1947) | [Parent 1947, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/checkouts/gecko/gfx/gl/GLContext.cpp:971
[task 2020-10-27T03:38:06.850Z] 03:38:06     INFO - GECKO(1947) | [Parent 1947, Renderer] WARNING: robustness marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:628
[task 2020-10-27T03:38:06.850Z] 03:38:06     INFO - GECKO(1947) | [2020-10-27T03:38:06Z WARN  webrender::device::gl] Missing optimized shader source for gpu_cache_update
[task 2020-10-27T03:38:06.894Z] 03:38:06     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:06.895Z] 03:38:06     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4280
[task 2020-10-27T03:38:07.193Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.193Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.194Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.195Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.617Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.618Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.619Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.619Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.619Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.619Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:07.619Z] 03:38:07     INFO - GECKO(1947) | [2020-10-27T03:38:07Z 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 2020-10-27T03:38:08.552Z] 03:38:08     INFO - GECKO(1947) | [2020-10-27T03:38:08Z 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 2020-10-27T03:38:08.552Z] 03:38:08     INFO - GECKO(1947) | [2020-10-27T03:38:08Z 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 2020-10-27T03:38:09.055Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.055Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.055Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.058Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.059Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.061Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.061Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.062Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.064Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.065Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.066Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.068Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.072Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.072Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.073Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.075Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.076Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.078Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.078Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.080Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.082Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.084Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.084Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.087Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.087Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.089Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.090Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.091Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.093Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.093Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.094Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.096Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.097Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.099Z] 03:38:09     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:09.250Z] 03:38:09     INFO - GECKO(1947) | [POINTEREVENT] Starting file_pointercapture_xorigin_iframe.html
[task 2020-10-27T03:38:09.472Z] 03:38:09     INFO - GECKO(1947) | [2268, Unnamed thread 7f0a1f45f5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-27T03:38:09.472Z] 03:38:09     INFO - GECKO(1947) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpfKF0wk.mozrunner/runtests_leaks.log
[task 2020-10-27T03:38:09.472Z] 03:38:09     INFO - GECKO(1947) | [2268, Unnamed thread 7f0a1f45f5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-27T03:38:09.472Z] 03:38:09     INFO - GECKO(1947) | [2268, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2020-10-27T03:38:09.594Z] 03:38:09     INFO - GECKO(1947) | [Child 2268, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:628
[task 2020-10-27T03:38:09.711Z] 03:38:09     INFO - GECKO(1947) | [Child 2146, Main Thread] WARNING: NS_ENSURE_TRUE(currentInner) failed: file /builds/worker/checkouts/gecko/dom/base/WindowDestroyedEvent.cpp:106
[task 2020-10-27T03:38:09.908Z] 03:38:09     INFO - GECKO(1947) | [POINTEREVENT] Finishing file_pointercapture_xorigin_iframe.html
[task 2020-10-27T03:38:09.924Z] 03:38:09     INFO - GECKO(1947) | [Child 2146, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2020-10-27T03:38:09.924Z] 03:38:09     INFO - GECKO(1947) | [Child 2146, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2020-10-27T03:38:10.270Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:370
[task 2020-10-27T03:38:10.291Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:10.293Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:10.313Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4282
[task 2020-10-27T03:38:10.329Z] 03:38:10     INFO - GECKO(1947) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-27T03:38:10.446Z] 03:38:10     INFO - GECKO(1947) | [Child 2159, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3359
[task 2020-10-27T03:38:10.466Z] 03:38:10     INFO - GECKO(1947) | [Child 2159, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4287
[task 2020-10-27T03:38:10.663Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: 'NS_FAILED(targetPrincipal->GetAsciiOrigin(targetOrigin))', file /builds/worker/checkouts/gecko/toolkit/components/antitracking/AntiTrackingUtils.cpp:347
[task 2020-10-27T03:38:10.719Z] 03:38:10     INFO - GECKO(1947) | [GLX] window 2200038 has VisualID 0x41
[task 2020-10-27T03:38:10.735Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Renderer] WARNING: robust_buffer_access_behavior marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:628
[task 2020-10-27T03:38:10.737Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Renderer] WARNING: Robustness supported, strategy is not LOSE_CONTEXT_ON_RESET!: file /builds/worker/checkouts/gecko/gfx/gl/GLContext.cpp:971
[task 2020-10-27T03:38:10.738Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Renderer] WARNING: robustness marked as unsupported: file /builds/worker/checkouts/gecko/gfx/gl/GLContextFeatures.cpp:628
[task 2020-10-27T03:38:10.739Z] 03:38:10     INFO - GECKO(1947) | [2020-10-27T03:38:10Z WARN  webrender::device::gl] Missing optimized shader source for gpu_cache_update
[task 2020-10-27T03:38:10.773Z] 03:38:10     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4280
[task 2020-10-27T03:38:10.991Z] 03:38:10     INFO - GECKO(1947) | [2020-10-27T03:38:10Z 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 2020-10-27T03:38:10.992Z] 03:38:10     INFO - GECKO(1947) | [2020-10-27T03:38:10Z 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 2020-10-27T03:38:10.993Z] 03:38:10     INFO - GECKO(1947) | [2020-10-27T03:38:10Z 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 2020-10-27T03:38:10.994Z] 03:38:10     INFO - GECKO(1947) | [2020-10-27T03:38:10Z 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 2020-10-27T03:38:11.250Z] 03:38:11     INFO - GECKO(1947) | [POINTEREVENT] Starting file_pointercapture_xorigin_iframe_pointerlock.html
[task 2020-10-27T03:38:11.635Z] 03:38:11     INFO - GECKO(1947) | [2020-10-27T03:38:11Z 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 2020-10-27T03:38:11.636Z] 03:38:11     INFO - GECKO(1947) | [2020-10-27T03:38:11Z 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 2020-10-27T03:38:11.637Z] 03:38:11     INFO - GECKO(1947) | [2020-10-27T03:38:11Z 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 2020-10-27T03:38:11.638Z] 03:38:11     INFO - GECKO(1947) | [2020-10-27T03:38:11Z 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 2020-10-27T03:38:11.639Z] 03:38:11     INFO - GECKO(1947) | [2020-10-27T03:38:11Z 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 2020-10-27T03:38:11.639Z] 03:38:11     INFO - GECKO(1947) | [2020-10-27T03:38:11Z 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 2020-10-27T03:38:11.640Z] 03:38:11     INFO - GECKO(1947) | [2020-10-27T03:38:11Z 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 2020-10-27T03:38:12.655Z] 03:38:12     INFO - GECKO(1947) | [2020-10-27T03:38:12Z 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 2020-10-27T03:38:12.656Z] 03:38:12     INFO - GECKO(1947) | [2020-10-27T03:38:12Z 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 2020-10-27T03:38:13.687Z] 03:38:13     INFO - GECKO(1947) | [2306, Unnamed thread 7feae195f5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-27T03:38:13.691Z] 03:38:13     INFO - GECKO(1947) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpfKF0wk.mozrunner/runtests_leaks.log
[task 2020-10-27T03:38:13.691Z] 03:38:13     INFO - GECKO(1947) | [2306, Unnamed thread 7feae195f5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp:202
[task 2020-10-27T03:38:13.691Z] 03:38:13     INFO - GECKO(1947) | [2306, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2020-10-27T03:38:13.840Z] 03:38:13     INFO - GECKO(1947) | [Child 2306, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:628
[task 2020-10-27T03:38:26.036Z] 03:38:26     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:26.037Z] 03:38:26     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:28.361Z] 03:38:28     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:38:28.361Z] 03:38:28     INFO - GECKO(1947) | [Parent 1947, Main Thread] WARNING: Not implemented in the parent process!: file /builds/worker/checkouts/gecko/docshell/shistory/SessionHistoryEntry.cpp:503
[task 2020-10-27T03:43:23.926Z] 03:43:23     INFO - TEST-INFO | started process screentopng
[task 2020-10-27T03:43:24.066Z] 03:43:24     INFO - TEST-INFO | screentopng: exit 0
[task 2020-10-27T03:43:24.067Z] 03:43:24     INFO - Buffered messages logged at 03:38:06
[task 2020-10-27T03:43:24.067Z] 03:43:24     INFO - must wait for load
[task 2020-10-27T03:43:24.067Z] 03:43:24     INFO - Testing file_pointercapture_xorigin_iframe.html
[task 2020-10-27T03:43:24.068Z] 03:43:24     INFO - Buffered messages logged at 03:38:09
[task 2020-10-27T03:43:24.068Z] 03:43:24     INFO - file_pointercapture_xorigin_iframe.html: add_task | Entering test test_pointer_capture_xorigin_iframe
[task 2020-10-27T03:43:24.068Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got pointerdown event on target 
[task 2020-10-27T03:43:24.068Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got gotpointercapture event on target 
[task 2020-10-27T03:43:24.069Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got pointermove event on target 
[task 2020-10-27T03:43:24.069Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got pointerup event on target 
[task 2020-10-27T03:43:24.069Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got lostpointercapture event on target 
[task 2020-10-27T03:43:24.070Z] 03:43:24     INFO - file_pointercapture_xorigin_iframe.html: add_task | Leaving test test_pointer_capture_xorigin_iframe
[task 2020-10-27T03:43:24.070Z] 03:43:24     INFO - must wait for focus
[task 2020-10-27T03:43:24.070Z] 03:43:24     INFO - Buffered messages logged at 03:38:10
[task 2020-10-27T03:43:24.070Z] 03:43:24     INFO - Testing file_pointercapture_xorigin_iframe_pointerlock.html
[task 2020-10-27T03:43:24.071Z] 03:43:24     INFO - Buffered messages logged at 03:38:13
[task 2020-10-27T03:43:24.071Z] 03:43:24     INFO - file_pointercapture_xorigin_iframe_pointerlock.html: add_task | Entering test test_pointer_capture_xorigin_iframe_pointer_lock
[task 2020-10-27T03:43:24.071Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe_pointerlock.html: got pointerdown event on target 
[task 2020-10-27T03:43:24.071Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe_pointerlock.html: got gotpointercapture event on target 
[task 2020-10-27T03:43:24.072Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe_pointerlock.html: got pointermove event on target 
[task 2020-10-27T03:43:24.073Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | Got pointerlockchange on iframe - "pointerlockchange" == "pointerlockchange" 
[task 2020-10-27T03:43:24.073Z] 03:43:24     INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | pointer lock element - {} == {} 
[task 2020-10-27T03:43:24.073Z] 03:43:24     INFO - Buffered messages finished
[task 2020-10-27T03:43:24.073Z] 03:43:24     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | Test timed out. ```

Comment 1

[Edgar Chen [:edgar]]

This doesn't look like a bug of test itself or pointer capture related code, there are three records in intermittent failures view for now. All of them have the same pattern.
Take https://treeherder.mozilla.org/logviewer.html#?job_id=319978995&repo=mozilla-central as an example,

Test harness says test start at 09:59:56

[task 2020-10-28T09:59:56.851Z] 09:59:56 INFO - TEST-START | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html

But the test is running after 5 min and it only takes a few seconds to finish.

[task 2020-10-28T10:05:14.255Z] 10:05:14 INFO - TEST-INFO | started process screentopng
[task 2020-10-28T10:05:14.397Z] 10:05:14 INFO - TEST-INFO | screentopng: exit 0
[task 2020-10-28T10:05:14.399Z] 10:05:14 INFO - Buffered messages logged at 09:59:57
[task 2020-10-28T10:05:14.400Z] 10:05:14 INFO - must wait for load
[task 2020-10-28T10:05:14.401Z] 10:05:14 INFO - Testing file_pointercapture_xorigin_iframe.html
[task 2020-10-28T10:05:14.401Z] 10:05:14 INFO - Buffered messages logged at 10:00:00
[task 2020-10-28T10:05:14.402Z] 10:05:14 INFO - file_pointercapture_xorigin_iframe.html: add_task | Entering test test_pointer_capture_xorigin_iframe
[task 2020-10-28T10:05:14.402Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got pointerdown event on target
[task 2020-10-28T10:05:14.403Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got gotpointercapture event on target
[task 2020-10-28T10:05:14.403Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got pointermove event on target
[task 2020-10-28T10:05:14.404Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got pointerup event on target
[task 2020-10-28T10:05:14.404Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe.html: got lostpointercapture event on target
[task 2020-10-28T10:05:14.404Z] 10:05:14 INFO - file_pointercapture_xorigin_iframe.html: add_task | Leaving test test_pointer_capture_xorigin_iframe
[task 2020-10-28T10:05:14.405Z] 10:05:14 INFO - must wait for focus
[task 2020-10-28T10:05:14.405Z] 10:05:14 INFO - Testing file_pointercapture_xorigin_iframe_pointerlock.html
[task 2020-10-28T10:05:14.406Z] 10:05:14 INFO - Buffered messages logged at 10:00:04
[task 2020-10-28T10:05:14.406Z] 10:05:14 INFO - file_pointercapture_xorigin_iframe_pointerlock.html: add_task | Entering test test_pointer_capture_xorigin_iframe_pointer_lock
[task 2020-10-28T10:05:14.407Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe_pointerlock.html: got pointerdown event on target
[task 2020-10-28T10:05:14.407Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe_pointerlock.html: got gotpointercapture event on target
[task 2020-10-28T10:05:14.407Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | file_pointercapture_xorigin_iframe_pointerlock.html: got pointermove event on target
[task 2020-10-28T10:05:14.408Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | Got pointerlockchange on iframe - "pointerlockchange" == "pointerlockchange"
[task 2020-10-28T10:05:14.409Z] 10:05:14 INFO - TEST-PASS | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | pointer lock element - {} == {}

And it reports timeout, but you could also see TEST-OK means test finish correctly.
I think the timeout mostly because the 5min gap between "test harness report start" and "test really start running".

[task 2020-10-28T10:05:14.409Z] 10:05:14 INFO - Buffered messages finished
[task 2020-10-28T10:05:14.410Z] 10:05:14 INFO - TEST-UNEXPECTED-FAIL | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | Test timed out.
[task 2020-10-28T10:05:14.410Z] 10:05:14 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2020-10-28T10:05:14.410Z] 10:05:14 INFO - reportError@SimpleTest/TestRunner.js:143:22
[task 2020-10-28T10:05:14.410Z] 10:05:14 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:165:18
[task 2020-10-28T10:05:15.269Z] 10:05:15 INFO - GECKO(1936) | MEMORY STAT | vsize 2600MB | residentFast 153MB | heapAllocated 10MB
[task 2020-10-28T10:05:15.287Z] 10:05:15 INFO - TEST-OK | dom/events/test/pointerevents/test_pointercapture_xorigin_iframe.html | took 318437ms

Sebastian, do you encounter any similar issue?

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

The test doesn't progresses anymore at 10:00 and gets terminated at 10:05. Screenshot of the application while it was stuck.

Last related message seems to be:

[POINTEREVENT] Starting file_pointercapture_xorigin_iframe_pointerlock.html

Comment 3

[Edgar Chen [:edgar]]

Test seems stuck in

[task 2020-10-28T10:00:01.748Z] 10:00:01 INFO - GECKO(1936) | [POINTEREVENT] Starting file_pointercapture_xorigin_iframe_pointerlock.html

Ah, okay, I think I got it the "TEST-*" log is printed after the fact. I was confused.

Comment 4

[Edgar Chen [:edgar]]

I am able to reproduce this on test verify locally, investigating.

Comment 5

[Edgar Chen [:edgar]]

The pointer capturing document stucks on waiting for lostpointercapture event after pointer lock is requested on OOP iframe.
The expected behaviour is

1. while pointer lock is requested on OOP iframe, OOP iframe would send IPC to parent process to request pointer lock
2. parent process sends IPC to notify pointer capturing process to release the pointer capture.
3. parent process sends IPC to notify pointer lock process to the request is accepted.
4. Generate eMouseExitFromWidget to pointer capturing process given that now mouse event would be dispatch to pointer lock process.

But when the issue happens the pointer capturing process receives eMouseExitFromWidget first then 2) because of the input event priority queue.

Comment 6

[Edgar Chen [:edgar]]

Attachment: Bug 1673530 - Make ReleaseAllPointerCapture use same priority as mouse event;

While pointer lock happens in different process, pointer capturing process relay
on eMouseExitFromWidget event to generate lostpointercaptre event. But input
event queue might make the order changes, i.e. pointer capturing process might
handle eMouseExitFromWidget event first then releasing request.

Comment 7

[Intermittent Failures Robot]

11 failures in 4275 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 9
• mozilla-central: 2

Platform breakdown:

• linux1804-64-qr: 11

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1673530&startday=2020-10-26&endday=2020-11-01&tree=all

Comment 8

[Bogdan Tara[:bogdan_tara | bogdant]]

In the last 7 days there have been 21 occurrences, all on linux1804-64, most linux1804-64-qr debug.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=321024677&repo=mozilla-central&lineNumber=2938

Who could review Edgar's patch?

Comment 9

[Edgar Chen [:edgar]]

I will try to verify the patch on try and find a reviewer on Monday.

Comment 10

[Intermittent Failures Robot]

22 failures in 4128 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 17
• mozilla-central: 5

Platform breakdown:

• linux1804-64-qr: 19
• linux1804-64: 2
• linux1804-64-asan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1673530&startday=2020-11-02&endday=2020-11-08&tree=all

Comment 11

[Intermittent Failures Robot]

20 failures in 4040 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 15
• try: 2
• mozilla-central: 3

Platform breakdown:

• linux1804-64-qr: 16
• linux1804-64-shippable-qr: 2
• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1673530&startday=2020-11-09&endday=2020-11-15&tree=all

Comment 12

[Edgar Chen [:edgar]]

(note to myself: another option, put release all pointer capture in input priority)

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/85a0d5665bb6
Make ReleaseAllPointerCapture use same priority as mouse event; r=smaug

Comment 14

[Cristina Coroiu [:ccoroiu]]

https://hg.mozilla.org/mozilla-central/rev/85a0d5665bb6

Comment 15

[Intermittent Failures Robot]

5 failures in 4810 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 4
• mozilla-central: 1

Platform breakdown:

• linux1804-64-qr: 4
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1673530&startday=2020-11-16&endday=2020-11-22&tree=all