UnmapNotify being called incorrectly

[totaam]

Issue migrated from trac ticket # 1974

component: server | priority: major | resolution: fixed

2018-10-02 12:40:34: mjharkin created the issue

---

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.

[totaam]

Please provide a sample Java application I can test against.

[totaam]

2018-10-02 13:38:44: mjharkin commented

---

It's a 3rd party application but I'll try and reproduce, it'll probably be a few days though.

[totaam]

2018-10-09 13:41:25: mjharkin uploaded file WindowVisible.zip (5.4 KiB)

Test Jar and Source

[totaam]

2018-10-09 13:50:47: mjharkin commented

---

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);

[totaam]

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.

[totaam]

2018-10-09 16:57:45: mjharkin commented

---

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 :)

[totaam]

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:

• when the window is created:

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))

• Java reconfigures the window:

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)

• Java sends a _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)

• we ignore a configure notify event because the corral window is not visible:

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

---

• When we receive the unmap:

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

• then immediately after, we process a configure + map, with the reparent notify in between:

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)

• next time we go through the same events, something different happens:

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?

[totaam]

2018-10-10 05:24:24: mjharkin commented

---

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.

[totaam]

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

[totaam]

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?

[totaam]

2018-10-10 07:41:55: mjharkin commented

---

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.