FreeRDP 🚀 - Long term test - Freerdp disconnects with fastpath error

If I go for the event viewer reason codes I get unfortunately:
exDiscReasonNoInfo (0x0000)

No additional information is available.

Maybe it is ->
Reason Code 0: Client Disconnect- network connectivity was lost.

The main problem seems to be this:
[19:31:42:196] [24952:24953] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[19:31:42:206] [24952:24953] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[19:31:42:206] [24952:24953] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail

When I try to establish a session without fastpath (-fast-path) I only get a blackened out monitor with my white mouse cursor and nothing happens.

T3N4K4 on 5 Oct 2016

Latest master build from today is still crashing:
[15:15:47:666] [19550:19551] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[15:15:47:668] [19550:19551] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[15:15:47:668] [19550:19551] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[15:15:47:668] [19550:19551] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[15:15:47:670] [19550:19551] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[15:15:47:670] [19550:19551] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

T3N4K4 on 13 Oct 2016

@T3N4K4 merged the rfx fixes #3545 today. were your tests before or after that merge?

akallabeth on 13 Oct 2016

Unfortunately just about half an hour after that merge.

T3N4K4 on 13 Oct 2016

@T3N4K4 if I read it correctly this happens on a 32 bit client machine? Do you have the possibility to do the same tests on a 64 bit machine as well?

bmiklautz on 14 Oct 2016

Sure I'll try it again.

T3N4K4 on 14 Oct 2016

@bmiklautz it still crashes. Even with 64bit.

T3N4K4 on 17 Oct 2016

@T3N4K4 thanks for testing. Would be interesting if we are able to reproduce the behavior. But just to make sure "crashing" means for you that you are getting disconnected but you don't get a segfault or similar, right?

bmiklautz on 17 Oct 2016

Yes, the sessions just ends itself. If I've been watching a video on youtube and would reconnect immediately the video would still be playing.
There are no segfaults or any messages in dmesg.

The latest command line I've been using was:
xfreerdp /u:$USER /p:$PASSWORD /d:windows /rfx /gdi:hw /bpp:32 +sec-tls -sec-nla +async-input +async-update /cert-ignore /v:$SERVER

The reason behind +async-input and +async-update is that the sessions tends to not respond or respond with a delay of up to 5 minutes when /rfx is set on graphic heavy content.

Server is 2012 R2 Standard Build 9600

As for the test case it is very easy -> Start freerdp with the command line above, watch youtube videos (for example 10h funny cat compilations) in fullscreen (browser fullscreen) in chrome (firefox seems to be crashing on my system after a while) and keep it running without moving the mouse or any other input. In my case the sessions kept running for 45 minutes up to 9 hours.

T3N4K4 on 17 Oct 2016

@T3N4K4 The issue with input starvation should fixed with #3364

akallabeth on 17 Oct 2016

👍1

@akallabeth the input starvation issue seems to be fixed and working for me.

Maybe the crash is gone too, I am currently testing the newest commits.

Edit: @bmiklautz
Still disconnecting a6f4117 ->
[14:19:32:694] [11794:11795] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[14:19:32:695] [11794:11795] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[14:19:32:695] [11794:11795] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[14:19:32:695] [11794:11795] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[14:19:32:695] [11794:11795] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[14:19:32:695] [11794:11795] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

I guess these are the only points where the freerdp can disconnect according to the error above:

https://github.com/FreeRDP/FreeRDP/blob/38c88d4319c1f37a424a22f77fb9aa48e3114dc2/libfreerdp/core/surface.c#L37
https://github.com/FreeRDP/FreeRDP/blob/38c88d4319c1f37a424a22f77fb9aa48e3114dc2/libfreerdp/core/surface.c#L57
https://github.com/FreeRDP/FreeRDP/blob/38c88d4319c1f37a424a22f77fb9aa48e3114dc2/libfreerdp/core/surface.c#L75

T3N4K4 on 20 Oct 2016

I have same problem: https://github.com/FreeRDP/FreeRDP/issues/3454

soar on 21 Oct 2016

Maybe it is a problem with Windows Server 2012 R2.
I can try next week to reproduce the error on 2008 R2.

T3N4K4 on 21 Oct 2016

As pointed out in #3454 it may be related to compression. Would be interesting, if the error vanishes if it is turned off.

akallabeth on 21 Oct 2016

👍1

Is it sufficient to use "-compression" in the command line or do I have to change the level of the compression to 0 ?

T3N4K4 on 22 Oct 2016

@T3N4K4 -compression is sufficient.

akallabeth on 23 Oct 2016

@T3N4K4 If the compression option does not help disabling async-update could be worth a try (the non responsive stuff should be resolved by #3364). Either way, would be interesting to get the root cause of your issue.

akallabeth on 24 Oct 2016

I've tested for an hour without compression - still working. Full command line:

xfreerdp /v:example.com +decorations +fonts +aero +window-drag +menu-anims +themes +wallpaper +compression /bpp:32 /kbd:US /sound:sys:pulse /microphone:sys:pulse /multimedia:sys:pulse /drive:USB,/mnt/usbdevice /smartcard /d:DOMAIN /u:'' /w:1900 /h:1000 /rfx /gdi:hw -compression

But still have problems with synchronization between audio and video streams (YouTube in Chrome).

soar on 24 Oct 2016

@soar

A/V sync: I see you use /multimedia redirection and /rfx in combination? So do you play the video in MS media player? If not (or if you do not use that switch) the A/V paths are quite different
Please do not use +compresseion and -compression in the same command line (it is a but in the parser that it is actually not aborting with an error)

akallabeth on 24 Oct 2016

@akallabeth Thanks - I forgot first compression occurrence in my run script. I think command-line options should be checked for such user typos...

And what about /multimedia, /sound, /microphone and /rfx? Am I wrong? How I should use them? I didn't found any explanation in docs.

soar on 24 Oct 2016

@akallabeth currently it is working fine with -compression, but I had some sessions which disconnected at around 7 - 8hours in, so I keep the test running for the moment.

@soar I guess (like @akallabeth said) /multimedia is for multimedia redirection which is working with the windows media player only.
/rfx and /multimedia are two different channels and therefore two different implementations.
So if you watch youtube in chrome /rfx is fine with /sound:sys:pulse.

Is the /audio-mode missing or is it not needed? (/audio-mode:1 = local sound, /audio-mode:2 = server sound, /audio-mode:0 = no sound)

T3N4K4 on 24 Oct 2016

@T3N4K4 so, if I use /multimedia and /rfx simultaneously - they should work fine? Or I shouldn't use /multimedia with /rfx at all?

soar on 24 Oct 2016

@soar Well, your mileage may vary, /multimedia has not seen many updates with FreeRDP in a long time. For anything newer thant windows 7 I'd also recommend using one of the /gfx options.

akallabeth on 24 Oct 2016

@T3N4K4 /sound implies /audio-mode:1. As for the tests, good to know, would be nice to find this nasty thing.

akallabeth on 24 Oct 2016

@akallabeth After two hours with -compression I've got same error.

soar on 24 Oct 2016

@akallabeth mine was running fine with this minimal command line parameters:
/opt/freerdp/bin/xfreerdp "/u:$USER" "/p:$PASSWD" "/d:windows.local" /v:$CON_SERVER /gdi:hw /bpp:32 /kbd:0x0407 /t:"Test" /rfx -compression /network:lan /cert-ignore

Going to test some more command line parameters I usually add.

T3N4K4 on 24 Oct 2016

@T3N4K4 how long did you test it? Without -compression I get crash after 10-20 minutes, with -compression - after ~2 hours.

soar on 24 Oct 2016

@soar for about 7 and a half hours with -compression.

T3N4K4 on 24 Oct 2016

@akallabeth with the new command line the session disconnected after one hour:

/opt/freerdp/bin/xfreerdp "/u:$USER" "/p:$PASSWD" "/d:$DOMAIN" /v:$CON_SERVER /gdi:hw -f -decorations /monitors:0 /bpp:32 /kbd:0x0407 /t:"Test" -async-input -async-update +sec-tls +sec-nla /rfx -bitmap-cache -grab-keyboard /sound:sys:pulse /audio-mode:0 /sound:latency:50 -compression /network:lan +fonts -aero -window-drag +menu-anims +themes -wallpaper +clipboard /cert-ignore

 [15:36:27:402] [12147:12148] [WARN][com.freerdp.core.client] - Skipping, channel already loaded
 [16:34:34:492] [12147:12148] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
 [16:34:34:493] [12147:12148] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
 [16:34:34:493] [12147:12148] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
 [16:34:34:493] [12147:12148] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
 [16:34:34:493] [12147:12148] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
 [16:34:34:493] [12147:12148] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor
 [16:34:34:505] [12147:12157] [ERROR][com.freerdp.channels.rdpsnd.client] - VirtualChannelWrite failed with CHANNEL_RC_NOT_CONNECTED [00000004]
 [16:34:34:505] [12147:12157] [ERROR][com.freerdp.channels.rdpsnd.client] - error confirming wave

The things @soar and my command lines have in common are sound, rfx, gdi, fonts, themes, menu-anims, compression.
My first command line had no sound, fonts, themes, menu-anims AND no sort of security other than the default sec-rdp...

I guess this is another problem, but with +sec-nla or +sec-tls my session sometimes crashes with

[08:10:38:124] [9119:9120] [ERROR][com.freerdp.core.transport] - BIO_read returned a system error 104: Connection reset by peer 
[08:10:38:124] [9119:9120] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0

T3N4K4 on 25 Oct 2016

👍1

can you rule out network and server side issues? your second disconnect issue (it is not a crash ;)) looks like a server side connection reset. also multiple /sound options won't work, the last one overrides all before that.

akallabeth on 25 Oct 2016

I guess the network is fine I switched to another server for now since I got every 10 - 15 minutes one of those BIO_read errors. At least it isn't a crash ;)
So for the sound is it correct to use/sound:sys:pulse,latency:50 ?

T3N4K4 on 25 Oct 2016

@T3N4K4 Yes, it is the only way you get both parameters used. You're just lucky the default backend is pulse if it is available.

akallabeth on 25 Oct 2016

@akallabeth I've tested some more.
Everytime my session disconnects either pulse main process has ended and is respawning or alsa got a buffer underrun.

ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
ALSA lib pcm.c:7843:(snd_pcm_recover) underrun occurred
[16:17:34:984] [4953:4954] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[16:17:34:984] [4953:4954] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[16:17:34:984] [4953:4954] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[16:17:34:984] [4953:4954] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[16:17:34:984] [4953:4954] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[16:17:34:984] [4953:4954] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

Command line parameter for alsa are same as above except for pulse it is->
/sound:sys:alsa,format:1,latency:0

Maybe @soar is on the right way when he says that the synchronization of video and audio are not working.

Since the line from above without sound did work maybe it has to do something with sound ?

Edit: On the otherhand in my first post it did disconnect without sound but I guess later than with sound.

T3N4K4 on 25 Oct 2016

@T3N4K4 I think you should not use /sound:sys:alsa when pulse is present in your system. Use it only when bare alsa manage your sound. I've tested many different situations - /sound:sys:pulse works much better and all settings could be done in pulse configuration.

soar on 25 Oct 2016

It does not matter which one I use. Pulse does not work correctly in some cases where I switched to alsa and it was just a test. But as a matter of fact both audio services are ending themselves just before the freerdp disconnect happens.

T3N4K4 on 26 Oct 2016

@akallabeth Further testing:

For all if not changed (/gdi:hw -f -decorations /bpp:32 -sec-tls -async-input -async-update +grab-keyboard /network:lan +fonts +menu-anims +themes -clipboard)

All tests -> for 2 hours youtube video.

With +sec-nla /sound:sys:pulse,latency:50 -compression (without rfx) no problems.

With /rfx +async-update +sec-nla /sound:sys:pulse,latency:50 -compression:

[10:10:21:533] [27002:27003] [WARN][com.freerdp.core.client] - Skipping, channel already loaded
[10:36:20:725] [27002:27003] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[10:36:20:725] [27002:27003] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[10:36:20:725] [27002:27003] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[10:36:20:726] [27002:27003] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[10:36:20:726] [27002:27003] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[10:36:20:726] [27002:27003] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor
[10:36:21:916] [27002:27009] [ERROR][com.freerdp.channels.rdpsnd.client] - VirtualChannelWrite failed with CHANNEL_RC_NOT_CONNECTED [00000004]
[10:36:21:916] [27002:27009] [ERROR][com.freerdp.channels.rdpsnd.client] - error treating sound channel message

With /gfx +async-update +sec-nla /sound:sys:pulse,latency:50 -compression (instant disconnect when youtube video is running)

[10:45:42:458] [16401:16415] [WARN][com.freerdp.core.client] - Skipping, channel already loaded
[10:45:43:584] [16401:16437] [ERROR][com.freerdp.gdi] - clear_decompress failure: -1
[10:45:43:584] [16401:16437] [ERROR][com.freerdp.channels.rdpgfx.client] - context->SurfaceCommand failed with error 1359
[10:45:43:584] [16401:16437] [ERROR][com.freerdp.channels.rdpgfx.client] - rdpgfx_decode failed with error 1359!
[10:45:43:584] [16401:16437] [ERROR][com.freerdp.channels.rdpgfx.client] - rdpgfx_recv_wire_to_surface_1_pdu failed with error 1359!
[10:45:43:584] [16401:16437] [ERROR][com.freerdp.channels.rdpgfx.client] - Error while parsing GFX cmdId: RDPGFX_CMDID_WIRETOSURFACE_1 (0x0001)
[10:45:43:584] [16401:16437] [ERROR][com.freerdp.channels.rdpgfx.client] - rdpgfx_recv_pdu failed with error 1359!
[10:45:43:584] [16401:16437] [ERROR][com.freerdp.channels.drdynvc.client] - drdynvc_order_recv failed with error 1359!
[10:45:43:584] [16401:16415] [ERROR][com.freerdp.core] - drdynvc_virtual_channel_client_thread reported an error. Error was 1359
[10:45:43:585] [16401:16415] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

With /rfx +bitmap-cache /nsc +sec-nla /sound:sys:pulse,latency:50 -compression

[10:48:05:996] [18028:18029] [WARN][com.freerdp.core.client] - Skipping, channel already loaded
[10:54:48:878] [18028:18029] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[10:54:48:879] [18028:18029] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[10:54:48:879] [18028:18029] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[10:54:48:879] [18028:18029] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[10:54:48:879] [18028:18029] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[10:54:48:879] [18028:18029] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

With /rfx /gdi:sw +sec-nla /sound:sys:pulse,latency:50 -compression

[11:16:02:997] [3329:3329] [INFO][com.freerdp.utils] - Registering signal hook...
[11:22:11:587] [3329:3330] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[11:22:11:587] [3329:3330] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[11:22:11:587] [3329:3330] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[11:22:11:587] [3329:3330] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[11:22:11:587] [3329:3330] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[11:22:11:587] [3329:3330] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

T3N4K4 on 27 Oct 2016

👍1

@akallabeth @bmiklautz still disconnecting with latest master. Is there anything else you need in order to be able to fix this ?

T3N4K4 on 18 Nov 2016

Still disconnecting with latest master (e60d0d529a3a436368b17915bab0ccbd648fe990)

T3N4K4 on 30 Nov 2016

@T3N4K4 Currently busy, will get back to this one soon. I've recreated a setup to reproduce. Need to narrow it down to a minimal command line otherwise the code paths to check is just too many.

akallabeth on 2 Dec 2016

The minimal line I've figured out is:
/opt/freerdp/bin/xfreerdp "/u:USER" "/p:PASSWORD" "/d:WINDOWS.LOCAL" /v:SERVER /rfx /sound:sys:pulse /cert-ignore
And the youtube video has to be in browser-fullscreen mode to almost 100% reproduce the error below.

Edit: I think if the freerdp window is small (640x480) there are no disconnects if the browser is not in fullscreen. In one of the last tests it disconnected without browser-fullscreen but with freerdp-fullscreen (/f).

The latest error message is:

[09:11:01:263] [20566:20567] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[09:11:01:263] [20566:20567] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[09:11:01:263] [20566:20567] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[09:11:01:263] [20566:20567] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[09:11:01:263] [20566:20567] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[09:11:01:263] [20566:20567] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor
[09:11:01:267] [20566:20575] [ERROR][com.freerdp.channels.rdpsnd.client] - pVirtualChannelWriteEx failed with CHANNEL_RC_NOT_CONNECTED [00000004]
[09:11:01:267] [20566:20575] [ERROR][com.freerdp.channels.rdpsnd.client] - error confirming wave

or

[15:13:01:585] [31267:31268] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[15:13:01:585] [31267:31268] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[15:13:01:585] [31267:31268] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[15:13:01:585] [31267:31268] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[15:13:01:585] [31267:31268] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[15:13:01:585] [31267:31268] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

T3N4K4 on 5 Dec 2016

@T3N4K4 So /rfx and /sound are required? Does it also happen without sound?

akallabeth on 6 Dec 2016

@akallabeth all of those tests are documented above I guess.
In my tests /rfx without sound worked and /sound without /rfx

T3N4K4 on 9 Dec 2016

@akallabeth Is it helpful to say that the smaller the window of the freerdp the longer the connection / session stays up...
If I test it with 1600x1200 the session lasts for about 10 minutes. With 640x480 it can almost run forever.

T3N4K4 on 20 Jan 2017

@T3N4K4 Looks like I've found some possible memory corruption issues with #3708 and #3710
Maybe they have something to do with it, not entirely sure though.

akallabeth on 23 Jan 2017

@akallabeth I've tested both individually (RangeeGmbH-fork merged up to #3710) and your fork with branch #3708 . Both are still disconnecting. Could it be that there is something wrong with my ubuntu ?

T3N4K4 on 23 Jan 2017

@T3N4K4 No, I've had disconnects too (but not as often as you have), so there is probably something still hidden

akallabeth on 23 Jan 2017

I am going on vacation for a week, so I had not yet the chance to test this fully..
But with the latest master and the optimizations from @akallabeth I had no disconnects yet (running for about 1 hour, since it disconnected after 10 minutes before).

What I noticed though is that pulseaudio went asynchronous after a while.

So @soar you can try to set /sound:sys:alsa,format:1,quality:high instead of /sound:sys:pulse .. etc.

T3N4K4 on 16 Feb 2017

@akallabeth @nfedera thanks to both of you.
I guess it can be closed. Currently my freerdp is running for 3 days stable without any problems.

T3N4K4 on 10 Apr 2017

@akallabeth @nfedera I have to reopen this.
FreeRDP with /gfx and /sound is running for days. With /rfx and /sound we experience still this issue that the session suddenly disconnects after a few minutes until a few hours.

[07:40:54:326] [24523:24525] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[07:40:54:326] [24523:24525] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[07:40:54:326] [24523:24525] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[07:40:54:326] [24523:24525] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[07:40:54:326] [24523:24525] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[07:40:54:326] [24523:24525] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor
*** Error in `/opt/freerdp/bin/xfreerdp': free(): invalid pointer: 0xb457c414 ***

T3N4K4 on 11 Apr 2017

On an earlier version of freerdp from (I think Sep. 2015) the error looks like this:

[17:15:33:270] [12414:12423] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[17:15:33:270] [12414:12423] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[17:15:33:270] [12414:12423] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[17:15:33:270] [12414:12423] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[17:15:33:270] [12414:12423] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[17:15:33:270] [12414:12423] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor
[17:15:33:323] [12414:12428] [ERROR][com.freerdp.channels.rdpsnd.client] - VirtualChannelWrite failed with CHANNEL_RC_NOT_CONNECTED [00000004]
[17:15:33:323] [12414:12428] [ERROR][com.freerdp.channels.rdpsnd.client] - error confirming wave

T3N4K4 on 13 Apr 2017

@akallabeth @nfedera it disconnects now even without sound.

[12:08:08:552] [6014:6016] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[12:08:08:552] [6014:6016] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[12:08:08:552] [6014:6016] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[12:08:08:552] [6014:6016] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[12:08:08:552] [6014:6016] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[12:08:08:552] [6014:6016] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor
*** Error in `/opt/freerdp/bin/xfreerdp': free(): invalid pointer: 0xb457661c ***

Latest FreeRDP-master with following command line:
xfreerdp /u: /p: /d: /v: /gdi:hw /f +sec-nla /rfx /cert-ignore to windows server 2012R2.

No sound involved.

I'll test it now with /gdi:sw.

Edit:
With /gdi:sw it is still disconnecting.

The testcase is -> connecting to the server, running chrome with the following youtube playlist in fullscreen https://www.youtube.com/watch?v=KS12fYYAfoY&index=1&list=PLGWGc5dfbzn_gRVGX1604EaM7WrBjXl1J at some point it suddenly disconnects. The times vary from 1hour until 4 hours.

The screen resolution is 1600x1200 if this matters.

Are there any server side settings which may provoke a disconnect ?

T3N4K4 on 19 Apr 2017

@T3N4K4 Which version are you using? I've never seen a invalid free on my test machines.

akallabeth on 20 Apr 2017

@T3N4K4 I'd suggest compiling with -DWITH_SANITIZE_ADDRESS=ON and -DCMAKE_BUILD_TYPE=Debug. That way you should get a stack trace whenever a memory corruption is detected.

akallabeth on 20 Apr 2017

@T3N4K4 Ok, had my test system running for a day now but no disconnect. (same setup as you described, remote end windows server 2012R2)

akallabeth on 20 Apr 2017

@akallabeth the Build_Type Version Debug is running fine for hours ... I don't know anymore whats going wrong.

As for the version, we compile it from the https://github.com/RangeeGmbH/FreeRDP/ RangeeGmbH Fork. It should be almost the same as master, except for some fixes which are working for us.
(Since nobody else seems to have some of our problems I did not create pull-requests for verification)

Could it be a codec error that the clientOS does not support the codec used in the youtube video ?

T3N4K4 on 20 Apr 2017

@T3N4K4 Ok, that is a crucial information! Could you please verify this also happens with current master?

akallabeth on 20 Apr 2017

@akallabeth sure. But as I said, it is almost the same as master. If I remember correctly there are no fixes which interfere with sound / bitmaps / rfx / gfx etc.
But sure, no problem.

T3N4K4 on 20 Apr 2017

@T3N4K4 The log you posted with the invalid pointer free tells otherwise.

akallabeth on 20 Apr 2017

@akallabeth yeah ... but in october (https://github.com/FreeRDP/FreeRDP/issues/3518#issuecomment-255087284) I said that the master disconnects ... but I'll test it again.

T3N4K4 on 20 Apr 2017

@akallabeth ok, the free() is in our code (but only happening when the FreeRDP is closing down, so no critical problem), the surface problem is still in the latest master ...... as I said:

This is FreeRDP version 2.0.0-dev (git bfcf8e7)

[15:50:41:330] [12008:12010] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[15:50:41:330] [12008:12010] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[15:50:41:330] [12008:12010] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[15:50:41:330] [12008:12010] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[15:50:41:331] [12008:12010] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[15:50:41:331] [12008:12010] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

This time checked with https://www.youtube.com/watch?v=ZqrXclgsAk4&list=PLGWGc5dfbzn_oXKrMl9P1jasL-PgulxNH

T3N4K4 on 20 Apr 2017

@T3N4K4 Added logging for possible errors, could you test https://github.com/akallabeth/FreeRDP/tree/surface_return_fix? Should give better indications on what is actually failing.

akallabeth on 24 Apr 2017

On my way. Thanks :)

T3N4K4 on 24 Apr 2017

@akallabeth

[12:42:35:287] [10837:10839] [ERROR][com.freerdp.core.surface] - invalid stream length, got 2 expected 6
[12:42:35:287] [10837:10839] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[12:42:35:287] [10837:10839] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[12:42:35:287] [10837:10839] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[12:42:35:287] [10837:10839] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[12:42:35:287] [10837:10839] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[12:42:35:287] [10837:10839] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor

T3N4K4 on 24 Apr 2017

@T3N4K4 That is strange. According to MS-RDPBCGR 2.2.9.2.3 the command must contain exactly 6 bytes. Just to ensure I'm on the right track, could you run with WLOG_PREFIX="[%hr:%mi:%se:%ml] [%pid:%tid] [%lv][%mn] [%fn:%ln] - "? That should clarify the exact code location

akallabeth on 24 Apr 2017

@akallabeth
Thats very useful :)

[18:30:39:577] [3553:3555] [ERROR][com.freerdp.core.surface] [update_recv_surfcmd_frame_marker:85] - invalid stream length, got 2 expected 6
[18:30:39:577] [3553:3555] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_update:387] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[18:30:39:577] [3553:3555] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_update_data:646] - fastpath_recv_update_data: fastpath_recv_update() - -1
[18:30:39:577] [3553:3555] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_updates:682] - fastpath_recv_update_data() fail
[18:30:39:577] [3553:3555] [ERROR][com.freerdp.core.transport] [transport_check_fds:1043] - transport_check_fds: transport->ReceiveCallback() - -1
[18:30:39:577] [3553:3555] [ERROR][com.freerdp.core] [freerdp_check_event_handles:369] - freerdp_check_fds() failed - 0
[18:30:39:577] [3553:3555] [ERROR][com.freerdp.client.x11] [xf_client_thread:1564] - Failed to check FreeRDP file descriptor

T3N4K4 on 25 Apr 2017

@T3N4K4 Ok, this is bad. update_recv_surfcmd_frame_marker is correct (at least to spec). You don't have the log with the previous received commands around?

akallabeth on 25 Apr 2017

@akallabeth I tried to produce a log with /log-level:TRACE, but the surface and fastpath log-filters are not inside the log anymore. How can I get a log which shows all different channels ? Or which channels do you need ?

Anyways:

[12:34:33:624] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:624] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=565 64).
[12:34:33:624] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 3467
[12:34:33:624] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886278 numRegions: 1
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=19 6).
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 120
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886279 numRegions: 1
[12:34:33:625] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=337 6).
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 1627
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886280 numRegions: 1
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=743 6).
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 2417
[12:34:33:626] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886281 numRegions: 1
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=337 58).
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 3554
[12:34:33:627] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886282 numRegions: 1
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=743 58).
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 4706
[12:34:33:628] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:629] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:629] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:630] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:630] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886283 numRegions: 1
[12:34:33:630] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:630] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=545 64).
[12:34:33:630] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 3698
[12:34:33:630] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886284 numRegions: 1
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=805 64).
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 3847
[12:34:33:631] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:632] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:632] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:633] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:633] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886285 numRegions: 1
[12:34:33:633] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:633] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=574 64).
[12:34:33:633] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 3172
[12:34:33:633] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886286 numRegions: 1
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=174 64).
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 939
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:634] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886287 numRegions: 1
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=477 64).
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 2213
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:635] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:636] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:636] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886288 numRegions: 1
[12:34:33:636] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:636] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=481 64).
[12:34:33:636] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 3275
[12:34:33:636] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886289 numRegions: 1
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=805 64).
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 4372
[12:34:33:637] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:638] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:638] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886290 numRegions: 1
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=254 64).
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 2232
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886291 numRegions: 1
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:639] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=82 64).
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 675
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886292 numRegions: 1
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=770 64).
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 8042
[12:34:33:640] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:641] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:641] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886293 numRegions: 1
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=123 25).
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 1106
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:642] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886294 numRegions: 1
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=190 25).
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 857
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886295 numRegions: 1
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=800 25).
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 5191
[12:34:33:643] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:644] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:644] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:644] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:644] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886296 numRegions: 1
[12:34:33:644] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:644] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=123 1).
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 471
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886297 numRegions: 1
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=800 1).
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 1982
[12:34:33:645] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:646] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:646] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:646] [23936:23938] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:94] - SurfaceFrameMarker: action: End (1) id: 0
[12:34:33:655] [23936:23938] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:94] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:34:33:690] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:690] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886298 numRegions: 1
[12:34:33:690] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:690] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:34:33:690] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 134725
[12:34:33:690] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:708] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:708] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:33:717] [23936:23938] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:94] - SurfaceFrameMarker: action: End (1) id: 0
[12:34:33:778] [23936:23938] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:94] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:34:33:798] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:33:798] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886299 numRegions: 1
[12:34:33:798] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:33:798] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:34:33:798] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 128469
[12:34:33:798] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:33:814] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:33:815] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:34:824] [23936:23938] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:94] - SurfaceFrameMarker: action: End (1) id: 0
[12:34:34:824] [23936:23938] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:94] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:34:34:836] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:34:34:837] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 886300 numRegions: 1
[12:34:34:837] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:34:34:837] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:34:34:837] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 130997
[12:34:34:837] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:34:34:853] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:34:34:853] [23936:23938] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:34:34:863] [23936:23938] [DEBUG][com.freerdp.core.rdp] [rdp_recv_callback:1421] - CONNECTION_STATE_ACTIVE - rdp_recv_pdu() - -1
[12:34:34:863] [23936:23938] [DEBUG][com.freerdp.core.rdp] [rdp_check_fds:1485] - transport_check_fds() - -1
[12:34:34:863] [23936:23938] [DEBUG][com.freerdp.core] [freerdp_check_fds:322] - rdp_check_fds() - -1
[12:34:34:863] [23936:23938] [INFO][com.freerdp.client.x11] [xf_auto_reconnect:1417] - Network disconnect!

Edit 3rd May 17:
If this log does not fit, it could be that one administrator killed the server at this time. Please message me here so I can create a new one.

T3N4K4 on 25 Apr 2017

@akallabeth I guess the WLog System is somehow broken ... it does not matter if I select more than one channel with /log-filters and choose different log-levels. The Error level won't get logged anymore if DEBUG is chosen.

T3N4K4 on 5 May 2017

@T3N4K4 No, WLog is working fine. If you do not get any error with extended logging it may be because there is a timing issue involved? Logging changes the run time behaviour quite a bit.

akallabeth on 8 May 2017

@akallabeth yes, it is working fine I guess. I played around with some of the DEBUG options in cmake and was able to produce this with your prefix line:

[12:23:56:408] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:43674
[12:23:56:408] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[12:23:56:408] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:23:56:408] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 10738 numRegions: 1
[12:23:56:408] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:23:56:408] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 602).
[12:23:56:408] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 43599
[12:23:56:409] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:23:56:417] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:8
[12:23:56:417] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:23:56:417] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:23:56:417] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:23:56:450] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:64426
[12:23:56:450] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[12:23:56:450] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:23:56:450] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 10739 numRegions: 1
[12:23:56:450] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:23:56:450] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:23:56:450] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 64351
[12:23:56:450] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:23:56:463] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:8
[12:23:56:463] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:23:56:463] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:23:56:463] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:23:56:484] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:62699
[12:23:56:484] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[12:23:56:484] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:23:56:484] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 10740 numRegions: 1
[12:23:56:484] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:23:56:484] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:23:56:484] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 62624
[12:23:56:484] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:23:56:496] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:23:56:497] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:23:56:500] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:8
[12:23:56:500] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:23:56:537] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:58731
[12:23:56:537] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[12:23:56:537] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:23:56:537] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 10741 numRegions: 1
[12:23:56:537] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:23:56:537] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:23:56:537] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 58656
[12:23:56:537] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:23:56:546] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:8
[12:23:56:546] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:23:56:549] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:23:56:549] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:23:56:570] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:58337
[12:23:56:570] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[12:23:56:570] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:23:56:570] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 10742 numRegions: 1
[12:23:56:570] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:23:56:570] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:23:56:570] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 58262
[12:23:56:570] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:23:56:579] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:8
[12:23:56:579] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:23:56:582] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:23:56:582] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:23:56:606] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:62688
[12:23:56:606] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[12:23:56:606] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:23:56:606] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 10743 numRegions: 1
[12:23:56:606] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:23:56:606] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:8
[12:23:56:607] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:23:56:607] [29950:29952] [DEBUG][com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[12:23:56:607] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 62613
[12:23:56:607] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:23:56:619] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:23:56:619] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[12:23:56:636] [29950:29952] [DEBUG][com.freerdp.core.rdp] [fastpath_recv_update:351] - recv Fast-Path Surface Commands Update (0x04), length:65532
[12:23:56:636] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[12:23:56:636] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 10744 numRegions: 1
[12:23:56:636] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[12:23:56:636] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[12:23:56:636] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 65461
[12:23:56:636] [29950:29952] [DEBUG][com.freerdp.core.rdp] [rdp_recv_callback:1421] - CONNECTION_STATE_ACTIVE - rdp_recv_pdu() - -1
[12:23:56:636] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[12:23:56:636] [29950:29952] [DEBUG][com.freerdp.core.rdp] [rdp_check_fds:1485] - transport_check_fds() - -1
[12:23:56:637] [29950:29952] [DEBUG][com.freerdp.core] [freerdp_check_fds:322] - rdp_check_fds() - -1
[12:23:56:637] [29950:29952] [INFO][com.freerdp.client.x11] [xf_auto_reconnect:1417] - Network disconnect!
[12:23:56:650] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[12:23:56:650] [29950:29957] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END

Maybe this one helps a bit more.

I can now reproduce it within a short time frame so the log does not get over 800mb anymore :).

T3N4K4 on 8 May 2017

@akallabeth even though rfx is serverside rendering.. which packets are sent to the client when rfx is active ? I may have found a solution to this problem.

Either it was the change from -DBUILTIN_CHANNELS=OFF to -DBUILTIN_CHANNELS=ON or one of the five libraries I replaced ... currently I cannot reproduce it anymore with the short video part where I could reproduce it 100%.

But if it was one of the libraries .. how could a codec library change the behaviour of serverside rendering ?

I have to test it for a long time though before I can close it.

Edit: Ok, still a problem ... he just survived longer :(

Edit 9th May 2017:
With +auto-reconnect it seems to skip the "broken frame".

T3N4K4 on 8 May 2017

@akallabeth the last few frames which were logged were a "full redraw of the screen".
[rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
Could it be that the bandwidth is too much or something like that, that the freerdp gets disconnected by the server ?

T3N4K4 on 9 May 2017

@T3N4K4 if -DBUILTIN_CHANNELS=ON did fix it for you it may be an old library in your system interfering with the installation. As for RFX, it is encoding the images with RemoteFX codec server side and sends it with FASTPATH_UPDATETYPE_SURFCMDS = 0x4 to the client for decoding. The client still needs to deserialize the stream and decode accordingly ;)

akallabeth on 9 May 2017

@T3N4K4 As for your current disconnection issue, this seems different than the one we observed before? As for bandwidth, RDP is using TCP/SSL, so if you have a working network it should not be a problem (except for the slowdown)

akallabeth on 9 May 2017

@akallabeth I don't know if it is exactly the same.. it happens on different intervals and has a bit of a random element in it. If it disconnects at one time and I rewind the video to the part where it should disconnect it just runs fine.

With +auto-reconnect I cannot see where it actually disconnects. In my small log-file I see the timestamps though:

[08:55:33:653] [13944:13945] [ERROR][com.freerdp.core.surface] - invalid stream length, got 2 expected 6
[08:55:33:665] [13944:13945] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[08:55:33:665] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[08:55:33:665] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[08:55:33:665] [13944:13945] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[08:55:33:665] [13944:13945] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[09:33:57:868] [13944:13945] [ERROR][com.freerdp.core.surface] - invalid stream length, got 2 expected 6
[09:33:57:868] [13944:13945] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[09:33:57:869] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[09:33:57:869] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[09:33:57:869] [13944:13945] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[09:33:57:869] [13944:13945] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[09:38:40:574] [13944:13945] [ERROR][com.freerdp.core.surface] - invalid stream length, got 2 expected 6
[09:38:40:591] [13944:13945] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[09:38:40:591] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[09:38:40:591] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[09:38:40:592] [13944:13945] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[09:38:40:592] [13944:13945] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[09:57:55:608] [13944:13945] [ERROR][com.freerdp.core.surface] - invalid stream length, got 2 expected 6
[09:57:55:609] [13944:13945] [ERROR][com.freerdp.core.fastpath] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[09:57:55:609] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data: fastpath_recv_update() - -1
[09:57:55:609] [13944:13945] [ERROR][com.freerdp.core.fastpath] - fastpath_recv_update_data() fail
[09:57:55:609] [13944:13945] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[09:57:55:609] [13944:13945] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0

T3N4K4 on 9 May 2017

@akallabeth I think it disconnects more frequently when a whole bunch of pixels have to be redrawn for example when closing some big windows.

How does the cache system in freerdp works ? Where is the cache placed ? I guess in the RAM.. is there any setting where I can increase the cache ?

Or can I maybe use /frame-ack:10 or something like that to skip the bad / unacknowledged frames ?

Huhm... disabling fast-path with -fast-path does not work either. It still throws fastpath errors is this intended ?

T3N4K4 on 10 May 2017

@akallabeth I guess thats the best I could get:

[08:49:36:432] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[08:49:36:433] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 2687531 numRegions: 1
[08:49:36:433] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[08:49:36:433] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1176 64).
[08:49:36:433] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 3574
[08:49:36:434] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[08:49:36:435] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[08:49:36:436] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[08:49:36:438] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[08:49:36:438] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 2687532 numRegions: 1
[08:49:36:439] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[08:49:36:439] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1680 881).
[08:49:36:439] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 65461
[08:49:36:440] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[08:49:36:445] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[08:49:36:446] [1867:1868] [DEBUG][com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[08:49:36:458] [1867:1868] [ERROR][com.freerdp.core.surface] [update_recv_surfcmd_frame_marker:87] - invalid stream length, got 2 expected 6
[08:49:36:459] [1867:1868] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_update:387] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[08:49:36:459] [1867:1868] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_update_data:646] - fastpath_recv_update_data: fastpath_recv_update() - -1
[08:49:36:459] [1867:1868] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_updates:682] - fastpath_recv_update_data() fail
[08:49:36:460] [1867:1868] [DEBUG][com.freerdp.core.rdp] [rdp_recv_callback:1421] - CONNECTION_STATE_ACTIVE - rdp_recv_pdu() - -1
[08:49:36:460] [1867:1868] [ERROR][com.freerdp.core.transport] [transport_check_fds:1043] - transport_check_fds: transport->ReceiveCallback() - -1
[08:49:36:460] [1867:1868] [DEBUG][com.freerdp.core.rdp] [rdp_check_fds:1485] - transport_check_fds() - -1
[08:49:36:461] [1867:1868] [DEBUG][com.freerdp.core] [freerdp_check_fds:322] - rdp_check_fds() - -1
[08:49:36:461] [1867:1868] [ERROR][com.freerdp.core] [freerdp_check_event_handles:369] - freerdp_check_fds() failed - 0
[08:49:36:461] [1867:1868] [INFO][com.freerdp.client.x11] [xf_auto_reconnect:1417] - Network disconnect!
[08:49:36:462] [1867:1868] [ERROR][com.freerdp.client.x11] [xf_client_thread:1564] - Failed to check FreeRDP file descriptor

Produced with the following command line:
WLOG_PREFIX="[%hr:%mi:%se:%ml] [%pid:%tid] [%lv:%mn] [%fn:%ln] - " WLOG_LEVEL=DEBUG /opt/freerdp/bin/xfreerdp /u: /p: /d: /v: /rfx /cert-ignore /size:1717x945

The size is the window-size of my virtual machine where I tried to sort out errors which may have something to do with libraries and OS etc.

And another one from another machine:

[11:15:38:748] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 180882
[11:15:38:748] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[11:15:38:767] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[11:15:38:767] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[11:15:38:776] [12013:12014] [DEBUG:com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[11:15:38:777] [12013:12014] [DEBUG:com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[11:15:38:792] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[11:15:38:792] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 491967 numRegions: 1
[11:15:38:792] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[11:15:38:792] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[11:15:38:792] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 177069
[11:15:38:792] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[11:15:38:814] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[11:15:38:816] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[11:15:38:825] [12013:12014] [DEBUG:com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: End (1) id: 0
[11:15:38:826] [12013:12014] [DEBUG:com.freerdp.core.update] [update_recv_surfcmd_frame_marker:96] - SurfaceFrameMarker: action: Begin (0) id: 0
[11:15:38:846] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC4 blockLen 14
[11:15:38:846] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_frame_begin:627] - RFX_FRAME_BEGIN: frameIdx: 491968 numRegions: 1
[11:15:38:846] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC6 blockLen 23
[11:15:38:847] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_region:710] - rect 0 (x,y=0,0 w,h=1600 900).
[11:15:38:847] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC7 blockLen 196533
[11:15:38:847] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_tileset:853] - quant 0 (6 6 6 6 7 7 8 8 8 9).
[11:15:38:886] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1028] - blockType 0xCCC5 blockLen 8
[11:15:38:886] [12013:12014] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_frame_end:641] - RFX_FRAME_END
[11:15:38:895] [12013:12014] [ERROR:com.freerdp.core.surface] [update_recv_surfcmd_frame_marker:87] - invalid stream length, got 2 expected 6
[11:15:38:895] [12013:12014] [ERROR:com.freerdp.core.fastpath] [fastpath_recv_update:387] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[11:15:38:895] [12013:12014] [ERROR:com.freerdp.core.fastpath] [fastpath_recv_update_data:646] - fastpath_recv_update_data: fastpath_recv_update() - -1
[11:15:38:895] [12013:12014] [ERROR:com.freerdp.core.fastpath] [fastpath_recv_updates:682] - fastpath_recv_update_data() fail
[11:15:38:895] [12013:12014] [DEBUG:com.freerdp.core.rdp] [rdp_recv_callback:1421] - CONNECTION_STATE_ACTIVE - rdp_recv_pdu() - -1
[11:15:38:895] [12013:12014] [ERROR:com.freerdp.core.transport] [transport_check_fds:1043] - transport_check_fds: transport->ReceiveCallback() - -1
[11:15:38:895] [12013:12014] [DEBUG:com.freerdp.core.rdp] [rdp_check_fds:1485] - transport_check_fds() - -1
[11:15:38:896] [12013:12014] [DEBUG:com.freerdp.core] [freerdp_check_fds:322] - rdp_check_fds() - -1
[11:15:38:896] [12013:12014] [ERROR:com.freerdp.core] [freerdp_check_event_handles:369] - freerdp_check_fds() failed - 0
[11:15:38:896] [12013:12014] [INFO:com.freerdp.client.x11] [xf_auto_reconnect:1417] - Network disconnect!
[11:15:38:896] [12013:12014] [ERROR:com.freerdp.client.x11] [xf_client_thread:1564] - Failed to check FreeRDP file descriptor

Command line used:
WLOG_PREFIX="[%hr:%mi:%se:%ml] [%pid:%tid] [%lv:%mn] [%fn:%ln] - " WLOG_LEVEL=DEBUG /opt/freerdp/bin/xfreerdp /u: /p: /d: /v: /rfx /cert-ignore /f

I've tried to debug the stream length a bit and recycled your DEBUG a bit:

[13:50:00:149] [16684:16685] [ERROR:com.freerdp.codec] [rfx_process_message_tileset:857] - Stream length, got 9074

[13:50:00:151] [16684:16685] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message:1032] - blockType 0xCCC5 blockLen 8

So we have a stream length of 9074..

[13:50:00:151] [16684:16685] [ERROR:com.freerdp.codec] [rfx_process_message:1033] - Stream length, got 2

[13:50:00:151] [16684:16685] [DEBUG:com.freerdp.codec.rfx] [rfx_process_message_frame_end:642] - RFX_FRAME_END

[13:50:00:151] [16684:16685] [ERROR:com.freerdp.codec] [rfx_process_message_frame_end:643] - Stream length, got 0
[13:50:00:152] [16684:16685] [ERROR:com.freerdp.core.surface] [update_recv_surfcmd_frame_marker:87] - invalid stream length, got 2 expected 6

[13:50:00:152] [16684:16685] [ERROR:com.freerdp.core.fastpath] [fastpath_recv_update:387] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[13:50:00:152] [16684:16685] [ERROR:com.freerdp.core.fastpath] [fastpath_recv_update_data:646] - fastpath_recv_update_data: fastpath_recv_update() - -1
[13:50:00:152] [16684:16685] [ERROR:com.freerdp.core.fastpath] [fastpath_recv_updates:682] - fastpath_recv_update_data() fail
[13:50:00:152] [16684:16685] [DEBUG:com.freerdp.core.rdp] [rdp_recv_callback:1421] - CONNECTION_STATE_ACTIVE - rdp_recv_pdu() - -1
[13:50:00:152] [16684:16685] [ERROR:com.freerdp.core.transport] [transport_check_fds:1043] - transport_check_fds: transport->ReceiveCallback() - -1
[13:50:00:152] [16684:16685] [DEBUG:com.freerdp.core.rdp] [rdp_check_fds:1485] - transport_check_fds() - -1
[13:50:00:152] [16684:16685] [DEBUG:com.freerdp.core] [freerdp_check_fds:322] - rdp_check_fds() - -1
[13:50:00:152] [16684:16685] [ERROR:com.freerdp.core] [freerdp_check_event_handles:369] - freerdp_check_fds() failed - 0
[13:50:00:152] [16684:16685] [INFO:com.freerdp.client.x11] [xf_auto_reconnect:1417] - Network disconnect!
[13:50:00:152] [16684:16685] [ERROR:com.freerdp.client.x11] [xf_client_thread:1564] - Failed to check FreeRDP file descriptor

In the function "static int update_recv_surfcmd_frame_marker(rdpUpdate* update, wStream* s, UINT32 *length)" why do we need *length (ok it is the command length which gets initialized with 0..) ? Length gets set to 6.. but the stream length is not dependant on length ?

The whole code is very confusing ... why can't the coder write speaking variable names instead of _t _v _s _etc...?

T3N4K4 on 11 May 2017

@akallabeth I guess we do not have more options now ... could you give me your buildconfig from your freerdp and if possible instructions / a listing of your build environment ? This way I can try to look if any parameter I set in cmake breaks this ....

T3N4K4 on 9 Jun 2017

@T3N4K4 Tested with the nightlies, so no special build stuff involved except ci.freerdp.com

akallabeth on 9 Jun 2017

@akallabeth okay.. I will test it then with the nighlies again .. maybe I find something.

T3N4K4 on 9 Jun 2017

@akallabeth unfortunately still the same:

Mi 21. Jun 12:35:18 CEST 2017
[12:35:18:675] [16587:16589] [WARN][com.freerdp.core.nego] [nego_process_negotiation_failure:964] - Error: SSL_NOT_ALLOWED_BY_SERVER
[14:24:14:555] [16587:16589] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_update:387] - FASTPATH_UPDATETYPE_SURFCMDS - update_recv_surfcmds() - -1
[14:24:14:555] [16587:16589] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_update_data:632] - fastpath_recv_update_data: fastpath_recv_update() - -1
[14:24:14:555] [16587:16589] [ERROR][com.freerdp.core.fastpath] [fastpath_recv_updates:668] - fastpath_recv_update_data() fail
[14:24:14:555] [16587:16589] [ERROR][com.freerdp.core.transport] [transport_check_fds:1043] - transport_check_fds: transport->ReceiveCallback() - -1
[14:24:14:555] [16587:16589] [ERROR][com.freerdp.core] [freerdp_check_event_handles:369] - freerdp_check_fds() failed - 0
[14:24:14:556] [16587:16589] [ERROR][com.freerdp.client.x11] [xf_client_thread:1567] - Failed to check FreeRDP file descriptor

T3N4K4 on 21 Jun 2017

I have same error.
armhf.

potatofamily on 16 Jul 2017

any update on this?

akallabeth on 23 Nov 2017

@akallabeth:
@hardening fixed some bugs lately. One for the graphical subsystem concerning (+|-)bitmap-cache and one for gfx with windows 2016 server.
Rfx though seems to be still bugged. But as a matter of fact rfx with windows 2016 server is working. It just disconnects the session on 2012R2 (and below?) with the fastpath error.

T3N4K4 on 23 Nov 2017

look forward to fix it.

potatofamily on 27 Dec 2017

still disconnect the session on windows7.

potatofamily on 29 Dec 2017

Any update?

potatofamily on 11 Jan 2018

Ok, seems like you're lucky.
Reread the current edition of the spec and found something that may explain the issue.
Could you test out my branch https://github.com/akallabeth/FreeRDP/tree/surface_cmd_fix ?

akallabeth on 28 Feb 2018

Ok, closing this as the missing handler for the optional fields in the parser fixed with #4459 was most likely the cause of this.
Reopen/create a new issue if you can still reproduce this.

akallabeth on 1 Mar 2018

I still get the fast path error with the new FreeRDP version2.0-14997f96e3

https://pastebin.com/HG4cjZL6

frondlu on 12 Mar 2018

@frondlu could you please run with /log-level:trace? Otherwise the output is useless :/

akallabeth on 12 Mar 2018

will do

frondlu on 12 Mar 2018

@frondlu I've rechecked the code responsible and created https://github.com/akallabeth/FreeRDP/tree/fastpath_fix
What I think was going on is that in case of a compressed packet the stream capacity/length was holding only one fastpath update command, whereas in case of an uncompressed packet the stream capacity/length was matching all of the updates.

Since I can not reliably check this, it would be great if you could try it and tell if it is working with these modifications.

akallabeth on 13 Mar 2018

I've uploaded a log file here: https://ufile.io/f5mla

the user first logs in at tag: 14:34:16:238

he works until 3:30pm

freerdp crashes and then he logs on again at 15:30:25:692

for search references: user is john.doe and domain is ourdomain

frondlu on 13 Mar 2018

@frondlu looks like the last part is missing (and so the reason for the disconnect)
btw, maybe unrelated, but we have an unresolved memory corruption in /sound channel that will be fixed once #4453 is merged. could you either use a build with the pull already merged or disable sound for your test?

akallabeth on 14 Mar 2018

I'm not sure how "the last part is missing".

the user first logs in at tag: 14:34:16:238

he works until 3:30pm

freerdp crashes and then he logs on again at 15:30:25:692

every log shown after 15:30:25:692 is because it's a new session and we append to the log file. The crash should be show in the logs between 14:34:16:238 and 15:30:25:692

frondlu on 14 Mar 2018

@frondlu Ah, so you did reconnect after the disconnect? Assumed you just had recorded one session ;)

akallabeth on 14 Mar 2018

yup, I figured it was important to mention that we append to the log file :)

frondlu on 14 Mar 2018

here's a new log: https://ufile.io/bv3f8

Here's the info about how it happened:
The user logged in at 13:13:56:881
She emailed me from her phone at 14:59 to let me know that she had gotten kicked out. I'm assuming she got kicked out in the minute or 2 before hand.

I looked at the logs and found something interesting. The timestamps jump from:

[14:58:35:204] [7134:7135 There seems to be something missing here Could it be the pop up error message that was waiting to be acnknowledge by pressing OK, which I did around 15:07

[15:07:40:712] [16497:16498] [INFO][com.freerdp.client.common.cmdline] - loading channelEx rdpdr
[15:07:40:712] [16497:16498] [INFO][com.freerdp.client.common.cmdline] - loading channelEx rdpsnd

frondlu on 14 Mar 2018

Here's the most clean log that I think I'll be able to give you: https://ufile.io/0np6j

It happened to me, I didn't have the /sound parameter at all in my command. I had a youtube clip playing(no sound) and then all of a sudden, my screen disapears and my session is gone

happened at 16:06

frondlu on 14 Mar 2018

@frondlu yes, on a second glance I can see that now too :)

akallabeth on 15 Mar 2018

@frondlu looks like you encountered a different issue here. Created https://github.com/akallabeth/FreeRDP/tree/advanced_logging with advanced log output to pinpoint that, so if you could use a version based on that branch we could get rid of that one too.

akallabeth on 15 Mar 2018

here's a log file that I've obtain after a crash using the fastpath_fix branch: https://ufile.io/id1ek

frondlu on 15 Mar 2018

@frondlu Sorry, but please stop misusing the word crash ^^
Unless you can send me a crashdump it is none ;)

akallabeth on 16 Mar 2018

@frondlu As expected, the fastpath_fix log did not help. But I was able to find (and fix) the black screen issue, looks like a macro was broken (nasty one that is)

akallabeth on 16 Mar 2018

here's an advanced log file of a random disconnect that happened to me this morning: https://ufile.io/4akro

Also, right after the disconnect, my terminal was showing: https://pastebin.com/HuTiGV8y

frondlu on 16 Mar 2018

got another disconnect, here's the log file: https://ufile.io/su7d3

Also, this is what the terminal was displaying after the disconnect: https://pastebin.com/j0yV08YL

frondlu on 16 Mar 2018

@frondlu Ok, something is wrong here. The log files and terminal messages you posted are completely different.

akallabeth on 19 Mar 2018

@frondlu Anyway, looked through the code paths and found one suspicious call.
Updated the pull accordingly, so hope that this is it.
A note though: Could you please compress the log files? The download service is quite slow ;)

akallabeth on 19 Mar 2018

Here's the newest log after a crash that happened a couple of minutes ago: https://ufile.io/7sura

compressed as indicated, sorry :)

frondlu on 19 Mar 2018

@frondlu Since this log (again) did not have any more indication what is breaking, I've added some more messages to the branch.
At a location for a (possible) source of the issue I've eliminated that.
Starting to get old this one, hope we can find it finally.

akallabeth on 20 Mar 2018

After this most recent branch update, i have a new log .zip file taken after a disconnect: https://ufile.io/opj2m

frondlu on 20 Mar 2018

@frondlu Ok, great, still nothing. Updated the pull with logs for the last remaining path I could find (bandwidth auto detection)
If there is now still no log entry something else is fishy :/

akallabeth on 20 Mar 2018

here's a new log file with the latest branch of advanced logging: https://ufile.io/2upuh

I've noticed that this random disconnect happens when I have a youtube clip running(chrome or IE). Also, I should specify that it isn't in full screen mode.

I have a dual monitor setup going, youtube in on the left and I'm working on the right.

frondlu on 21 Mar 2018

@frondlu Ok, now I have to say your log file is impossible with the current branch. Could you check that xfreerdp /buildconfig states This is FreeRDP version 2.0.0-dev2 (c6c8dee9c)?

akallabeth on 21 Mar 2018

here's a good log: https://ufile.io/6trjx

I believe this compiled with the proper branch ID

frondlu on 22 Mar 2018

@frondlu Are you sure? /buildconfig should show the same hash (or short version of) as the command git log in the first line

akallabeth on 22 Mar 2018

it wasn't the proper build. You had made changes afterwards and I hadn't refreshed my page. I'm currently running commit c8215ea which is the most recent one. Once I have logs, i'll upload them.

thanks!

frondlu on 23 Mar 2018

@frondlu Ah, good ^^
Thought I'm going insane as the messages I was expecting were not there :/

akallabeth on 23 Mar 2018

this should be a good log: https://ufile.io/mhfst

frondlu on 23 Mar 2018

@frondlu sorry, no way.
there is no error log from any of the messages written when any of the subfunctions are called.
btw, /log-level:trace should add a bit more information, maybe that can reveal the culprit better.

akallabeth on 24 Mar 2018

here's a new log: https://ufile.io/9lgpo

my command line is the following: xfreerdp /v: *** /u: * /d: ** /multimon /sound /cert-ignore -sec-rdp -sec-nla /rfx /nsc /bpp:32 -grab-keyboard /network:lan +wallpaper +fonts -window-drag -menu-anims -toggle-fullscreen /log-level:trace 2>&1 |tee /home/lab/FreeRDP/logs/log.log

and my build version is: This is FreeRDP version 2.0.0-dev2 (c8215ea)

frondlu on 27 Mar 2018

here's another log: https://ufile.io/0v05m

frondlu on 27 Mar 2018

@frondlu Now we are on track again.
All the nice log messages for nothing, we are back in the other code path :/

akallabeth on 27 Mar 2018

@frondlu I've (yet again) updated the branch, now to accommodate for the new direction the log has taken me

akallabeth on 27 Mar 2018

here's a new log file, branch has been updated: https://ufile.io/skbf1

This is FreeRDP version 2.0.0-dev2 (1339e54)

frondlu on 27 Mar 2018

here's another one, newest branch as indicated in post above: https://ufile.io/ynlec

frondlu on 27 Mar 2018

here's another log: https://ufile.io/mk8g1

frondlu on 27 Mar 2018

@frondlu The first two logs contain the source of the issue, did you forget to add the 2>&1 on the third? There are again no error logs.
Anyway, added a possible workaround in the branch (may be a server or documentation bug, but can only tell after test)

akallabeth on 28 Mar 2018

here's a new log: https://ufile.io/33l9h

frondlu on 29 Mar 2018

@frondlu Ok, got the exact spot now. You don't, by any chance use one of the +async-* options?

akallabeth on 30 Mar 2018

xfreerdp /v:** /u:*** /d:** /multimon /sound /cert-ignore -sec-rdp -sec-nla /rfx /nsc /bpp:32 -grab-keyboard /network:lan +wallpaper +fonts -window-drag -menu-anims -toggle-fullscreen /log-level:trace 2>&1 |tee /home/lab/FreeRDP/logs/log.log

hate to say, but no. The command above is what i'm using

frondlu on 30 Mar 2018

Any update?

potatofamily on 22 Aug 2018

@potatofamily As it stands it seems to be an issue with certain RDP server versions violating the spec.
Using +auto-reconnect might mitigate.

akallabeth on 22 Aug 2018

@akallabeth +auto-reconnect does not seem to work, because it is stuck rather than disconnected. I have to kill the process.

potatofamily on 12 Oct 2018

@potatofamily Which version? Fixed some autoreconnect related issues with #4880, #4885 and others.

akallabeth on 12 Oct 2018

@akallabeth I am using the September 4th version. I will try the newest version.

potatofamily on 16 Oct 2018

FYI: I created that bug while I was working at Rangee GmbH. I quit there this year. Therefore I am currently not able to provide further information to that. Maybe you should contact then anyone of the current devs there. Sorry for the inconvenience.

T3N4K4 on 23 Oct 2018

Closing this as the only remaining issue is as protocol violation.
+auto-reconnect issues have been addressed with 2.0.0-rc4 and should be a workable mitigation.

akallabeth on 26 Nov 2018

Freerdp: Long term test - Freerdp disconnects with fastpath error

All 139 comments

Related issues