Server on Centos7 r20582 Client both Python and HTML on Windows r20582 Can't reproduce outside Xpra.
When trying to open a window in a Java application the window "randomly" closes.
Both logs below show a "loading" window (win 16, 8) closing as it should, however the 1st log shows the next window (win 17) closing when it shouldn't.
Server Log (debug=window) with window closing early
do_xpra_unmap_event(<X11:UnmapNotify {'delivered_to': u'0xc0023c', 'send_event': '0', 'window': u'0xc0023c', 'serial': '0x2ae1', 'type': '18', 'display': ':0'}>) client window unmapped, last_unmap_serial=0x0 remove_window: 16 - WindowModel(0xc0023c) cancel_damage() wid=16, dropping delayed region (4071565.833320778, [R(158, 19, 6, 18)], 'rgb', {}), 0 queued encodes, and all sequences up to 33 encoding_totals for wid=16 with primary encoding=rgb : {'rgb24': [16, 54664]} unmanaging window: WindowModel(0xc0023c) (<gtk.gdk.Window object at 0x7fc3d4114d70 (GdkWindow at 0x135cd80)> - <gtk.gdk.Window object at 0x7fc3d4114690 (GdkWindow at 0x1372240)>) Window.do_unmanaged(False) damage_forward_handle=674, composite=CompositeHelper(0xc0023c) encode_ended() close_damage_handle() invalidating named pixmap, contents handle=PixmapWrapper(0x4000f1, 260, 82) invalidating named pixmap, contents handle=None scrub_x11() x11 properties=['WM_STATE', '_NET_FRAME_EXTENTS', '_NET_WM_ALLOWED_ACTIONS'] Property changed on 0xc0024f: _NET_WM_ALLOWED_ACTIONS Property changed on 0xc0024f: XdndAware Property changed on 0xc0024f: _NET_FRAME_EXTENTS Property changed on 0xc0024f: _NET_WM_STATE Property changed on 0xc0024f: WM_STATE invalidating named pixmap, contents handle=None Property changed on 0xc0024f: WM_NORMAL_HINTS WM_NORMAL_HINTS={u'position': (-19, 0), u'win_gravity': 1, u'size': (1387, 1117)} updateprop(size-hints, {u'position': (-19, 0), 'gravity': 1, u'size': (1387, 1117)}) previous value={u'position': (-19, 0), 'minimum-size': (690, 470), 'gravity': 1, u'size': (1393, 1125)} _update_client_geometry: ignored, owner=None, setup_done=True _do_update_client_geometry: allocated 1393x1125 (from <function window_size at 0x7fc3d41c0f50>) _do_update_client_geometry: size({u'position': (-19, 0), 'gravity': 1, u'size': (1387, 1117)})=1393x1125 _do_update_client_geometry: position=-19x0 (from <function window_position at 0x7fc3d6954ed8>) updateprop(geometry, (-19, 0, 1393, 1125)) unchanged do_xpra_unmap_event(<X11:UnmapNotify {'delivered_to': u'0xc0024f', 'send_event': '0', 'window': u'0xc0024f', 'serial': '0x2b21', 'type': '18', 'display': ':0'}>) client window unmapped, last_unmap_serial=0x0 remove_window: 17 - WindowModel(0xc0024f) cancel_damage() wid=17, dropping delayed region None, 0 queued encodes, and all sequences up to 1 encoding_totals for wid=17 with primary encoding=rgb : {} unmanaging window: WindowModel(0xc0024f) (<gtk.gdk.Window object at 0x7fc3d413d0a0 (GdkWindow at 0x1372360)> - <gtk.gdk.Window object at 0x7fc3d4142e10 (GdkWindow at 0x135ca20)>) encode_ended() Window.do_unmanaged(False) damage_forward_handle=720, composite=CompositeHelper(0xc0024f) close_damage_handle()
Server Log (debug=window) with window opening correctly
do_xpra_unmap_event(<X11:UnmapNotify {'delivered_to': u'0xc0011d', 'send_event': '0', 'window': u'0xc0011d', 'serial': '0x194a', 'type': '18', 'display': ':0'}>) client window unmapped, last_unmap_serial=0x0 remove_window: 8 - WindowModel(0xc0011d) cancel_damage() wid=8, dropping delayed region None, 0 queued encodes, and all sequences up to 21 encoding_totals for wid=8 with primary encoding=rgb : {'rgb24': [10, 51532]} unmanaging window: WindowModel(0xc0011d) (<gtk.gdk.Window object at 0x7fc3d646c820 (GdkWindow at 0x135c5a0)> - <gtk.gdk.Window object at 0x7fc3d41611e0 (GdkWindow at 0x135c480)>) encode_ended() couldn't TranslateCoordinates (maybe window is gone) Window.do_unmanaged(False) damage_forward_handle=346, composite=CompositeHelper(0xc0011d) close_damage_handle() invalidating named pixmap, contents handle=PixmapWrapper(0x4000a8, 260, 82) invalidating named pixmap, contents handle=None scrub_x11() x11 properties=['WM_STATE', '_NET_FRAME_EXTENTS', '_NET_WM_ALLOWED_ACTIONS'] Property changed on 0xc00134: _NET_FRAME_EXTENTS Property changed on 0xc00134: WM_NAME _NET_WM_NAME=WinTitle updateprop(title, WinTitle) unchanged Property changed on 0xc00134: _NET_WM_NAME _NET_WM_NAME=WinTitle updateprop(title, WinTitle) unchanged Property changed on 0xc00134: WM_ICON_NAME _NET_WM_ICON_NAME=WinTitle updateprop(icon-title, WinTitle) unchanged Property changed on 0xc00134: _NET_WM_ICON_NAME _NET_WM_ICON_NAME=WinTitle updateprop(icon-title, WinTitle) unchanged get(override-redirect, False) returning default value=False get(tray, False) returning default value=False damage(6, 154, 605, 69, {}) wid=5, using existing delayed {} regions created 0.2ms ago WindowModel.do_xpra_configure_event(<X11:ConfigureNotify {'delivered_to': u'0xc00134', 'send_event': '0', 'height': '1125', 'width': '1393', 'window': u'0xc00134', 'above': '0', 'y': '0', 'x': '-7', 'serial': '0x197d', 'border_width': '0', 'type': '22', 'display': ':0'}>) corral=0x4000ac, client=0xc00134, managed=True WindowModel.do_xpra_configure_event: corral window is not visible invalidating named pixmap, contents handle=None WindowModel.do_xpra_configure_event(<X11:ConfigureNotify {'delivered_to': u'0xc00134', 'send_event': '0', 'height': '1117', 'width': '1387', 'window': u'0xc00134', 'above': '0', 'y': '0', 'x': '-7', 'serial': '0x198e', 'border_width': '0', 'type': '22', 'display': ':0'}>) corral=0x4000ac, client=0xc00134, managed=True WindowModel.do_xpra_configure_event: corral window is not visible invalidating named pixmap, contents handle=None
Interestingly adding debug=window seems to decrease the chances of the window closing incorrectly. So I'm guessing there's some kind of race codition here.
Please provide a sample Java application I can test against.
It's a 3rd party application but I'll try and reproduce, it'll probably be a few days though.
Test Jar and Source
I've attached a test case. To run java -jar windowVisible.jar.
The expectation here is that the window should be visible almost all the time as setVisible(true) is immediately after setVisible(false) and the 3 second delay is while the window is visible.
What I'm seeing is that the window will sometimes remain not visible for the 3 seconds instead.
If I add a slight delay between the two commands (Thread.sleep(50);) then the window behaves as expected (very small time not visible, 3 seconds visible).
window.frame.setVisible(false); //Thread.sleep(50); window.frame.setVisible(true); Thread.sleep(3000);
I am afraid that this is probably unavoidable: the client and server are not synchronized, you're triggering the iconification loop avoidance code (r8352 / #790). The server tells the client to minimize the window, by the time it has done so and tells the server to make it minimized, the server has restored it - who is correct, I don't think we can tell. The delay introduced by that fix is there to ensure we don't flip back and forth forever.
Thanks, I'll look into a bit and get back if I can figure something out. The 50ms delay was a very lucky guess then :)
I was wrong in comment:4, maybe this does not involve the client, or at least not directly.
Got this log with -d window,x11,state
:
parse_event(..)=<X11:CreateNotify {'delivered_to': u'0x299', 'send_event': '0', \ 'height': '1', 'width': '1', 'window': u'0xe00008', 'serial': '0x9fd', 'type': '16', 'display': ':15'}> do_child_configure_request_event(<X11:ConfigureRequest {'delivered_to': u'0x299', \ 'send_event': '0', 'type': '23', 'detail': '0', 'height': '270', 'width': '440', \ 'window': u'0xe00007', 'above': '0', 'y': '100', 'x': '100', 'serial': '0xa09', \ 'border_width': '0', 'value_mask': '64', 'display': ':15'}>) value_mask=StackMode, \ reconfigure on withdrawn window parse_event(..)=<X11:MapRequest {'delivered_to': u'0x299', 'send_event': '0', \ 'window': u'0xe00007', 'serial': '0xa09', 'type': '20', 'display': ':15'}> initial X11 position and size: requested((100, 100, 440, 270), \ {u'position': (100, 100), 'gravity': 1, u'size': (440, 270)})=(100, 100, 440, 270) client @19.030 make_new_window(..) window(2)=GLClientWindow(2 : gtk3.GLDrawingArea(2, (440, 270), None))
do_child_configure_request_event(<X11:ConfigureRequest {'delivered_to': u'0x40003c', \ 'send_event': '0', 'type': '23', 'detail': '0', 'height': '263', 'width': '450', \ 'window': u'0xe00007', 'above': '0', 'y': '0', 'x': '0', 'serial': '0xa6e', \ 'border_width': '0', 'value_mask': '12', 'display': ':15'}>) client=0xe00007, \ corral=0x40003c, value_mask=Width|Height, size-hints={u'position': (100, 100), \ 'gravity': 1, u'size': (450, 263)} #(and same again for X|Y)
_NET_WM_STATE
message:
process_client_message_event(<X11:ClientMessage {'delivered_to': u'0xe00007', 'send_event': \ '1', 'format': '32', 'data': '(0, 247, 0, 0, 0)', 'window': u'0xe00007', 'type': '33', \ 'serial': '0xa6e', 'message_type': '_NET_WM_STATE', 'display': ':15'}>) window above=False after REMOVE (current state=False)
WindowModel.do_xpra_configure_event(<X11:ConfigureNotify {'delivered_to': u'0xe00007', \ 'send_event': '0', 'height': '263', 'width': '450', 'window': u'0xe00007', \ 'above': '0', 'y': '100', 'x': '100', 'serial': '0xa97', 'border_width': '0', \ 'type': '22', 'display': ':15'}>) corral=0x40003c, client=0xe00007, managed=True WindowModel.do_xpra_configure_event: corral window is not visible
487 do_xpra_unmap_event(<X11:UnmapNotify {'delivered_to': u'0xe00007', 'send_event': '0', \ 'window': u'0xe00007', 'serial': '0xb44', 'type': '18', 'display': ':15'}>) \ client window unmapped, last_unmap_serial=0x0
509 parse_event(..)=<X11:MapRequest {'delivered_to': u'0x40003c', 'send_event': '0', \ 'window': u'0xe00007', 'serial': '0xb47', 'type': '20', 'display': ':15'}> 510 parse_event(..)=<X11:ReparentNotify {'delivered_to': u'0xe00007', 'send_event': '0', \ 'window': u'0xe00007', 'serial': '0xb50', 'type': '21', 'display': ':15'}> 519 do_child_configure_request_event(<X11:ConfigureRequest {'delivered_to': u'0x299', \ 'send_event': '0', 'type': '23', 'detail': '0', 'height': '263', 'width': '450', \ 'window': u'0xe00007', 'above': '0', 'y': '0', 'x': '0', 'serial': '0xb59', \ 'border_width': '0', 'value_mask': '12', 'display': ':15'}>) \ value_mask=Width|Height, reconfigure on withdrawn window #(and same again for X|Y)
We ignore the map request and the window stays hidden. This note seems relevant:
def do_child_map_request_event(self, event): # If we get a MapRequest then it might mean that someone tried to map # this window multiple times in quick succession, before we actually # mapped it (so that several MapRequests ended up queued up; FSF Emacs # 22.1.50.1 does this, at least). It alternatively might mean that # the client is naughty and tried to map their window which is # currently not displayed. In either case, we should just ignore the # request. log("do_child_map_request_event(%s)", event)
parse_event(..)=<X11:MapRequest {'delivered_to': u'0x299', 'send_event': '0', 'window': u'0xe00007', 'serial': '0xb5b', 'type': '20', 'display': ':15'}> Found a potential client new window 0xe00007
So the problem seems to come from us ignoring a valid MapRequest
?
Yes, this seems more likely as I could also reproduce on the html client but less likely to happen and disabling the iconify functionality didn't help. I'll continue on this path.
With XPRA_X11_DEBUG_EVENTS=MapRequest xpra start ...
, we can see:
021 parse_event(..)=<X11:MapRequest {'delivered_to': u'0x40003d', 'send_event': '0', \ 'window': u'0x1000007', 'serial': '0xa09', 'type': '20', 'display': ':15'}> 021 MapRequest event 0xa09 : <X11:MapRequest {'delivered_to': u'0x40003d', 'send_event': '0', \ 'window': u'0x1000007', 'serial': '0xa09', 'type': '20', 'display': ':15'}> 021 delivering event to parent window: 0x40003d (signal=child-map-request-event) 022 no handler registered for parent window 0x40003d (None), ignoring event 022 no handler registered for fallback (None), ignoring event 022 no handler registered for catchall (None), ignoring event 022 x_event_filter event=(None, u'child-map-request-event')/MapRequest took 1.9ms 022 x_event_filter event=(u'xpra-reparent-event', None)/ReparentNotify window=0x1000007 022 parse_event(..)=<X11:ReparentNotify {'delivered_to': u'0x1000007', 'send_event': '0', 'window': u'0x1000007', 'serial': '0xa12', 'type': '21', 'display': ':15'}> 023 x_event_filter event=(u'xpra-reparent-event', None)/ReparentNotify took 0.6ms 026 parse_event(..)=<X11:UnmapNotify {'delivered_to': u'0x299', 'send_event': '0', \ 'window': u'0x400039', 'serial': '0x95b', 'type': '18', 'display': ':15'}>
So the window is in the process of being unreparented (all happening within 1ms) when we get the MapRequest
.
The corral window (0x400039
) is destroyed at that point, just pending the notification..
The window tree looks like this (xwininfo -tree -root
, the xterm and other utility windows can be ignored:
xwininfo: Window id: 0x299 (the root window) "Xpra" Root window id: 0x299 (the root window) "Xpra" Parent window id: 0x0 (none) 14 children: 0x400039 "Xpra-CorralWindow-0x1000007": () 450x263+100+100 +100+100 1 child: 0x1000007 " ": ("sun-awt-X11-XFramePeer" "Main") 450x263+0+0 +100+100 2 children: 0x100001f "FocusProxy": ("Focus-Proxy-Window" "FocusProxy") 1x1+-1+-1 +99+99 0x100001c "Content window": ("sun-awt-X11-XContentWindow" "Main") 450x300+0+-37 +100+63 0x1000008 "Main": ("Main" "Main") 1x1+1+1 +1+1 0xe00001 "Xpra Audio record": ("Xpra-Audio-record" "Xpra-Audio-record") 10x10+10+10 +10+10 0x40002b "Xpra-CorralWindow-0xc00022": () 499x316+0+71 +0+71 1 child: 0xc00022 "antoine@desktop:~/Downloads/WindowVisible": ("xterm" "XTerm") 499x316+0+0 +0+71 1 child: 0xc0002d (has no name): () 499x316+0+0 +0+71 1 child: 0xc00033 (has no name): () 14x316+-1+-1 +-1+70 0x400026 (has no name): () 1x1+-1+-1 +-1+-1 0x400022 "Xpra-SystemTray": () 1x1+0+0 +0+0 1 child: 0x400023 (has no name): () 1x1+-1+-1 +-1+-1 0x400020 "Xpra": () 10x10+-100+-100 +-100+-100 0x40001f "Xpra": () 10x10+-100+-100 +-100+-100 0x40001e "Xpra": () 10x10+-100+-100 +-100+-100 0x40001b "Xpra-WorldWindow": ("xpra" "Xpra") 7680x2560+0+0 +0+0 1 child: 0x40001c (has no name): () 1x1+-1+-1 +-1+-1 0x40001a "Xpra": () 1x1+0+0 +0+0 0x400003 "Xpra-ManagerSelection": () 10x10+-100+-100 +-100+-100 0x400001 "xpra": ("xpra" "Xpra") 10x10+10+10 +10+10 1 child: 0x400002 (has no name): () 1x1+-1+-1 +9+9 0x200001 "xpra": ("xpra" "Xpra") 10x10+10+10 +10+10 1 child: 0x200002 (has no name): () 1x1+-1+-1 +9+9
r20637 looks like the right fix for this, it is a race condition to do with reparenting and MapRequest
events.
@mjharkin: does that work for you?
Great work. Yes, the fix in r20637 works perfectly with both the test case and the issue I was trying to replicate.
This was the last of our major blockers for running in Xpra, really appreciate the work you've put in.
this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/1974