Spinners not going away

[totaam]

Issue migrated from trac ticket # 871

component: client | priority: major | resolution: fixed

2015-05-25 16:17:26: ddoole created the issue

---

Starting in xpra 0.14.23 and continuing in 0.14.24, I've had several instances where I've had a network hiccup and the spinners have appeared. Yet once the network is moving again, the spinners have remained on some of the windows (not all) even though they are otherwise responding properly. That is, I'm editing text, cutting & pasting, etc. but the spinner is sitting in front of everything. Needless to say, it makes the affected windows pretty much unusable. Interestingly, the spinner is not spinning freely, but is tied to window refreshes - if nothing is happening in the window then the spinner is static, but if something is changing (typing text, flashing cursor), then the spinner rotates each time the window changes.

Once this has happened, the only way I can clear things up is to drop the client connection and re-connect to the server or by toggling OpenGL off/on at the client.

I am not able to reproduce this on demand, but it has happened a few times now. I have no idea what the trigger might be. I had not seen this problem before upgrading to 0.14.23. Both the server and the client are running Ubuntu 14.04. The client is running KDE.

When it fails, I've had konsole and gvim sessions up. Sometimes other applications are up as well (such as totalview).

I've attached the bug report tool information to this ticket.

[totaam]

2015-05-25 16:18:11: ddoole uploaded file spinnerBug.zip (32.6 KiB)

Bug Report tool output.

[totaam]

2015-05-25 16:19:51: ddoole commented

---

Here's a client side log with "-d client" from an earlier occurence of the problem on xpra 0.14.23.

2015-05-06 11:06:35,078 server is not responding, drawing spinners over the windows
2015-05-06 11:06:35,196 ping echo server load=(0, 20, 50), measured client latency=2ms
2015-05-06 11:06:35,205 server is OK again
2015-05-06 11:06:35,206 process_draw 109990 bytes for window 1 using png encoding with options={'compress_level': 2}
2015-05-06 11:06:35,219 process_draw 99427 bytes for window 1 using png encoding with options={'compress_level': 2}
2015-05-06 11:06:35,228 record_decode_time(True) wid=1, png: 575x768, 22.3ms
2015-05-06 11:06:35,231 record_decode_time(True) wid=1, png: 575x768, 11.0ms
2015-05-06 11:06:35,287 process_draw 125023 bytes for window 1 using png encoding with options={'compress_level': 2}
2015-05-06 11:06:35,297 record_decode_time(True) wid=1, png: 575x768, 10.3ms
2015-05-06 11:06:40,269 process_draw 122605 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:40,286 record_decode_time(True) wid=1, png: 575x768, 17.4ms
2015-05-06 11:06:42,228 process_draw 124183 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:42,246 record_decode_time(True) wid=1, png: 575x768, 18.0ms
2015-05-06 11:06:42,385 process_draw 123751 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:42,403 record_decode_time(True) wid=1, png: 575x768, 18.2ms
2015-05-06 11:06:44,065 check_echo_timeout(1430924744063) last_ping_echoed_time=1430924794068
2015-05-06 11:06:44,069 average server latency=6.5, using max wait 1.01s
2015-05-06 11:06:44,072 ping echo server load=(0, 20, 50), measured client latency=3ms
2015-05-06 11:06:47,007 process_draw 125209 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:47,025 record_decode_time(True) wid=1, png: 575x768, 17.4ms
2015-05-06 11:06:48,871 process_draw 105618 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:48,884 record_decode_time(True) wid=1, png: 575x768, 12.4ms
2015-05-06 11:06:54,071 average server latency=6.5, using max wait 1.01s
2015-05-06 11:06:54,072 check_echo_timeout(1430924754065) last_ping_echoed_time=1430924804069
2015-05-06 11:06:54,074 ping echo server load=(0, 20, 50), measured client latency=7ms
2015-05-06 11:06:54,231 process_draw 106959 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:54,254 record_decode_time(True) wid=1, png: 575x768, 22.5ms
2015-05-06 11:06:57,833 process_draw 110440 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:57,847 record_decode_time(True) wid=1, png: 575x768, 13.5ms
2015-05-06 11:06:58,493 process_draw 108951 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:58,507 record_decode_time(True) wid=1, png: 575x768, 13.5ms
2015-05-06 11:06:58,922 process_draw 104383 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:58,943 record_decode_time(True) wid=1, png: 575x768, 20.0ms
2015-05-06 11:06:58,957 process_draw 101628 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:06:58,973 record_decode_time(True) wid=1, png: 575x768, 15.9ms
2015-05-06 11:06:59,230 process_draw 753 bytes for window 1 using png encoding with options={'compress_level': 3, 'store': 634, 'delta': 604}
2015-05-06 11:06:59,232 record_decode_time(True) wid=1, png: 553x15, 1.9ms
2015-05-06 11:07:03,057 server cursor sizes: default=85, max=(64, 64)
2015-05-06 11:07:03,057 new cursor at 6,4 with serial=135, dimensions: 24x24, len(pixels)=2304, default cursor size is 25, maximum=(64, 64)
2015-05-06 11:07:03,276 server cursor sizes: default=85, max=(64, 64)
2015-05-06 11:07:03,277 new cursor at 11,11 with serial=3, dimensions: 24x24, len(pixels)=2304, default cursor size is 25, maximum=(64, 64)
2015-05-06 11:07:03,304 server cursor sizes: default=85, max=(64, 64)
2015-05-06 11:07:03,305 new cursor at 6,4 with serial=114, dimensions: 24x24, len(pixels)=2304, default cursor size is 25, maximum=(64, 64)
2015-05-06 11:07:03,448 server cursor sizes: default=85, max=(64, 64)
2015-05-06 11:07:03,448 new cursor at 11,11 with serial=3, dimensions: 24x24, len(pixels)=2304, default cursor size is 25, maximum=(64, 64)
2015-05-06 11:07:03,871 update_focus(1, True) focused=None, grabbed=None
2015-05-06 11:07:03,871 send_focus(1)
2015-05-06 11:07:03,888 process_draw 90 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:07:03,891 record_decode_time(True) wid=1, png: 7x15, 2.6ms
2015-05-06 11:07:04,067 check_echo_timeout(1430924764066) last_ping_echoed_time=1430924814071
2015-05-06 11:07:04,072 average server latency=6.5, using max wait 1.01s
2015-05-06 11:07:04,077 ping echo server load=(0, 20, 50), measured client latency=3ms
2015-05-06 11:07:05,009 handle_key_action(GLClientWindow(1 : GLPixmapBacking(1, (575, 768), None)), <GTKKeyEvent object, contents: {'modifiers': [], 'group': 0, 'string': '\r', 'keyname': 'Return', 'pressed': True, 'keyval': 65293, 'keycode': 36}>) wid=1
2015-05-06 11:07:05,035 server cursor sizes: default=85, max=(64, 64)
2015-05-06 11:07:05,035 new cursor at 8,8 with serial=4, dimensions: 16x16, len(pixels)=1024, default cursor size is 25, maximum=(64, 64)
2015-05-06 11:07:05,072 handle_key_action(GLClientWindow(1 : GLPixmapBacking(1, (575, 768), None)), <GTKKeyEvent object, contents: {'modifiers': [], 'group': 0, 'string': '\r', 'keyname': 'Return', 'pressed': False, 'keyval': 65293, 'keycode': 36}>) wid=1
2015-05-06 11:07:05,112 process_draw 99622 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:07:05,131 record_decode_time(True) wid=1, png: 575x748, 18.8ms
2015-05-06 11:07:05,563 server cursor sizes: default=85, max=(64, 64)
2015-05-06 11:07:05,563 new cursor at 11,11 with serial=3, dimensions: 24x24, len(pixels)=2304, default cursor size is 25, maximum=(64, 64)
2015-05-06 11:07:06,183 update_focus(1, False) focused=1, grabbed=None
2015-05-06 11:07:06,204 send_focus(0)
2015-05-06 11:07:06,218 process_draw 104 bytes for window 1 using png encoding with options={'compress_level': 3}
2015-05-06 11:07:06,220 record_decode_time(True) wid=1, png: 7x15, 1.0ms
2015-05-06 11:07:14,074 average server latency=6.5, using max wait 1.01s
2015-05-06 11:07:14,074 check_echo_timeout(1430924774067) last_ping_echoed_time=1430924824072
2015-05-06 11:07:14,077 ping echo server load=(0, 20, 50), measured client latency=3ms
2015-05-06 11:07:24,068 check_echo_timeout(1430924784068) last_ping_echoed_time=1430924834073
2015-05-06 11:07:24,074 average server latency=6.5, using max wait 1.01s
2015-05-06 11:07:24,077 ping echo server load=(0, 20, 50), measured client latency=4ms

[totaam]

2015-05-26 05:54:48: totaam changed owner from antoine to ddoole

[totaam]

2015-05-26 05:54:48: totaam commented

---

Thanks for the details. Can you tell us roughly how often this occurs? As a percentage of the number of times that the spinners show up?

Some related links:

• 9272 fixed a bug which may have caused crashes in the past (paint from the wrong thread)
• 9167 / #818: may have caused this bug: we now paint via opengl. (and we're not reverting that because mixing cairo and opengl is worse)
• r9265: I was hoping this was the cause of this problem, apparently not

Changes I have just made:

• r9520 adds more debugging (enable with -d window) to trunk (will be 0.16)
• 9521 is a bug I think (see commit message) - this could be it, but it would be quite difficult to hit it
• 9522 backports r9271 to v0.14.x and v0.15.x branches so it will be easier to test the spinner code:

  XPRA_FAKE_BROKEN_CONNECTION=10 xpra attach

  Will now show the spinners for 5 seconds every 10 seconds. (whereas before it was an on or off thing) It is worth trying it to see if you can trigger the bug (you will have to keep an eye on the client output to know when the spinners are meant to be drawn and when they are not).

Since that's what you are using, I have made trusty pre-release 0.14.25 builds with these 2 changes for you to test.

[totaam]

2015-05-26 15:12:11: ddoole commented

---

The stuck spinners is rather random. I've seen it happen very frequently and very rarely. When I started this discussion in email I saw the problem 4 times in one day (so 4 times out of 10-15 appearances of the spinners.) Lately it's more like 1 out of 100. (There's something strange going on in SSH on one of my machines - I'm getting a depressing number of spinners :-( )

With the test code - do I need to update client and server, or just the client?

[totaam]

2015-05-26 15:22:23: totaam commented

---

With the test code - do I need to update client and server, or just the client? [[BR]] Just the client.

[totaam]

2015-06-01 16:21:45: ddoole commented

---

Unfortunately I got sidetracked and wasn't able to try out the debug build until now. However I see that there's also 0.15 available.

Should I try the debug build, or 0.15?

[totaam]

2015-06-01 16:51:04: totaam commented

---

0.15, the changes landed there first anyway.

[totaam]

2015-06-01 17:18:19: ddoole commented

---

I am still seeing the problem on 0.15 (server is still at 0.14.24). I was just using the client normally (no XPRA_FAKE_BROKEN_CONNECTION) to see if the probem had gone away.

I'll enable -d window and post when I hit the issue again.

[totaam]

2015-06-17 16:31:20: ddoole changed status from new to closed

[totaam]

2015-06-17 16:31:20: ddoole set resolution to fixed

[totaam]

2015-06-17 16:31:20: ddoole commented

---

I have been unable to reproduce the stuck spinner issue since that first day on 0.15. (So maybe I'd forgot to restart the client after upgrading.)

I'm marking this defect fixed.