Client does not handle DesktopResize if heartbeat is enabled #5437

agners · 2019-06-17T11:24:04Z

Describe the bug
When connecting with a client to Weston running the RDP backend (which makes use of FreeRDP) with hearbeat enabled (+heartbeat). It only happens if the Weston --no-clients-resize flag is set. It seems that the call to DesktopResize (client->update->DesktopResize(client->context); in libweston/backend-rdp/rdp.c) is causing the client (or server?) to misbehave.

To Reproduce
Steps to reproduce the behavior:

Use Weston with RDP backend: weston --backend=rdp-backend.so --rdp-tls-key=tls.key --rdp-tls-cert=tls.crt --no-clients-resize
Connect using xfreerdp /v:localhost +heartbeat
Client will exit with an error

Expected behavior
The Client should show the Weston Desktop.

** Application details

FreeRDP 2.0.0-rc4 (noticed with master as well, where +heartbeat is default..., the reason we noticed this issue)
Command line: xfreerdp /v:localhost +heartbeat

$ xfreerdp /v:localhost +heartbeat /log-level:trace 
[13:22:08:232] [6740:6741] [INFO][com.freerdp.client.common.cmdline] - loading channelEx rdpdr
[13:22:08:232] [6740:6741] [INFO][com.freerdp.client.common.cmdline] - loading channelEx rdpsnd
[13:22:08:232] [6740:6741] [DEBUG][com.freerdp.channels.cliprdr.client] - VirtualChannelEntryEx
[13:22:08:232] [6740:6741] [INFO][com.freerdp.client.common.cmdline] - loading channelEx cliprdr
[13:22:08:233] [6740:6741] [INFO][com.freerdp.client.x11] - No user name set. - Using login name: ags
[13:22:08:233] [6740:6741] [DEBUG][com.freerdp.client.x11] - Searching for XInput pointer device
[13:22:08:234] [6740:6741] [DEBUG][com.freerdp.client.x11] - Pointer device: 6
[13:22:08:236] [6740:6741] [DEBUG][com.freerdp.core.nego] - Enabling security layer negotiation: TRUE
[13:22:08:236] [6740:6741] [DEBUG][com.freerdp.core.nego] - Enabling restricted admin mode: FALSE
[13:22:08:236] [6740:6741] [DEBUG][com.freerdp.core.nego] - Enabling RDP security: TRUE
[13:22:08:236] [6740:6741] [DEBUG][com.freerdp.core.nego] - Enabling TLS security: TRUE
[13:22:08:236] [6740:6741] [DEBUG][com.freerdp.core.nego] - Enabling NLA security: TRUE
[13:22:08:237] [6740:6741] [DEBUG][com.freerdp.core.nego] - Enabling NLA extended security: FALSE
[13:22:08:237] [6740:6741] [DEBUG][com.freerdp.core.nego] - state: NEGO_STATE_NLA
[13:22:08:237] [6740:6741] [DEBUG][com.freerdp.core.nego] - Attempting NLA security
[13:22:08:237] [6740:6741] [DEBUG][com.freerdp.core] - connecting to peer 127.0.0.1
[13:22:08:237] [6740:6741] [DEBUG][com.freerdp.core.nego] - RequestedProtocols: 3
[13:22:08:238] [6740:6741] [DEBUG][com.freerdp.core.nego] - RDP_NEG_RSP
[13:22:08:238] [6740:6741] [DEBUG][com.freerdp.core.nego] - selected_protocol: 1
[13:22:08:238] [6740:6741] [DEBUG][com.freerdp.core.nego] - state: NEGO_STATE_FINAL
[13:22:08:238] [6740:6741] [DEBUG][com.freerdp.core.nego] - Negotiated TLS security
[13:22:08:238] [6740:6741] [DEBUG][com.freerdp.core.nego] - nego_security_connect with PROTOCOL_TLS
[13:22:08:240] [6740:6741] [DEBUG][com.freerdp.core.gcc] - Server rdp encryption method: NONE
[13:22:08:240] [6740:6741] [DEBUG][com.freerdp.core.info] - Client Info Packet Flags = INFO_MOUSE|INFO_DISABLECTRLALTDEL|INFO_UNICODE|INFO_MAXIMIZESHELL|INFO_LOGONNOTIFY|INFO_COMPRESSION|INFO_ENABLEWINDOWSKEY|INFO_FORCE_ENCRYPTED_CS_PDU|INFO_LOGONERRORS|INFO_MOUSE_HAS_WHEEL|INFO_NOAUDIOPLAYBACK
[13:22:08:240] [6740:6741] [DEBUG][com.winpr.timezone] - tz: Bias=-60 sn='W. Europe Standard Time' dln='W. Europe Daylight Time'
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x1f size=37 channelId=1008)
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x14 size=41 channelId=1008)
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x14 size=41 channelId=1008)
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x27 size=41 channelId=1008)
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - recv Synchronize Data PDU (0x1F), length: 4
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - recv Control Data PDU (0x14), length: 8
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - recv Control Data PDU (0x14), length: 8
[13:22:08:241] [6740:6741] [DEBUG][com.freerdp.core.rdp] - recv Font Map Data PDU (0x28), length: 8
[13:22:08:241] [6740:6741] [INFO][com.freerdp.gdi] - Local framebuffer format  PIXEL_FORMAT_BGRX32
[13:22:08:241] [6740:6741] [INFO][com.freerdp.gdi] - Remote framebuffer format PIXEL_FORMAT_RGB16
[13:22:08:265] [6740:6741] [INFO][com.winpr.clipboard] - initialized POSIX local file subsystem
[13:22:08:266] [6740:6758] [INFO][com.freerdp.channels.rdpsnd.client] - Loaded fake backend for rdpsnd
[13:22:08:266] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x1f size=37 channelId=1008)
[13:22:08:266] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x14 size=41 channelId=1008)
[13:22:08:266] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x14 size=41 channelId=1008)
[13:22:08:266] [6740:6741] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x27 size=41 channelId=1008)
[13:22:08:266] [6740:6741] [DEBUG][com.freerdp.core.update] - SurfaceFrameMarker: action: Begin (0) id: 1
[13:22:08:266] [6740:6741] [DEBUG][com.freerdp.gdi] - frameId 1 frameAction 0
[13:22:08:267] [6740:6741] [DEBUG][com.freerdp.core.rdp] - transport_check_fds() - -1
[13:22:08:267] [6740:6741] [ERROR][com.freerdp.core.rdp] - rdp_recv_tpkt_pdu: rdp_recv_deactivate_all() fail
[13:22:08:267] [6740:6741] [DEBUG][com.freerdp.core.rdp] - CONNECTION_STATE_ACTIVE - rdp_recv_pdu() - -1
[13:22:08:267] [6740:6741] [ERROR][com.freerdp.core.transport] - transport_check_fds: transport->ReceiveCallback() - -1
[13:22:08:267] [6740:6741] [DEBUG][com.freerdp.core.rdp] - transport_check_fds() - -1
[13:22:08:267] [6740:6741] [DEBUG][com.freerdp.core] - rdp_check_fds() - -1
[13:22:08:267] [6740:6741] [ERROR][com.freerdp.core] - freerdp_check_fds() failed - 0
[13:22:08:267] [6740:6741] [INFO][com.freerdp.client.common] - Network disconnect!
[13:22:08:267] [6740:6741] [ERROR][com.freerdp.client.x11] - Failed to check FreeRDP file descriptor
[13:22:08:267] [6740:6758] [DEBUG][com.freerdp.channels.rdpsnd.client] - Device already closed

The text was updated successfully, but these errors were encountered:

akallabeth · 2019-06-18T11:39:52Z

@agners Sorry for the silly question, but I don´t get the error part correct from your description.

If you enable heartbeat the client disconnects, ok
Does the server send an invalid PDU? (from [13:22:08:267] [6740:6741] [ERROR][com.freerdp.core.rdp] - rdp_recv_tpkt_pdu: rdp_recv_deactivate_all() fail this seams possible)
Does the server disconnect the client? (what does the server tell in the logs?)
Does this also happen if you don´t connect from localhost? (some exotic rdp features require a real network and fail on loopback)

(sorry, can not get it to work with fedora 30 here, weston is crashing :/)

agners · 2019-06-18T13:09:17Z

@akallabeth

It is not 100% clear to me whether its a server side or client side issue. I just noticed that when I commented out the DesktopResize call on the server side, it works (although, desktop has wrong size then of course).

We noticed this first when connecting remotely (connecting to an embedded board), however, to debug it I only used localhost.

Servers side log with WLOG_LEVEL=trace looks like this:

Date: 2019-06-18 CEST
[15:07:45.305] weston 6.0.90
               https://wayland.freedesktop.org
               Bug reports to: https://gitlab.freedesktop.org/wayland/weston/issues/
               Build: 6.0.0-91-g5ca4ef13+
[15:07:45.305] Command line: /home/ags/projects/weston/weston/build/compositor/weston --backend=/home/ags/projects/weston/weston/build/libweston/backend-rdp/rdp-backend.so --rdp-tls-key=/home/ags/projects/weston/weston/tls.key --rdp-tls-cert=/home/ags/projects/weston/weston/tls.crt --no-clients-resize
[15:07:45.305] OS: Linux, 4.19.50-1-lts, #1 SMP Tue Jun 11 19:36:23 CEST 2019, x86_64
[15:07:45.305] Starting with no config file.
[15:07:45.305] weston_compositor_set_xkb_rule_names, context (nil)
[15:07:45.305] Output repaint window is 7 ms maximum.
[15:07:45.305] Loading module '/usr/local/lib/libweston-7/rdp-backend.so'
[15:07:45.323] using FreeRDP version 2.0.0
[15:07:45.323] TLS support activated
[15:07:45:441] [1776:1776] [INFO][com.freerdp.core.listener] - Listening on 0.0.0.0:3389
[15:07:45.323] Registered plugin API 'weston_rdp_output_api_v1' of size 8
[15:07:45.323] Output 'rdp' enabled with head(s) rdp
[15:07:45.323] Compositor capabilities:
               arbitrary surface rotation: yes
               screen capture uses y-flip: yes
               presentation clock: CLOCK_MONOTONIC_RAW, id 4
               presentation clock resolution: 0.000000001 s
[15:07:45.323] libwayland: unable to lock lockfile /run/user/1000/wayland-0.lock, maybe another compositor is running
[15:07:45.324] Loading module '/usr/local/lib/weston/desktop-shell.so'
[15:07:45.324] launching '/usr/local/libexec/weston-keyboard'
[15:07:45.324] launching '/usr/local/libexec/weston-desktop-shell'
[15:07:46:088] [1776:1776] [DEBUG][com.freerdp.core.nego] - received cookie [Cookie: mstshash=ags]
[15:07:46:088] [1776:1776] [DEBUG][com.freerdp.core.nego] - RDP_NEG_REQ: RequestedProtocol: 0x00000003
[15:07:46:088] [1776:1776] [INFO][com.freerdp.core.connection] - Client Security: NLA:1 TLS:1 RDP:0
[15:07:46:088] [1776:1776] [INFO][com.freerdp.core.connection] - Server Security: NLA:0 TLS:1 RDP:1
[15:07:46:088] [1776:1776] [INFO][com.freerdp.core.connection] - Negotiated Security: NLA:0 TLS:1 RDP:0
[15:07:46:090] [1776:1776] [INFO][com.freerdp.core.connection] - Accepted client: trochilidae
[15:07:46:090] [1776:1776] [INFO][com.freerdp.core.connection] - Accepted channels:
[15:07:46:090] [1776:1776] [INFO][com.freerdp.core.connection] -  rdpdr
[15:07:46:090] [1776:1776] [INFO][com.freerdp.core.connection] -  rdpsnd
[15:07:46:090] [1776:1776] [INFO][com.freerdp.core.connection] -  cliprdr
[15:07:46:090] [1776:1776] [INFO][com.freerdp.core.gcc] - Active rdp encryption level: NONE
[15:07:46:090] [1776:1776] [INFO][com.freerdp.core.gcc] - Selected rdp encryption method: NONE
[15:07:46:090] [1776:1776] [DEBUG][com.freerdp.core.info] - rdp client address: [127.0.0.1]
[15:07:46:090] [1776:1776] [DEBUG][com.freerdp.core.info] - rdp client dir: [C:\Windows\System32\mstscax.dll]
[15:07:46:090] [1776:1776] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x1f size=37 channelId=1008)
[15:07:46:090] [1776:1776] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x14 size=41 channelId=1008)
[15:07:46:090] [1776:1776] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x14 size=41 channelId=1008)
[15:07:46:090] [1776:1776] [DEBUG][com.freerdp.core.rdp] - rdp_send_data_pdu: sending data (type=0x28 size=41 channelId=1008)
[15:07:46.973] kbd_layout:0x409 kbd_type:0x4 kbd_subType:0x0 kbd_functionKeys:0xc
[15:07:46.973] xf_peer_activate: matching layout=us variant=(null)
[15:07:46:123] [1776:1776] [ERROR][com.freerdp.core.transport] - BIO_should_retry returned a system error 32: Broken pipe
[15:07:46:123] [1776:1776] [ERROR][com.freerdp.core.transport] - BIO_should_retry returned an error: error:1409E10F:SSL routines:ssl3_write_bytes:bad length
[15:07:46:123] [1776:1776] [ERROR][com.freerdp.core.transport] - BIO_read returned a system error 0: Success
[15:07:46:123] [1776:1776] [DEBUG][com.freerdp.core.transport] - transport_check_fds: transport_read_pdu() - -1
[15:07:46:123] [1776:1776] [DEBUG][com.freerdp.core.rdp] - transport_check_fds() - -1
[15:07:47.006] unable to checkDescriptor for 0x55e1ec7a9080

akallabeth · 2019-06-18T13:28:20Z

Had a short look and the main difference between our shadow server and weston is that the resizing code is part of the Activate callback whereas in shadow it is done in PostConnect.
Might be a starting point, but to be sure some investigation is necessary.

agners · 2019-06-18T15:09:43Z

I gave this a shot with the following patch, however, the client has still the same issue and shows the very same output. Also here, when I comment out DesktopResize, things start to work.

diff --git a/libweston/backend-rdp/rdp.c b/libweston/backend-rdp/rdp.c
index 1f39d03c..82dc2fb5 100644
--- a/libweston/backend-rdp/rdp.c
+++ b/libweston/backend-rdp/rdp.c
@@ -969,37 +969,6 @@ xf_peer_activate(freerdp_peer* client)
 		return FALSE;
 	}
 
-	if (output->base.width != (int)settings->DesktopWidth ||
-			output->base.height != (int)settings->DesktopHeight)
-	{
-		if (b->no_clients_resize) {
-			/* RDP peers don't dictate their resolution to weston */
-			if (!settings->DesktopResize) {
-				/* peer does not support desktop resize */
-				weston_log("%s: client doesn't support resizing, closing connection\n", __FUNCTION__);
-				return FALSE;
-			} else {
-				settings->DesktopWidth = output->base.width;
-				settings->DesktopHeight = output->base.height;
-				client->update->DesktopResize(client->context);
-			}
-		} else {
-			/* ask weston to adjust size */
-			struct weston_mode new_mode;
-			struct weston_mode *target_mode;
-			new_mode.width = (int)settings->DesktopWidth;
-			new_mode.height = (int)settings->DesktopHeight;
-			target_mode = ensure_matching_mode(&output->base, &new_mode);
-			if (!target_mode) {
-				weston_log("client mode not found\n");
-				return FALSE;
-			}
-			weston_output_mode_set_native(&output->base, target_mode, 1);
-			output->base.width = new_mode.width;
-			output->base.height = new_mode.height;
-		}
-	}
-
 	weston_output = &output->base;
 	RFX_RESET(peerCtx->rfx_context, weston_output->width, weston_output->height);
 	NSC_RESET(peerCtx->nsc_context, weston_output->width, weston_output->height);
@@ -1076,6 +1045,46 @@ xf_peer_activate(freerdp_peer* client)
 static BOOL
 xf_peer_post_connect(freerdp_peer *client)
 {
+	RdpPeerContext *peerCtx;
+	struct rdp_backend *b;
+	struct rdp_output *output;
+	rdpSettings *settings;
+
+	peerCtx = (RdpPeerContext *)client->context;
+	b = peerCtx->rdpBackend;
+	output = b->output;
+	settings = client->settings;
+	if (output->base.width != (int)settings->DesktopWidth ||
+			output->base.height != (int)settings->DesktopHeight)
+	{
+		if (b->no_clients_resize) {
+			/* RDP peers don't dictate their resolution to weston */
+			if (!settings->DesktopResize) {
+				/* peer does not support desktop resize */
+				weston_log("%s: client doesn't support resizing, closing connection\n", __FUNCTION__);
+				return FALSE;
+			} else {
+				settings->DesktopWidth = output->base.width;
+				settings->DesktopHeight = output->base.height;
+				client->update->DesktopResize(client->context);
+			}
+		} else {
+			/* ask weston to adjust size */
+			struct weston_mode new_mode;
+			struct weston_mode *target_mode;
+			new_mode.width = (int)settings->DesktopWidth;
+			new_mode.height = (int)settings->DesktopHeight;
+			target_mode = ensure_matching_mode(&output->base, &new_mode);
+			if (!target_mode) {
+				weston_log("client mode not found\n");
+				return FALSE;
+			}
+			weston_output_mode_set_native(&output->base, target_mode, 1);
+			output->base.width = new_mode.width;
+			output->base.height = new_mode.height;
+		}
+	}
+
 	return TRUE;
 }

akallabeth · 2019-06-19T07:15:38Z

sorry, can only tell you what I know.
you can test with freerdp shadow server against xfreerdp yourself (the former does resize the client to the required size) and that one works.
Might still need some other patch, but don´t know without further research.

hardening · 2019-06-19T09:11:29Z

@agners I will give a look tomorrow (I did write the weston backend)

agners · 2019-06-19T10:49:58Z

@hardening thx! As you can see above, I tried a few things, but for me its really not clear at that point whether that is really a backend issue.

hardening · 2019-06-19T12:55:34Z

The bug can also be in the server-side part of FreeRDP used by weston...

agners · 2019-06-27T13:55:15Z

@hardening did you had a chance looking into it?

akallabeth · 2020-03-10T14:13:28Z

@hardening you had time to look at this?

akallabeth added the waiting-feedback label Mar 10, 2020

akallabeth assigned hardening Mar 10, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Client does not handle DesktopResize if heartbeat is enabled #5437

Client does not handle DesktopResize if heartbeat is enabled #5437

agners commented Jun 17, 2019

akallabeth commented Jun 18, 2019

agners commented Jun 18, 2019

akallabeth commented Jun 18, 2019

agners commented Jun 18, 2019

akallabeth commented Jun 19, 2019

hardening commented Jun 19, 2019

agners commented Jun 19, 2019

hardening commented Jun 19, 2019

agners commented Jun 27, 2019

akallabeth commented Mar 10, 2020

Client does not handle DesktopResize if heartbeat is enabled #5437

Client does not handle DesktopResize if heartbeat is enabled #5437

Comments

agners commented Jun 17, 2019

akallabeth commented Jun 18, 2019

agners commented Jun 18, 2019

akallabeth commented Jun 18, 2019

agners commented Jun 18, 2019

akallabeth commented Jun 19, 2019

hardening commented Jun 19, 2019

agners commented Jun 19, 2019

hardening commented Jun 19, 2019

agners commented Jun 27, 2019

akallabeth commented Mar 10, 2020