Closed Bug 1726269 Opened 3 years ago Closed 3 years ago

Intermittent editor/libeditor/tests/test_bug525389.html | Timed out while polling clipboard for initialized data, got: 123

Tracking

()

Status:

RESOLVED FIXED

Milestone:

94 Branch

Tracking Flags:

Tracking

Status

firefox94

---

fixed

People

(Reporter: intermittent-bug-filer, Assigned: mbrodesser-Igalia)

References

(Blocks 2 open bugs)

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

Bug 1726269: part 1) Repeatedly call `::OleSetClipboard` for the Windows-specific clipboard. r=smaug 3 years ago Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h 48 bytes, text/x-phabricator-request		Details \| Review
Bug 1726269: part 2) Repeatedly call `::OleGetClipboard` for the Windows-specific clipboard. r=smaug 3 years ago Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h 48 bytes, text/x-phabricator-request		Details \| Review
Bug 1726269: part 3) Repeatedly call `IDataObject::GetData` in Windows-specific clipboard code. r=smaug 3 years ago Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h 48 bytes, text/x-phabricator-request		Details \| Review

Treeherder Bug Filer

Reporter

Description

•

3 years ago

treeherder

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

[task 2021-08-17T23:44:28.603Z] 23:44:28     INFO - TEST-START | editor/libeditor/tests/test_bug525389.html
[task 2021-08-17T23:44:34.245Z] 23:44:34     INFO - TEST-INFO | started process screenshot
[task 2021-08-17T23:44:34.314Z] 23:44:34     INFO - TEST-INFO | screenshot: exit 0
[task 2021-08-17T23:44:34.326Z] 23:44:34     INFO - Buffered messages logged at 23:44:28
[task 2021-08-17T23:44:34.327Z] 23:44:34     INFO - add_task | Entering test test_copy
[task 2021-08-17T23:44:34.327Z] 23:44:34     INFO - Initializing clipboard with "waitForClipboard-known-value-0.6184495897828183"...
[task 2021-08-17T23:44:34.328Z] 23:44:34     INFO - Succeeded initializing clipboard, start requested things...
[task 2021-08-17T23:44:34.329Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | Clipboard has the given value: 'HelloKitty' 
[task 2021-08-17T23:44:34.329Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | undefined assertion name 
[task 2021-08-17T23:44:34.330Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | paste event was not triggered 
[task 2021-08-17T23:44:34.331Z] 23:44:34     INFO - Initializing clipboard with "waitForClipboard-known-value-0.8296844704436729"...
[task 2021-08-17T23:44:34.331Z] 23:44:34     INFO - Succeeded initializing clipboard, start requested things...
[task 2021-08-17T23:44:34.332Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | Clipboard has the given value: '    Hello Kitty
[task 2021-08-17T23:44:34.332Z] 23:44:34     INFO - 
[task 2021-08-17T23:44:34.332Z] 23:44:34     INFO - HelloKitty' 
[task 2021-08-17T23:44:34.333Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | undefined assertion name 
[task 2021-08-17T23:44:34.333Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | paste event was not triggered 
[task 2021-08-17T23:44:34.334Z] 23:44:34     INFO - Initializing clipboard with "waitForClipboard-known-value-0.3876409838290865"...
[task 2021-08-17T23:44:34.334Z] 23:44:34     INFO - Succeeded initializing clipboard, start requested things...
[task 2021-08-17T23:44:34.335Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | Clipboard has the given value: 'Kitty
[task 2021-08-17T23:44:34.335Z] 23:44:34     INFO - 
[task 2021-08-17T23:44:34.335Z] 23:44:34     INFO - Hello' 
[task 2021-08-17T23:44:34.336Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | undefined assertion name 
[task 2021-08-17T23:44:34.337Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | paste event was not triggered 
[task 2021-08-17T23:44:34.337Z] 23:44:34     INFO - Initializing clipboard with "waitForClipboard-known-value-0.34572369448568685"...
[task 2021-08-17T23:44:34.338Z] 23:44:34     INFO - Succeeded initializing clipboard, start requested things...
[task 2021-08-17T23:44:34.338Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | Clipboard has the given value: '123' 
[task 2021-08-17T23:44:34.339Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | undefined assertion name 
[task 2021-08-17T23:44:34.339Z] 23:44:34     INFO - TEST-PASS | editor/libeditor/tests/test_bug525389.html | paste event was not triggered 
[task 2021-08-17T23:44:34.340Z] 23:44:34     INFO - Initializing clipboard with "waitForClipboard-known-value-0.20604086322724513"...
[task 2021-08-17T23:44:34.340Z] 23:44:34     INFO - Buffered messages finished
[task 2021-08-17T23:44:34.341Z] 23:44:34     INFO - TEST-UNEXPECTED-FAIL | editor/libeditor/tests/test_bug525389.html | Timed out while polling clipboard for initialized data, got: 123

Michelle Goossens [:masterwayz]

Updated

•

3 years ago

Blocks: 1726423

Comment hidden (Intermittent Failures Robot)

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Updated

•

3 years ago

Updated

•

3 years ago

OS: Unspecified → Windows

Kagami Rosylight [:saschanaz] (they/them)

Updated

•

3 years ago

Blocks: 1727738

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 2

•

3 years ago

Locally reproducible with ./mach mochitest --run-until-failure --repeat 3000 editor/libeditor/tests/test_bug525389.html.

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Updated

•

3 years ago

Assignee: nobody → mbrodesser

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 3

•

3 years ago

Changing severity to S3 because the failing test is only one representative of a set of failing tests and broken clipboard functionality, see bug 1727738.

Severity: S4 → S3

Priority: P5 → P3

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Updated

•

3 years ago

Depends on: 1728955

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 4

•

3 years ago

With some additional logging one sees:

when the test succeeds:

 0:27.64 INFO Initializing clipboard with "waitForClipboard-known-value-0.4156758907763154"...
 0:27.64 GECKO(12228) [Parent 11668: Main Thread]: D/BaseClipboard SetData
 0:27.64 GECKO(12228) [Parent 11668: Main Thread]: D/BaseClipboard GetData
 0:27.64 GECKO(12228) [Parent 11668: Main Thread]: D/nsClipboard GetNativeClipboardData aWhichClipboard=1
 0:27.64 GECKO(12228) [Parent 11668: Main Thread]: D/nsClipboard GetDataFromDataObject
 0:27.64 GECKO(12228) [Parent 11668: Main Thread]: D/nsClipboard GetNativeDataOffClipboard: overload2
 0:27.64 GECKO(12228) [Parent 11668: Main Thread]: I/nsClipboard S_OK
 0:27.64 GECKO(12228) [Parent 11668: Main Thread]: I/nsClipboard S_OK
 0:27.64 INFO Succeeded initializing clipboard, start requested things...

and when it fails:

 0:27.66 INFO Initializing clipboard with "waitForClipboard-known-value-0.5535988841017634"...
 0:27.67 GECKO(12228) [Parent 11668: Main Thread]: D/BaseClipboard SetData
 0:27.67 GECKO(12228) [Parent 11668: Main Thread]: D/BaseClipboard GetData
 0:27.67 GECKO(12228) [Parent 11668: Main Thread]: D/nsClipboard GetNativeClipboardData aWhichClipboard=1
 0:27.67 GECKO(12228) [Parent 11668: Main Thread]: D/nsClipboard GetDataFromDataObject
 0:27.67 GECKO(12228) [Parent 11668: Main Thread]: D/nsClipboard GetNativeDataOffClipboard: overload2
 0:27.67 GECKO(12228) [Parent 11668: Main Thread]: I/nsClipboard S_OK
 0:27.67 GECKO(12228) [Parent 11668: Main Thread]: I/nsClipboard S_OK
 0:27.77 GECKO(12228) [Parent 11668: Main Thread]: D/BaseClipboard GetData
[...]
 0:33.21 GECKO(12228) [Parent 11668: Main Thread]: I/nsClipboard S_OK
 0:33.33 FAIL Timed out while polling clipboard for initialized data, got: HelloKitty
    SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
    putAndVerify@SimpleTest/SimpleTest.js:1215:16
 0:33.33 FAIL Error: Timed out while polling clipboard for initialized data, got: HelloKitty - Should not throw any errors

So the bug might be around nsBaseClipboard::SetData.

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 5

•

3 years ago

Some more logging reveals:

 1:56.47 INFO Initializing clipboard with "waitForClipboard-known-value-0.12485531250382076"...
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/BaseClipboard SetData
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/BaseClipboard EmptyClipboard: clipboard=1
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard SetNativeClipboardData
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard SetupNativeDataObject
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard SetupNativeDataObject: plain text content=waitForClipboard-known-value-0.12485531250382076
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/BaseClipboard GetData
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard GetNativeClipboardData aWhichClipboard=1
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard GetDataFromDataObject
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard GetNativeDataOffClipboard: overload2
 1:56.48 GECKO(8260) [Parent 7084: Main Thread]: I/nsClipboard S_OK

[...]

2:01.66 GECKO(8260) [Parent 7084: Main Thread]: D/BaseClipboard GetData
 2:01.66 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard GetNativeClipboardData aWhichClipboard=1
 2:01.66 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard GetDataFromDataObject
 2:01.66 GECKO(8260) [Parent 7084: Main Thread]: D/nsClipboard GetNativeDataOffClipboard: overload2
 2:01.66 GECKO(8260) [Parent 7084: Main Thread]: I/nsClipboard S_OK
 2:01.66 GECKO(8260) [Parent 7084: Main Thread]: I/nsClipboard S_OK
 2:01.76 FAIL Timed out while polling clipboard for initialized data, got:     Hello Kitty

HelloKitty
    SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
    putAndVerify@SimpleTest/SimpleTest.js:1215:16
 2:01.76 FAIL Error: Timed out while polling clipboard for initialized data, got:     Hello Kitty

HelloKitty - Should not throw any errors

That is, initializing the clipboard fails, despite the transferable containing the correct content in nsClipboard::SetNativeDataObject.

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 6

•

3 years ago

With more logging:

 0:59.10 PASS Clipboard has the given value: 'HelloKitty'
 0:59.09 GECKO(2312) [Parent 11272: Main Thread]: D/BaseClipboard GetData
 0:59.09 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetNativeClipboardData aWhichClipboard=1
 0:59.09 GECKO(2312) [Parent 11272: Main Thread]: V/nsClipboard GetNativeClipboardData: use OLE IDataObject.
 0:59.09 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetDataFromDataObject
 0:59.09 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetNativeDataOffClipboard: overload2
 0:59.09 GECKO(2312) [Parent 11272: Main Thread]: I/nsClipboard S_OK
 0:59.09 GECKO(2312) [Parent 11272: Main Thread]: I/nsClipboard S_OK
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: V/nsClipboard GetGlobalData
 0:59.11 PASS undefined assertion name
 0:59.11 PASS paste event was not triggered
 0:59.11 INFO Initializing clipboard with "waitForClipboard-known-value-0.36185022145230816"...
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/BaseClipboard SetData
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/BaseClipboard EmptyClipboard: clipboard=1
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard SetNativeClipboardData
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard SetupNativeDataObject
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard SetupNativeDataObject: plain text content=waitForClipboard-known-value-0.36185022145230816
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard SetNativeClipboardData: CreateNativeDataObject suceeded.
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/BaseClipboard GetData
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetNativeClipboardData aWhichClipboard=1
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: V/nsClipboard GetNativeClipboardData: use OLE IDataObject.
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetDataFromDataObject
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetNativeDataOffClipboard: overload2
 0:59.11 GECKO(2312) [Parent 11272: Main Thread]: I/nsClipboard S_OK

[...]

 1:04.05 GECKO(2312) [Parent 11272: Main Thread]: V/nsClipboard GetGlobalData
 1:04.15 GECKO(2312) [Parent 11272: Main Thread]: D/BaseClipboard GetData
 1:04.15 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetNativeClipboardData aWhichClipboard=1
 1:04.16 GECKO(2312) [Parent 11272: Main Thread]: V/nsClipboard GetNativeClipboardData: use OLE IDataObject.
 1:04.16 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetDataFromDataObject
 1:04.16 GECKO(2312) [Parent 11272: Main Thread]: D/nsClipboard GetNativeDataOffClipboard: overload2
 1:04.16 GECKO(2312) [Parent 11272: Main Thread]: I/nsClipboard S_OK
 1:04.16 GECKO(2312) [Parent 11272: Main Thread]: I/nsClipboard S_OK
 1:04.16 GECKO(2312) [Parent 11272: Main Thread]: V/nsClipboard GetGlobalData
 1:04.26 FAIL Timed out while polling clipboard for initialized data, got: HelloKitty
    SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
    putAndVerify@SimpleTest/SimpleTest.js:1215:16
 1:04.26 FAIL Error: Timed out while polling clipboard for initialized data, got: HelloKitty - Should not throw any errors

one sees that apparently "SetNativeClipboardData: CreateNativeDataObject suceeded.". That is, it could be that Windows' OleSetClipboard fails. The latter presumption is strengthened by the fact that this and related clipboard tests started failing after the Windows 10 Azure migration (see bug 1726423).

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 7

•

3 years ago

•

Edited

Indeed OleSetClipboard fails. It returns a value different from S_OK, which should've been returned on success (see https://docs.microsoft.com/en-us/windows/win32/api/ole2/nf-ole2-olesetclipboard#return-value).

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 8

•

3 years ago

It returns CLIPBRD_E_CANT_OPEN, which is silently ignored. According to https://docs.microsoft.com/en-us/windows/win32/api/ole2/nf-ole2-olesetclipboard#return-value and https://docs.microsoft.com/en-us/windows/win32/api/winuser/nf-winuser-openclipboard#remarks, this happens when another window has the clipboard opened.

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Updated

•

3 years ago

Priority: P3 → P2

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 9

•

3 years ago

Attached file Bug 1726269: part 1) Repeatedly call `::OleSetClipboard` for the Windows-specific clipboard. r=smaug — Details

Other apps might block the keyboard. There's no clean fix for this, but
this should solve the problem in practice. That's based on the
assumption that other apps cooperate and access the clipboard only for a
short duration.

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 10

•

3 years ago

Attached file Bug 1726269: part 2) Repeatedly call `::OleGetClipboard` for the Windows-specific clipboard. r=smaug — Details

::OleGetClipboard may fail too, therefore call it repeatedely. See
also part 1).

Depends on D125661

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Comment 11

•

3 years ago

Attached file Bug 1726269: part 3) Repeatedly call `IDataObject::GetData` in Windows-specific clipboard code. r=smaug — Details

IDataObject::GetData may fail with CLIPBRD_E_CANT_OPEN, too. See
part 1 of this bug.

Depends on D125662

Pulsebot

Comment 12

•

3 years ago

Pushed by mbrodesser@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/51e5e2b0c2b4
part 1) Repeatedly call `::OleSetClipboard` for the Windows-specific clipboard. r=smaug
https://hg.mozilla.org/integration/autoland/rev/10ecf1a13f7e
part 2) Repeatedly call `::OleGetClipboard` for the Windows-specific clipboard. r=smaug
https://hg.mozilla.org/integration/autoland/rev/00677970b792
part 3) Repeatedly call `IDataObject::GetData` in Windows-specific clipboard code. r=smaug

Narcis Beleuzu [:NarcisB]

Comment 13

•

3 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/51e5e2b0c2b4
https://hg.mozilla.org/mozilla-central/rev/10ecf1a13f7e
https://hg.mozilla.org/mozilla-central/rev/00677970b792

Status: NEW → RESOLVED

Closed: 3 years ago

status-firefox94: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 94 Branch

Mirko Brodesser (:mbrodesser-Igalia), offline until April 25h

Assignee

Updated

•

3 years ago

Blocks: 1703329