xpra icon
Bug tracker and wiki

Opened 3 months ago

Closed 2 months ago

#1855 closed defect (fixed)

Continuous Spamming of Network Quality Issues

Reported by: stdedos Owned by: stdedos
Priority: major Milestone: 2.4
Component: client Version: 2.3.x
Keywords: Cc:

Description (last modified by Antoine Martin)

Windows 10 (1803/17134.48) (connecting wirelessly @ 240 Mbit/s) connecting to Ubuntu 16.04.3 (Ethernet, 1 Gbit/s)

Xpra gtk2 client version 2.3-r19246 64-bit
 running on Microsoft Windows 10
GStreamer version 1.14.0 for Python 2.7.15 64-bit
 desktop size is 1600x900 with 1 screen:
  2\WinSta-Default (423x238 mm - DPI: 96x96) workarea: 1600x860
    DISPLAY1 (310x174 mm - DPI: 131x131)
 downscaled by 75%, virtual screen size: 2133x1200
  2\WinSta-Default (423x238 mm - DPI: 128x128) workarea: 2133x1147
    DISPLAY1 (310x174 mm - DPI: 174x175)
 keyboard settings: layout=us
enabled remote logging
Xpra shadow server version 2.3-r19255 64-bit
 running on Linux Ubuntu 16.04 xenial
setting scaling to 67%:
sending updated screen size to server: 2402x1351 with 1 screens
  2\WinSta-Default (423x238 mm - DPI: 144x144) workarea: 2402x1291
    DISPLAY1 (310x174 mm - DPI: 196x197)

After some time, I keep getting "Network Performance Issue", "Your connection is struggling to keep up".

It doesn't matter if I press "Lower bandwidth limit" or "Cancel". I've tried both, it keeps coming up. I've tried to change the settings to the tray icon (Speed / Quality), but nothing happens. However, I feel that it's possible that tray icon is not listening to me i.e. it does not apply my options.

Trying to WinSCP a 1GB file I get a speed ~7 - 22 MB/s, so, I wouldn't say that actual network speed is problematic

Attachments (4)

xpra-run.log (9.3 KB) - added by stdedos 3 months ago.
xpra_bandwidth.log.gz (60.0 KB) - added by Jordan 3 months ago.
log of bandwidth notification spamming
xpra-2018-05-31.tar.bz2 (6.4 KB) - added by stdedos 3 months ago.
1855-follow-up.7z (26.3 KB) - added by stdedos 2 months ago.

Download all attachments as: .zip

Change History (25)

Changed 3 months ago by stdedos

Attachment: xpra-run.log added

comment:1 Changed 3 months ago by stdedos

Component: androidclient

comment:2 Changed 3 months ago by Antoine Martin

Description: modified (diff)
Owner: changed from Antoine Martin to stdedos

I guess we haven't tested this well enough with problematic connections like wifi.
Can you post the "-d bandwidth" server log?

Clicking the "Ignore" button should prevent any further warnings. (the "-d bandwidth" logs should show it, maybe add "-d notification")

Trying to WinSCP a 1GB file I get a speed ~7 - 22 MB/s, so, I wouldn't say that actual network speed is problematic

That's the maximum bandwidth your connection is capable of. But wifi has a lot of jitter, and xpra is very sensitive to that.

comment:3 Changed 3 months ago by Antoine Martin

Milestone: 2.4

comment:4 Changed 3 months ago by Antoine Martin

Another workaround is to start your server with:

XPRA_ACK_TOLERANCE=1000 xpra start ...

I have also created a ticket to improve this and detect jittery connections: #1860

Changed 3 months ago by Jordan

Attachment: xpra_bandwidth.log.gz added

log of bandwidth notification spamming

comment:5 Changed 3 months ago by Jordan

I captured a log of this issue. I started xpra with the following parameters:

--debug bandwidth,notifications --encoding=png --dpi=96 --speaker=off --pulseaudio=no \
    --resize-display=no --printing=no --file-transfer=no --notifications=no --webcam=no :991

But I don't think it actually logged notification debug messages.

I connected at 21:27:48 and opened glxgears. I ran that for a while and it didn't trigger. I then opened firefox and started a youtube video. I saw the bandwidth notification show up at about 21:32:29, 21:33:37, and 21:34:51. Each time I clicked on 'ignore'.

This test is run over wifi -> internet -> remote xpra server. The internet connection is about 30 mbps.

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

comment:6 Changed 3 months ago by Antoine Martin

Owner: changed from stdedos to Antoine Martin
Status: newassigned

FWIW:

  • using --encoding=png is always going to be problematic, you should be using --min-quality=90 instead.

PNG is a CPU pig and not particularly efficient at compressing either.

  • --resize-display=no is usually a bad idea.
  • --notifications=no should have prevented the notifications in the first place - probably a bug

As for the log itself:

  • this shows that a packet took an extra second to return! (so the warning really is warranted in this case: xpra is not going to work well with a 1 second packet round-trip time)
    2018-05-29 21:27:57,306 networksend_congestion_event(late-ack for sequence     77: late by 1029ms, target latency=144 ((7, 37, 0, 100)), 3068, 86243) 55Kbps
     (average=936Kbps)
    

(probably caused by wifi packet loss)

  • after that, it seems to settle nicely, guessing that it should use about 5Mbps of bandwidth (ie: may_send_delayed() wid= 2 : bandwidth limit=4770064, used=4656565 : 97%) - 5Mbps may sound low, but this may be the maximum that the wifi is capable of sustaining without incurring the costly packet loss which tanks the latency.
  • it also sticks to that budget pretty well, hovering over the 100% utilization mark
  • when it goes over 150% utilization, it triggers new congestion events, ie:
    may_send_delayed() wid=  2 : bandwidth limit=4770064, used=7545664 : 158%
    networksend_congestion_event(soft-expire limit: 28ms, 5/5, 1000, 0) 3022Kbps (average=3022Kbps)
    
  • and again later:
    may_send_delayed() wid=  2 : bandwidth limit=5112628, used=7419747 : 145%
    may_send_delayed() wid=  2 : bandwidth limit=5112628, used=5742900 : 112%
    networksend_congestion_event(soft-expire limit: 45ms, 5/5, 1000, 0) 1740Kbps (average=1740Kbps)
    
  • but there are also some late packets (probably due to wifi jitter) out of the blue:
    networksend_congestion_event(late-ack for sequence   1000: late by 998ms, target latency=118 ((7, 11, 0, 100)), 9241, 88880) 67Kbps 
    (average=4669Kbps)
    

I have no idea why the notifications keep showing up, but now at least I should be able to reproduce it by artificially triggering the same events.

comment:7 Changed 3 months ago by Antoine Martin

Owner: changed from Antoine Martin to stdedos
Status: assignednew

Turns out that this is trivial to test with this server env var:

XPRA_ACK_TOLERANCE=-500 xpra start --start=xterm

Will use a negative value for the ack tolerance, which triggers the warnings every time.
With this in place, I got the warnings on the win32 client, but clicking "Ignore" silenced all warnings for all windows until the session ended.

@stdedos: if you can still reproduce, please post the "-d bandwidth,notify" debug log.

comment:8 Changed 3 months ago by stdedos

I can still replicate (see attachments)

Changed 3 months ago by stdedos

Attachment: xpra-2018-05-31.tar.bz2 added

comment:10 Changed 3 months ago by stdedos

Hopefully now it comes okay. ...However, I noticed I had the original files stored.

So, you have 2 log traces! :-D

(on the second one, I also added -d bandwidth,notify on the client)

comment:11 Changed 3 months ago by stdedos

server trace always leads with:

2018-05-31 18:22:22,393 Warning: the python netifaces package is missing
2018-05-31 18:22:22,503 init bandwidth_limit=None
2018-05-31 18:22:22,506 bandwidth-limit setting=None, socket-speed=None
2018-05-31 18:22:22,506 bandwidth-limit capability=0
shadow session now available on display :0

(however, not on the /run file I assume)

comment:12 Changed 3 months ago by Antoine Martin

I only just noticed that you're using a shadow server.
The fix is in r19547 + r19549. beta packages with these fixes will land here: https://xpra.org/beta.

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

comment:13 in reply to:  12 Changed 2 months ago by stdedos

Replying to Antoine Martin:

I only just noticed that you're using a shadow server.
The fix is in r19547 + r19549. beta packages with these fixes will land here: https://xpra.org/beta.

Note: xpra_2.4-20180531r19548-1_amd64.deb is there; however, missing the r19549

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

comment:14 Changed 2 months ago by Antoine Martin

however, missing the r19549

Sorry forgot to push some newer builds, try now.

comment:15 Changed 2 months ago by stdedos

I have follow-up on that. Now passing notifications works.

However, pushing "limit bandwidth" does really kill the connection (see attachments).

Should we continue here or at #1860?

Changed 2 months ago by stdedos

Attachment: 1855-follow-up.7z added

comment:16 Changed 2 months ago by Antoine Martin

However, pushing "limit bandwidth" does really kill the connection (see attachments).

Nothing suspicious there, but there have been fixes to bandwidth handling lately.
Please try the latest beta builds, both client and server side.

Should we continue here or at #1860?

The only think to verify there is documented in ticket:1860#comment:4.
Do you see the correct value on your setup?

comment:17 in reply to:  16 Changed 2 months ago by stdedos

Replying to Antoine Martin:

Should we continue here or at #1860?

The only think to verify there is documented in ticket:1860#comment:4.
Do you see the correct value on your setup?

Unfortunately, that will have to wait until Monday :/


One last thing, I always wanted to ask: Are all these errors "known/safe to ignore" etc etc?

* Error: avcodec error -1094995529 decoding [...]
* Error: decode failed on  [...]
* unknown string message: 0xc08fL  [...]
* C:/Program Files/Xpra/library.zip/xpra/gtk_common/gtk_util.py:658: GtkWarning: gdk_property_delete: assertion 'window != NULL' failed
* Error collecting system bug report data using [...]

comment:18 Changed 2 months ago by Antoine Martin

Error: avcodec error -1094995529 decoding [...]
Error: decode failed on [...]

Fixed: #1868

unknown string message: 0xc08fL

Safe to ignore.

GtkWarning: gdk_property_delete: assertion 'window != NULL' failed

Safe to ignore.

Error collecting system bug report data using [...]

No idea: what is [...] ?

comment:19 in reply to:  18 Changed 2 months ago by stdedos

Replying to Antoine Martin:

Error collecting system bug report data using [...]

No idea: what is [...] ?

I didn't want to pollute comments - so I truncated the error(s). On the end of 1855-follow-up.7z​ > 1855-follow-up_terminal.txt:

2018-06-08 12:51:26,707 Error collecting system bug report data using <function get_sys_info at 0x00000000233675f0>
Traceback (most recent call last):
  File "./xpra/client/gtk_base/bug_report.py", line 281, in get_text_data
  File "./xpra/client/gtk_base/bug_report.py", line 137, in get_sys_info
  File "./xpra/scripts/config.py", line 385, in read_xpra_defaults
  File "./xpra/os_util.py", line 439, in osexpand
TypeError: object of type 'NoneType' has no len()

comment:20 Changed 2 months ago by Antoine Martin

Error collecting system bug report data using <function get_sys_info at 0x00000000233675f0>

I can't reproduce it, but in any case it should be fixed in r19594.

comment:21 in reply to:  20 Changed 2 months ago by stdedos

Replying to Antoine Martin:

Error collecting system bug report data using <function get_sys_info at 0x00000000233675f0>

I can't reproduce it, but in any case it should be fixed in r19594.

I guess it's complicated, since user is in AD

comment:22 Changed 2 months ago by Antoine Martin

Resolution: fixed
Status: newclosed

I believe this bug is fixed, let's follow up in ticket:1860#comment:4.

Note: See TracTickets for help on using tickets.