neutrinolabs / xrdp

xrdp: an open source RDP server
http://www.xrdp.org/
Apache License 2.0
5.62k stars 1.73k forks source link

xrdp copy paste doesn't work (provided solution) #1632

Closed Mikky83 closed 11 months ago

Mikky83 commented 4 years ago

Hi All, I've found many issues related with copy-paste functionality via xrdp. Following up all of those threads, I couldn't find a solution for my issue. So, I was able to track the issue in my case and find what is the root cause. I would like to share it here, it might help to somebody and I believe dev team could prevent the issue in the upcoming versions. When copy-paste functionality doesn't work, you will see the following in the logs: [ERROR] xrdp_mm_connect_chansrv: connect failed trying again... [DEBUG] Closed socket 18 (AF_UNIX) [ERROR] xrdp_mm_connect_chansrv: connect failed trying again... [DEBUG] Closed socket 18 (AF_UNIX) [ERROR] xrdp_mm_connect_chansrv: connect failed trying again... [DEBUG] Closed socket 18 (AF_UNIX) [ERROR] xrdp_mm_connect_chansrv: connect failed trying again... [ERROR] xrdp_mm_connect_chansrv: error in trans_connect chan

Also you will see that xrdp-chansrv service is in "defunct" state.

root cause in my case: Each user when connecting to xrdp creates chansrv.$number.log under /tmp. $number is the session number. When working with Xvnc you could find the session number after "Xvnc:" process line. If a user logout for some reason sometimes chansrv.$number.log under /tmp is not cleaned up. Same is happening when you restart the xrdp service or even when you restart the OS. When a new user connects with a session number which was previously closed by another user, then chansrv.$number.log under /tmp exists with the same name. log file is owned by another user. Normally xrdp-chansrv process cannot write to the log because of permission issue and automatically goes to defunct state. Solution is to remove old chansrv log files and make a new connection. xrdp-chansrv process works and copy-paste also works.

Dev team, please fix this behaviour. I would recommend to either create one common log file and set all users to write to it, or to remove old chansrv logs from /tmp after service restart. You can make it the same as for cleaning up the files under /tmp/.xrdp/. That one works fine except when X server crashes, but that's another topic :)

matt335672 commented 4 years ago

Hi @Mikky83

Thanks for reporting this.

What platform are you on, or are you building from scratch?

Some of this should be sortable without any significant changes. For example, the logic for the chansrv log file path is:-

The intention is for each user to have a private directory for chansrv. This should not be shared.

coreypenford commented 4 years ago

I was going to create my own issue for this but I believe it is related to the above.

To give context to my problem: I am connecting from a Windows laptop at home, over a VPN, to my Linux desktop at the office.

The VPN may occasionally drop for a few seconds throughout the day, which causes the RDP connection to my Linux desktop to die with a an "an internal error has occurred" popup. Irregardless that is not the issue I am opening here.

Something I have noticed when reconnecting to the RDP session after one of these drops, is that there is a pause on a black screen. No styled cursor is seen, just a small white dot. This seems to prelude there being a clipboard issue. After a while my existing session loads in as normal, but the clipboard sharing functionality is broken directly afterwards.

I can copy stuff while inside the RDP window on the Linux machine, and see the "[DEBUG] VNC got clip data" appear in the xrdp.log, but I am unable to then paste that data on Windows. Or paste data from Windows to the Linux machine. Their clipboards are separate for the time being.

Mikky83's post led me to investigate the chansrv files that for me were located at the $HOME/.local/share/xrdp location. In that directory I can see xrdp-chansrv.13.log, which matches my display number in the logs. It appears something goes wrong with the chansrv process when a disconnect happens.

Since my issue is reproducible by having a network disconnect, by manually disconnecting the VPN and reconnecting it I can force the behavior at will. Let me show the following logs

1) Normal logs on first connection. Clipboard working fine.

xrdp.log

[20200728-15:42:57] [INFO ] Socket 12: AF_INET connection received from 10.60.5.44 port 58690
[20200728-15:42:57] [DEBUG] Closed socket 12 (AF_INET 10.60.5.47:3389)
[20200728-15:42:57] [DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20200728-15:42:57] [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
[20200728-15:42:57] [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
[20200728-15:42:57] [DEBUG] TLSv1.3 enabled
[20200728-15:42:57] [DEBUG] TLSv1.2 enabled
[20200728-15:42:57] [DEBUG] Security layer: requested 11, selected 1
[20200728-15:42:57] [DEBUG] Closed socket 12 (AF_INET 10.60.5.47:3389)
[20200728-15:42:57] [INFO ] Socket 12: AF_INET connection received from 10.60.5.44 port 58691
[20200728-15:42:57] [DEBUG] Closed socket 12 (AF_INET 10.60.5.47:3389)
[20200728-15:42:57] [DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20200728-15:42:57] [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
[20200728-15:42:57] [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
[20200728-15:42:57] [DEBUG] TLSv1.3 enabled
[20200728-15:42:57] [DEBUG] TLSv1.2 enabled
[20200728-15:42:57] [DEBUG] Security layer: requested 11, selected 1
[20200728-15:42:57] [INFO ] connected client computer name: VB3225
[20200728-15:42:57] [INFO ] adding channel item name rdpdr chan_id 1004 flags 0x80800000
[20200728-15:42:57] [INFO ] adding channel item name rdpsnd chan_id 1005 flags 0xc0000000
[20200728-15:42:57] [INFO ] adding channel item name cliprdr chan_id 1006 flags 0xc0a00000
[20200728-15:42:57] [INFO ] adding channel item name drdynvc chan_id 1007 flags 0xc0800000
[20200728-15:42:57] [INFO ] TLS connection established from 10.60.5.44 port 58691: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384
[20200728-15:42:57] [DEBUG] xrdp_000058f0_wm_login_mode_event_00000001
[20200728-15:42:57] [INFO ] Loading keymap file /etc/xrdp/km-00000409.ini
[20200728-15:42:57] [WARN ] local keymap file for 0x00000409 found and doesn't match built in keymap, using local keymap file
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: connecting to sesman ip 127.0.0.1 port 3350
[20200728-15:43:05] [INFO ] xrdp_wm_log_msg: sesman connect ok
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: sending login info to session manager, please wait...
[20200728-15:43:05] [DEBUG] return value from xrdp_mm_connect 0
[20200728-15:43:05] [INFO ] xrdp_wm_log_msg: login successful for display 13
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC started connecting
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC connecting to 127.0.0.1 5913
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC tcp connected
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC security level is 2 (1 = none, 2 = standard)
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC password ok
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC sending share flag
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC receiving server init
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC receiving pixel format
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC receiving name length
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC receiving name
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC sending pixel format
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC sending encodings
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC sending framebuffer update request
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC sending cursor
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: VNC connection complete, connected ok
[20200728-15:43:05] [DEBUG] xrdp_wm_log_msg: connected ok
[20200728-15:43:05] [DEBUG] xrdp_mm_connect_chansrv: chansrv connect successful
[20200728-15:43:05] [DEBUG] Closed socket 18 (AF_INET 127.0.0.1:35102)
[20200728-15:43:05] [DEBUG] VNC got clip data

xrdp-sesman.log

[20200728-15:43:05] [INFO ] A connection received from 127.0.0.1 port 35102
[20200728-15:43:05] [INFO ] ++ created session (access granted): username *PRIVATE_USER*, ip 10.60.5.44:58691 - socket: 12
[20200728-15:43:05] [INFO ] starting Xvnc session...
[20200728-15:43:05] [DEBUG] Closed socket 13 (AF_INET 0.0.0.0:5913)
[20200728-15:43:05] [DEBUG] Closed socket 13 (AF_INET 0.0.0.0:6013)
[20200728-15:43:05] [DEBUG] Closed socket 13 (AF_INET 0.0.0.0:6213)
[20200728-15:43:05] [DEBUG] Closed socket 10 (AF_INET 127.0.0.1:3350)
[20200728-15:43:05] [INFO ] calling auth_start_session from pid 22772
[20200728-15:43:05] [DEBUG] Closed socket 9 (AF_INET 127.0.0.1:3350)
[20200728-15:43:05] [DEBUG] Closed socket 10 (AF_INET 127.0.0.1:3350)
[20200728-15:43:05] [INFO ] Xvnc :13 -auth .Xauthority -geometry 1920x1080 -depth 32 -rfbauth /home/*PRIVATE_USER*/.vnc/sesman_passwd-*PRIVATE_USER*@*PRIVATE_HOSTNAME*:13 -bs -nolisten tcp -localhost -dpi 96  
[20200728-15:43:05] [CORE ] waiting for window manager (pid 22773) to exit

xrdp-chansrv.13.log

[20200728-15:43:05] [CORE ] main: app started pid 22785(0x00005901)
[20200728-15:43:05] [INFO ] main: DISPLAY env var set to :13.0
[20200728-15:43:05] [INFO ] main: using DISPLAY 13
[20200728-15:43:05] [INFO ] channel_thread_loop: thread start
[20200728-15:43:05] [INFO ] Socket 12: AF_UNIX connection received

2) Now, let me manually disconnect and reconnect the VPN while connected to my Linux workstation over XRDP. This simulates the disconnects I receive. I will then reconnect to my existing session.

xrdp.log I notice here there is no log of my connection dropping, only of me reconnecting to my existing session

[20200728-15:45:35] [DEBUG] VNC got clip data 
[20200728-15:47:20] [INFO ] Socket 12: AF_INET connection received from 10.60.5.44 port 59495
[20200728-15:47:20] [DEBUG] Closed socket 12 (AF_INET 10.60.5.47:3389)
[20200728-15:47:20] [DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20200728-15:47:20] [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
[20200728-15:47:20] [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
[20200728-15:47:20] [DEBUG] TLSv1.3 enabled
[20200728-15:47:20] [DEBUG] TLSv1.2 enabled
[20200728-15:47:20] [DEBUG] Security layer: requested 11, selected 1
[20200728-15:47:20] [DEBUG] Closed socket 12 (AF_INET 10.60.5.47:3389)
[20200728-15:47:20] [INFO ] Socket 12: AF_INET connection received from 10.60.5.44 port 59496
[20200728-15:47:20] [DEBUG] Closed socket 12 (AF_INET 10.60.5.47:3389)
[20200728-15:47:20] [DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
[20200728-15:47:20] [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
[20200728-15:47:20] [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
[20200728-15:47:20] [DEBUG] TLSv1.3 enabled
[20200728-15:47:20] [DEBUG] TLSv1.2 enabled
[20200728-15:47:20] [DEBUG] Security layer: requested 11, selected 1
[20200728-15:47:20] [INFO ] connected client computer name: VB3225
[20200728-15:47:20] [INFO ] adding channel item name rdpdr chan_id 1004 flags 0x80800000
[20200728-15:47:20] [INFO ] adding channel item name rdpsnd chan_id 1005 flags 0xc0000000
[20200728-15:47:20] [INFO ] adding channel item name cliprdr chan_id 1006 flags 0xc0a00000
[20200728-15:47:20] [INFO ] adding channel item name drdynvc chan_id 1007 flags 0xc0800000
[20200728-15:47:20] [INFO ] TLS connection established from 10.60.5.44 port 59496: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384
[20200728-15:47:20] [DEBUG] xrdp_00005c9b_wm_login_mode_event_00000001
[20200728-15:47:20] [INFO ] Loading keymap file /etc/xrdp/km-00000409.ini
[20200728-15:47:20] [WARN ] local keymap file for 0x00000409 found and doesn't match built in keymap, using local keymap file
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: connecting to sesman ip 127.0.0.1 port 3350
[20200728-15:47:27] [INFO ] xrdp_wm_log_msg: sesman connect ok
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: sending login info to session manager, please wait...
[20200728-15:47:27] [DEBUG] return value from xrdp_mm_connect 0
[20200728-15:47:27] [INFO ] xrdp_wm_log_msg: login successful for display 13
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC started connecting
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC connecting to 127.0.0.1 5913
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC tcp connected
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC security level is 2 (1 = none, 2 = standard)
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC password ok
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC sending share flag
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC receiving server init
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC receiving pixel format
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC receiving name length
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC receiving name
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC sending pixel format
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC sending encodings
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC sending framebuffer update request
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC sending cursor
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: VNC connection complete, connected ok
[20200728-15:47:27] [DEBUG] xrdp_wm_log_msg: connected ok
[20200728-15:47:31] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200728-15:47:31] [DEBUG] Closed socket 20 (AF_UNIX)
[20200728-15:47:35] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200728-15:47:35] [DEBUG] Closed socket 20 (AF_UNIX)
[20200728-15:47:39] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200728-15:47:39] [DEBUG] Closed socket 20 (AF_UNIX)
[20200728-15:47:43] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200728-15:47:43] [ERROR] xrdp_mm_connect_chansrv: error in trans_connect chan
[20200728-15:47:43] [DEBUG] Closed socket 18 (AF_INET 127.0.0.1:35138)

xrdp-sesman.log

[20200728-15:43:05] [CORE ] waiting for window manager (pid 22773) to exit 
[20200728-15:47:27] [INFO ] A connection received from 127.0.0.1 port 35138
[20200728-15:47:27] [INFO ] ++ reconnected session: username *PRIVATE_USER*, display :13.0, session_pid 22772, ip 10.60.5.44:59496 - socket: 12
[20200728-15:47:27] [DEBUG] Closed socket 10 (AF_INET 127.0.0.1:3350)

xrdp-chansrv.13.log

[~/.local/share/xrdp]$ ls -ltr 
total 4
-rw-------. 1  311 Jul 28 15:43 xrdp-chansrv.13.log
[ ~/.local/share/xrdp]$ cat xrdp-chansrv.13.log
[20200728-15:43:05] [CORE ] main: app started pid 22785(0x00005901)
[20200728-15:43:05] [INFO ] main: DISPLAY env var set to :13.0
[20200728-15:43:05] [INFO ] main: using DISPLAY 13
[20200728-15:43:05] [INFO ] channel_thread_loop: thread start
[20200728-15:43:05] [INFO ] Socket 12: AF_UNIX connection received

At this point, the shared clipboard is broken and it seems the only way to regain it is logging out and in again. Looking at xrdp-chansrv.13.log it seems to not have been updated at all since my initial login at 15:43:05, and isn't receiving a new connection. Mikky83 mentions this file should be regenerated on each login, but my situation is a bit different as I am simply reconnecting to an existing session.

Let me know if there's anything else I can test or look at, I'll monitor this issue.

coreypenford commented 4 years ago

Small update here, I think I've seen what makes the clipboard work again for me.

Notice the following in the below logs.

xrdp.log

[20200729-09:05:48] [DEBUG] xrdp_wm_log_msg: connected ok
[20200729-09:05:49] [DEBUG] xrdp_mm_connect_chansrv: chansrv connect successful
[20200729-09:05:49] [DEBUG] Closed socket 18 (AF_INET 127.0.0.1:38266)
....
[20200729-09:10:29] [DEBUG] xrdp_wm_log_msg: VNC connection complete, connected ok
[20200729-09:10:29] [DEBUG] xrdp_wm_log_msg: connected ok
[20200729-09:10:33] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200729-09:10:33] [DEBUG] Closed socket 20 (AF_UNIX)
[20200729-09:10:37] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200729-09:10:37] [DEBUG] Closed socket 20 (AF_UNIX)
[20200729-09:10:41] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200729-09:10:41] [DEBUG] Closed socket 20 (AF_UNIX)
[20200729-09:10:45] [ERROR] xrdp_mm_connect_chansrv: connect failed trying again...
[20200729-09:10:45] [ERROR] xrdp_mm_connect_chansrv: error in trans_connect chan
[20200729-09:10:45] [DEBUG] Closed socket 18 (AF_INET 127.0.0.1:38530)
....
[20200729-09:25:54] [DEBUG] Closed socket 12 (AF_INET 10.60.5.47:3389)
[20200729-09:25:54] [DEBUG] xrdp_mm_module_cleanup
[20200729-09:25:54] [DEBUG] VNC mod_exit
[20200729-09:25:54] [DEBUG] Closed socket 19 (AF_INET 127.0.0.1:46196)
[20200729-09:25:54] [DEBUG] Closed socket 20 (AF_UNIX)
....
[20200729-09:39:03] [DEBUG] xrdp_wm_log_msg: VNC sending cursor
[20200729-09:39:03] [DEBUG] xrdp_wm_log_msg: VNC connection complete, connected ok
[20200729-09:39:03] [DEBUG] xrdp_wm_log_msg: connected ok
[20200729-09:39:03] [DEBUG] xrdp_mm_connect_chansrv: chansrv connect successful
[20200729-09:39:03] [DEBUG] Closed socket 18 (AF_INET 127.0.0.1:38852)

xrdp-sesman.log

[20200729-09:05:48] [INFO ] A connection received from 127.0.0.1 port 38266
[20200729-09:05:48] [INFO ] ++ created session (access granted): username *PRIVATE_USER*, ip 10.60.5.44:51362 - socket: 12
[20200729-09:05:48] [INFO ] starting Xvnc session...
[20200729-09:05:48] [DEBUG] Closed socket 13 (AF_INET 0.0.0.0:5913)
[20200729-09:05:48] [DEBUG] Closed socket 13 (AF_INET 0.0.0.0:6013)
[20200729-09:05:48] [DEBUG] Closed socket 13 (AF_INET 0.0.0.0:6213)
[20200729-09:05:48] [DEBUG] Closed socket 10 (AF_INET 127.0.0.1:3350)
[20200729-09:05:48] [INFO ] calling auth_start_session from pid 30822
[20200729-09:05:48] [DEBUG] Closed socket 9 (AF_INET 127.0.0.1:3350)
[20200729-09:05:48] [DEBUG] Closed socket 10 (AF_INET 127.0.0.1:3350)
[20200729-09:05:48] [INFO ] Xvnc :13 -auth .Xauthority -geometry 1920x1080 -depth 32 -rfbauth /home/*PRIVATE_USER*/.vnc/sesman_passwd-*PRIVATE_USER*@*PRIVATE_HOSTNAME*:13 -bs -nolisten tcp -localhost -dpi 96  
[20200729-09:05:48] [CORE ] waiting for window manager (pid 30823) to exit
[20200729-09:10:28] [INFO ] A connection received from 127.0.0.1 port 38530
[20200729-09:10:29] [INFO ] ++ reconnected session: username *PRIVATE_USER*, display :13.0, session_pid 30822, ip 10.60.5.44:53839 - socket: 12
[20200729-09:10:29] [DEBUG] Closed socket 10 (AF_INET 127.0.0.1:3350)
[20200729-09:39:03] [INFO ] A connection received from 127.0.0.1 port 38852
[20200729-09:39:03] [INFO ] ++ reconnected session: username *PRIVATE_USER*, display :13.0, session_pid 30822, ip 10.60.5.44:54957 - socket: 12
[20200729-09:39:03] [DEBUG] Closed socket 10 (AF_INET 127.0.0.1:3350)

xrdp-chansrv.13.log

[20200729-09:05:48] [CORE ] main: app started pid 30835(0x00007873)
[20200729-09:05:48] [INFO ] main: DISPLAY env var set to :13.0
[20200729-09:05:48] [INFO ] main: using DISPLAY 13
[20200729-09:05:48] [INFO ] channel_thread_loop: thread start
[20200729-09:05:49] [INFO ] Socket 12: AF_UNIX connection received
[20200729-09:25:54] [INFO ] channel_thread_loop: trans_check_wait_objs error resetting
[20200729-09:39:03] [INFO ] Socket 12: AF_UNIX connection received

So my best guess (from my uninformed view) is this [20200729-09:25:54] [DEBUG] xrdp_mm_module_cleanup is the "fix", but seems to require a re-connection afterwards for the channel to be set up properly.

Since xrdp.log doesn't detect a connection dropping, running that cleanup function on disconnect doesn't seem possible. But possibly if it were to run before every re-connection (atleast before xrdp_mm_connect_chansrv runs), then I believe the clipboard wouldn't break when a disconnect happens? This may also fix Mikky83's original issue.

I'm just spitballing here, could have the details all wrong. As I said yesterday, let me know if there's anything else I can test or provide.

ivzhh commented 4 years ago

I reported a bug 2291 to Remmina. It seems related to this issue. When connect Xrdp (Fedora 32 xrdp-0.9.14-3.fc32.src.rpm) from Remmina (git latest 1.4.8 branch and freerdp 2.2.0), clipboard keeps failing. So the Remmina becomes very slow (<1FPS).

In addition, use Microsoft's RDP from Mac to connect to Xrdp, copy/paste won't work, but it is not slow.

SolidState214 commented 2 years ago

I am also experiencing this issue, chansrv connections fail, causing clipboard, audio, and drive redirection failures. This is on Almalinux 8 and 9, with Linux and Mac clients running Remmina and Microsoft RDP client for Mac, respectively.

[20220619-10:12:48] [INFO ] Socket 12: AF_INET6 connection received from ::ffff:172.24.16.88 port 46012
[20220619-10:12:48] [DEBUG] Closed socket 12 (AF_INET6 ::ffff:192.168.33.247 port 3389)
[20220619-10:12:48] [DEBUG] Closed socket 11 (AF_INET6 :: port 3389)
[20220619-10:12:48] [DEBUG] item ini_version, value 1
[20220619-10:12:48] [DEBUG] item fork, value true
[20220619-10:12:48] [DEBUG] item port, value 3389
[20220619-10:12:48] [DEBUG] item use_vsock, value false
[20220619-10:12:48] [DEBUG] item tcp_nodelay, value true
[20220619-10:12:48] [DEBUG] item tcp_keepalive, value true
[20220619-10:12:48] [DEBUG] item security_layer, value negotiate
[20220619-10:12:48] [DEBUG] item crypt_level, value high
[20220619-10:12:48] [DEBUG] item certificate, value 
[20220619-10:12:48] [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
[20220619-10:12:48] [DEBUG] item key_file, value 
[20220619-10:12:48] [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
[20220619-10:12:48] [DEBUG] item ssl_protocols, value TLSv1.2, TLSv1.3
[20220619-10:12:48] [DEBUG] TLSv1.3 enabled
[20220619-10:12:48] [DEBUG] TLSv1.2 enabled
[20220619-10:12:48] [DEBUG] item autorun, value 
[20220619-10:12:48] [DEBUG] item allow_channels, value true
[20220619-10:12:48] [DEBUG] item allow_multimon, value true
[20220619-10:12:48] [DEBUG] item bitmap_cache, value true
[20220619-10:12:48] [DEBUG] item bitmap_compression, value true
[20220619-10:12:48] [DEBUG] item bulk_compression, value true
[20220619-10:12:48] [DEBUG] item max_bpp, value 32
[20220619-10:12:48] [DEBUG] item new_cursors, value true
[20220619-10:12:48] [DEBUG] item use_fastpath, value both
[20220619-10:12:48] [DEBUG] item blue, value 009cb5
[20220619-10:12:48] [DEBUG] item grey, value dedede
[20220619-10:12:48] [DEBUG] item ls_top_window_bg_color, value 009cb5
[20220619-10:12:48] [DEBUG] item ls_width, value 350
[20220619-10:12:48] [DEBUG] item ls_height, value 430
[20220619-10:12:48] [DEBUG] item ls_bg_color, value dedede
[20220619-10:12:48] [DEBUG] item ls_logo_filename, value 
[20220619-10:12:48] [DEBUG] item ls_logo_x_pos, value 55
[20220619-10:12:48] [DEBUG] item ls_logo_y_pos, value 50
[20220619-10:12:48] [DEBUG] item ls_label_x_pos, value 30
[20220619-10:12:48] [DEBUG] item ls_label_width, value 65
[20220619-10:12:48] [DEBUG] item ls_input_x_pos, value 110
[20220619-10:12:48] [DEBUG] item ls_input_width, value 210
[20220619-10:12:48] [DEBUG] item ls_input_y_pos, value 220
[20220619-10:12:48] [DEBUG] item ls_btn_ok_x_pos, value 142
[20220619-10:12:48] [DEBUG] item ls_btn_ok_y_pos, value 370
[20220619-10:12:48] [DEBUG] item ls_btn_ok_width, value 85
[20220619-10:12:48] [DEBUG] item ls_btn_ok_height, value 30
[20220619-10:12:48] [DEBUG] item ls_btn_cancel_x_pos, value 237
[20220619-10:12:48] [DEBUG] item ls_btn_cancel_y_pos, value 370
[20220619-10:12:48] [DEBUG] item ls_btn_cancel_width, value 85
[20220619-10:12:48] [DEBUG] item ls_btn_cancel_height, value 30
[20220619-10:12:48] [INFO ] Security protocol: configured [SSL|RDP], requested [SSL|HYBRID|RDP], selected [SSL]
[20220619-10:12:48] [DEBUG] Using TLS security, and setting RDP security crypto to LEVEL_NONE and METHOD_NONE
[20220619-10:12:48] [DEBUG] [MCS Connection Sequence] receive connection request
[20220619-10:12:48] [INFO ] Connected client computer name: omitted
[20220619-10:12:48] [DEBUG] The connection is using TLS, skipping RDP crypto negotiation
[20220619-10:12:48] [DEBUG] Adding channel: name rdpdr, channel id 1004, flags 0xc0800000
[20220619-10:12:48] [DEBUG] Adding channel: name rdpsnd, channel id 1005, flags 0xc0000000
[20220619-10:12:48] [DEBUG] Adding channel: name cliprdr, channel id 1006, flags 0xc0a00000
[20220619-10:12:48] [DEBUG] Adding channel: name drdynvc, channel id 1007, flags 0xc0800000
[20220619-10:12:48] [WARN ] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc006 is unknown (ignored)
[20220619-10:12:48] [WARN ] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc00a is unknown (ignored)
[20220619-10:12:48] [DEBUG] [MCS Connection Sequence] construct connection reponse
[20220619-10:12:48] [DEBUG] using no security
[20220619-10:12:48] [DEBUG] [MCS Connection Sequence] send connection reponse
[20220619-10:12:48] [DEBUG] [MCS Connection Sequence] receive erect domain request
[20220619-10:12:48] [DEBUG] [MCS Connection Sequence] receive attach user request
[20220619-10:12:48] [DEBUG] [MCS Connection Sequence] send attach user confirm
[20220619-10:12:48] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] receive channel join request
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] send channel join confirm
[20220619-10:12:49] [DEBUG] [MCS Connection Sequence] completed
[20220619-10:12:49] [INFO ] xrdp_load_keyboard_layout: Keyboard information sent by the RDP client, keyboard_type:[0x04], keyboard_subtype:[0x00], keylayout:[0x00000409]
[20220619-10:12:49] [DEBUG] keyboard_cfg_file /etc/xrdp/xrdp_keyboard.ini
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item rdp_layout_us value 0x00000409
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: skipping configuration item - rdp_layout_us, continuing to next section
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item rdp_layout_us value us
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: skipping configuration item - rdp_layout_us, continuing to next section
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item keyboard_type value 4
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item keyboard_subtype value 3
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item keyboard_type value 7
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item keyboard_subtype value 2
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item model value pc105
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item rdp_layouts value default_rdp_layouts
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item layouts_map value default_layouts_map
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: item rdp_layout_us value us
[20220619-10:12:49] [DEBUG] xrdp_load_keyboard_layout: skipping configuration item - rdp_layout_us, continuing to next section
[20220619-10:12:49] [INFO ] xrdp_load_keyboard_layout: model [] variant [] layout [us] options []
[20220619-10:12:49] [INFO ] TLS connection established from ::ffff:172.24.16.88 port 46012: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384
[20220619-10:12:49] [DEBUG] Client requested auto logon.
[20220619-10:12:49] [DEBUG] Client requested compression enabled.
[20220619-10:12:49] [DEBUG] Client supplied domain: 
[20220619-10:12:49] [DEBUG] Client supplied username: omitted
[20220619-10:12:49] [DEBUG] Client supplied password: <omitted from log>
[20220619-10:12:49] [DEBUG] Client supplied program: 
[20220619-10:12:49] [DEBUG] Client supplied directory: 
[20220619-10:12:49] [INFO ] xrdp_caps_process_pointer: client supports new(color) cursor
[20220619-10:12:49] [INFO ] xrdp_process_offscreen_bmpcache: support level 1 cache size 7864320 MB cache entries 2000
[20220619-10:12:49] [INFO ] xrdp_caps_process_codecs: RemoteFX, codec id 3, properties len 49
[20220619-10:12:49] [WARN ] Client Capability: not enough orders supported by client, client wants off screen bitmap but offscreen bitmaps disabled
[20220619-10:12:49] [DEBUG] xrdp_00000a7d_wm_login_state_event_00000001
[20220619-10:12:49] [INFO ] Loading keymap file /etc/xrdp/km-00000409.ini
[20220619-10:12:49] [WARN ] local keymap file for 0x00000409 found and doesn't match built in keymap, using local keymap file
[20220619-10:12:49] [DEBUG] Login state change request WMLS_RESET -> WMLS_RESET
[20220619-10:12:49] [DEBUG] xrdp_wm_login_mode_changed: login_mode is 0
[20220619-10:12:49] [DEBUG] Login state change request WMLS_RESET -> WMLS_USER_PROMPT
[20220619-10:12:49] [DEBUG] in xrdp_wm_init: 
[20220619-10:12:49] [DEBUG] ini_version:             1
[20220619-10:12:49] [DEBUG] use_bitmap_cache:        1
[20220619-10:12:49] [DEBUG] use_bitmap_compression:  1
[20220619-10:12:49] [DEBUG] port:                    3389
[20220619-10:12:49] [DEBUG] crypt_level:             3
[20220619-10:12:49] [DEBUG] allow_channels:          1
[20220619-10:12:49] [DEBUG] max_bpp:                 32
[20220619-10:12:49] [DEBUG] fork:                    1
[20220619-10:12:49] [DEBUG] tcp_nodelay:             1
[20220619-10:12:49] [DEBUG] tcp_keepalive:           1
[20220619-10:12:49] [DEBUG] tcp_send_buffer_bytes:   0
[20220619-10:12:49] [DEBUG] tcp_recv_buffer_bytes:   0
[20220619-10:12:49] [DEBUG] new_cursors:             1
[20220619-10:12:49] [DEBUG] allow_multimon:          1
[20220619-10:12:49] [DEBUG] grey:                    14606046
[20220619-10:12:49] [DEBUG] black:                   0
[20220619-10:12:49] [DEBUG] dark_grey:               0
[20220619-10:12:49] [DEBUG] blue:                    40117
[20220619-10:12:49] [DEBUG] dark_blue:               0
[20220619-10:12:49] [DEBUG] white:                   0
[20220619-10:12:49] [DEBUG] red:                     0
[20220619-10:12:49] [DEBUG] green:                   0
[20220619-10:12:49] [DEBUG] background:              0
[20220619-10:12:49] [DEBUG] autorun:                 
[20220619-10:12:49] [DEBUG] hidelogwindow:           0
[20220619-10:12:49] [DEBUG] require_credentials:     0
[20220619-10:12:49] [DEBUG] bulk_compression:        1
[20220619-10:12:49] [DEBUG] new_cursors:             1
[20220619-10:12:49] [DEBUG] nego_sec_layer:          0
[20220619-10:12:49] [DEBUG] allow_multimon:          1
[20220619-10:12:49] [DEBUG] enable_token_login:      0
[20220619-10:12:49] [DEBUG] ls_top_window_bg_color:  b59c00
[20220619-10:12:49] [DEBUG] ls_width:                350
[20220619-10:12:49] [DEBUG] ls_height:               430
[20220619-10:12:49] [DEBUG] ls_bg_color:             dedede
[20220619-10:12:49] [DEBUG] ls_title:                
[20220619-10:12:49] [DEBUG] ls_logo_filename:        
[20220619-10:12:49] [DEBUG] ls_logo_x_pos:           55
[20220619-10:12:49] [DEBUG] ls_logo_y_pos:           50
[20220619-10:12:49] [DEBUG] ls_label_x_pos:          30
[20220619-10:12:49] [DEBUG] ls_label_width:          65
[20220619-10:12:49] [DEBUG] ls_input_x_pos:          110
[20220619-10:12:49] [DEBUG] ls_input_width:          210
[20220619-10:12:49] [DEBUG] ls_input_y_pos:          220
[20220619-10:12:49] [DEBUG] ls_btn_ok_x_pos:         142
[20220619-10:12:49] [DEBUG] ls_btn_ok_y_pos:         370
[20220619-10:12:49] [DEBUG] ls_btn_ok_width:         85
[20220619-10:12:49] [DEBUG] ls_btn_ok_height:        30
[20220619-10:12:49] [DEBUG] ls_btn_cancel_x_pos:     237
[20220619-10:12:49] [DEBUG] ls_btn_cancel_y_pos:     370
[20220619-10:12:49] [DEBUG] ls_btn_cancel_width:     85
[20220619-10:12:50] [DEBUG] ls_btn_cancel_height:    30
[20220619-10:12:50] [DEBUG] libxrdp_query_channel - Channel 0 name rdpdr
[20220619-10:12:50] [DEBUG] xrdp_wm_init: channel rdpdr channel id 0 is enabled
[20220619-10:12:50] [DEBUG] Enabling channel 1004 (rdpdr)
[20220619-10:12:50] [DEBUG] libxrdp_query_channel - Channel 1 name rdpsnd
[20220619-10:12:50] [DEBUG] xrdp_wm_init: channel rdpsnd channel id 1 is enabled
[20220619-10:12:50] [DEBUG] Enabling channel 1005 (rdpsnd)
[20220619-10:12:50] [DEBUG] libxrdp_query_channel - Channel 2 name cliprdr
[20220619-10:12:50] [DEBUG] xrdp_wm_init: channel cliprdr channel id 2 is enabled
[20220619-10:12:50] [DEBUG] Enabling channel 1006 (cliprdr)
[20220619-10:12:50] [DEBUG] libxrdp_query_channel - Channel 3 name drdynvc
[20220619-10:12:50] [DEBUG] xrdp_wm_init: channel drdynvc channel id 3 is enabled
[20220619-10:12:50] [DEBUG] Enabling channel 1007 (drdynvc)
[20220619-10:12:50] [DEBUG] Login state change request WMLS_USER_PROMPT -> WMLS_START_CONNECT
[20220619-10:12:50] [DEBUG] out xrdp_wm_init: 
[20220619-10:12:50] [DEBUG] xrdp_wm_login_mode_changed: login_mode is 2
[20220619-10:12:50] [DEBUG] Login state change request WMLS_START_CONNECT -> WMLS_CONNECT_IN_PROGRESS
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: connecting to sesman on 127.0.0.1:3350
[20220619-10:12:50] [INFO ] connecting to sesman on 127.0.0.1:3350
[20220619-10:12:50] [INFO ] xrdp_wm_log_msg: sesman connect ok
[20220619-10:12:50] [INFO ] sesman connect ok
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: sending login info to session manager. Please wait...
[20220619-10:12:50] [INFO ] sending login info to session manager. Please wait...
[20220619-10:12:50] [DEBUG] xrdp_wm_login_mode_changed: login_mode is 3
[20220619-10:12:50] [INFO ] xrdp_wm_log_msg: login successful for user omitted on display 10
[20220619-10:12:50] [INFO ] login successful for user omitted on display 10
[20220619-10:12:50] [INFO ] loaded module 'libvnc.so' ok, interface size 4064, version 4
[20220619-10:12:50] [DEBUG] Layout from client_info (geom=3840x1080 #screens=1) : 0:(3840x1080+0+0)
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC started connecting
[20220619-10:12:50] [INFO ] VNC started connecting
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC connecting to 127.0.0.1 5910
[20220619-10:12:50] [INFO ] VNC connecting to 127.0.0.1 5910
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC tcp connected
[20220619-10:12:50] [INFO ] VNC tcp connected
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC security level is 1 (1 = none, 2 = standard)
[20220619-10:12:50] [INFO ] VNC security level is 1 (1 = none, 2 = standard)
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC sending share flag
[20220619-10:12:50] [INFO ] VNC sending share flag
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC receiving server init
[20220619-10:12:50] [INFO ] VNC receiving server init
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC receiving pixel format
[20220619-10:12:50] [INFO ] VNC receiving pixel format
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC receiving name length
[20220619-10:12:50] [INFO ] VNC receiving name length
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC receiving name
[20220619-10:12:50] [INFO ] VNC receiving name
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC sending pixel format
[20220619-10:12:50] [INFO ] VNC sending pixel format
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC sending cursor
[20220619-10:12:50] [INFO ] VNC sending cursor
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: VNC connection complete, connected ok
[20220619-10:12:50] [INFO ] VNC connection complete, connected ok
[20220619-10:12:50] [INFO ] VNC: Clipboard (if available) is provided by chansrv facility
[20220619-10:12:50] [DEBUG] xrdp_wm_log_msg: connected ok
[20220619-10:12:50] [INFO ] connected ok
[20220619-10:12:54] [WARN ] xrdp_mm_chansrv_connect: connect failed trying again...
[20220619-10:12:54] [DEBUG] Closed socket 20 (AF_UNIX)
[20220619-10:12:58] [WARN ] xrdp_mm_chansrv_connect: connect failed trying again...
[20220619-10:12:58] [DEBUG] Closed socket 20 (AF_UNIX)
[20220619-10:13:02] [WARN ] xrdp_mm_chansrv_connect: connect failed trying again...
[20220619-10:13:02] [DEBUG] Closed socket 20 (AF_UNIX)
[20220619-10:13:06] [WARN ] xrdp_mm_chansrv_connect: connect failed trying again...
[20220619-10:13:06] [ERROR] xrdp_mm_chansrv_connect: error in trans_connect chan
[20220619-10:13:06] [DEBUG] status from xrdp_mm_connect() : 0

The xrdp-chansrv process goes into defunct state upon login and no redirection seems to work.

matt335672 commented 2 years ago

@SolidState214

I assume you're using the latest xrdp from EPEL?

When this happens, try the following in a terminal window in your xrdp session:-

fusermount -u ~/thinclient_drives
xrdp-chansrv

That should restart chansrv and leave it running in the terminal window.

Then disconnect the RDP client and reconnect it. See what happens in the terminal window. If you get a crash, can you provide the contents of ~/.local/share/xrdp/xrdp-chansrv.$DISPLAY.log

Thanks.

SolidState214 commented 2 years ago

@matt335672 I managed to resolve my issue. As it turns out, an Ansible role I was using to configure xrdp was setting permissions on the sesman.ini file when it was setting options, causing the file to be unreadable by users other than root. Setting the correct permissions on the file caused the clipboard to start working again. Color me embarrassed, thanks for your help.