Cannot connect from Wyse Thin clients

neutrinolabs / xrdp

xrdp: an open source RDP server

http://www.xrdp.org/

Apache License 2.0

5.62k stars 1.73k forks source link

Cannot connect from Wyse Thin clients #2166

Closed christheradioguy closed 2 years ago

christheradioguy commented 2 years ago

Hey All,

I have stumbled across this issue https://github.com/neutrinolabs/xrdp/issues/874 while researching an issue I have been having with some Wyse sx0 thin clients and I believe it is the same issue.

The original issue was closed because the developers were unable to get a hold of one of the clients, I have a box of them and would be happy to ship a few out if it could help fix this issue.

metalefty commented 2 years ago

Hi, thanks for the offer and sorry for the inconvenience.

@matt335672 Can you spend time on this? Unfortunately, I can't spend much time on this now even if I received the hardware client. I think you're most eligible person for receiving the hardware client.

@jsorg71 How about you? If you received the client, can you work on that?

matt335672 commented 2 years ago

I remember these from a previous life. I ran one as an ICA client for quite a few years, and it seemed pretty solid. I never tried it with native RDP though.

@christheradioguy - we might be able to sort this out without shipping a box depending on how you're set up.

TLS may be a non-starter - the protocol has moved on since 2008. Also, in the leaflet linked from #874 (assuming you have an s10), SSL/TLS is only mentioned with respect to ICA.

A couple of questions for you:- 1) For the purposes of others reading this thread, can you determine the model number of the machine, and the installed firmware? this site has some useful info. 2) Are you in a position to build software where you are? 3) Can you try with v0.9.17 or later (ideally the latest devel build which has better logging) and the following settings in xrdp.ini:-

   security_layer=rdp
   crypt_level=low

If by some chance that works we can improve the security until it breaks.

christheradioguy commented 2 years ago

Thanks for the reply, I'll try compiling the latest version over the weekend. I just tried with

security_layer=rdp
crypt_level=low

on the latest package supplied with Linux Mint 20.3 (xrdp 0.9.12) and just get an immediate disconnection from the thin client and then the following log:

[20220303-21:46:46] [DEBUG] TLSv1.3 enabled
[20220303-21:46:46] [DEBUG] TLSv1.2 enabled
[20220303-21:46:46] [DEBUG] Security layer: requested 0, selected 0
[20220303-21:46:46] [INFO ] connected client computer name: WT008064857377
[20220303-21:46:46] [INFO ] adding channel item name rdpdr chan_id 1004 flags 0x82000000
[20220303-21:46:46] [INFO ] adding channel item name cliprdr chan_id 1005 flags 0x98000000
[20220303-21:46:46] [INFO ] adding channel item name CUVA chan_id 1006 flags 0x88000000
[20220303-21:46:46] [INFO ] adding channel item name AURTCX chan_id 1007 flags 0x88000000
[20220303-21:46:46] [INFO ] adding channel item name USBVDX chan_id 1008 flags 0x88000000
[20220303-21:46:46] [INFO ] adding channel item name CARANOC chan_id 1009 flags 0x82000000
[20220303-21:46:46] [DEBUG] Closed socket 12 (AF_INET6 ::ffff:10.4.9.34 port 3389)

christheradioguy commented 2 years ago

Software version is 6.5.0_30, I'm assuming this is an S10 because it has 0MB of flash (according to the hardware information page in Wyse OS)

matt335672 commented 2 years ago

Thanks.

It looks like it's at least getting the channel list from the client. There's a couple of standard ones there, and then some specials.

That's quite early on in the connection sequence ([MS-RDPBCGR]).Technically it's the 'client network data' part of the Client MCS Connect Initial PDU. On the face of it, it looks like were either getting something in the PDU we don't like, or the client doesn't like our response. Please be aware I'm not an expert in this bit of the code.

Compiling the latest version will be really helpful. If you build the latest xrdp version with --enable-devel-all you'll get a lot more debug logging which may be useful. That can really impact performance, but at the moment that's not likely to be an issue.

christheradioguy commented 2 years ago

Alright, had some free time this evening and compiled the latest version from the repo:

xrdp --version
Argument 0 - xrdp
Argument 1 - --version
xrdp 0.9.18
  A Remote Desktop Protocol Server.
  Copyright (C) 2004-2020 Jay Sorg, Neutrino Labs, and all contributors.
  See https://github.com/neutrinolabs/xrdp for more information.

  Configure options:
      --enable-devel-all

  Compiled with OpenSSL 1.1.1f  31 Mar 2020

Tried connecting from the thin client and getting the following log:

[20220304-21:28:41] [INFO ] [g_sck_accept(os_calls.c:1384)] Socket 12: AF_INET connection received from 10.13.37.205 port 3244
[20220304-21:28:41] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220304-21:28:41] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20220304-21:28:41] [INFO ] [xrdp_iso_negotiate_security(xrdp_iso.c:194)] Security protocol: configured [SSL|RDP], requested [RDP], selected [RDP]
[20220304-21:28:41] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1974)] Connected client computer name: WT008064857377
[20220304-21:28:41] [ERROR] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:746)] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25
[20220304-21:28:41] [ERROR] [xrdp_mcs_incoming(xrdp_mcs.c:1242)] [MCS Connection Sequence] receive channel join request failed
[20220304-21:28:41] [ERROR] [xrdp_sec_incoming(xrdp_sec.c:2869)] xrdp_sec_incoming: xrdp_mcs_incoming failed
[20220304-21:28:41] [ERROR] [xrdp_rdp_incoming(xrdp_rdp.c:921)] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20220304-21:28:41] [ERROR] [xrdp_process_main_loop(xrdp_process.c:302)] xrdp_process_main_loop: libxrdp_process_incoming failed

Let me know what else I can provide

christheradioguy commented 2 years ago

I just realized when I ran make install the crypt and security_layer were reset. I have put them back to RDP and low, here's the latest log

[20220304-21:31:23] [INFO ] [g_sck_accept(os_calls.c:1384)] Socket 12: AF_INET connection received from 10.13.37.205 port 3247
[20220304-21:31:23] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220304-21:31:23] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20220304-21:31:23] [INFO ] [xrdp_iso_negotiate_security(xrdp_iso.c:194)] Security protocol: configured [RDP], requested [RDP], selected [RDP]
[20220304-21:31:23] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1974)] Connected client computer name: WT008064857377
[20220304-21:31:23] [ERROR] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:746)] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25
[20220304-21:31:23] [ERROR] [xrdp_mcs_incoming(xrdp_mcs.c:1242)] [MCS Connection Sequence] receive channel join request failed
[20220304-21:31:23] [ERROR] [xrdp_sec_incoming(xrdp_sec.c:2869)] xrdp_sec_incoming: xrdp_mcs_incoming failed
[20220304-21:31:23] [ERROR] [xrdp_rdp_incoming(xrdp_rdp.c:921)] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20220304-21:31:23] [ERROR] [xrdp_process_main_loop(xrdp_process.c:302)] xrdp_process_main_loop: libxrdp_process_incoming failed

TOMATO-ONE commented 2 years ago

Hello! @christheradioguy @matt335672

I had a WYSE 1200LE Terminal over 10 years ago, but no longer have it. I think ThinOS was a robust terminal with very fast system start-up.

I was interested in this issue, so I got a Dell WYSE 3040 from an online auction and tested it. As it turned out, I was able to connect to xrdp with standard RDP in ThinOS.

my Terminal: WYSE 3040 ThinOS System Version 8.5_009 , Supported RDP10.0
my Host: CentOS7 , xrdp 0.9.18.1  , xorgxrdp 0.2.18

security_layer=negotiate
crypt_level=high

I assume that the connection was made because ThinOS is a newer version. Please let me know if you need my logs for comparison.

christheradioguy commented 2 years ago

Hello! @christheradioguy @matt335672

I had a WYSE 1200LE Terminal over 10 years ago, but no longer have it. I think ThinOS was a robust terminal with very fast system start-up.

I was interested in this issue, so I got a Dell WYSE 3040 from an online auction and tested it. As it turned out, I was able to connect to xrdp with standard RDP in ThinOS.
my Terminal: WYSE 3040 ThinOS System Version 8.5_009 , Supported RDP10.0
my Host: CentOS7 , xrdp 0.9.18.1  , xorgxrdp 0.2.18

security_layer=negotiate
crypt_level=high
I assume that the connection was made because ThinOS is a newer version. Please let me know if you need my logs for comparison.

Very interesting! I have been unable to get connected using those settings, however, as you say you are running on a much newer version of ThinOS.

I'll have to see what the latest version supported by the SX0 is, maybe there's a chance I can upgrade it to a newer version, though I suspect I might be on the latest

TOMATO-ONE commented 2 years ago

I have also looked into the Sx0 series of devices. The Sx0 has ThinOS Ver 6.5 installed on the built-in 2 MB NOR Flash.

The Sx0 can be upgraded to netboot-only firmware. In that case, as far as I know, it can be upgraded to ThinOS Ver 7.1. However, once upgraded to netboot-only firmware, it seems that it cannot be reverted.

christheradioguy commented 2 years ago

@TOMATO-ONE I have a box of these things so I figured I'd update one of them to 7.1 and it worked. Successful connection to xrdp using the following settings:

security_layer=negotiate
crypt_level=high

So the issue seems to be with firmware version 6.5 and earlier.

My immediate issue is now resolved with the 7.1 firmware, but @matt335672 if you're still interested in gathering information about the encryption issue on the older firmware I'm happy to help as I have many of these on the older firmware.

TOMATO-ONE commented 2 years ago

I record the situation at the moment for future viewers of this issue.

I have installed different versions of ThinOS on my 3040 and tried connecting to xrdp, all with success.

my Host: CentOS 7 x86_64 , xrdp 0.9.18.1, xorgxrdp 0.2.18 
my Terminal : DELL Wyse 3040 with 8GB eMMC/WiFi
ThinOS versions tested:  8.5.009, 8.6.710, 9.1.6108

Note: Ver 8.5.009 and Ver 8.6.710 are faster than Ver 9.1.6108 in terms of screen update speed.

matt335672 commented 2 years ago

@TOMATO-ONE - that's really helpful. Thanks for your input.

@christheradioguy - the errors you're getting are not related to encryption, but rather to the connection setup sequence to do with channels.

Referring to section 1.3.1.1 of [MS-RDPBCGR], xrdp sends an 'MCS Attach User Confirm PDU`, and then expects a number of 'Channel Join Request PDUs'. This message is telling us that we've got a 'send data request PDU' where we were expecting a 'Channel join request PDU':-

[20220304-21:31:23] [ERROR] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:746)] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25

Looking at the code, it looks like the thin client thinks there are less channels than the server is expecting to support.

We can get more logging if you set the logging level to DEBUG. Or you could try playing around with the requested facilities on the ThinOS (although I have no idea how you'd do that).

I can't find any on-line release notes for ThinOS that old, so I'm unable to advise you on what extra facilities may be present on the newer firmware.

matt335672 commented 2 years ago

@christheradioguy - do you want to take this any further?

christheradioguy commented 2 years ago

Yeah, I'll try and gather some more info with the DEBUG log level this weekend.

christheradioguy commented 2 years ago

Alright, here's what I get with DEBUG mode:

[20220404-19:26:37] [INFO ] setting send buffer to 262144 bytes
[20220404-19:26:37] [INFO ] send buffer set to 425984 bytes
[20220404-19:26:37] [INFO ] xrdp_listen_pp done
[20220404-19:26:37] [DEBUG] Closed socket 7 (AF_INET 0.0.0.0:3389)
[20220404-19:26:39] [INFO ] starting xrdp with pid 34088
[20220404-19:26:39] [INFO ] address [0.0.0.0] port [3389] mode 1
[20220404-19:26:39] [INFO ] listening to port 3389 on 0.0.0.0
[20220404-19:26:39] [INFO ] setting send buffer to 262144 bytes
[20220404-19:26:39] [INFO ] send buffer set to 425984 bytes
[20220404-19:26:39] [INFO ] xrdp_listen_pp done
[20220404-19:35:15] [INFO ] Socket 12: AF_INET connection received from 10.13.37.123 port 3400
[20220404-19:35:15] [DEBUG] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220404-19:35:15] [DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20220404-19:35:15] [DEBUG] item ini_version, value 1
[20220404-19:35:15] [DEBUG] item fork, value true
[20220404-19:35:15] [DEBUG] item port, value 3389
[20220404-19:35:15] [DEBUG] item use_vsock, value false
[20220404-19:35:15] [DEBUG] item tcp_nodelay, value false
[20220404-19:35:15] [DEBUG] item tcp_keepalive, value true
[20220404-19:35:15] [DEBUG] item tcp_send_buffer_bytes, value 262144
[20220404-19:35:15] [DEBUG] item security_layer, value negotiate
[20220404-19:35:15] [DEBUG] item crypt_level, value low
[20220404-19:35:15] [DEBUG] item certificate, value 
[20220404-19:35:15] [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220404-19:35:15] [DEBUG] item key_file, value 
[20220404-19:35:15] [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
[20220404-19:35:15] [DEBUG] item ssl_protocols, value TLSv1.2, TLSv1.3
[20220404-19:35:15] [DEBUG] TLSv1.3 enabled
[20220404-19:35:15] [DEBUG] TLSv1.2 enabled
[20220404-19:35:15] [DEBUG] item autorun, value 
[20220404-19:35:15] [DEBUG] item allow_channels, value true
[20220404-19:35:15] [DEBUG] item allow_multimon, value true
[20220404-19:35:15] [DEBUG] item bitmap_cache, value true
[20220404-19:35:15] [DEBUG] item bitmap_compression, value true
[20220404-19:35:15] [DEBUG] item bulk_compression, value true
[20220404-19:35:15] [DEBUG] item max_bpp, value 128
[20220404-19:35:15] [DEBUG] item xserverbpp, value 128
[20220404-19:35:15] [DEBUG] item use_compression, value yes
[20220404-19:35:15] [DEBUG] item new_cursors, value true
[20220404-19:35:15] [DEBUG] item use_fastpath, value both
[20220404-19:35:15] [DEBUG] item blue, value 009cb5
[20220404-19:35:15] [DEBUG] item grey, value dedede
[20220404-19:35:15] [DEBUG] item ls_top_window_bg_color, value 009cb5
[20220404-19:35:15] [DEBUG] item ls_width, value 350
[20220404-19:35:15] [DEBUG] item ls_height, value 430
[20220404-19:35:15] [DEBUG] item ls_bg_color, value dedede
[20220404-19:35:15] [DEBUG] item ls_logo_filename, value 
[20220404-19:35:15] [DEBUG] item ls_logo_x_pos, value 55
[20220404-19:35:15] [DEBUG] item ls_logo_y_pos, value 50
[20220404-19:35:15] [DEBUG] item ls_label_x_pos, value 30
[20220404-19:35:15] [DEBUG] item ls_label_width, value 65
[20220404-19:35:15] [DEBUG] item ls_input_x_pos, value 110
[20220404-19:35:15] [DEBUG] item ls_input_width, value 210
[20220404-19:35:15] [DEBUG] item ls_input_y_pos, value 220
[20220404-19:35:15] [DEBUG] item ls_btn_ok_x_pos, value 142
[20220404-19:35:15] [DEBUG] item ls_btn_ok_y_pos, value 370
[20220404-19:35:15] [DEBUG] item ls_btn_ok_width, value 85
[20220404-19:35:15] [DEBUG] item ls_btn_ok_height, value 30
[20220404-19:35:15] [DEBUG] item ls_btn_cancel_x_pos, value 237
[20220404-19:35:15] [DEBUG] item ls_btn_cancel_y_pos, value 370
[20220404-19:35:15] [DEBUG] item ls_btn_cancel_width, value 85
[20220404-19:35:15] [DEBUG] item ls_btn_cancel_height, value 30
[20220404-19:35:15] [INFO ] Security protocol: configured [SSL|RDP], requested [RDP], selected [RDP]
[20220404-19:35:15] [DEBUG] Using RDP security, and reading the server configuration
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive connection request
[20220404-19:35:15] [INFO ] Connected client computer name: WT00806465d8c3
[20220404-19:35:15] [DEBUG] Client supports 40 bit encryption
[20220404-19:35:15] [DEBUG] Client supports 128 bit encryption
[20220404-19:35:15] [DEBUG] Client supports 56 bit encryption
[20220404-19:35:15] [DEBUG] Client supports fips encryption
[20220404-19:35:15] [DEBUG] Client and server both support low encryption, using RDP 40-bit encryption.
[20220404-19:35:15] [DEBUG] Adding channel: name rdpdr, channel id 1004, flags 0x82000000
[20220404-19:35:15] [DEBUG] Adding channel: name cliprdr, channel id 1005, flags 0x98000000
[20220404-19:35:15] [DEBUG] Adding channel: name CUVA, channel id 1006, flags 0x88000000
[20220404-19:35:15] [DEBUG] Adding channel: name AURTCX, channel id 1007, flags 0x88000000
[20220404-19:35:15] [DEBUG] Adding channel: name USBVDX, channel id 1008, flags 0x88000000
[20220404-19:35:15] [DEBUG] Adding channel: name CARANOC, channel id 1009, flags 0x82000000
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] construct connection reponse
[20220404-19:35:15] [DEBUG] using 2048 bit RSA key
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send connection reponse
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive erect domain request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive attach user request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send attach user confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220404-19:35:15] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220404-19:35:16] [ERROR] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25
[20220404-19:35:16] [ERROR] [MCS Connection Sequence] receive channel join request failed
[20220404-19:35:16] [ERROR] xrdp_sec_incoming: xrdp_mcs_incoming failed
[20220404-19:35:16] [ERROR] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20220404-19:35:16] [ERROR] xrdp_process_main_loop: libxrdp_process_incoming failed
[20220404-19:35:16] [DEBUG] Closed socket 12 (AF_INET 10.4.9.34:3389)

matt335672 commented 2 years ago

There seems to be a mismatch between the number of channels we're expecting, and the number of channel join requests that are sent.

What version of xrdp are you using for this? The version I'm looking at has much better logging in this area, but it needs to be built with the enable-devel-logging (or --enable-devel-all) argument to configure.

christheradioguy commented 2 years ago

Apologies, I forgot to compile with the --enable-devel-all argument. The output looks pretty simialr though.

This is the version I am running

# xrdp --version
Argument 0 - xrdp
Argument 1 - --version
xrdp 0.9.19
  A Remote Desktop Protocol Server.
  Copyright (C) 2004-2020 Jay Sorg, Neutrino Labs, and all contributors.
  See https://github.com/neutrinolabs/xrdp for more information.

  Configure options:
      --enable-devel-all

  Compiled with OpenSSL 1.1.1f  31 Mar 2020

[20220406-17:32:56] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220406-17:32:56] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220406-17:32:56] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220406-17:32:56] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 7 (AF_INET 0.0.0.0:3389)
[20220406-17:32:58] [INFO ] [main(xrdp.c:685)] starting xrdp with pid 54331
[20220406-17:32:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:678)] address [0.0.0.0] port [3389] mode 1
[20220406-17:32:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:687)] listening to port 3389 on 0.0.0.0
[20220406-17:32:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220406-17:32:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220406-17:32:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220406-17:34:33] [INFO ] [g_sck_accept(os_calls.c:1395)] Socket 12: AF_INET connection received from 10.13.37.123 port 3477
[20220406-17:34:33] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220406-17:34:33] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ini_version, value 1
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item fork, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item port, value 3389
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_vsock, value false
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_nodelay, value false
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_keepalive, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_send_buffer_bytes, value 262144
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item security_layer, value negotiate
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item crypt_level, value low
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item certificate, value 
[20220406-17:34:33] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item key_file, value 
[20220406-17:34:33] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ssl_protocols, value TLSv1.2, TLSv1.3
[20220406-17:34:33] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1458)] TLSv1.3 enabled
[20220406-17:34:33] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1470)] TLSv1.2 enabled
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item autorun, value 
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_channels, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_multimon, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_cache, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_compression, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bulk_compression, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item max_bpp, value 128
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item xserverbpp, value 128
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_compression, value yes
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item new_cursors, value true
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_fastpath, value both
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item blue, value 009cb5
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item grey, value dedede
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_top_window_bg_color, value 009cb5
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_width, value 350
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_height, value 430
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_bg_color, value dedede
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_filename, value 
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_x_pos, value 55
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_y_pos, value 50
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_x_pos, value 30
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_width, value 65
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_x_pos, value 110
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_width, value 210
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_y_pos, value 220
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_x_pos, value 142
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_y_pos, value 370
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_width, value 85
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_height, value 30
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_x_pos, value 237
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_y_pos, value 370
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_width, value 85
[20220406-17:34:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_height, value 30
[20220406-17:34:33] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:485)] [ITU-T X.224] Connection Sequence: receive connection request
[20220406-17:34:33] [INFO ] [xrdp_iso_negotiate_security(xrdp_iso.c:194)] Security protocol: configured [SSL|RDP], requested [RDP], selected [RDP]
[20220406-17:34:33] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:587)] [ITU-T X.224] Connection Sequence: send connection confirmation
[20220406-17:34:33] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:594)] [ITU-T X.224] Connection Sequence: completed
[20220406-17:34:33] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2709)] Using RDP security, and reading the server configuration
[20220406-17:34:33] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2742)] Server config: pub_mod bytes 256
[20220406-17:34:33] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2753)] Server config: pri_exp 256
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1188)] [MCS Connection Sequence] receive connection request
[20220406-17:34:33] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1972)] Connected client computer name: WT00806465d8c3
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2151)] Client supports 40 bit encryption
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2155)] Client supports 128 bit encryption
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2159)] Client supports 56 bit encryption
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2163)] Client supports fips encryption
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2225)] Client and server both support low encryption, using RDP 40-bit encryption.
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data(xrdp_sec.c:2460)] Received [MS-RDPBCGR] TS_UD_CS_CLUSTER - no-op
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name rdpdr, channel id 1004, flags 0x82000000
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name cliprdr, channel id 1005, flags 0x98000000
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CUVA, channel id 1006, flags 0x88000000
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name AURTCX, channel id 1007, flags 0x88000000
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name USBVDX, channel id 1008, flags 0x88000000
[20220406-17:34:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CARANOC, channel id 1009, flags 0x82000000
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1202)] [MCS Connection Sequence] construct connection reponse
[20220406-17:34:33] [DEBUG] [xrdp_mcs_out_gcc_data(xrdp_mcs.c:1038)] using 2048 bit RSA key
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1209)] [MCS Connection Sequence] send connection reponse
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1216)] [MCS Connection Sequence] receive erect domain request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1223)] [MCS Connection Sequence] receive attach user request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1230)] [MCS Connection Sequence] send attach user confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220406-17:34:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220406-17:34:33] [ERROR] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:746)] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25
[20220406-17:34:33] [ERROR] [xrdp_mcs_incoming(xrdp_mcs.c:1242)] [MCS Connection Sequence] receive channel join request failed
[20220406-17:34:33] [ERROR] [xrdp_sec_incoming(xrdp_sec.c:2773)] xrdp_sec_incoming: xrdp_mcs_incoming failed
[20220406-17:34:33] [ERROR] [xrdp_rdp_incoming(xrdp_rdp.c:921)] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20220406-17:34:33] [ERROR] [xrdp_process_main_loop(xrdp_process.c:302)] xrdp_process_main_loop: libxrdp_process_incoming failed
[20220406-17:34:33] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220406-17:34:33] [DEBUG] [close_rdp_socket(xrdp_mcs.c:1387)] xrdp_mcs_disconnect - socket closed

matt335672 commented 2 years ago

My bad - sorry.

Having a closer look at the code, the messages we want are in xrdp_sec_process_mcs_data_channels(). They are TRACE level.

I can't recommend you enable TRACE for all development messages as I'm sure you've got better things to do. However, you can enable them selectively for this function.

Edit /etc/xrdp/xrdp.ini and locate the [LoggingPerLogger] section. In there, add this line:-

xrdp_sec_process_mcs_data_channels()=TRACE

Then restart xrdp.

On my system I get these additional messages:-

[20220407-11:03:47] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2283)] Received [MS-RDPBCGR] TS_UD_CS_NET channelCount 4
[20220407-11:03:47] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 0, name rdpdr, options 0xc0800000
[20220407-11:03:47] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 1, name rdpsnd, options 0xc0000000
[20220407-11:03:47] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 2, name cliprdr, options 0xc0a00000
[20220407-11:03:47] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 3, name drdynvc, options 0xc0800000

At the moment I can't see any other logging that'll be useful without making code changes to xrdp_mcs_recv_cjrq(). It might come to that, but see what you get from the above.

christheradioguy commented 2 years ago

Alright, here's what I get from enabling TRACE on that channel

[20220408-16:31:56] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220408-16:31:56] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220408-16:31:56] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220408-16:31:56] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 7 (AF_INET 0.0.0.0:3389)
[20220408-16:31:58] [INFO ] [main(xrdp.c:685)] starting xrdp with pid 61029
[20220408-16:31:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:678)] address [0.0.0.0] port [3389] mode 1
[20220408-16:31:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:687)] listening to port 3389 on 0.0.0.0
[20220408-16:31:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220408-16:31:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220408-16:31:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220408-16:33:46] [INFO ] [g_sck_accept(os_calls.c:1395)] Socket 12: AF_INET connection received from 10.13.37.123 port 3564
[20220408-16:33:46] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220408-16:33:46] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ini_version, value 1
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item fork, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item port, value 3389
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_vsock, value false
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_nodelay, value false
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_keepalive, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_send_buffer_bytes, value 262144
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item security_layer, value negotiate
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item crypt_level, value low
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item certificate, value 
[20220408-16:33:46] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item key_file, value 
[20220408-16:33:46] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ssl_protocols, value TLSv1.2, TLSv1.3
[20220408-16:33:46] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1458)] TLSv1.3 enabled
[20220408-16:33:46] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1470)] TLSv1.2 enabled
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item autorun, value 
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_channels, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_multimon, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_cache, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_compression, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bulk_compression, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item max_bpp, value 128
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item xserverbpp, value 128
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_compression, value yes
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item new_cursors, value true
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_fastpath, value both
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item blue, value 009cb5
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item grey, value dedede
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_top_window_bg_color, value 009cb5
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_width, value 350
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_height, value 430
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_bg_color, value dedede
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_filename, value 
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_x_pos, value 55
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_y_pos, value 50
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_x_pos, value 30
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_width, value 65
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_x_pos, value 110
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_width, value 210
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_y_pos, value 220
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_x_pos, value 142
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_y_pos, value 370
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_width, value 85
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_height, value 30
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_x_pos, value 237
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_y_pos, value 370
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_width, value 85
[20220408-16:33:46] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_height, value 30
[20220408-16:33:46] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:485)] [ITU-T X.224] Connection Sequence: receive connection request
[20220408-16:33:46] [INFO ] [xrdp_iso_negotiate_security(xrdp_iso.c:194)] Security protocol: configured [SSL|RDP], requested [RDP], selected [RDP]
[20220408-16:33:46] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:587)] [ITU-T X.224] Connection Sequence: send connection confirmation
[20220408-16:33:46] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:594)] [ITU-T X.224] Connection Sequence: completed
[20220408-16:33:46] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2709)] Using RDP security, and reading the server configuration
[20220408-16:33:46] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2742)] Server config: pub_mod bytes 256
[20220408-16:33:46] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2753)] Server config: pri_exp 256
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1188)] [MCS Connection Sequence] receive connection request
[20220408-16:33:46] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1972)] Connected client computer name: WT00806465d8c3
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2151)] Client supports 40 bit encryption
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2155)] Client supports 128 bit encryption
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2159)] Client supports 56 bit encryption
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2163)] Client supports fips encryption
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2225)] Client and server both support low encryption, using RDP 40-bit encryption.
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data(xrdp_sec.c:2460)] Received [MS-RDPBCGR] TS_UD_CS_CLUSTER - no-op
[20220408-16:33:46] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2283)] Received [MS-RDPBCGR] TS_UD_CS_NET channelCount 6
[20220408-16:33:46] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 0, name rdpdr, options 0x82000000
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name rdpdr, channel id 1004, flags 0x82000000
[20220408-16:33:46] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 1, name cliprdr, options 0x98000000
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name cliprdr, channel id 1005, flags 0x98000000
[20220408-16:33:46] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 2, name CUVA, options 0x88000000
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CUVA, channel id 1006, flags 0x88000000
[20220408-16:33:46] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 3, name AURTCX, options 0x88000000
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name AURTCX, channel id 1007, flags 0x88000000
[20220408-16:33:46] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 4, name USBVDX, options 0x88000000
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name USBVDX, channel id 1008, flags 0x88000000
[20220408-16:33:46] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 5, name CARANOC, options 0x82000000
[20220408-16:33:46] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CARANOC, channel id 1009, flags 0x82000000
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1202)] [MCS Connection Sequence] construct connection reponse
[20220408-16:33:46] [DEBUG] [xrdp_mcs_out_gcc_data(xrdp_mcs.c:1038)] using 2048 bit RSA key
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1209)] [MCS Connection Sequence] send connection reponse
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1216)] [MCS Connection Sequence] receive erect domain request
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1223)] [MCS Connection Sequence] receive attach user request
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1230)] [MCS Connection Sequence] send attach user confirm
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220408-16:33:46] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:47] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220408-16:33:47] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:47] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220408-16:33:47] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:47] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] send channel join confirm
[20220408-16:33:47] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1239)] [MCS Connection Sequence] receive channel join request
[20220408-16:33:47] [ERROR] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:746)] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25
[20220408-16:33:47] [ERROR] [xrdp_mcs_incoming(xrdp_mcs.c:1242)] [MCS Connection Sequence] receive channel join request failed
[20220408-16:33:47] [ERROR] [xrdp_sec_incoming(xrdp_sec.c:2773)] xrdp_sec_incoming: xrdp_mcs_incoming failed
[20220408-16:33:47] [ERROR] [xrdp_rdp_incoming(xrdp_rdp.c:921)] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20220408-16:33:47] [ERROR] [xrdp_process_main_loop(xrdp_process.c:302)] xrdp_process_main_loop: libxrdp_process_incoming failed
[20220408-16:33:47] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220408-16:33:47] [DEBUG] [close_rdp_socket(xrdp_mcs.c:1387)] xrdp_mcs_disconnect - socket closed

matt335672 commented 2 years ago

Interesting - thanks.

On our side, we expect channelCount + 2 channel join requests. The + 2 comes from additional channels mentioned in [MS-RDPBCGR] 2.2.1.8. On my initial reading of the spec, I'd have expected + 3, so there's something I don't understand there. Regardless of that, the client is sending one less channel join request than we are expecting.

We could do with still more logging. Can I ask you to apply a patch, and also to add another entry to the [LoggingPerLogger] section?

The patch is :-

--- a/libxrdp/xrdp_mcs.c
+++ b/libxrdp/xrdp_mcs.c
@@ -718,6 +718,10 @@ xrdp_mcs_recv_cjrq(struct xrdp_mcs *self)
 {
     int opcode;
     struct stream *s;
+#ifdef USE_DEVEL_LOGGING
+    int initiator;
+    int channel_id;
+#endif

     s = libxrdp_force_read(self->iso_layer->trans);
     if (s == 0)
@@ -753,8 +757,13 @@ xrdp_mcs_recv_cjrq(struct xrdp_mcs *self)
         return 1;
     }

+#ifdef USE_DEVEL_LOGGING
+    in_uint16_be(s, initiator);
+    in_uint16_be(s, channel_id);
+#else
     in_uint8s(s, 4); /* initiator (2 bytes)
                         channelId (2 bytes) */
+#endif

     /*
      * [MS-RDPBCGR] 2.2.1.8 says that the mcsAUrq field is 5 bytes (which have
@@ -772,8 +781,9 @@ xrdp_mcs_recv_cjrq(struct xrdp_mcs *self)
     }

     LOG_DEVEL(LOG_LEVEL_TRACE, "Received [ITU-T T.125] ChannelJoinRequest "
-              "initiator (ignored), channelId (ignored), "
+              "initiator %d, channelId %d, "
               "nonStandard (%s)",
+              initiator, channel_id,
               (opcode & 2) ? "present" : "not present");

     if (!s_check_end_and_log(s, "MCS protocol error [ITU-T T.125] ChannelJoinRequest"))

The complete [LoggingPerLogger] section should look like this:-

[LoggingPerLogger]
xrdp_sec_process_mcs_data_channels()=TRACE
xrdp_mcs_recv_cjrq()=TRACE

On my system I get these messages from a Remmina client:-

[20220409-17:21:00] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2285)] Received [MS-RDPBCGR] TS_UD_CS_NET channelCount 4
[20220409-17:21:00] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 0, name rdpdr, options 0xc0800000
[20220409-17:21:00] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name rdpdr, channel id 1004, flags 0xc0800000
[20220409-17:21:00] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 1, name rdpsnd, options 0xc0000000
[20220409-17:21:00] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name rdpsnd, channel id 1005, flags 0xc0000000
[20220409-17:21:00] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 2, name cliprdr, options 0xc0a00000
[20220409-17:21:00] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name cliprdr, channel id 1006, flags 0xc0a00000
[20220409-17:21:00] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 3, name drdynvc, options 0xc0800000
[20220409-17:21:00] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name drdynvc, channel id 1007, flags 0xc0800000
[20220409-17:21:00] [WARN ] [xrdp_sec_process_mcs_data(xrdp_sec.c:2575)] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc006 is unknown (ignored)
[20220409-17:21:00] [WARN ] [xrdp_sec_process_mcs_data(xrdp_sec.c:2575)] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc00a is unknown (ignored)
[20220409-17:21:00] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220409-17:21:00] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1002, nonStandard (not present)
[20220409-17:21:00] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220409-17:21:00] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1003, nonStandard (not present)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1004, nonStandard (not present)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1005, nonStandard (not present)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1006, nonStandard (not present)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220409-17:21:01] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1007, nonStandard (not present)

So I can pair up the channel join requests with the channels.

That should let us hopefully work out which channel isn't generating a channel join request.

It'll take me a while to get back to you on this one - I've got a busy week coming up. I feel we're making progress though.

christheradioguy commented 2 years ago

Finally got around to applying the patch, there's the latest debug log

Definitely feel like we're getting somewhere, appreciate the persistance.

[20220417-09:02:38] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220417-09:02:38] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220417-09:02:38] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220417-09:02:38] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 7 (AF_INET 0.0.0.0:3389)
[20220417-09:02:40] [INFO ] [main(xrdp.c:685)] starting xrdp with pid 103615
[20220417-09:02:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:678)] address [0.0.0.0] port [3389] mode 1
[20220417-09:02:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:687)] listening to port 3389 on 0.0.0.0
[20220417-09:02:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220417-09:02:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220417-09:02:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220417-09:05:21] [INFO ] [g_sck_accept(os_calls.c:1395)] Socket 12: AF_INET connection received from 10.13.37.123 port 3585
[20220417-09:05:21] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220417-09:05:21] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ini_version, value 1
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item fork, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item port, value 3389
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_vsock, value false
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_nodelay, value false
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_keepalive, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_send_buffer_bytes, value 262144
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item security_layer, value negotiate
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item crypt_level, value low
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item certificate, value 
[20220417-09:05:21] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item key_file, value 
[20220417-09:05:21] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ssl_protocols, value TLSv1.2, TLSv1.3
[20220417-09:05:21] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1458)] TLSv1.3 enabled
[20220417-09:05:21] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1470)] TLSv1.2 enabled
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item autorun, value 
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_channels, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_multimon, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_cache, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_compression, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bulk_compression, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item max_bpp, value 128
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item xserverbpp, value 128
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_compression, value yes
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item new_cursors, value true
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_fastpath, value both
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item blue, value 009cb5
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item grey, value dedede
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_top_window_bg_color, value 009cb5
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_width, value 350
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_height, value 430
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_bg_color, value dedede
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_filename, value 
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_x_pos, value 55
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_y_pos, value 50
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_x_pos, value 30
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_width, value 65
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_x_pos, value 110
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_width, value 210
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_y_pos, value 220
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_x_pos, value 142
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_y_pos, value 370
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_width, value 85
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_height, value 30
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_x_pos, value 237
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_y_pos, value 370
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_width, value 85
[20220417-09:05:21] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_height, value 30
[20220417-09:05:21] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:485)] [ITU-T X.224] Connection Sequence: receive connection request
[20220417-09:05:21] [INFO ] [xrdp_iso_negotiate_security(xrdp_iso.c:194)] Security protocol: configured [SSL|RDP], requested [RDP], selected [RDP]
[20220417-09:05:21] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:587)] [ITU-T X.224] Connection Sequence: send connection confirmation
[20220417-09:05:21] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:594)] [ITU-T X.224] Connection Sequence: completed
[20220417-09:05:21] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2709)] Using RDP security, and reading the server configuration
[20220417-09:05:21] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2742)] Server config: pub_mod bytes 256
[20220417-09:05:21] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2753)] Server config: pri_exp 256
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1198)] [MCS Connection Sequence] receive connection request
[20220417-09:05:21] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1972)] Connected client computer name: WT00806465d8c3
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2151)] Client supports 40 bit encryption
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2155)] Client supports 128 bit encryption
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2159)] Client supports 56 bit encryption
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2163)] Client supports fips encryption
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2225)] Client and server both support low encryption, using RDP 40-bit encryption.
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data(xrdp_sec.c:2460)] Received [MS-RDPBCGR] TS_UD_CS_CLUSTER - no-op
[20220417-09:05:21] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2283)] Received [MS-RDPBCGR] TS_UD_CS_NET channelCount 6
[20220417-09:05:21] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 0, name rdpdr, options 0x82000000
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name rdpdr, channel id 1004, flags 0x82000000
[20220417-09:05:21] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 1, name cliprdr, options 0x98000000
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name cliprdr, channel id 1005, flags 0x98000000
[20220417-09:05:21] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 2, name CUVA, options 0x88000000
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CUVA, channel id 1006, flags 0x88000000
[20220417-09:05:21] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 3, name AURTCX, options 0x88000000
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name AURTCX, channel id 1007, flags 0x88000000
[20220417-09:05:21] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 4, name USBVDX, options 0x88000000
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name USBVDX, channel id 1008, flags 0x88000000
[20220417-09:05:21] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 5, name CARANOC, options 0x82000000
[20220417-09:05:21] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CARANOC, channel id 1009, flags 0x82000000
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1212)] [MCS Connection Sequence] construct connection reponse
[20220417-09:05:21] [DEBUG] [xrdp_mcs_out_gcc_data(xrdp_mcs.c:1048)] using 2048 bit RSA key
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1219)] [MCS Connection Sequence] send connection reponse
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1226)] [MCS Connection Sequence] receive erect domain request
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1233)] [MCS Connection Sequence] receive attach user request
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1240)] [MCS Connection Sequence] send attach user confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1003, nonStandard (not present)
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1004, nonStandard (not present)
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1005, nonStandard (not present)
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1006, nonStandard (not present)
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1007, nonStandard (not present)
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1008, nonStandard (not present)
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1009, nonStandard (not present)
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220417-09:05:21] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220417-09:05:21] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 25 (ChannelJoinRequest)
[20220417-09:05:21] [ERROR] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:750)] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25
[20220417-09:05:21] [ERROR] [xrdp_mcs_incoming(xrdp_mcs.c:1252)] [MCS Connection Sequence] receive channel join request failed
[20220417-09:05:21] [ERROR] [xrdp_sec_incoming(xrdp_sec.c:2773)] xrdp_sec_incoming: xrdp_mcs_incoming failed
[20220417-09:05:21] [ERROR] [xrdp_rdp_incoming(xrdp_rdp.c:921)] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20220417-09:05:21] [ERROR] [xrdp_process_main_loop(xrdp_process.c:302)] xrdp_process_main_loop: libxrdp_process_incoming failed
[20220417-09:05:21] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220417-09:05:21] [DEBUG] [close_rdp_socket(xrdp_mcs.c:1397)] xrdp_mcs_disconnect - socket closed

matt335672 commented 2 years ago

Thanks @christheradioguy. When we've gotten to the end of this process I'll merge in some of these logging improvements.

It looks like the client isn't sending over a join request for one of the standard channels. I'll take a look later in the week - as I said it's not an area I'm that familiar with.

matt335672 commented 2 years ago

I've had a think about this, and I think at this point we out to make a quick mod to xrdp to check we're on the right lines.

The problem seems to be that we're expecting one more channel join request than the client is sending. It seems likely this is the client's fault as we've not seen this before, and a firmware upgrade fixes the issue, but I don't think even that's certain.

Let's try hard-coding xrdp to expect one less channel join request to get over this hurdle, and see how the thin client works then.

After applying the patch, line 1247 of xrdp/xrdp_mcs.c looks like this:-

for (index = 0; index < self->channel_list->count + 2; index++)

Can you change the '+2` to a '+1', so we can see what happens?

Thanks.

christheradioguy commented 2 years ago

Apologies for the late reply. I tested the patch by changing count + 2 to count + 1 and it does indeed work! I can successfully connect from the Wyse client and access the desktop via xrdp.

Here's a debug log if it helps

[20220507-10:13:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220507-10:13:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220507-10:13:40] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220507-10:13:40] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 7 (AF_INET 0.0.0.0:3389)
[20220507-10:13:42] [INFO ] [main(xrdp.c:685)] starting xrdp with pid 170562
[20220507-10:13:42] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:678)] address [0.0.0.0] port [3389] mode 1
[20220507-10:13:42] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:687)] listening to port 3389 on 0.0.0.0
[20220507-10:13:42] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220507-10:13:42] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220507-10:13:42] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220507-10:13:55] [INFO ] [g_sck_accept(os_calls.c:1395)] Socket 12: AF_INET connection received from 10.13.37.123 port 3590
[20220507-10:13:55] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220507-10:13:55] [DEBUG] [g_sck_close(os_calls.c:766)] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ini_version, value 1
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item fork, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item port, value 3389
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_vsock, value false
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_nodelay, value false
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_keepalive, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_send_buffer_bytes, value 262144
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item security_layer, value negotiate
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item crypt_level, value low
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item certificate, value 
[20220507-10:13:55] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item key_file, value 
[20220507-10:13:55] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ssl_protocols, value TLSv1.2, TLSv1.3
[20220507-10:13:55] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1458)] TLSv1.3 enabled
[20220507-10:13:55] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1470)] TLSv1.2 enabled
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item autorun, value 
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_channels, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_multimon, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_cache, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_compression, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bulk_compression, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item max_bpp, value 128
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item xserverbpp, value 128
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_compression, value yes
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item new_cursors, value true
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_fastpath, value both
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item blue, value 009cb5
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item grey, value dedede
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_top_window_bg_color, value 009cb5
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_width, value 350
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_height, value 430
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_bg_color, value dedede
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_filename, value 
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_x_pos, value 55
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_y_pos, value 50
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_x_pos, value 30
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_width, value 65
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_x_pos, value 110
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_width, value 210
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_y_pos, value 220
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_x_pos, value 142
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_y_pos, value 370
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_width, value 85
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_height, value 30
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_x_pos, value 237
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_y_pos, value 370
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_width, value 85
[20220507-10:13:55] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_height, value 30
[20220507-10:13:55] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:485)] [ITU-T X.224] Connection Sequence: receive connection request
[20220507-10:13:55] [INFO ] [xrdp_iso_negotiate_security(xrdp_iso.c:194)] Security protocol: configured [SSL|RDP], requested [RDP], selected [RDP]
[20220507-10:13:55] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:587)] [ITU-T X.224] Connection Sequence: send connection confirmation
[20220507-10:13:55] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:594)] [ITU-T X.224] Connection Sequence: completed
[20220507-10:13:55] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2709)] Using RDP security, and reading the server configuration
[20220507-10:13:55] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2742)] Server config: pub_mod bytes 256
[20220507-10:13:55] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2753)] Server config: pri_exp 256
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1198)] [MCS Connection Sequence] receive connection request
[20220507-10:13:55] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1972)] Connected client computer name: WT00806465d8c3
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2151)] Client supports 40 bit encryption
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2155)] Client supports 128 bit encryption
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2159)] Client supports 56 bit encryption
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2163)] Client supports fips encryption
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2225)] Client and server both support low encryption, using RDP 40-bit encryption.
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data(xrdp_sec.c:2460)] Received [MS-RDPBCGR] TS_UD_CS_CLUSTER - no-op
[20220507-10:13:55] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2283)] Received [MS-RDPBCGR] TS_UD_CS_NET channelCount 6
[20220507-10:13:55] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 0, name rdpdr, options 0x82000000
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name rdpdr, channel id 1004, flags 0x82000000
[20220507-10:13:55] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 1, name cliprdr, options 0x98000000
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name cliprdr, channel id 1005, flags 0x98000000
[20220507-10:13:55] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 2, name CUVA, options 0x88000000
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CUVA, channel id 1006, flags 0x88000000
[20220507-10:13:55] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 3, name AURTCX, options 0x88000000
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name AURTCX, channel id 1007, flags 0x88000000
[20220507-10:13:55] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 4, name USBVDX, options 0x88000000
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name USBVDX, channel id 1008, flags 0x88000000
[20220507-10:13:55] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2304)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 5, name CARANOC, options 0x82000000
[20220507-10:13:55] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2310)] Adding channel: name CARANOC, channel id 1009, flags 0x82000000
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1212)] [MCS Connection Sequence] construct connection reponse
[20220507-10:13:55] [DEBUG] [xrdp_mcs_out_gcc_data(xrdp_mcs.c:1048)] using 2048 bit RSA key
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1219)] [MCS Connection Sequence] send connection reponse
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1226)] [MCS Connection Sequence] receive erect domain request
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1233)] [MCS Connection Sequence] receive attach user request
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1240)] [MCS Connection Sequence] send attach user confirm
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1003, nonStandard (not present)
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1004, nonStandard (not present)
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1005, nonStandard (not present)
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1006, nonStandard (not present)
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1007, nonStandard (not present)
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1008, nonStandard (not present)
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:745)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220507-10:13:55] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:783)] Received [ITU-T T.125] ChannelJoinRequest initiator 1, channelId 1009, nonStandard (not present)
[20220507-10:13:55] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1256)] [MCS Connection Sequence] send channel join confirm

matt335672 commented 2 years ago

Thanks for that.

The question then is which join request is xrdp expecting that the client isn't sending. We probably need more logging, but it might take me a while to get to it.

matt335672 commented 2 years ago

Hi @christheradioguy

I've had a bit of time to look into this. At the moment I think this is actually a bug on the xrdp side.

[MS-RDPBCGR] contains this line in 2.2.1.8 :-

The client uses the MCS Channel Join Request PDU to join the user channel obtained from the Attach User Confirm PDU, the I/O channel (section 2.2.1.4.4), the message channel (section 2.2.1.4.5), and all of the static virtual channels obtained from the Server Network Data structure (section 2.2.1.4.4)

The static virtual channels for this client are clearly logged as 1004 - 1009. In addition we're getting a channel join request for 1003. This is the "I/O channel", and is fixed. The "message channel" isn't actually used by xrdp, so that just leaves the "user channel" which the client isn't sending.

There's a bit of interpretation of the spec needed here which I won't go into, but essentially xrdp is setting a user channel of 1002, which is the same as the server channel. This seems odd to me. I've looked at the Microsoft RDP server responses, and also the code in FreeRDP. These both set a user channel which is one more than the last allocated static virtual channel.

After (quite) a bit of effort, I've built a branch which I think does what Windows server actually does. Since I imagine your terminals have been tested on Windows targets, I'm quietly confident that this branch might work for you unmodified on your thin clients. If it doesn't the logging will in any case be interesting.

I'll give you a couple of options for testing this:-

1) You can clone my repo at https://github.com/matt335672/xrdp.git, checkout the wyse_thin_client branch, and build from source. 2) You can just apply the attached patch to v0.9.19 wyse_thin_client.patch.txt

Please let me know how it goes. I've tested this patch on a Remmina client and mstsc.exe so far.

Also, thanks for a very interesting problem - it's getting me into some very interesting corners of [MS-RDPBCGR]!

christheradioguy commented 2 years ago

Thanks for the reply.

I checked out the wyse_thin_client branch and re-compiled but still unable to connect from the client. Below is the debug log I gathered

[20220510-21:19:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220510-21:19:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220510-21:19:58] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220510-21:19:58] [DEBUG] [g_sck_close(os_calls.c:755)] Closed socket 7 (AF_INET 0.0.0.0:3389)
[20220510-21:20:00] [INFO ] [main(xrdp.c:691)] starting xrdp with pid 197801
[20220510-21:20:00] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:678)] address [0.0.0.0] port [3389] mode 1
[20220510-21:20:00] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:687)] listening to port 3389 on 0.0.0.0
[20220510-21:20:00] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:719)] setting send buffer to 262144 bytes
[20220510-21:20:00] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:734)] send buffer set to 425984 bytes
[20220510-21:20:00] [INFO ] [xrdp_listen_process_startup_params(xrdp_listen.c:674)] xrdp_listen_pp done
[20220510-21:22:33] [INFO ] [g_sck_accept(os_calls.c:1384)] Socket 12: AF_INET connection received from 10.13.37.123 port 3584
[20220510-21:22:33] [DEBUG] [g_sck_close(os_calls.c:755)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220510-21:22:33] [DEBUG] [g_sck_close(os_calls.c:755)] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ini_version, value 1
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item fork, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item port, value 3389
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_vsock, value false
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_nodelay, value false
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_keepalive, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item tcp_send_buffer_bytes, value 262144
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item security_layer, value negotiate
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item crypt_level, value low
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item certificate, value 
[20220510-21:22:33] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:225)] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item key_file, value 
[20220510-21:22:33] [INFO ] [xrdp_rdp_read_config(xrdp_rdp.c:257)] Using default X.509 key file: /etc/xrdp/key.pem
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ssl_protocols, value TLSv1.2, TLSv1.3
[20220510-21:22:33] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1458)] TLSv1.3 enabled
[20220510-21:22:33] [DEBUG] [ssl_get_protocols_from_string(ssl_calls.c:1470)] TLSv1.2 enabled
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item autorun, value 
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_channels, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item allow_multimon, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_cache, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bitmap_compression, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item bulk_compression, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item max_bpp, value 128
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item xserverbpp, value 128
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_compression, value yes
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item new_cursors, value true
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item use_fastpath, value both
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item blue, value 009cb5
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item grey, value dedede
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_top_window_bg_color, value 009cb5
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_width, value 350
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_height, value 430
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_bg_color, value dedede
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_filename, value 
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_x_pos, value 55
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_logo_y_pos, value 50
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_x_pos, value 30
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_label_width, value 65
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_x_pos, value 110
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_width, value 210
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_input_y_pos, value 220
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_x_pos, value 142
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_y_pos, value 370
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_width, value 85
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_ok_height, value 30
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_x_pos, value 237
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_y_pos, value 370
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_width, value 85
[20220510-21:22:33] [DEBUG] [xrdp_rdp_read_config(xrdp_rdp.c:69)] item ls_btn_cancel_height, value 30
[20220510-21:22:33] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:485)] [ITU-T X.224] Connection Sequence: receive connection request
[20220510-21:22:33] [INFO ] [xrdp_iso_negotiate_security(xrdp_iso.c:194)] Security protocol: configured [SSL|RDP], requested [RDP], selected [RDP]
[20220510-21:22:33] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:587)] [ITU-T X.224] Connection Sequence: send connection confirmation
[20220510-21:22:33] [DEBUG] [xrdp_iso_incoming(xrdp_iso.c:594)] [ITU-T X.224] Connection Sequence: completed
[20220510-21:22:33] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2808)] Using RDP security, and reading the server configuration
[20220510-21:22:33] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2841)] Server config: pub_mod bytes 256
[20220510-21:22:33] [DEBUG] [xrdp_sec_incoming(xrdp_sec.c:2852)] Server config: pri_exp 256
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1190)] [MCS Connection Sequence] receive connection request
[20220510-21:22:33] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1974)] Connected client computer name: WT00806465d8c3
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2153)] Client supports 40 bit encryption
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2157)] Client supports 128 bit encryption
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2161)] Client supports 56 bit encryption
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2165)] Client supports fips encryption
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_CS_SECURITY(xrdp_sec.c:2227)] Client and server both support low encryption, using RDP 40-bit encryption.
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data(xrdp_sec.c:2559)] Received [MS-RDPBCGR] TS_UD_CS_CLUSTER - no-op
[20220510-21:22:33] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2285)] Received [MS-RDPBCGR] TS_UD_CS_NET channelCount 6
[20220510-21:22:33] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 0, name rdpdr, options 0x82000000
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name rdpdr, channel id 1004, flags 0x82000000
[20220510-21:22:33] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 1, name cliprdr, options 0x98000000
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name cliprdr, channel id 1005, flags 0x98000000
[20220510-21:22:33] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 2, name CUVA, options 0x88000000
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name CUVA, channel id 1006, flags 0x88000000
[20220510-21:22:33] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 3, name AURTCX, options 0x88000000
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name AURTCX, channel id 1007, flags 0x88000000
[20220510-21:22:33] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 4, name USBVDX, options 0x88000000
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name USBVDX, channel id 1008, flags 0x88000000
[20220510-21:22:33] [TRACE] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2306)] Received [MS-RDPBCGR] TS_UD_CS_NET.CHANNEL_DEF 5, name CARANOC, options 0x82000000
[20220510-21:22:33] [DEBUG] [xrdp_sec_process_mcs_data_channels(xrdp_sec.c:2312)] Adding channel: name CARANOC, channel id 1009, flags 0x82000000
[20220510-21:22:33] [DEBUG] [xrdp_mcs_set_user_channel_id(xrdp_mcs.c:1456)] MCS user is 9, channel id is 1010
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1204)] [MCS Connection Sequence] construct connection reponse
[20220510-21:22:33] [DEBUG] [xrdp_mcs_out_gcc_data(xrdp_mcs.c:1040)] using 2048 bit RSA key
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1211)] [MCS Connection Sequence] send connection reponse
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1218)] [MCS Connection Sequence] receive erect domain request
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1225)] [MCS Connection Sequence] receive attach user request
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1232)] [MCS Connection Sequence] send attach user confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:775)] Received [ITU-T T.125] ChannelJoinRequest initiator 9, channelId 1003, nonStandard (not present)
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1253)] [MCS Connection Sequence] send channel join confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:775)] Received [ITU-T T.125] ChannelJoinRequest initiator 9, channelId 1004, nonStandard (not present)
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1253)] [MCS Connection Sequence] send channel join confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:775)] Received [ITU-T T.125] ChannelJoinRequest initiator 9, channelId 1005, nonStandard (not present)
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1253)] [MCS Connection Sequence] send channel join confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:775)] Received [ITU-T T.125] ChannelJoinRequest initiator 9, channelId 1006, nonStandard (not present)
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1253)] [MCS Connection Sequence] send channel join confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:775)] Received [ITU-T T.125] ChannelJoinRequest initiator 9, channelId 1007, nonStandard (not present)
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1253)] [MCS Connection Sequence] send channel join confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:775)] Received [ITU-T T.125] ChannelJoinRequest initiator 9, channelId 1008, nonStandard (not present)
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1253)] [MCS Connection Sequence] send channel join confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 14 (ChannelJoinRequest)
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:775)] Received [ITU-T T.125] ChannelJoinRequest initiator 9, channelId 1009, nonStandard (not present)
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1253)] [MCS Connection Sequence] send channel join confirm
[20220510-21:22:33] [DEBUG] [xrdp_mcs_incoming(xrdp_mcs.c:1246)] [MCS Connection Sequence] receive channel join request
[20220510-21:22:33] [TRACE] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:742)] Received [ITU-T T.125] DomainMCSPDU choice index 25 (ChannelJoinRequest)
[20220510-21:22:33] [ERROR] [xrdp_mcs_recv_cjrq(xrdp_mcs.c:747)] Parsed [ITU-T T.125] DomainMCSPDU choice index expected 14, received 25
[20220510-21:22:33] [ERROR] [xrdp_mcs_incoming(xrdp_mcs.c:1249)] [MCS Connection Sequence] receive channel join request failed
[20220510-21:22:33] [ERROR] [xrdp_sec_incoming(xrdp_sec.c:2872)] xrdp_sec_incoming: xrdp_mcs_incoming failed
[20220510-21:22:33] [ERROR] [xrdp_rdp_incoming(xrdp_rdp.c:921)] xrdp_rdp_incoming: xrdp_sec_incoming failed
[20220510-21:22:33] [ERROR] [xrdp_process_main_loop(xrdp_process.c:302)] xrdp_process_main_loop: libxrdp_process_incoming failed
[20220510-21:22:33] [DEBUG] [g_sck_close(os_calls.c:755)] Closed socket 12 (AF_INET 10.4.9.34:3389)
[20220510-21:22:33] [DEBUG] [close_rdp_socket(xrdp_mcs.c:1393)] xrdp_mcs_disconnect - socket closed

Really appreciate all the time spent on this so far.

matt335672 commented 2 years ago

Heigh ho. Thanks for getting back to me. I appreciate it's not always easy to find the time to build this and try it.

The logging is certainly helpful. I think we can quite clearly see that the client is not sending back a channel join for the user channel. Given that the user channel isn't actually used for any messages (it's just a hang-over from using T.125 I think), that shouldn't affect functionality.

The spec does contain this line in 3.2.5.3.8:-

Sending of the MCS Channel Join Request PDUs MUST continue until all channels have been successfully joined.

if we were adhering to exactly what the spec does, at this point I'd call a halt to this operation. However, since your clients work OK with some Windows operating systems I don't think MS is adhering to the letter of the spec either. In the event of a mismatch between the spec and real-world operation, we tend to go with the latter.

These clients are pretty old. Have you tried them with Windows 10 (or even 11) say? It's a useful data point.

I'll have a think about what we could do at this point to move forward and let you know.

matt335672 commented 2 years ago

I've had another look at #874, which makes the point that this stuff worked for xrdp v0.6.1.

Looking at the code for that version, it was a lot more lax on exactly what virtual channel join requests it received from the client. However, it did not have to contend with TLS support which came in with version 5.2 of the RDP protocol, according to Wikipedia at least.

I'd like to see what version your clients are - we might be able to do something with that if we can also assume TLS support is not required, like fall back to the older code.

I've pushed a new version of the wyse_thin_client branch which logs the client version and tidies up a few things. It was a force push, so you might need to reclone my repo to get hold of it (easiest way).

When you've tried to connect you should have a line like the following in /var/log/xrdp.log:-

$ sudo grep 'RDP version' /var/log/xrdp.log 
[20220511-13:37:53] [INFO ] [xrdp_sec_process_mcs_data_CS_CORE(xrdp_sec.c:1976)] Connected client RDP version: 0008000d

I'd like to know what that version is for your clients. The example above is for a Windows 10 client.

Thanks again for the challenging problem.

christheradioguy commented 2 years ago

I'll try and slot some time in to re-try with the latest code this week.

Regarding connection to modern operating systems, I did have these clients successfully connecting to Win server 2016. There was a few group policy changes I needed to make from what I recall (this was a few years ago heh). I believe I needed to set the encryption level to client compatible, And I needed to set the 'Require use of specific security layer' to 'negotiate.' Also needed to disable network-level auth

matt335672 commented 2 years ago

That's great - thanks. That fits with my existing mental model of how the Windows side is working.

I've got some time here today, so I'll see what I can discover with a modified copy of xfreerdp talking to Windows 10. I'll post back before close-of-play UK time (UTC+1:00)

matt335672 commented 2 years ago

Bit more info regarding Windows 10 as a server.

Just built xfreerdp stable-2.0, commit FreeRDP/FreeRDP@b8be481a56021208e2c86704876147699397c9e9.

First job is to establish a connection using the RDP protocol rather than TLS. That needed the following to be done:-

On the Windows 10 target, in group policy Administrative Templates\Windows Components\Remote Desktop Services\Remote Desktop Session Host\Security I set Require use of specific security layer for remote (RDP) connections to Negotiate.
Connect to the target from xfreerdp by using the /sec:rdp switch.

That's all OK. Next I added this patch to FreeRDP to log the channel connections:-

--- a/libfreerdp/core/mcs.c
+++ b/libfreerdp/core/mcs.c
@@ -1085,6 +1085,7 @@ BOOL mcs_send_channel_join_request(rdpMcs* mcs, UINT16 channelId)
                return FALSE;
        }

+       WLog_INFO(TAG, "\tJoining channel:%" PRIu16 "", channelId);
        mcs_write_domain_mcspdu_header(s, DomainMCSPDU_ChannelJoinRequest, length, 0);
        per_write_integer16(s, mcs->userId, MCS_BASE_CHANNEL_ID);
        per_write_integer16(s, channelId, 0);

On my system I got:-

[11:08:57:861] [5572:5573] [INFO][com.freerdp.core] -   Joining channel:1009
[11:08:57:962] [5572:5573] [INFO][com.freerdp.core] -   Joining channel:1003
[11:08:57:062] [5572:5573] [INFO][com.freerdp.core] -   Joining channel:1004
[11:08:57:163] [5572:5573] [INFO][com.freerdp.core] -   Joining channel:1005
[11:08:57:264] [5572:5573] [INFO][com.freerdp.core] -   Joining channel:1006
[11:08:57:365] [5572:5573] [INFO][com.freerdp.core] -   Joining channel:1007

So channel 1009 is the user channel, 1003 is the I/O channel, and 1004-1007 are the static channels.

I then applied this further patch to FreeeRDP to disable sending the user channel:-

--- a/libfreerdp/core/rdp.c
+++ b/libfreerdp/core/rdp.c
@@ -1603,7 +1603,8 @@ int rdp_recv_callback(rdpTransport* transport, wStream* s, void* extra)
                                return -1;
                        }

-                       if (!mcs_send_channel_join_request(rdp->mcs, rdp->mcs->userId))
+                       rdp->mcs->userChannelJoined = TRUE;
+                       if (!mcs_send_channel_join_request(rdp->mcs, MCS_GLOBAL_CHANNEL_ID))
                        {
                                WLog_ERR(TAG, "mcs_send_channel_join_request failure");
                                return -1;

Result:-

[11:15:46:353] [6404:6405] [INFO][com.freerdp.core] -   Joining channel:1003
[11:15:47:453] [6404:6405] [INFO][com.freerdp.core] -   Joining channel:1004
[11:15:47:554] [6404:6405] [INFO][com.freerdp.core] -   Joining channel:1005
[11:15:47:654] [6404:6405] [INFO][com.freerdp.core] -   Joining channel:1006
[11:15:47:754] [6404:6405] [INFO][com.freerdp.core] -   Joining channel:1007

The connection was successful. The client RDP version for this version of FreeRDP is 10.7 (0x0008000C)

Windows server can also cope with the missing user channel with TLS enabled. This can be seen by dropping the /sec:rdp switch from the command line.

Summary so far:- 1) [MS-RDPBCGR] requires the user channel to be sent. 2) Windows 10 RDS does not strictly conform to the spec in that it can cope with at least a missing user channel (and maybe others - I haven't investigated further). 3) For Windows 10 RDS, it does not matter whether TLS or RDP security is set.

My proposal is to investigate modifying xrdp to cope without the user channel join in non-TLS mode. This will allow us to support older clients, such as this one, which do not conform to the spec. These clients can in any case not use modern TLS, so users of them will need to take additional security measures in any case. In TLS mode xrdp will be adhere to the spec.

This is a pragmatic decision. To support Windows behaviour fully, we'd need to look at the octets after each channel join, and decide whether they were a channel join, an MCS data PDU, or the start of a TLS client hello. for the latter two we'd then need to rewind the channel somehow before continuing. This is going to significantly complicate the code for no benefit that I can see at the moment. I do however see benefit in supporting older clients in non-TLS mode.

matt335672 commented 2 years ago

@christheradioguy - I've implemented the changes I've proposed in my previous message and repushed my branch.

I've only tested so far from a hacked and non-hacked version of xfreerdp, and both seem to work. If it works with your thin client, I think we're there.

When you get a chance, let me know how it goes.

matt335672 commented 2 years ago

Quick update - I've tested the modified branch on mstsc.exe (both TLS and non-TLS) and Moba-xterm (both TLS and non-TLS). It all seems to be good.

christheradioguy commented 2 years ago

Bingo! Confirmation that the latest build of wyse_thin_client works with the wyse sx0 terminal!

matt335672 commented 2 years ago

Great - glad we got there in the end.

At the moment we're looking at the next major version of xrdp (v0.10.x possibly), so I'm going to rebase my branch on that. However, we don't have a release date for that yet, so I've made a patch which applies to v0.9.19, so anyone interested in this thread can try it out.

wyse_thin_client_v0_9_19.patch.txt

Thanks again @christheradioguy for helping to improve the product.