Xpra: Ticket #2674: Clipboard local to server failing with OSX client 3.0.7-r25628

Starting a 3.0.7-r25627 server on Fedora 30 with my usual command line, then launching the Xpra-Python3-x86_64-3.0.7-r25628.dmg OSX client from your dists repo... I'm finding I can't copy locally and then paste into the server session.

Connecting the client with -d clipboard, this is all I see, hopefully it means something to you.

2020-03-23 15:38:57,316 client   3 @25.372 timer_clipboard_check() was 17, now 17
2020-03-23 15:38:57,597 client   3 @25.877 timer_clipboard_check() was 17, now 17
2020-03-23 15:38:57,646 client   3 @26.076 process_clipboard_packet: clipboard-request, helper=OSXClipboardProtocolHelper
2020-03-23 15:38:57,646 client   3 @26.077 process clipboard request, request_id=21, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING
2020-03-23 15:38:57,646 client   3 @26.078 get_clipboard_text() NSStringPboardType=12312 gamma st  (<class 'objc.pyobjc_unicode'>)
2020-03-23 15:38:57,653 client   3 @26.079 proxy_got_contents(21, CLIPBOARD, STRING, bytes, 8, <class 'str'>:15) data=0x31323331322067616d6d6120737420..
2020-03-23 15:38:57,654 client   3 @26.079 perform clipboard limit checking - datasize - 15, -1
2020-03-23 15:38:57,683 client   3 @26.080 _munge_raw_selection_to_wire('STRING', 'bytes', 8, "'12312 gamma st '")
2020-03-23 15:38:57,683 client   3 @26.080 _do_munge_raw_selection_to_wire(STRING, bytes, 8, <class 'str'>:15)
2020-03-23 15:38:57,684 client   3 @26.080 clipboard raw -> wire: ('bytes', 8, "'12312 gamma st '") -> '"(b\'bytes\', \'12312 gamma st \')"'
2020-03-23 15:38:57,684 client   3 @26.080 clipboard_send: clipboard-contents
2020-03-23 15:38:57,684 client   3 @26.113 process_clipboard_packet: clipboard-pending-requests, helper=OSXClipboardProtocolHelper
2020-03-23 15:38:57,684 client   3 @26.113 clipboard_progress(None, 1)
2020-03-23 15:38:57,684 client   3 @26.114 clipboard_notify(1) notification timer=None
2020-03-23 15:38:57,724 client   3 @26.158 process_clipboard_packet: clipboard-request, helper=OSXClipboardProtocolHelper
2020-03-23 15:38:57,728 client   3 @26.158 process clipboard request, request_id=22, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING
2020-03-23 15:38:57,729 client   3 @26.159 get_clipboard_text() NSStringPboardType=12312 gamma st  (<class 'objc.pyobjc_unicode'>)
2020-03-23 15:38:57,729 client   3 @26.159 proxy_got_contents(22, CLIPBOARD, STRING, bytes, 8, <class 'str'>:15) data=0x31323331322067616d6d6120737420..
2020-03-23 15:38:57,729 client   3 @26.160 perform clipboard limit checking - datasize - 15, -1
2020-03-23 15:38:57,729 client   3 @26.160 _munge_raw_selection_to_wire('STRING', 'bytes', 8, "'12312 gamma st '")
2020-03-23 15:38:57,758 client   3 @26.160 _do_munge_raw_selection_to_wire(STRING, bytes, 8, <class 'str'>:15)
2020-03-23 15:38:57,758 client   3 @26.161 clipboard raw -> wire: ('bytes', 8, "'12312 gamma st '") -> '"(b\'bytes\', \'12312 gamma st \')"'
2020-03-23 15:38:57,759 client   3 @26.161 clipboard_send: clipboard-contents
2020-03-23 15:38:57,839 client   3 @26.257 process_clipboard_packet: clipboard-pending-requests, helper=OSXClipboardProtocolHelper
2020-03-23 15:38:57,839 client   3 @26.257 clipboard_progress(None, 0)
2020-03-23 15:38:57,840 client   3 @26.257 clipboard_notify(0) notification timer=None
2020-03-23 15:38:57,953 client   3 @26.380 timer_clipboard_check() was 17, now 17

Some quick checking - I find that the clipboard works fine in the other direction (server to local), and multiple copy events or paste events doesn't seem to produce any different results (so it doesn't seem to be a sync timing issue, maybe).

The HTML5 client (on OSX 10.12, using Chrome locally) also has no sign of this problem.



Tue, 24 Mar 2020 10:24:27 GMT - Antoine Martin: owner changed

Weird one, found some issues with macos clipboard target names (obviously they're using their own names here, nothing standard as that would be too easy) and we weren't translating those targets properly or keeping track of the actual target name to use for the response (oops), both bugs are fixed in r25753.

The other problem is that we needed the same workaround as r24248 was for win32, done in r25754. More minor tweaks in r25755.

The only (small) backports to v3.0 for now are r25756 and r25757. (new macos beta build posted) The other changes are all too intrusive, and I will probably just backport the whole module for 3.1.

FYI: there are many clipboard fixes already pulled into 3.0.8, see browser/xpra/tags/v3.0.x/src/NEWS.


Thu, 26 Mar 2020 22:06:04 GMT - alas: owner changed

Went ahead and downloaded the Xpra-Python3-x86_64-4.0-r25756 client... but when I ran a dnf update on the Fedora 30 server, I realized it is still using the stable repo and it didn't update from 3.0.7-r25627.

The local to server clipboard sync (or paste event, possibly) is still failing.

When I copy something locally (with -d clipboard) I see a clipboard ownership change message (I assume).

2020-03-26 14:38:20,700 timer_clipboard_check() was 40, now 40
2020-03-26 14:38:21,202 timer_clipboard_check() was 40, now 41
2020-03-26 14:38:21,203 local_clipboard_changed()
2020-03-26 14:38:21,203 clipboard: CLIPBOARD owner_changed, enabled=True, can-send=True, can-receive=True, have_token=False, greedy_client=False, block_owner_change=False
2020-03-26 14:38:21,704 timer_clipboard_check() was 41, now 41

And, a couple of seconds later, when I try to paste.

2020-03-26 14:38:24,722 timer_clipboard_check() was 41, now 41
2020-03-26 14:38:24,798 process_clipboard_packet: clipboard-request, helper=OSXClipboardProtocolHelper
2020-03-26 14:38:24,798 process clipboard request, request_id=25, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING
2020-03-26 14:38:24,799 get_contents('STRING', <function ClipboardProtocolHelperCore._process_clipboard_request.<locals>.got_contents at 0x10f426e50>)
2020-03-26 14:38:24,799 proxy_got_contents(25, CLIPBOARD, STRING, STRING, 8, <class 'bytes'>:0) data=0x..
2020-03-26 14:38:24,799 _munge_raw_selection_to_wire('STRING', 'STRING', 8, '')
2020-03-26 14:38:24,800 _do_munge_raw_selection_to_wire(STRING, STRING, 8, <class 'bytes'>:0)
2020-03-26 14:38:24,800 clipboard raw -> wire: ('STRING', 8, b'') -> (b'bytes', b'')
2020-03-26 14:38:24,800 clipboard_send: clipboard-contents
2020-03-26 14:38:24,809 process_clipboard_packet: clipboard-pending-requests, helper=OSXClipboardProtocolHelper
2020-03-26 14:38:24,809 clipboard_progress(None, 1)
2020-03-26 14:38:24,809 clipboard_notify(1) notification timer=None
2020-03-26 14:38:24,862 process_clipboard_packet: clipboard-request, helper=OSXClipboardProtocolHelper
2020-03-26 14:38:24,863 process clipboard request, request_id=26, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING
2020-03-26 14:38:24,863 get_contents('STRING', <function ClipboardProtocolHelperCore._process_clipboard_request.<locals>.got_contents at 0x1248d4040>)
2020-03-26 14:38:24,863 proxy_got_contents(26, CLIPBOARD, STRING, STRING, 8, <class 'bytes'>:0) data=0x..
2020-03-26 14:38:24,864 _munge_raw_selection_to_wire('STRING', 'STRING', 8, '')
2020-03-26 14:38:24,864 _do_munge_raw_selection_to_wire(STRING, STRING, 8, <class 'bytes'>:0)
2020-03-26 14:38:24,864 clipboard raw -> wire: ('STRING', 8, b'') -> (b'bytes', b'')
2020-03-26 14:38:24,864 clipboard_send: clipboard-contents
2020-03-26 14:38:24,940 process_clipboard_packet: clipboard-request, helper=OSXClipboardProtocolHelper
2020-03-26 14:38:24,941 process clipboard request, request_id=27, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING
2020-03-26 14:38:24,941 get_contents('STRING', <function ClipboardProtocolHelperCore._process_clipboard_request.<locals>.got_contents at 0x1248d43a0>)
2020-03-26 14:38:24,941 proxy_got_contents(27, CLIPBOARD, STRING, STRING, 8, <class 'bytes'>:0) data=0x..
2020-03-26 14:38:24,942 _munge_raw_selection_to_wire('STRING', 'STRING', 8, '')
2020-03-26 14:38:24,942 _do_munge_raw_selection_to_wire(STRING, STRING, 8, <class 'bytes'>:0)
2020-03-26 14:38:24,943 clipboard raw -> wire: ('STRING', 8, b'') -> (b'bytes', b'')
2020-03-26 14:38:24,943 clipboard_send: clipboard-contents
2020-03-26 14:38:24,976 process_clipboard_packet: clipboard-pending-requests, helper=OSXClipboardProtocolHelper
2020-03-26 14:38:24,977 clipboard_progress(None, 0)
2020-03-26 14:38:24,977 clipboard_notify(0) notification timer=None
2020-03-26 14:38:25,223 timer_clipboard_check() was 41, now 41

Interestingly, in the last set of logs before the changes, I did see the contents of what I was trying to paste in the logs. clipboard raw -> wire: ('bytes', 8, "'12312 gamma st '") -> '"(b\'bytes\', \'12312 gamma st \')"' ... '12312 gamma st' was the clipboard content that was supposed to be sync'ing.

In this case, though, assuming that content should be in the same line of the logs... I'm not seeing the content anymore (which I assume is a step backward?). clipboard raw -> wire: ('STRING', 8, b'') -> (b'bytes', b'') In this test I was trying to paste 'module-x11-publish' into a google search bar to see if my server's failure to open it might be impacting my pulseaudio performance? (A vain attempt at multi-tasking/multi-testing?)

In a mad attempt to compare behaviors... I tried updating the server to 4.0-r25719, then tried to connect the older 4.0-r25654 and 4.0-r25729 clients... both of which hit the library issues (#2672)... and finally going back to the 3.0.7-r25628 I started this ticket with... the paste again failed (but with the to-be-pasted contents displayed in clipboard logs)... but then trying to disconnect I hit an odd error, which you may not care about since it is a 3.0.7 client being used against the 4.0-r25719 server... but the logs:

2020-03-26 14:54:46,119 Error closing connection
2020-03-26 14:54:46,120  local variable 'printer' referenced before assignment
2020-03-26 14:54:46,120 Error processing a 'connection-lost' packet
2020-03-26 14:54:46,120  received from Protocol(None):
2020-03-26 14:54:46,120  using <bound method ServerCore._process_connection_lost of <server.XpraServer object at 0x7fac098a7870 (xpra+x11+server+XpraServer at 0x5556281d2940)>>
Traceback (most recent call last):
  File "/usr/lib64/python3.7/site-packages/xpra/server/server_base.py", line 1022, in process_packet
    handler(proto, packet)
  File "/usr/lib64/python3.7/site-packages/xpra/server/server_core.py", line 1609, in _process_connection_lost
    self.cleanup_protocol(proto)
  File "/usr/lib64/python3.7/site-packages/xpra/server/server_base.py", line 884, in cleanup_protocol
    self.cleanup_source(source)
  File "/usr/lib64/python3.7/site-packages/xpra/server/server_base.py", line 898, in cleanup_source
    source.close()
  File "/usr/lib64/python3.7/site-packages/xpra/server/source/client_connection_factory.py", line 102, in close
    raise Exception("failed to initialize %s: %s" % (bc, e)) from None
Exception: failed to initialize <class 'xpra.server.source.fileprint_mixin.FilePrintMixin'>: local variable 'printer' referenced before assignment

Trying now with the matching newer 4.0-r25719 server and the 4.0-r25756 OSX client... the paste is still failing.

Copy event clipboard debug output.

2020-03-26 15:01:03,011 client   2 @13.524 timer_clipboard_check() was 47, now 47
2020-03-26 15:01:03,513 client   2 @14.027 timer_clipboard_check() was 47, now 48
2020-03-26 15:01:03,514 client   2 @14.027 local_clipboard_changed()
2020-03-26 15:01:03,514 client   2 @14.028 clipboard: CLIPBOARD owner_changed, enabled=True, can-send=True, can-receive=True, have_token=False, greedy_client=False, block_owner_change=False
2020-03-26 15:01:04,017 client   2 @14.531 timer_clipboard_check() was 48, now 48
2020-03-26 15:01:04,517 client   2 @15.033 timer_clipboard_check() was 48, now 48

And... the paste attempt event (still no sign of the expected test - 'The owner will be changed' in the logs).

2020-03-26 15:01:11,184 client   2 @21.695 process_clipboard_packet: clipboard-request, helper=OSXClipboardProtocolHelper
2020-03-26 15:01:11,206 client   2 @21.695 process clipboard request, request_id=2, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING
2020-03-26 15:01:11,207 client   2 @21.696 get_contents('STRING', <function ClipboardProtocolHelperCore._process_clipboard_request.<locals>.got_contents at 0x12deb1160>)
2020-03-26 15:01:11,207 client   2 @21.696 proxy_got_contents(2, CLIPBOARD, STRING, STRING, 8, <class 'bytes'>:0) data=0x..
2020-03-26 15:01:11,207 client   2 @21.696 _munge_raw_selection_to_wire('STRING', 'STRING', 8, '')
2020-03-26 15:01:11,208 client   2 @21.697 _do_munge_raw_selection_to_wire(STRING, STRING, 8, <class 'bytes'>:0)
2020-03-26 15:01:11,208 client   2 @21.697 clipboard raw -> wire: ('STRING', 8, b'') -> (b'bytes', b'')
2020-03-26 15:01:11,208 client   2 @21.697 clipboard_send: clipboard-contents
2020-03-26 15:01:11,208 client   2 @21.723 process_clipboard_packet: clipboard-pending-requests, helper=OSXClipboardProtocolHelper
2020-03-26 15:01:11,215 client   2 @21.724 clipboard_progress(None, 1)
2020-03-26 15:01:11,216 client   2 @21.724 clipboard_notify(1) notification timer=None
2020-03-26 15:01:11,263 client   2 @21.759 process_clipboard_packet: clipboard-request, helper=OSXClipboardProtocolHelper
2020-03-26 15:01:11,263 client   2 @21.760 process clipboard request, request_id=3, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING
2020-03-26 15:01:11,264 client   2 @21.760 get_contents('STRING', <function ClipboardProtocolHelperCore._process_clipboard_request.<locals>.got_contents at 0x12deb10d0>)
2020-03-26 15:01:11,264 client   2 @21.760 proxy_got_contents(3, CLIPBOARD, STRING, STRING, 8, <class 'bytes'>:0) data=0x..
2020-03-26 15:01:11,264 client   2 @21.760 _munge_raw_selection_to_wire('STRING', 'STRING', 8, '')
2020-03-26 15:01:11,264 client   2 @21.761 _do_munge_raw_selection_to_wire(STRING, STRING, 8, <class 'bytes'>:0)
2020-03-26 15:01:11,265 client   2 @21.761 clipboard raw -> wire: ('STRING', 8, b'') -> (b'bytes', b'')
2020-03-26 15:01:11,265 client   2 @21.761 clipboard_send: clipboard-contents
2020-03-26 15:01:11,362 client   2 @21.868 process_clipboard_packet: clipboard-pending-requests, helper=OSXClipboardProtocolHelper
2020-03-26 15:01:11,362 client   2 @21.869 clipboard_progress(None, 0)
2020-03-26 15:01:11,362 client   2 @21.869 clipboard_notify(0) notification timer=None
2020-03-26 15:01:11,553 client   2 @22.069 timer_clipboard_check() was 48, now 48

I do notice you mentioned an r25756 and r25757... but the beta client is only r25756... is it possible r25757 is all that's needed? (And is it expected to be needed server-side?)


Fri, 27 Mar 2020 04:54:31 GMT - Antoine Martin: owner changed

And, a couple of seconds later, when I try to paste. (..) process clipboard request, request_id=26, selection=CLIPBOARD, local name=CLIPBOARD, target=STRING

This looks correct. But you need r25770 or later to handle STRING on the client, or r25769 to handle it on the server. (translation to text/plain)

And... the paste attempt event (still no sign of the expected test - 'The owner will be changed' in the logs).

Changing the contents of the selection is not enough, you have to copy with another application, then with a different one again to trigger a change in the counter:

timer_clipboard_check() was 48, now 48

Until that number changes, we don't do anything. When it does, we claim the clipboard.

Trying now with the matching newer 4.0-r25719 server and the 4.0-r25756 OSX client... the paste is still failing.

Damn.

local variable 'printer' referenced before assignment

Ooops, that had been fixed in trunk by r25605. Now backported to v3 in 25795.

I do notice you mentioned an r25756 and r25757... but the beta client is only r25756... is it possible r25757 is all that's needed? (And is it expected to be needed server-side?)

Yes, I think that's what's happening. I'm uploading newer builds for all platforms.


Wed, 15 Apr 2020 18:47:14 GMT - alas: status changed; resolution set

Sure enough, with a new client - Xpra-Python3-x86_64-3.0.9-r26126 against an updated server, 3.0.9-r26132 ... clipboard is working as expected.

Closing.


Sat, 23 Jan 2021 05:57:45 GMT - migration script:

this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/2674