xpra icon
Bug tracker and wiki

Opened 4 months ago

Closed 4 months ago

#2649 closed defect (fixed)

clipboard syncing ... again

Reported by: stdedos Owned by: stdedos
Priority: minor Milestone: 4.0
Component: server Version: 3.0.x
Keywords: Cc:

Description (last modified by stdedos)

Continuation from #2603:

I have no concurrent connected xpra sessions on the Windows client - shadow or "gnome-terminal client". Can you identify what's the issue here?

Is there "some way" to keep polling who has/gets the clipboard lock? Kind of like the gtk-keyboard applet.

It does not appear to be shadow-specific. Both of these instances started with: I want to copy from server (in the client, I wanted to copy-paste between Chrome tabs of the same server).

Attachments (2)

xpra-clipboard-logs.log (51.4 KB) - added by stdedos 4 months ago.
xpra-2649-windowspy.png (14.1 KB) - added by stdedos 4 months ago.

Download all attachments as: .zip

Change History (15)

Changed 4 months ago by stdedos

Attachment: xpra-clipboard-logs.log added

comment:1 Changed 4 months ago by stdedos

Description: modified (diff)
Summary: shadow clipboard ... againclipboard syncing ... again

It's a weird request; but I'll go ahead anyway: Can you add diagnostics "of a higher level" than normal diagnostics, that would show:

  • clipboard sync start, origin: server/client, type: text/plain, data: data[100:]
  • clipboard sync done, type: text/plain

or equivalent? I know for you these are not "useful enough"; for me though would give a peace of mind that I did press cut/copy shortcut, and the status is OK/Fail.

Last edited 4 months ago by stdedos (previous) (diff)

comment:2 Changed 4 months ago by stdedos

Description: modified (diff)

comment:3 Changed 4 months ago by Antoine Martin

Owner: changed from Antoine Martin to stdedos

From your logs it looks like we're sending a new token following our own clipboard update, whereas we should just ignore it.
I'm not seeing that on my test system, but it is clearly possible.
Normally the remove_block feature takes care of avoiding this.

Does r25661 improve things? (new beta build available)

Is there "some way" to keep polling who has/gets the clipboard lock?

No, I attempted to implement that, but getting the window title from the hwnd proved futile.

Can you add diagnostics "of a higher level" than normal diagnostics, that would show:

Not really, it's in there already.

clipboard sync start

Two options:

  • the other end is asking for clipboard data: process_clipboard_packet: clipboard-request
  • we have new clipboard data to send: clipboard event: CLIPBOARDUPDATE

followed by clipboard_send: clipboard-contents

clipboard sync done

We have: SetClipboardData(..) done

That's for win32, X11 looks very different.

comment:4 in reply to:  3 ; Changed 4 months ago by stdedos

Description: modified (diff)

Is there "some way" to keep polling who has/gets the clipboard lock?

No, I attempted to implement that, but getting the window title from the hwnd proved futile.

I trust you; I've been trying to enumerate what windows could a PID or any of its parents' own (without starting by iterating through all the windows).

However, "for now", could the list contain PIDs and pid_name? Not as useful, but maybe helpful enough.

"Later", if good ideas come, it could be amended.

Can you add diagnostics "of a higher level" than normal diagnostics, that would show:

Not really, it's in there already.

clipboard sync start

Two options:

  • the other end is asking for clipboard data: process_clipboard_packet: clipboard-request
  • we have new clipboard data to send: clipboard event: CLIPBOARDUPDATE

followed by clipboard_send: clipboard-contents

clipboard sync done

We have: SetClipboardData(..) done

That's for win32, X11 looks very different.

My issue here is that sometimes debug logs raise the cognitive load too much for me when I try to read them.

I mean, you can argue "it's none of your business as end-user" and that's end of discussion.

However, in this context, in this specific situation, it would be much easier for me to see that "yes, I did press Ctrl+C" and something happens, but OOPS. Also, these extra logs are ~200 lines; in my head, would be seeing 2 lines (or 5 or 10 depending on "how" this works).

Last edited 4 months ago by Antoine Martin (previous) (diff)

comment:5 in reply to:  4 ; Changed 4 months ago by Antoine Martin

However, "for now", could the list contain PIDs and pid_name? Not as useful, but maybe helpful enough.

Excellent idea, as of r25666 + r25667, we will now show the pid and name of the process which is updating the clipboard. See latest beta build.

(..)

My issue here is that sometimes debug logs raise the cognitive load too much for me when I try to read them.

It's too much even for me most of the time.
But every detail that is being logged is there because it means something.

Also, these extra logs are ~200 lines; in my head, would be seeing 2 lines (or 5 or 10 depending on "how" this works).

I think that the reason you were getting 200 lines was the bug fixed in comment:3.

Normal clipboard events are 20 lines or so. For example when receiving (simplified pseudo code):

  • route the packet to the clipboard handler
  • parse packet
  • find the callback waiting for this data
  • filter the clipboard targets
  • convert the clipboard data from wire format to native format
  • open OS clipboard (and retry if needed)
  • set value
  • free resources

Every one of these steps does something relevant, and they can all fail or deny / filter the clipboard data.
Without seeing all of those, I risk missing something.

comment:6 in reply to:  5 Changed 4 months ago by stdedos

Replying to Antoine Martin:

However, "for now", could the list contain PIDs and pid_name? Not as useful, but maybe helpful enough.

Excellent idea, as of r25666 + r25667, we will now show the pid and name of the process which is updating the clipboard. See latest beta build.

(..)

Why not pack them in somewhere inside a get_current_clipboard_owner or something?
You could update what it looks like in the future.

I'll download again then, because thing is not fixed.
Again, copy is from server, to be used internally. At least with non-Windows servers, I have the middle-click option (which is safe from "touching", therefore reliably working)


Every one of these steps does something relevant, and they can all fail or deny / filter the clipboard data.
Without seeing all of those, I risk missing something.

But every detail that is being logged is there because it means something.

I trust that it probably does.
I'll just add the other two lines that have being thinking and drop this:

... I risk missing something.

I know, hence my dummy suggestion to

Can you add diagnostics "of a higher level" than normal diagnostics

loglevel INFO_ISH=15 (I don't remember how the python syntax for that is).

I see the massive shitstorm that would come your way to do that for little-to-no benefit to you (hence dropping)

Last edited 4 months ago by Antoine Martin (previous) (diff)

comment:7 in reply to:  3 Changed 4 months ago by stdedos

Replying to Antoine Martin:

From your logs it looks like we're sending a new token following our own clipboard update, whereas we should just ignore it.
I'm not seeing that on my test system, but it is clearly possible.
Normally the remove_block feature takes care of avoiding this.

Does r25661 improve things? (new beta build available)

No :/

2020-03-16 20:35:16,273 clipboard update comes from pid 15728
2020-03-16 20:35:16,275 clipboard update comes from 'C:\Users\user.win\AppData\Local\Vivaldi\Application\vivaldi.exe' with pid 15728
2020-03-16 20:35:16,277 schedule_emit_token() elapsed=385811983 (max=100)
2020-03-16 20:35:16,278 _send_clipboard_token_handler(Win32ClipboardProxy, ())
2020-03-16 20:35:16,279 clipboard_send: clipboard-token
2020-03-16 20:35:16,280 remove_block: CLIPBOARD
2020-03-16 20:35:16,345 process_clipboard_packet: clipboard-request, helper=ClipboardProtocolHelperCore
2020-03-16 20:35:16,349 process clipboard request, request_id=306, selection=CLIPBOARD, local name=CLIPBOARD, target=TARGETS
2020-03-16 20:35:16,350 get_contents('TARGETS', <function ClipboardProtocolHelperCore._process_clipboard_request.<locals>.got_contents at 0x0000000008646f70>)
2020-03-16 20:35:16,351 proxy_got_contents(306, CLIPBOARD, TARGETS, ATOM, 32, <class 'list'>:3) data=0x5b27746578742f706c61696e272c2027746578742f706c61696e3b636861727365743d7574662d38272c2027555446385f535452494e47275d..
2020-03-16 20:35:16,353 _filter_targets(['text/plain', 'text/plain;charset=utf-8', 'UTF8_STRING'])=('text/plain', 'text/plain;charset=utf-8', 'UTF8_STRING')
2020-03-16 20:35:16,354 clipboard raw -> wire: ('ATOM', 32, ['text/plain', 'text/plain;charset=utf-8', 'UTF8_STRING']) -> ('atoms', ('text/plain', 'text/plain;charset=utf-8', 'UTF8_STRING'))
2020-03-16 20:35:16,356 clipboard_send: clipboard-contents
2020-03-16 20:35:16,358 process_clipboard_packet: clipboard-pending-requests, helper=ClipboardProtocolHelperCore
2020-03-16 20:35:16,362 clipboard_progress(None, 1)
2020-03-16 20:35:16,364 clipboard_notify(1) notification timer=None
2020-03-16 20:35:16,500 process_clipboard_packet: clipboard-pending-requests, helper=ClipboardProtocolHelperCore
2020-03-16 20:35:16,503 clipboard_progress(None, 0)
2020-03-16 20:35:16,504 clipboard_notify(0) notification timer=None
2020-03-16 20:35:44,078 process_clipboard_packet: clipboard-token, helper=ClipboardProtocolHelperCore
2020-03-16 20:35:44,080 ignoring token for clipboard 'PRIMARY' (no proxy)
2020-03-16 20:35:44,081 process_clipboard_packet: clipboard-token, helper=ClipboardProtocolHelperCore
2020-03-16 20:35:44,081 ignoring token for clipboard 'PRIMARY' (no proxy)
2020-03-16 20:35:44,082 process_clipboard_packet: clipboard-token, helper=ClipboardProtocolHelperCore
2020-03-16 20:35:44,082 process clipboard token selection=CLIPBOARD, local clipboard name=CLIPBOARD, proxy=Win32ClipboardProxy
2020-03-16 20:35:44,084 wire selection to raw, encoding=bytes, type=STRING, format=8, len(data)=229
2020-03-16 20:35:44,085 got token, selection=CLIPBOARD, targets=(b'STRING', b'UTF8_STRING', b'text/plain', b'TEXT'), target data={'STRING': ('STRING', 8, b'http://clip-url')}, claim=True, can-receive=True
2020-03-16 20:35:44,086 _filter_targets((b'STRING', b'UTF8_STRING', b'text/plain', b'TEXT'))=('STRING', 'UTF8_STRING', 'text/plain', 'TEXT')
2020-03-16 20:35:44,087 _filter_targets((b'STRING', b'UTF8_STRING', b'text/plain', b'TEXT'))=('STRING', 'UTF8_STRING', 'text/plain', 'TEXT')
2020-03-16 20:35:44,089 got_contents: tell OS we have STRING, UTF8_STRING, text/plain, TEXT
2020-03-16 20:35:44,094 we got a byte string: b'http://clip-url'
2020-03-16 20:35:44,095 MultiByteToWideChar wlen=229
2020-03-16 20:35:44,096 GlobalAlloc buf=0x8d70078
2020-03-16 20:35:44,097 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646280>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646040>, 10, 10)
2020-03-16 20:35:44,099 OpenClipboard(0xa095e)=1
2020-03-16 20:35:44,121 SetClipboardData(..) done
2020-03-16 20:35:44,123 <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646280>()=True
2020-03-16 20:35:44,125 process_clipboard_packet: clipboard-token, helper=ClipboardProtocolHelperCore
2020-03-16 20:35:44,126 process clipboard token selection=CLIPBOARD, local clipboard name=CLIPBOARD, proxy=Win32ClipboardProxy
2020-03-16 20:35:44,128 wire selection to raw, encoding=bytes, type=STRING, format=8, len(data)=229
2020-03-16 20:35:44,129 got token, selection=CLIPBOARD, targets=(b'STRING', b'UTF8_STRING', b'text/plain', b'TEXT'), target data={'STRING': ('STRING', 8, b'http://clip-url')}, claim=True, can-receive=True
2020-03-16 20:35:44,130 _filter_targets((b'STRING', b'UTF8_STRING', b'text/plain', b'TEXT'))=('STRING', 'UTF8_STRING', 'text/plain', 'TEXT')
2020-03-16 20:35:44,134 _filter_targets((b'STRING', b'UTF8_STRING', b'text/plain', b'TEXT'))=('STRING', 'UTF8_STRING', 'text/plain', 'TEXT')
2020-03-16 20:35:44,135 got_contents: tell OS we have STRING, UTF8_STRING, text/plain, TEXT
2020-03-16 20:35:44,137 we got a byte string: b'http://clip-url'
2020-03-16 20:35:44,138 MultiByteToWideChar wlen=229
2020-03-16 20:35:44,140 GlobalAlloc buf=0x8d70078
2020-03-16 20:35:44,141 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 10, 10)
2020-03-16 20:35:44,142 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,147 clipboard event: CLIPBOARDUPDATE, owner=657758, our window=657758
2020-03-16 20:35:44,148 remove_block: CLIPBOARD
2020-03-16 20:35:44,158 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 9, 15)
2020-03-16 20:35:44,159 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,176 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 8, 20)
2020-03-16 20:35:44,177 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,201 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 7, 25)
2020-03-16 20:35:44,204 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,231 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 6, 30)
2020-03-16 20:35:44,234 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,265 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 5, 35)
2020-03-16 20:35:44,268 OpenClipboard(0xa095e)=1
2020-03-16 20:35:44,280 clipboard event: DESTROYCLIPBOARD, owner=657758, our window=657758
2020-03-16 20:35:44,292 <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>()=False
2020-03-16 20:35:44,294 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,296 clipboard event: CLIPBOARDUPDATE, owner=657758, our window=657758
2020-03-16 20:35:44,331 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 4, 40)
2020-03-16 20:35:44,334 OpenClipboard(0xa095e)=1
2020-03-16 20:35:44,345 clipboard event: DESTROYCLIPBOARD, owner=657758, our window=657758
2020-03-16 20:35:44,357 <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>()=False
2020-03-16 20:35:44,358 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,360 clipboard event: CLIPBOARDUPDATE, owner=657758, our window=657758
2020-03-16 20:35:44,401 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 3, 45)
2020-03-16 20:35:44,404 OpenClipboard(0xa095e)=1
2020-03-16 20:35:44,416 clipboard event: DESTROYCLIPBOARD, owner=657758, our window=657758
2020-03-16 20:35:44,428 <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>()=False
2020-03-16 20:35:44,429 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,432 clipboard event: CLIPBOARDUPDATE, owner=657758, our window=657758
2020-03-16 20:35:44,477 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 2, 50)
2020-03-16 20:35:44,480 OpenClipboard(0xa095e)=1
2020-03-16 20:35:44,492 clipboard event: DESTROYCLIPBOARD, owner=657758, our window=657758
2020-03-16 20:35:44,504 <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>()=False
2020-03-16 20:35:44,505 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,507 clipboard event: CLIPBOARDUPDATE, owner=657758, our window=657758
2020-03-16 20:35:44,558 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 1, 55)
2020-03-16 20:35:44,561 OpenClipboard(0xa095e)=1
2020-03-16 20:35:44,573 clipboard event: DESTROYCLIPBOARD, owner=657758, our window=657758
2020-03-16 20:35:44,585 <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>()=False
2020-03-16 20:35:44,586 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,588 clipboard event: CLIPBOARDUPDATE, owner=657758, our window=657758
2020-03-16 20:35:44,644 with_clipboard_lock(<function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>, <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_error at 0x0000000008646280>, 0, 60)
2020-03-16 20:35:44,647 OpenClipboard(0xa095e)=1
2020-03-16 20:35:44,659 clipboard event: DESTROYCLIPBOARD, owner=657758, our window=657758
2020-03-16 20:35:44,671 <function Win32ClipboardProxy.set_clipboard_text.<locals>.set_clipboard_data at 0x0000000008646160>()=False
2020-03-16 20:35:44,673 OpenClipboard(0xa095e)=[WinError 0] The operation completed successfully., owner=0xa095e
2020-03-16 20:35:44,674 set_clipboard_error(OpenClipboard: too many failed attempts, giving up)
2020-03-16 20:35:44,676 Warning: failed to set clipboard data
2020-03-16 20:35:44,678  OpenClipboard: too many failed attempts, giving up
2020-03-16 20:35:44,680 clipboard event: CLIPBOARDUPDATE, owner=657758, our window=657758
2020-03-16 20:35:44,682 remove_block: CLIPBOARD

comment:8 Changed 4 months ago by stdedos

However, "for now", could the list contain PIDs and pid_name? Not as useful, but maybe helpful enough.

I did call it:

2020-03-16 21:39:11,155 clipboard update comes from 'C:\Users\user.win\AppData\Local\AutoHotkey\AutoHotkey.exe' with pid 3600

That solves half of my mystery: I have a script trying to infer file's full path when "copied" via Ctrl+Shift+C from explorer.exe (which obviously interferes with Terminal-Copy). I'll fix my script to ignore that.

Could you change your windows' ahk_class? I'd prefer not to depend on ahk_exe filename if possible.


Sadly, I don't have much knowledge what does that mean; but I am confident enough AutoHotKey is not "inventing" that class; a lot of AHK namespacing starts with A_, ahk_.

Changed 4 months ago by stdedos

Attachment: xpra-2649-windowspy.png added

comment:9 Changed 4 months ago by Antoine Martin

Owner: changed from stdedos to Antoine Martin
Status: newassigned

By looking at the log sample from comment:7, I found a way to reproduce your problem. We get two clipboard requests within 50ms of each other (and with exactly the same value - not sure what's happening here: it could be a server bug, or an application doing something odd):

2020-03-16 20:35:44,094 we got a byte string: b'http://clip-url'
...
2020-03-16 20:35:44,137 we got a byte string: b'http://clip-url'

And for some reason, the win32 API doesn't like doing this.
I can reproduce using this simple command in an xterm:

echo foo | xclip -i -selection CLIPBOARD;echo bar | xclip -i -selection CLIPBOARD;

Adding a small delay between the first and second command "fixes" the problem.
There's no difference between our first attempt to update the clipboard and the subsequent ones:

  • OpenClipboard
  • EmptyClipboard
  • SetClipboardData - this one fails with The handle is not valid

I'm stumped.

(r25668 improves the debug logging)

Could you change your windows' ahk_class? I'd prefer not to depend on ahk_exe filename if possible.

Can you please create a separate ticket for this?

Last edited 4 months ago by Antoine Martin (previous) (diff)

comment:10 in reply to:  9 Changed 4 months ago by stdedos

I do feel that "somewhat recently" server may get stuck when pressing a "character" key.
But I am too afraid to report it, considering the amount of logging required, and the low/random reproducibility of seeing that. I have ended up typing brrrrrrrrrrrrrrrrrrrreak not by my own will.

Could you change your windows' ahk_class? I'd prefer not to depend on ahk_exe filename if possible.

Can you please create a separate ticket for this?

#2652

Last edited 4 months ago by Antoine Martin (previous) (diff)

comment:11 Changed 4 months ago by Antoine Martin

I do feel that "somewhat recently" server may get stuck when pressing a "character" key.

Until recently, keyboard-sync was not being honoured due to a bug. Try turning it off.

comment:12 Changed 4 months ago by Antoine Martin

Owner: changed from Antoine Martin to stdedos
Status: assignednew

The fix turned out to be simple: r25669.

Works-for-me(tm).

comment:13 Changed 4 months ago by stdedos

Resolution: fixed
Status: newclosed

Works like a charm :-D Thank you.

keyboard-sync felt less broken when it was broken :-p I'll keep disabling it for now I guess

Note: See TracTickets for help on using tickets.