With osx client r4905 mouse cursor focus seems to become confused when there is a single click on an xpra session window overlapping a second xpra session window.
Testing with windows client (0.11.0r4903) against a fedora 19 server (0.11.0r4904) the erratic cursor/focus behavior does not occur.
In the edited logs that I included in #438 (I'll load those logs into this ticket when I get a chance), there is an initial focus on window 55 (first drawn on line 31 of the log, comes into focus line 139), followed by a focus shift to window 82 (first drawn on line 43, comes into initial focus on line 157, I think)... then there follows what I assume are indications of mouse-wheel scrolling events occurring on window 55 (lines 174 on). That is the 'event'. The logs aren't clear that focus shifted to window 82, from what I can tell, but what I did was to click on 55, then click 82, then click 82 again on a portion of the window which, once 82 'rose' to focus, was now overlapping 55. From then on, I never clicked on window 55 again, nor did I scroll the mouse off of window 82. From the point of line 157 in the log on, my cursor remained hovering over window 82 ... but the mouse scrolling events all seem to register on the lower window (55) despite the appearance of focus being on window 82. Testing this with xterms showed that the keystrokes would register on the apparently focused window, but also that clicking on a portion of an 'upper' window (with apparent focus) which was 'above' a window space with a link would trigger the link 'through' the apparent-focus window.
Edited output from cursor/window focus issue
Full -d all output (--no-speaker) of cursor/window focus test
Moving text from wrong ticket, afarr wrote: "It looks like window focus, as far as the cursor is concerned, is being confused when one xpra session window overlaps another xpra session window (have only tested so far with osx).
If there is an xterm overlapping a chrome window, and the focus is on the chrome window, then the mouse scrolls over to a portion of the xterm window which overlaps the chrome window and the mouse is clicked- then the mouse focus returns to the chrome window (the window that previously had focus) while the focus for the keyboard (as well as the moving to the 'front' display) shifts to the xterm (the window newly clicked on).
At this point, the cursor will display as it would in the window with the cursor focus, the mousewheel will scroll the window with the cursor focus, and clicking will activate any links on the window with the cursor focus ... while keystrokes will register on the top-displayed window which 'should' have focus. (In the case of the example above, keystrokes will register on the xterm that is 'above' the chrome window, while wheel scrolling or link clicking will register on the chrome window which is 'below' the xterm.
Repeating the experiment in various permutations shows the same behavior... shifting from an xterm to a chrome window will reverse the above described behavior; shifting from a firefox window to a chrome window will result in the same behavior, etc.
I am not sure if it is a coincidence, but this seems to be similar to the behavior with pop-up menu behaviors."
Is this a regression? - I am not sure, to be honest. It seems to remain an issue specific to the osx client
Partial answer: "It may be a case of focus-follows-mouse, which may or may not be a bug. OTOH: the top-level window should always have keyboard focus and receive key events (even when the mouse is somewhere else - local platform event delivery allowing), but mouse-wheel and key modifier changes can be delivered to non-top-level windows without raising them to the top."
r5444 adds focus debugging loggers, which means we can get all the focus debug logging (and nothing else), by starting both the client and server with:
xpra -d focus ...
Please post logs of the problematic behaviour, and doing exactly the same thing but on a machine which does not exhibit the problem, hopefully we can spot the difference.
Note: this may also be related to #214, worth checking.
Did the following:
--start-child=xterm
x2) & client session.
xterm
(window[2]
) to the side.
xterm
(window[1]
) & navigated to youtube (lots of handy buttons).
xpra info | grep window window[1].focused=False window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[2].focused=False window[2].position=(1227, 490) window[2].title=jimador@elpatron:~ window[3].focused=False window[3].position=(0, 44) window[3].title=YouTube - Google Chrome
xterm
(window[2]
) back over an area of youtube (window[3]
) that had a button (video link).
window[2]
on area "over" the button - behavior as expected (focus remains on xterm, link not triggered).
window[3]
) - space with no links.
xterm
(window[2]
), "above" button - focus shifts back to window[2]
window[2]
)
window[2]
), "above" link on window[3]
(still within boundaries of window[2]
xterm
).
Attaching client and server debug output.
Client-side -d focus output
Server-side -d focus output
Trying to reproduce the problem with something a bit easier to manage (gnome-calculator
instead of chrome) and moving the xterm over it I got an xpra client crash:
python[21006:10b] *** -[NSCFType convertScreenToBase:]: unrecognized selector sent to instance 0x1b3cf9d0 python[21006:10b] An uncaught exception was raised python[21006:10b] *** -[NSCFType convertScreenToBase:]: unrecognized selector sent to instance 0x1b3cf9d0 python[21006:10b] *** Terminating app due to uncaught exception 'NSInvalidArgumentException', \ reason: '*** -[NSCFType convertScreenToBase:]: unrecognized selector sent to instance 0x1b3cf9d0' 2014-02-14 03:26:17.222 python[21006:10b] Stack: ( 7090155, 10059323, ...
Can you find me an application I can test with more easily? I've tried gnome-calculator
, gedit
and chromium
. I just cannot reproduce the focus problem.
I am a bit unclear on whether this is specific to youtube or if it occurs on other sites, does it require a page using flash?
Does it do that exclusively on OSX? (I have only tested 10.5.8)
I was not able to reproduce this on windows.
I was, however, able to reproduce it with gedit
.
--start-child=gedit --start-child=xterm
) server & client
gedit
(still overlapping xterm
)
xpra info | grep window window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[2].position=(40, 259) window[2].title=Unsaved Document 1 - gedit
gedit
xterm
(above gedit
top menu buttons)
Clipping of server output file at point in time while alt img showing "through" xterm
, but before clicking:
2014-02-14 12:21:07,166 focus wid=2 has_focus=2 2014-02-14 12:21:07,286 focus wid=2 has_focus=2 2014-02-14 12:22:04,266 process_focus: wid=0 2014-02-14 12:22:04,266 focus wid=0 has_focus=2 2014-02-14 12:22:04,266 reset_focus() 2 / WindowModel(0xa00025) had focus 2014-02-14 12:22:04,267 reset_x_focus: widget with focus: None 2014-02-14 12:22:04,267 Take Focus -> world window 2014-02-14 12:22:04,267 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x36c35a0 (GdkWindow at 0x27b2a20)>, 178253574L 2014-02-14 12:22:04,273 process_focus: wid=1 2014-02-14 12:22:04,273 focus wid=1 has_focus=0 2014-02-14 12:22:04,273 focus: giving focus to WindowModel(0x800022) 2014-02-14 12:22:04,273 focus: will set modified mask to ('mod2',) 2014-02-14 12:22:04,274 Giving focus to <gtk.gdk.Window object at 0x7f59ec015280 (GdkWin$ 2014-02-14 12:22:04,274 ... using XSetInputFocus
Immediate server output:
2014-02-14 12:23:36,572 process_focus: wid=0 2014-02-14 12:23:36,572 focus wid=0 has_focus=1 2014-02-14 12:23:36,572 reset_focus() 1 / WindowModel(0x800022) had focus 2014-02-14 12:23:36,572 reset_x_focus: widget with focus: None 2014-02-14 12:23:36,573 Take Focus -> world window 2014-02-14 12:23:36,573 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x36c35a0 (GdkWindow at 0x27b2a20)>, 178345879L 2014-02-14 12:23:36,577 process_focus: wid=2 2014-02-14 12:23:36,577 focus wid=2 has_focus=0 2014-02-14 12:23:36,577 focus: giving focus to WindowModel(0xa00025) 2014-02-14 12:23:36,577 focus: will set modified mask to ('mod2',) 2014-02-14 12:23:36,578 Giving focus to <gtk.gdk.Window object at 0x7f59ec015b90 (GdkWindow at 0x3631360)> 2014-02-14 12:23:36,578 ... using XSetInputFocus 2014-02-14 12:23:36,579 ... using WM_TAKE_FOCUS 2014-02-14 12:23:36,579 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x7f59ec015b90 (GdkWindow at 0x3631360)>, 178345885L (gedit:25104): Gtk-WARNING **: Calling Inhibit failed: GDBus.Error:org.freedesktop.DBus.Err$ 2014-02-14 12:23:36,933 process_focus: wid=0 2014-02-14 12:23:36,933 focus wid=0 has_focus=2 2014-02-14 12:23:36,934 reset_focus() 2 / WindowModel(0xa00025) had focus 2014-02-14 12:23:36,934 reset_x_focus: widget with focus: None 2014-02-14 12:23:36,935 Take Focus -> world window 2014-02-14 12:23:36,935 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x36c35a0 (GdkWindow at 0x27b2a20)>, 178346242L 2014-02-14 12:23:36,950 process_focus: wid=4 2014-02-14 12:23:36,950 focus wid=4 has_focus=0 2014-02-14 12:23:36,950 focus: giving focus to WindowModel(0xa003a2) 2014-02-14 12:23:36,950 focus: will set modified mask to ('mod2',) 2014-02-14 12:23:36,950 focus: giving focus to WindowModel(0xa003a2) 2014-02-14 12:23:36,950 focus: will set modified mask to ('mod2',) 2014-02-14 12:23:36,951 Giving focus to <gtk.gdk.Window object at 0x7f599c0420f0 (GdkWindow at 0x3631d80)> 2014-02-14 12:23:36,951 ... using XSetInputFocus 2014-02-14 12:23:36,953 ... using WM_TAKE_FOCUS 2014-02-14 12:23:36,953 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x7f599c0420f0 (GdkWindow at 0x3631d80)>, 178346258L
Client output for same portion:
2014-02-14 12:23:36,570 focus-out-event for wid=1 2014-02-14 12:23:36,570 _focus_change((<GLClientWindow object at 0x7ab2bc0 (xpra+client+gtk2+client_window+ClientWindow at 0x140$ 2014-02-14 12:23:36,570 update_focus(1, False) _focused=1 2014-02-14 12:23:36,570 send_focus(0) 2014-02-14 12:23:36,571 focus-in-event for wid=2 2014-02-14 12:23:36,571 _focus_change((<GLClientWindow object at 0x7ac0468 (xpra+client+gtk2+client_window+ClientWindow at 0x140$ 2014-02-14 12:23:36,571 update_focus(2, True) _focused=None 2014-02-14 12:23:36,571 send_focus(2) 2014-02-14 12:23:36,574 _unfocus() wid=3 2014-02-14 12:23:36,920 focus-out-event for wid=2 2014-02-14 12:23:36,920 _focus_change((<GLClientWindow object at 0x7ac0468 (xpra+client+gtk2+client_window+ClientWindow at 0x140$ 2014-02-14 12:23:36,921 update_focus(2, False) _focused=2 2014-02-14 12:23:36,921 send_focus(0) 2014-02-14 12:23:36,921 focus-in-event for wid=4 2014-02-14 12:23:36,921 _focus_change((<ClientWindow object at 0x905c5d0 (xpra+client+gtk2+client_window+ClientWindow at 0xf68b2$ 2014-02-14 12:23:36,927 _focus_change(('initial',)) wid=4, has-toplevel-focus=True, _been_mapped=True 2014-02-14 12:23:36,927 update_focus(4, True) _focused=None 2014-02-14 12:23:36,927 send_focus(4) 2014-02-14 12:25:11,883 focus-out-event for wid=4 2014-02-14 12:25:11,884 _focus_change((<ClientWindow object at 0x905c5d0 (xpra+client+gtk2+client_window+ClientWindow at 0xf68b2$ 2014-02-14 12:25:11,884 update_focus(4, False) _focused=4 2014-02-14 12:25:11,884 send_focus(0)
Since there are already full output files from previous test, I will spare you the attachment of more. Let me know if the full output files are liable to be useful though, and I can attach them.
How easy is it to reproduce? I don't understand why I am not seeing it... I don't think virtualbox interferes in my testing. I must be doing it wrong. Maybe a screenshot showing the exact position of the windows would help?
Please include the focus events before the problem manifests itself: by the time the log sample starts, the gedit
window already has the focus (focus wid=2 has_focus=2
). We need to find out why it did get the focus since you said the last click was to focus the xterm
.
Your log samples are truncated just where it gets interesting! (looks like an 80 character limit?) You should redirect to a file if your terminal application is not capable of respecting line width.
The _focus_change
lines in particular are missing the crucial bits of information..
Please also include the "xid" for each window (from xpra info
) so we can try to reconcile this with the value found in the logging for WindowModel
(which sits in a different layer and does not know about window ID).
Newer versions of the server also include the window's xid (for log lines like the WM_TAKE_FOCUS
), which will be useful too.
What looks suspicious so far:
2014-02-14 12:23:36,574 _unfocus() wid=3
- I assume this is one of those tooltips, why does it lose focus if it never had it, odd) - maybe your test showed two tooltips (wid 4 has more details)
-d mouse,focus
" to the server command line
I'm not sure what window 3 was. In this run there were (supposed to be) only 2 xpra windows. I was using a separate machine entirely to pull clippings from the server, so there shouldn't've been any focus shifts to other windows at all. (Note, there are the connection and disconnection messages in the output logs where the other machine queried for xpra info.)
I'll post the entire server log for that run through.
I ran through once more though (without the -d mouse
), to isolate the log info from before I wiggled my mouse sufficiently to pull up the alt-img tag from the menu of the lower window - I'll post that entire log as well, but I'll here note before and after, and I'll also post a before and after screenshot, after including the alt-img showing "through" the xterm.
xpra info | grep window window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[2].position=(49, 186) window[2].title=Unsaved Document 1 - gedit
2014-02-18 11:28:19,356 process_focus: wid=2 2014-02-18 11:28:19,356 focus wid=2 has_focus=0 2014-02-18 11:28:19,356 focus: giving focus to WindowModel(0xa00025) 2014-02-18 11:28:19,356 focus: will set modified mask to ('mod2',) 2014-02-18 11:28:19,356 Giving focus to <gtk.gdk.Window object at 0x26c2b90 (GdkWindow at 0x26bf360)> 2014-02-18 11:28:19,356 ... using XSetInputFocus 2014-02-18 11:28:19,356 ... using WM_TAKE_FOCUS 2014-02-18 11:28:19,356 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x26c2b90 (GdkWindow at 0x26bf360)>, 52062866$
2014-02-18 11:31:28,920 process_focus: wid=0 2014-02-18 11:31:28,920 focus wid=0 has_focus=2 2014-02-18 11:31:28,920 reset_focus() 2 / WindowModel(0xa00025) had focus 2014-02-18 11:31:28,920 reset_x_focus: widget with focus: None 2014-02-18 11:31:28,920 Take Focus -> world window 2014-02-18 11:31:28,921 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x27991e0 (GdkWindow at 0x1840a20)>, 520818227L 2014-02-18 11:31:28,927 process_focus: wid=1 2014-02-18 11:31:28,927 focus wid=1 has_focus=0 2014-02-18 11:31:28,928 focus: giving focus to WindowModel(0x800022) 2014-02-18 11:31:28,928 focus: will set modified mask to ('mod2',) 2014-02-18 11:31:28,928 Giving focus to <gtk.gdk.Window object at 0x26c2280 (GdkWindow at 0x26bf000)> 2014-02-18 11:31:28,928 ... using XSetInputFocus 2014-02-18 11:31:37,760 process_focus: wid=0 2014-02-18 11:31:37,760 focus wid=0 has_focus=1 2014-02-18 11:31:37,760 reset_focus() 1 / WindowModel(0x800022) had focus 2014-02-18 11:31:37,761 reset_x_focus: widget with focus: None 2014-02-18 11:31:37,761 Take Focus -> world window 2014-02-18 11:31:37,761 sending WM_TAKE_FOCUS: <gtk.gdk.Window object at 0x27991e0 (GdkWindow at 0x1840a20)>, 520827067L 2014-02-18 11:31:37,765 process_focus: wid=2 2014-02-18 11:31:37,765 focus wid=2 has_focus=0 2014-02-18 11:31:37,765 focus: giving focus to WindowModel(0xa00025) 2014-02-18 11:31:37,765 focus: will set modified mask to ('mod2',) 2014-02-18 11:31:37,766 Giving focus to <gtk.gdk.Window object at 0x26c2b90 (GdkWindow at 0x26bf360)>
I'll also try to run the same test again with -d mouse, focus
as soon as I get a chance.
First gedit test - server output
Second gedit test (with hints of before focus shift) - server output
screenshot of gedit moved slightly askew from underlying xterm (buttons overlapping)
screenshot after focus shifted to xterm from gedit, mouse wiggled over buttons until alt-img shows through
Using the command dbus-launch xpra --no-daemon --bind-tcp=0.0.0.0:1201 --start-child=xterm --start-child=gedit start :23 -d focus > ticket469-server-output5.txt 2>&1
, I get an xterm window and a gedit window atop that when the client connects.
gedit window pulled askew | focus shift to xterm and wiggled the mouse |
---|---|
Pull it askew enough so that focus can shift to the xterm (but still overlap the save, print, etc. buttons); click to shift focus to the xterm, and then just drag the mouse back and forth a bit over the portion of the xterm that overlaps the buttons. Within a second, two at most, I find an alt-img tag showing through (I can often click the buttons "through" the xterm prior to seeing the alt-img... but the alt-img is a particularly dramatic indication that the buttons are being seen "through" the xterm).
With two windows that each have buttons, the focus issue will work either way, it is not just something occurring with xterms.
Odd, using the command dbus-launch xpra --no-daemon --bind-tcp=0.0.0.0:1201 --start-child=xterm --start-child=gedit start :23 -d focus,mouse > ticket469-server-output6.txt 2>&1
the server output includes the following:
GLib-GIO-Message: Using the 'memory' GSettings backend. Your settings will not be saved or shared with other applications. ** (gedit:10584): WARNING **: AT-SPI: Could not obtain desktop path or name ** (gedit:10584): WARNING **: atk-bridge: get_device_events_reply: unknown signature ** (gedit:10584): WARNING **: atk-bridge: get_device_events_reply: unknown signature ** (gedit:10584): WARNING **: atk-bridge: GetRegisteredEvents returned message with unknown signature ** (gedit:10584): WARNING **: AT-SPI: Could not obtain desktop path or name ** (gedit:10584): WARNING **: AT-SPI: Could not obtain desktop path or name
... and client-side I get:
Traceback (most recent call last): File "<string>", line 1, in <module> File "xpra/scripts/main.pyc", line 62, in main File "xpra/scripts/main.pyc", line 197, in parse_cmdline UnboundLocalError: local variable 'enabled_str' referenced before assignment
... and the client won't connect.
Trying again with just -d mouse
produces the same results.
Just to clarify:
I'm not sure what window 3 was
(...)
I find an alt-img tag showing through
This is not a browser so there are no "alt-img
" tags here.
I believe this is in fact a tooltip window (should have window type set to "TOOLTIP
").
The enabled_str
error is fixed in r5500. The gedit
server side warnings are not new and can safely be ignored - starting the gnome-settings
daemon should fix those.
So... I wasn't being dumb or anything, I have followed your steps exactly and I just cannot reproduce the bug. Which means that I am going to have to figure it out with logs alone.. So please post logs with updated client and server, without forgetting the "xid
" from xpra info
so I can reconcile the logs more easily.
It could be useful to do the exact same steps on a system that does not have the bug (ie: windows or linux) and post the exact same debug log (both client and server for completeness). Something should be different.
Ok, I went through the routine with r5515 with -d focus,mouse
enabled. The first time through I wasn't able to reproduce the bug, but I think I might have just not found the right space for the buttons. Looking at the output with the -d mouse
, I notice that the window xid does indeed seem to have shifted.
window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[1].xid=0x800022 window[2].position=(55, 172) window[2].title=Unsaved Document 1 - gedit window[2].xid=0xa00025
... and part way through the logs I do notice the following:
2014-02-19 12:31:09,320 raising WindowModel(0x800022) 2014-02-19 12:31:09,320 move_pointer(1, (310, 297)) 2014-02-19 12:31:09,360 raising WindowModel(0x800022) 2014-02-19 12:31:09,361 move_pointer(1, (309, 297)) 2014-02-19 12:31:09,522 raising WindowModel(0x800022) 2014-02-19 12:31:09,522 move_pointer(1, (308, 297)) 2014-02-19 12:31:11,141 raising WindowModel(0xa00025) 2014-02-19 12:31:11,142 move_pointer(2, (307, 297)) 2014-02-19 12:31:11,262 raising WindowModel(0xa00025) 2014-02-19 12:31:11,262 move_pointer(2, (306, 297))
I won't post any of the rest of that output, since the test that produced the bug is more interesting.
window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[1].xid=0x800022 window[2].position=(22, 252) window[2].title=Unsaved Document 1 - gedit window[2].xid=0xa00025
2014-02-19 12:34:10,249 ... using WM_TAKE_FOCUS 2014-02-19 12:34:10,249 sending WM_TAKE_FOCUS: 0xa00025, 610979554L 2014-02-19 12:34:18,511 process_focus: wid=2 2014-02-19 12:34:18,511 focus wid=2 has_focus=0 2014-02-19 12:34:18,511 focus: giving focus to WindowModel(0xa00025) 2014-02-19 12:34:18,511 focus: will set modified mask to ('mod2',) 2014-02-19 12:34:18,512 Giving focus to 0xa00025 2014-02-19 12:34:18,512 ... using XSetInputFocus 2014-02-19 12:34:18,512 ... using WM_TAKE_FOCUS 2014-02-19 12:34:18,512 sending WM_TAKE_FOCUS: 0xa00025, 610987818L
2014-02-19 12:35:36,953 raising WindowModel(0x800022) 2014-02-19 12:35:36,954 move_pointer(1, (54, 295)) 2014-02-19 12:35:37,068 raising WindowModel(0x800022) 2014-02-19 12:35:37,068 move_pointer(1, (55, 295)) 2014-02-19 12:35:38,162 raising WindowModel(0xa00025) 2014-02-19 12:35:38,162 move_pointer(2, (56, 295)) 2014-02-19 12:35:38,331 raising WindowModel(0xa00025)
2014-02-19 12:35:42,018 raising WindowModel(0xa00025) 2014-02-19 12:35:42,018 move_pointer(2, (145, 310)) 2014-02-19 12:35:42,019 raising WindowModel(0xa00025) 2014-02-19 12:35:42,020 move_pointer(2, (146, 311)) 2014-02-19 12:35:42,056 raising WindowModel(0xa00025) 2014-02-19 12:35:42,056 move_pointer(2, (146, 313)) 2014-02-19 12:35:42,082 raising WindowModel(0xa00025) 2014-02-19 12:35:42,082 move_pointer(2, (147, 314))
I will attach the entirety of the server-side and client side logs (output11)... and then go through the whole process again with a windows client.
ticket469 server output with -d mouse, focus, osx client
ticket469 osx client output -d focus,mouse
Testing with a windows client, r5515, there isn't much of anything interesting going on.
window[1].position=(8, 30) window[1].title=jimador@elpatron:~ window[1].xid=0x800022 window[2].position=(44, 262) window[2].title=Unsaved Document 1 - gedit window[2].xid=0xa00025
gedit
window moved, but before shifting focus to xterm:
2014-02-19 13:28:13,075 raising WindowModel(0xa00025) 2014-02-19 13:28:13,075 move_pointer(2, (451, 36)) 2014-02-19 13:28:13,076 raising WindowModel(0xa00025) 2014-02-19 13:28:13,076 move_pointer(2, (451, 35)) 2014-02-19 13:28:13,077 raising WindowModel(0xa00025) 2014-02-19 13:28:13,077 move_pointer(2, (450, 35)) 2014-02-19 13:28:13,077 raising WindowModel(0xa00025) 2014-02-19 13:28:13,077 move_pointer(2, (450, 34)) 2014-02-19 13:28:13,162 raising WindowModel(0xa00025) 2014-02-19 13:28:13,162 move_pointer(2, (449, 32))
raising WindowModel()
corresponds to a shift from the xid of the xterm
back to the "underlying" gedit
window).
The question seems to be why the WindowModel? changes... I hope you can see something in this output to give you a hint, because I don't.
Let me know if you need me to resort to a -d all
.
ticket 469 server output with windows client and -d focus,mouse
ticket 469 windows client output with -d focus,mouse (expected behavior)
(Hooray - I can reproduce it)
First, I've edited the samples slightly to remove some cruft that should never have been there (some left over from yesterday's nvenc debugging I forgot to take out, now more permanently removed by r5516 + r5517, and some sound stuff - which you should disable unless it is relevant, which is very doubtful)
Portion of logs where the mouse seems to perceive a shift of window focus
All you have to do to see this, is move over a window then over another one.
There is some confusion here over "focus" and "raising"... The raising of windows isn't the same as the input focus... You can have a window raised (on top of all windows) and it doesn't necessarily have the focus... And a window at the bottom of the stack, may still have the focus. Those are two separate, yet overlapping concepts. We raise the window to ensure that the window which is under the mouse movement is the one that will receive the events.
More on this subject here: wikipedia: Focus (see "focus follows pointer" for example)
The client OS (via GTK) is the one that tells us where the mouse cursor is, and what window received the motion (or click) event. Which brings me to this really puzzling bit:
And the end-portion of the (server-side) logs once the tooltip appears, before clicking on it.
move_pointer(2, (56, 295))
This event is on the gedit
window (window id=2). OSX is telling us at this point that the mouse is *over* gedit
and not the xterm
.
That could be the source of the problems and would be a bug in gtk-osx.
And that finally helped me reproduce the bug: one has to wait for the first gedit
tooltip window to appear before moving the mouse back to the xterm
. This is what causes the bug. Somehow... but now I can investigate properly at least.
On Linux (no bug), here's what I see (sanitized) with: -d mouse,focus,window,-encoding,-refresh
on the server:
move_pointer(2, (226, 221)) raising WindowModel(0xa00029)
Discovered new override-redirect window: 0xa00224 (tray=None)
followed by damage processing and not much else
xterm
:
move_pointer(1, (234, 144)) raising WindowModel(0x800022)
lost_window: 3 - OverrideRedirectWindowModel(0xa00224)
Client side is straightforward:
<class 'xpra.client.gtk2.client_window.ClientWindow'>(\ <XpraClient object at 0x27c8550 (xpra+client+gtk2+client+XpraClient at 0x1f933a0)>, \ <gtk.gdk.Window object at 0x7f72ac5ba280 (GdkWindow at 0x34ca6c0)>, \ 3, 156, 162, 143, 33, {'fullscreen': False, 'has-alpha': True, \ 'xid': '0xa00224', 'pid': 11722, 'window-type': ('TOOLTIP',), \ 'maximized': False, 'override-redirect': True}, \ True, {}, 0)
_unfocus() wid=3
And then I switch over to OSX... and I just cannot reproduce the bug again. WTH? I had made lots of improvements to the debug logging (see r5521), hoping to spot the cause... and now I get nothing! Help!
Heh... I had the same problem my first time running through it again with the logs running. Neglected to have a second machine handy to pull the logs... and after I'd gone to another window to connect and grab info once I had the tooltip up, when I returned to click on the xterm
it behaved properly. I had to click back on the gedit
, then click back on the xterm
, then click on it a second time near the button-overlap region, then mouse around a bit more before I got the cursor to change to an arrow and was able to click through.
In case there's anything useful in that run through, I'll present that info and output files (output13)... followed by a second run through with "cleaner" output logs (output14).
Client & server r5531
(Note, an attempt to fix our libraries to solve the clipboard issue has now broken the ability to start a server with -—start-child=gedit
, so I’m starting with two xterms and using one to create a gedit
instance. The xterm
used to fire up gedit
is the one whose position is obviously well out of the action.)
xpra info | grep windows
window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[1].xid=0xa00022 window[2].position=(475, 953) window[2].title=jimador@elpatron:~ window[2].xid=0x800022 window[3].position=(36, 256) window[3].title=Unsaved Document 1 - gedit window[3].xid=0xc00025
2014-02-21 14:40:45,378 raising WindowModel(0xc00025) 2014-02-21 14:40:45,378 move_pointer(3, (460, 266)) 2014-02-21 14:40:45,397 raising WindowModel(0xc00025) 2014-02-21 14:40:45,397 move_pointer(3, (525, 295)) 2014-02-21 14:40:45,404 raising WindowModel(0xc00025) 2014-02-21 14:40:45,404 move_pointer(3, (643, 349)) 2014-02-21 14:40:47,103 process_focus: wid=0 2014-02-21 14:40:47,103 focus wid=0 has_focus=3 2014-02-21 14:40:47,104 reset_focus() 3 / WindowModel(0xc00025) had focus 2014-02-21 14:40:47,104 reset_x_focus: widget with focus: None 2014-02-21 14:40:47,104 Take Focus -> world window 2014-02-21 14:40:47,104 sending WM_TAKE_FOCUS: 0x40001e, X11 timestamp=1484358L 2014-02-21 14:40:55,570 New connection received: SocketConnection(/home/jimador/.xpra/elpatron.spikes.eng-23) 2014-02-21 14:40:55,570 New connection received: SocketConnection(/home/jimador/.xpra/elpatron.spikes.eng-23) 2014-02-21 14:40:55,573 Connection lost
2014-02-21 14:47:13,813 raising WindowModel(0xc00025) 2014-02-21 14:47:13,813 move_pointer(3, (478, 463)) 2014-02-21 14:47:13,835 raising WindowModel(0xc00025) 2014-02-21 14:47:13,835 move_pointer(3, (549, 509)) 2014-02-21 14:47:13,847 raising WindowModel(0xc00025) 2014-02-21 14:47:13,847 move_pointer(3, (591, 537)) 2014-02-21 14:47:15,141 process_focus: wid=0 2014-02-21 14:47:15,141 focus wid=0 has_focus=1 2014-02-21 14:47:15,141 reset_focus() 1 / WindowModel(0xa00022) had focus 2014-02-21 14:47:15,142 reset_x_focus: widget with focus: None 2014-02-21 14:47:15,142 Take Focus -> world window 2014-02-21 14:47:15,142 sending WM_TAKE_FOCUS: 0x40001e, X11 timestamp=1872396L
xpra info | grep window
window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[1].xid=0x800022 window[2].position=(495, 940) window[2].title=jimador@elpatron:~ window[2].xid=0xa00022 window[3].position=(33, 258) window[3].title=Unsaved Document 1 - gedit window[3].xid=0xc00025
gedit
window, and after pulling the gedit window askew from the underlying xterm
2014-02-21 15:01:39,900 raising WindowModel(0xc00025) 2014-02-21 15:01:39,900 move_pointer(3, (399, 270)) 2014-02-21 15:01:39,929 raising WindowModel(0xc00025) 2014-02-21 15:01:39,929 move_pointer(3, (395, 273)) 2014-02-21 15:01:39,949 raising WindowModel(0xc00025) 2014-02-21 15:01:39,949 move_pointer(3, (394, 275)) 2014-02-21 15:01:39,950 raising WindowModel(0xc00025) 2014-02-21 15:01:39,950 move_pointer(3, (393, 276)) 2014-02-21 15:01:46,676 New connection received: SocketConnection(/home/jimador$ 2014-02-21 15:01:46,676 New connection received: SocketConnection(/home/jimador$ 2014-02-21 15:01:46,679 Connection lost 2014-02-21 15:01:46,685 processing info request from SocketConnection(/home/jim$ 2014-02-21 15:01:46,686 processing info request from SocketConnection(/home/jim$ 2014-02-21 15:01:46,993 Connection lost
2014-02-21 15:03:03,039 raising WindowModel(0xc00025) 2014-02-21 15:03:03,039 move_pointer(3, (221, 309)) 2014-02-21 15:03:03,059 raising WindowModel(0xc00025) 2014-02-21 15:03:03,059 move_pointer(3, (220, 310)) 2014-02-21 15:03:03,089 raising WindowModel(0xc00025) 2014-02-21 15:03:03,089 move_pointer(3, (219, 310)) 2014-02-21 15:03:03,109 raising WindowModel(0xc00025) 2014-02-21 15:03:03,109 move_pointer(3, (216, 311)) 2014-02-21 15:03:03,139 raising WindowModel(0xc00025) 2014-02-21 15:03:03,139 move_pointer(3, (215, 311)) 2014-02-21 15:03:03,140 raising WindowModel(0xc00025) 2014-02-21 15:03:03,140 move_pointer(3, (213, 311)) 2014-02-21 15:03:03,140 raising WindowModel(0xc00025) 2014-02-21 15:03:03,140 move_pointer(3, (213, 311))
server output, near failed run, 2/21 test
client output, near failed run, 2/21 tests
server output, clean run, 2/21 tests
client output, clean run, 2/21 tests
an attempt to fix our libraries to solve the clipboard issue has now broken the ability to start a server with
--start-child
The clipboard issue is client side (OSX), and --start-child
is server side... I don't understand how one could affect the other.
I had to click back on the
gedit
, then click back on...
No amount of clicking allows me to reproduce the bug here. Yesterday it was reliable, today the exact same steps do not work. Weird, and frustrating.
Please post the server logs with the same debug flags as comment:15
And please keep an eye on the client log file as you do it to verify that the window id shown in the move_pointer
events is the one that is meant to be there.
Sorry, didn't fully digest those debug flags (or think to add them to my own run through).
The clipboard issue is client side (OSX), and
--start-child
is server side...
I could have been more precise. For some reason, with our r5531 build that included some library work in an attempt to fix our osx clipboard issues, when I try to connect to a server which has a
--startchild=gedit
with an osx client, thegedit
window fails to properly start, leaving a frame which is non-interactive... and in the process making it impossible to focus on any of the other xpra session windows (xterms, in my case). The server is fine with other clients with a--start-child=xterm
... but with an osx client at the moment, not-so-much.
But that is neither here nor there.
I went through the test case with the newer flags in place. Again, I am running the gedit
out of an xterm
, so there are 3 windows to grep.
xpra info | grep window
window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[1].xid=0x800022 window[2].position=(245, 473) window[2].title=jimador@elpatron:~ window[2].xid=0xc00022 window[2].position=(33, 244) window[2].title=Unsaved Document 1 - gedit window[2].xid=0xa00025
I have commented the points of interest in the logs and will attach both server and client.
server output with -d focus,mouse,window,-encoding,-refresh
client output with -d focus,mouse,window,-encoding,-refresh
Here's what I see happening:
TOOLTIP
window appears:
2014-02-22 09:31:23,393 Discovered new override-redirect window: 0xa00311 (tray=None) 2014-02-22 09:31:23,397 grab: listening for: ['0xa00311L']
2014-02-22 09:33:43,908 lost_window: 4 - OverrideRedirectWindowModel(0xa00311) 2014-02-22 09:33:43,909 grab: unmap
xterm
has lost focus:
2014-02-22 09:33:43,998 process_focus: wid=0 2014-02-22 09:33:43,998 focus wid=0 has_focus=1
gedit
window has gained focus:
2014-02-22 09:33:43,999 process_focus: wid=3 2014-02-22 09:33:44,000 focus wid=3 has_focus=0
I assume the events after that aren't relevant. Hard to tell.
Assuming this is the case, then I don't see too much wrong here (server side), unless the client is wrong about which window has the focus? (the one on top).
It is a little bit odd how this all happens within 100ms.. And why does the xterm
window lose its focus only when the tooltip disappears? More questions than answers.
This log doesn't seem to match the client log, which has a different timeline (Window 4 appears at 09:30:00
in the client log for example). To debug, I need matching logs.
We want to know why the client is telling the server that the xterm
window has lost focus.
I'm not sure it will make much of a difference (still unable to reproduce the bug here), but it is worth trying r5615 (server side change). (it would be more of a workaround than an actual fix since the server only seems to be doing exactly what the client is asking for)
Testing with r5616 client-side and r5618 server-side ... I was able to reproduce the bug, unfortunately.
Both the client-output16 and server-output16 were from the same test... however, a quick check of date
with the server and one of the machines I was using for the test shows a time difference of about a minute and a half (though, I think I was using a different machine for the client-side tests with the 16 output logs, so I'm not certain what the time differences there might be).
I will do a rdate -s time.nist.gov
before doing another run through the tests in order to post some logs that should actually match up timewise (should've checked on how to do that before, yes... oops).
In the meantime, a few words about how I found the points I commented in the output logs. The cleint-side I had streaming with a tail -f
and I went in after the fact to comment following the bits of output I saw at the various points. Meanwhile, on the server side I was using another machine to nano
the output logs and copy the output at the point after whatever action, in order to go back in later and mark the interesting points. Assuming the difference to also be about a minute and a half, the logs do actually seem to match up. (2014-02-22 09:31:22,771
server-side seems to about match up with 2014-02-22 09:30:00,985
client side.)
Since you probably, understandably, don't feel like sorting through that hassle... I'll post matching time logs tomorrow.
server output with syncd time, 2/28 (action starts at 11:49:44,982)
client output, syncd 2/28 (action starts at 11:49:44,954)
Ok, ran a syncd test. Commented within the output logs the interesting points. Note, I was clipping bits of the tailings from the server-side logs after the cursor changed from an xterm style cursor to an arrow... and when I turned back to the client machine, a tooltip had appeared. That point of action on the client-side logs is clearly marked, but the change of cursor, obviously, occurred a couple of seconds before.
In any case, the final piece of the puzzle (we can hope):
xpra info | grep window window[1].position=(0, 44) window[1].title=jimador@elpatron:~ window[1].xid=0xc00022 window[2].position=(919, 972) window[2].title=jimador@elpatron:~ window[2].xid=0xa00022 window[3].position=(28, 238 window[3].title=Unsaved Document 1 - gedit window[3].xid=0x800025
I can't think of anything else to add, except it was, again, server r5618 and client r5616.
I am still unable to reproduce this, and I can't see anything suspicious in the logs (only it gives me a minor headache each time..)
One thing I have noticed is that on every other platform we do get mouse events when the mouse is over one of our windows, even if those windows are not currently focused. On OSX, we get nothing unless an Xpra window has top level focus. This may be related, or even be causing this problem somehow if we are missing some events that normally end up setting the correct window as being on top.
afarr: please re-test trunk, does #589 make any difference? (it might)
You can find a beta build here: http://xpra.org/beta/osx/x86 (made today, also with an updated gtk+ build - I have not tested opengl with it, I hope it doesn't need a rebuild)
Testing with our 0.14.0 r6713 osx build against a fedora 20 0.14.0 r6713 server...
As per ticket:490#comment:10, please provide a short video of how to reproduce this. The platform_window_focus
code in that ticket may be useful here too.
ticket 469 repro movie (8 seconds)
Thanks! I've reproduced it!
Running with full debug and then looking for the point where the new window popped up, then working back up from there I hit:
do_motion_notify_event(<gtk.gdk.Event at 0x19229dd0: GDK_MOTION_NOTIFY x=466.00, y=163.00>) wid=1, pointer=(470, 208), modifiers=['mod2'], buttons=[]
_button_action(1, <gtk.gdk.Event at 0x19229dd0: GDK_BUTTON_PRESS x=466.00, y=163.00, button=1>, True) wid=1, pointer=(470, 208), modifiers=['mod2'], buttons=[] _button_action(1, <gtk.gdk.Event at 0x19229f80: GDK_BUTTON_RELEASE x=466.00, y=163.00, button=1>, False) wid=1, pointer=(470, 208), modifiers=['mod2'], buttons=[1]
do_motion_notify_event(<gtk.gdk.Event at 0x19229dd0: GDK_MOTION_NOTIFY x=183.00, y=35.00>) wid=3, pointer=(470, 209), modifiers=['mod2'], buttons=[]
With nothing relevant in between (just paints). So we tell the server that the window 3 has the focus at that position, it raises it and that's why the click ends up on the wrong window. Looks like a GTK bug on OSX.
r7361 should fix this problem, works-for-me. (could be backported after some time). Problem is that this changes the behaviour of the client on all platforms, not just on OSX. I would much rather not have to add a per-platform check there. So, please test thoroughly with anything that relies on mouse movements and focus, especially on platforms that have had good behaviour all along (mostly *nix) so that this does not cause regressions.
Unfortunately, it's still not working for me.
Testing a 0.14.2-r7389 osx client (both on a 10.6.8 and a 10.9 OS, with --opengl=on
as well as with it blacklisted to off) against a 0.15.0-r7376 fedora 20 server ... I'm still able to reproduce exactly as with the above video.
I assume you don't need any new logs?
afarr: you have not tested the fix. r7361 is a trunk commit, which 0.14.x does not have.
If you do reproduce it with the patch applied (either trunk or backported), please post the log samples containing do_motion_notify_event
and _button_action
as a summary, and maybe the full log attached.
Ahh, I was wondering what had gone wrong.
Testing again with osx 0.15.0-r7416 against a fedora 20 0.15.0-r7416 ... Clicks no longer register "through" the xterm window!!
I am still able to make the cursor change from a "][" to a pointer, and I'm still able to get the underlying window's tooltips window to render... but I see that sort of behavior with local chrome regularly.
I think this is ready to close at last.
Backport to v0.14.x in r7417. Closing.
Not fixed: I have just seen it again. (could be related to #490 ?)
It seems that the first click is registered on the right window (the one in front), but subsequent motion and click events are registered on the wrong one (the one behind) causing us to raise it. We have a workaround for using the focused window id when sending motion events (a really ugly hack), maybe we need the same hack for click events...
r8239 tries to uses the same workaround we already had for motion events, but now also for click events: we ignore the window that GTK tells us the event occurred on and use the one that has focus instead (if there is one - otherwise, we hope that the value is correct..). Sadly, this does not work: we also get a focus event from GTK telling us to focus the window in the background!? Looks to me like this is a GTK bug...
r8652 undoes r8239 for all platforms except osx, as this was causing all sorts of focus / window layer problems. Maybe we should take it out altogether and find a better solution for osx? No idea what that would be though!
Still TODO: limit the scope of this hack, so maybe it won't apply to OR / non-OR windows? (still need to figure out which ones cause problems and in which direction!)
re-scheduling
Milestone renamed
See also ticket:1293#comment:15.
I cannot reproduce this, but then again I struggled at the best of times...
@afarr: I think we should just close this and re-open if we ever manage to reproduce this. (and include "-d mouse,focus" then)
I just reproduced while testing fixes in #770.
Do you want the "-d mouse,focus" on the client, server, or both... sides? (It's currently late, but I seem to have a magic touch for repro'ing this... let me know and I'll get some logs.)
Movie here: attachment/ticket/469/ticket469-repro.mov
Will try again now that I found the movie. Maybe the ugly code in "get_mouse_event_wid" of r13690 is still needed.
A quick note about the movie... it doesn't seem to have shown it, but one sure way to know you'll be able to "click through" a window (in this case the xterm) is to watch for the alt-text popup to appear for the window below when the mouse is "also" hovering over the button below.
reproduced with a button click
I seem to be able to reproduce this more easily by clicking in the window, over the window that should be in the background, from that point onwards the motion events we get from macos come from the wrong window id.
Excerpts from the log above (wid=1 has focus and we click on it, wid=2 should never get any events.. but it does):
do_motion_notify_event(<gtk.gdk.Event at 0x133ac710: GDK_MOTION_NOTIFY x=363.00, y=54.00>) wid=1 / focus=1, device=Core Pointer, pointer=(435, 99), modifiers=['mod2'], buttons=[] _button_action(1, <gtk.gdk.Event at 0x133ac710: GDK_BUTTON_PRESS x=363.00, y=54.00, button=1>, True) wid=1 / focus=1, device=Core Pointer, pointer=(435, 99), modifiers=['mod2'], buttons=[] _button_action(1, <gtk.gdk.Event at 0x1343d650: GDK_BUTTON_RELEASE x=363.00, y=54.00, button=1>, False) wid=1 / focus=1, device=Core Pointer, pointer=(435, 99), modifiers=['mod2'], buttons=[1] do_motion_notify_event(<gtk.gdk.Event at 0x133ac710: GDK_MOTION_NOTIFY x=149.00, y=22.00>) wid=2 / focus=1, device=Core Pointer, pointer=(434, 99), modifiers=['mod2'], buttons=[]
I was hoping that maybe there was a packet or event we were handling between the button click and the next motion notify, but there isn't (was running with "-d all"). So we're not doing anything wrong.
Also spotted this: How to find a window under the cursor: Tracking mouseMoved events works fine for me, there is no problem. But it tells me nothing about the window under the cursor! Events passed to mouseMoved: method contain a pointer to the main window, not the window under the cursor. yep.
So it's pretty bad, I added code to log the gdk window-at-pointer, and it's pretty much always wrong if there are stacked windows.
The macos implementation in _gdk_windowing_window_at_pointer
uses gdk_window_quartz_get_pointer_helper
which then calls find_child_window_helper
(via _gdk_quartz_window_find_child
).
It first calls update_toplevel_order
, then goes through the sorted_children
list of windows.
This function prepends the windows to the list but the orderedwindows API it uses returns front to back... so back will be first?
Solutions:
example code using the window from the notification object
Some posts mention a MacFindWindow
function, but this isn't documented anywhere.
I noticed that we do get focus change events as we click right in the middle of the top level window and that's probably the source of it all. From that point onwards, we're out of sync and no patching can save us.
The events come from _gdk_quartz_events_update_focus_window
which fires from windowDidResignKey (for "focus-out").
It uses the gdk window in scope, I thought that maybe it should be using NSWindow *win = [notification object];
instead so I tried this: attachment/ticket/469/osx-notification-window.c, but that doesn't make any difference to the window being reported in the focus event.
And in any case, these focus events are bogus: we're clicking in the top level window - which already has focus, so no focus events should fire. (what window overlap behind this window should not make any difference at all)
Another interesting thing is that the first click on the overlapping area does not trigger a focus event, but it does change the window that motion events get reported against. The second click triggers even more of a mess by triggering window focus events.
So r13881 takes a rather brutal approach: we detect when the GTK focus is going wrong on osx (ie: when the pointer event is within the area of the current window in focus, but this is not the window it is reported against) and we patch it up:
Unfortunately, GTK is so messed up at that point that we cannot use gtk.Window.present(), which has side effects: it makes the window flicker as we process a brand new map event for every mouse movement... this stops as soon as you move the mouse outside of the window. (maybe we could re-write this using Cython to call makeKeyAndOrderFront directly on the nswindow - assuming we can get the handle of the correct one..)
This workaround can be disabled by running the client with XPRA_OSX_FOCUS_WORKAROUND=0
.
@afarr: this should fix the problem you reported (more than 3 years ago now!), hopefully this nasty fix does not cause more problems than it solves...
Well, tested with osx client 1.0 r13977 against a fedora 23 server 1.0 r13979.
In first test I wasn't able to "click through" my xterm to the gedit window below, but I was also unable to get the gedit window to get any focus at all, even when clicking on it (in this case with a gedit application launched from the start-new-commands
option from the application menu. Noticed an odd xxhash warning on server output (#1331). Haven't been able to repro this, just mention it in case it helps clarify #1331.
Tried again, launching the server with two xterm start childs, and was able to rather promptly click through, though in that event I was able to shift focus as expected (well, until I clicked through).
Repro'd that consistently - client logs are rather brief, but this ticket is messy enough, so I'll attach those as logs, as well as server side logs (note, for server side I connected, set up everything, then disconnected & re-connected client to keep client logs as clean as possible - so the "client 2" portion of the server logs should be where the interesting stuff is... though the use of the start-command to launch the gedit window might be of interest, done with "client 1").
server -d focus logs of a click through (1.0 r13979)
concise client logs of click through (1.0 r13977)
Taking this back: I've undone the change in r15262 because this caused #1453.
The focus problems with GTK on macos are very real, so r15264 takes the "conservative" approach and re-enables the workaround, just not for OR windows (so #1453 remains fixed). r15265 does the same for the v1.0.x branch.
See also the focus workaround in ticket:490#comment:12
I'm closing this because this is probably as good as it is going to get unless GTK2 is fixed, the real long term solution is to move to a better toolkit.
See also ticket:1999#comment:15.
this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/469