Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

xrdp_mm_connect_chansrv: connect failed #1901

Closed
saddy001 opened this issue May 27, 2021 · 7 comments
Closed

xrdp_mm_connect_chansrv: connect failed #1901

saddy001 opened this issue May 27, 2021 · 7 comments

Comments

@saddy001
Copy link

  • xrdp v0.9.16, Linux, Guacamole

When certain characters are used in the user's password, the connection fails to establish (black screen). For example the " character triggers the issue, but there are more. Without these chars, everything works as expected. May be related: #1435

[20210527-17:55:22] [INFO ] Socket 12: AF_INET connection received from 127.0.0.1 port 56816
[20210527-17:55:22] [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
[20210527-17:55:22] [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
[20210527-17:55:22] [INFO ] Connected client computer name: Guacamole RDP
[20210527-17:55:22] [WARN ] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc006 is unknown (ignored)
[20210527-17:55:22] [WARN ] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc00a is unknown (ignored)
[20210527-17:55:23] [INFO ] xrdp_load_keyboard_layout: keyboard_type [4] keyboard_subtype [0]
[20210527-17:55:23] [INFO ] xrdp_load_keyboard_layout: model [] variant [] layout [de] options []
[20210527-17:55:23] [INFO ] TLS connection established from 127.0.0.1 port 56816: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384
[20210527-17:55:23] [INFO ] xrdp_caps_process_pointer: client supports new(color) cursor
[20210527-17:55:23] [INFO ] xrdp_process_offscreen_bmpcache: support level 1 cache size 7864320 MB cache entries 2000
[20210527-17:55:23] [WARN ] Client Capability: not enough orders supported by client, client wants off screen bitmap but offscreen bitmaps disabled
[20210527-17:55:23] [WARN ] Dynamic Virtual Channel named 'drdynvc' not found, channel not initialized
[20210527-17:55:23] [INFO ] Loading keymap file /etc/xrdp/km-00000407.ini
[20210527-17:55:23] [WARN ] local keymap file for 0x00000407 found and doesn't match built in keymap, using local keymap file
[20210527-17:55:23] [INFO ] connecting to sesman ip 127.0.0.1 port 3350
[20210527-17:55:23] [INFO ] xrdp_wm_log_msg: sesman connect ok
[20210527-17:55:23] [INFO ] sesman connect ok
[20210527-17:55:23] [INFO ] sending login info to session manager, please wait...
[20210527-17:55:23] [INFO ] xrdp_wm_log_msg: login successful for display 10
[20210527-17:55:23] [INFO ] login successful for display 10
[20210527-17:55:23] [INFO ] loaded module 'libxup.so' ok, interface size 10288, version 4
[20210527-17:55:23] [INFO ] started connecting
[20210527-17:55:23] [INFO ] lib_mod_connect: connecting via UNIX socket
[20210527-17:55:23] [INFO ] lib_mod_log_peer: xrdp_pid=7565 connected to X11rdp_pid=7581 X11rdp_uid=1041 X11rdp_gid=1042 client_ip=127.0.0.1 client_port=56816
[20210527-17:55:23] [INFO ] connected ok
[20210527-17:55:27] [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
[20210527-17:55:31] [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
[20210527-17:55:35] [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
[20210527-17:55:39] [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
[20210527-17:55:39] [ERROR] xrdp_mm_connect_chansrv: error in trans_connect chan
[20210527-17:55:39] [ERROR] SSL_shutdown: Failure in SSL library (protocol error?)
@saddy001
Copy link
Author

Here's another trigger char: `

@matt335672
Copy link
Member

Hi @saddy001

I'm unable to reproduce this with a password ending in " on either the Guacamole client or mstsc.exe

Can you provide a password where you see this happening?

Also, it doesn't seem like this can be a root cause. If you've already authenticated, as the log above shows, there's nothing else on the xrdp side which uses the password. It's more likely your session is ending unexpectedly.

Can you post the xrdp-sesman log when this happens as well please?

@saddy001
Copy link
Author

Only WARN log level here, so there's not much to see:

[20210527-17:55:23] [WARN ] Window manager (pid 7580, display 10) exited with non-zero exit code 2 and signal 0. This could indicate a window manager config problem
[20210527-17:55:23] [WARN ] Window manager (pid 7580, display 10) exited quickly (0 secs). This could indicate a window manager config problem

I tested with the password d"dd

@matt335672
Copy link
Member

That's really useful - thanks.

This scenario fits the evidence we have so far:-

  1. sesman validates password, starts X server and session, sends an acknowledgement back to xrdp.
  2. xrdp connects to X server
  3. Session exits
  4. xrdp can't find chansrv to connect to.

The session exiting may or may not be anything to do with your password characters.

Can we get a log from the system when the failure happens? Procedure is:-

  1. Make a note of the system time in hours, minutes and seconds (HH:MM:SS)
  2. Try to log in
  3. Post the output of sudo journalctl -S HH:MM:SS where HH:MM:SS is the time you noted in step 1.

Hopefully that will give us more clues.

@saddy001
Copy link
Author

saddy001 commented Jun 1, 2021

The tested password was
!$%&/()=?`{[]}+*~#',.-;:_<>|

not
d"dd

Mai 27 17:55:22 myhost guacd[1665]: Creating new client for protocol "rdp"
Mai 27 17:55:22 myhost guacd[1665]: Connection ID is "$5c1cc564-481f-431d-83ef-1eed18cd9824"
Mai 27 17:55:22 myhost guacd[1665]: guacd[1665]: INFO:        Creating new client for protocol "rdp"
Mai 27 17:55:22 myhost guacd[1665]: guacd[1665]: INFO:        Connection ID is "$5c1cc564-481f-431d-83ef-1eed18cd9824"
Mai 27 17:55:22 myhost guacd[7551]: Security mode: Negotiate (ANY)
Mai 27 17:55:22 myhost guacd[1665]: guacd[7551]: INFO:        Security mode: Negotiate (ANY)
Mai 27 17:55:22 myhost guacd[1665]: guacd[7551]: INFO:        Resize method: reconnect
Mai 27 17:55:22 myhost guacd[1665]: guacd[7551]: INFO:        User "@70deb7e4-06c4-42e4-85ed-6c611bbfd84e" joined connection "$5c1cc564-481f-431d-83ef-1eed18cd9824" (1 users now present)
Mai 27 17:55:22 myhost guacd[7551]: Resize method: reconnect
Mai 27 17:55:22 myhost guacd[7551]: User "@70deb7e4-06c4-42e4-85ed-6c611bbfd84e" joined connection "$5c1cc564-481f-431d-83ef-1eed18cd9824" (1 users now present)
Mai 27 17:55:22 myhost guacd[7551]: Loading keymap "base"
Mai 27 17:55:22 myhost guacd[1665]: guacd[7551]: INFO:        Loading keymap "base"
Mai 27 17:55:22 myhost guacd[1665]: guacd[7551]: INFO:        Loading keymap "de-de-qwertz"
Mai 27 17:55:22 myhost guacd[7551]: Loading keymap "de-de-qwertz"
Mai 27 17:55:22 myhost xrdp[1785]: [INFO ] Socket 12: AF_INET connection received from 127.0.0.1 port 56816
Mai 27 17:55:22 myhost xrdp[7565]: [INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
Mai 27 17:55:22 myhost xrdp[7565]: [INFO ] Using default X.509 key file: /etc/xrdp/key.pem
Mai 27 17:55:22 myhost xrdp[7565]: [INFO ] Connected client computer name: Guacamole RDP
Mai 27 17:55:22 myhost xrdp[7565]: [WARN ] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc006 is unknown (ignored)
Mai 27 17:55:22 myhost xrdp[7565]: [WARN ] Received [MS-RDPBCGR] TS_UD_HEADER type 0xc00a is unknown (ignored)
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] xrdp_load_keyboard_layout: keyboard_type [4] keyboard_subtype [0]
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] xrdp_load_keyboard_layout: model [] variant [] layout [de] options []
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] TLS connection established from 127.0.0.1 port 56816: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] xrdp_caps_process_pointer: client supports new(color) cursor
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] xrdp_process_offscreen_bmpcache: support level 1 cache size 7864320 MB cache entries 2000
Mai 27 17:55:23 myhost xrdp[7565]: [WARN ] Client Capability: not enough orders supported by client, client wants off screen bitmap but offscreen bitmaps disabled
Mai 27 17:55:23 myhost xrdp[7565]: [WARN ] Dynamic Virtual Channel named 'drdynvc' not found, channel not initialized
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] Loading keymap file /etc/xrdp/km-00000407.ini
Mai 27 17:55:23 myhost xrdp[7565]: [WARN ] local keymap file for 0x00000407 found and doesn't match built in keymap, using local keymap file
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] connecting to sesman ip 127.0.0.1 port 3350
Mai 27 17:55:23 myhost xrdp-sesman[1704]: [INFO ] A connection received from 127.0.0.1 port 55998
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] xrdp_wm_log_msg: sesman connect ok
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] sesman connect ok
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] sending login info to session manager, please wait...
Mai 27 17:55:23 myhost xrdp-sesman[1704]: [INFO ] Terminal Server Users group is disabled, allowing authentication
Mai 27 17:55:23 myhost xrdp-sesman[1704]: [INFO ] ++ created session (access granted): username test25, ip 127.0.0.1:56816 - socket: 12
Mai 27 17:55:23 myhost xrdp-sesman[1704]: [INFO ] starting Xorg session...
Mai 27 17:55:23 myhost xrdp-sesman[1704]: [INFO ] Starting session: session_pid 7567, display :10.0, width 1676, height 942, bpp 24, client ip 127.0.0.1:56816 - socket: 12, user name test25
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] [session start] (display 10): calling auth_start_session from pid 7567
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] xrdp_wm_log_msg: login successful for display 10
Mai 27 17:55:23 myhost xrdp-sesman[7567]: pam_unix(xrdp-sesman:session): session opened for user test25 by (uid=0)
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] login successful for display 10
Mai 27 17:55:23 myhost systemd[1]: Created slice User Slice of test25.
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] loaded module 'libxup.so' ok, interface size 10288, version 4
Mai 27 17:55:23 myhost systemd[1]: Starting User Manager for UID 1041...
Mai 27 17:55:23 myhost systemd[7568]: pam_unix(systemd-user:session): session opened for user test25 by (uid=0)
Mai 27 17:55:23 myhost systemd-logind[1145]: New session c4 of user test25.
Mai 27 17:55:23 myhost systemd[1]: Started Session c4 of user test25.
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] started connecting
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] lib_mod_connect: connecting via UNIX socket
Mai 27 17:55:23 myhost systemd[7568]: Listening on GnuPG network certificate management daemon.
Mai 27 17:55:23 myhost systemd[7568]: Reached target Timers.
Mai 27 17:55:23 myhost systemd[7568]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Mai 27 17:55:23 myhost systemd[7568]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Mai 27 17:55:23 myhost systemd[7568]: Listening on GnuPG cryptographic agent and passphrase cache.
Mai 27 17:55:23 myhost systemd[7568]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Mai 27 17:55:23 myhost systemd[7568]: Starting D-Bus User Message Bus Socket.
Mai 27 17:55:23 myhost systemd[7568]: Reached target Paths.
Mai 27 17:55:23 myhost systemd[7568]: Listening on D-Bus User Message Bus Socket.
Mai 27 17:55:23 myhost systemd[7568]: Reached target Sockets.
Mai 27 17:55:23 myhost systemd[7568]: Reached target Basic System.
Mai 27 17:55:23 myhost systemd[7568]: Reached target Default.
Mai 27 17:55:23 myhost systemd[7568]: Startup finished in 27ms.
Mai 27 17:55:23 myhost systemd[1]: Started User Manager for UID 1041.
Mai 27 17:55:23 myhost xrdp-sesman[7581]: [INFO ] Starting X server on display 10: Xorg :10 -auth .Xauthority -config xrdp/xorg.conf -noreset -nolisten tcp -logfile .xorgxrdp.%s.log
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] lib_mod_log_peer: xrdp_pid=7565 connected to X11rdp_pid=7581 X11rdp_uid=1041 X11rdp_gid=1042 client_ip=127.0.0.1 client_port=56816
Mai 27 17:55:23 myhost xrdp[7565]: [INFO ] connected ok
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] Found X server running at /tmp/.X11-unix/X10
Mai 27 17:55:23 myhost xrdp-sesman[7580]: [INFO ] Found X server running at /tmp/.X11-unix/X10
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] Session started successfully for user test25 on display 10
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] Session in progress on display 10, waiting until the window manager (pid 7580) exits to end the session
Mai 27 17:55:23 myhost xrdp-sesman[7580]: [INFO ] Found X server running at /tmp/.X11-unix/X10
Mai 27 17:55:23 myhost xrdp-sesman[7580]: [INFO ] Starting user requested window manager on display 10 with embeded arguments using a shell: /home/user/start.sh <snip>
Mai 27 17:55:23 myhost xrdp-sesman[7597]: [INFO ] Starting the xrdp channel server for display 10
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [WARN ] Window manager (pid 7580, display 10) exited with non-zero exit code 2 and signal 0. This could indicate a window manager config problem
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [WARN ] Window manager (pid 7580, display 10) exited quickly (0 secs). This could indicate a window manager config problem
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] Calling auth_stop_session and auth_end from pid 7567
Mai 27 17:55:23 myhost xrdp-sesman[7567]: pam_unix(xrdp-sesman:session): session closed for user test25
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] Terminating X server (pid 7581) on display 10
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] Terminating the xrdp channel server (pid 7597) on display 10
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] X server on display 10 (pid 7581) returned exit code 0 and signal number 0
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] xrdp channel server for display 10 (pid 7597) exit code 0 and signal number 0
Mai 27 17:55:23 myhost xrdp-sesman[7567]: [INFO ] cleanup_sockets:
Mai 27 17:55:23 myhost xrdp-sesman[1704]: [INFO ] ++ terminated session:  username test25, display :10.0, session_pid 7567, ip 127.0.0.1:56816 - socket: 12
Mai 27 17:55:23 myhost systemd-logind[1145]: Removed session c4.
Mai 27 17:55:23 myhost systemd[1]: Stopping User Manager for UID 1041...
Mai 27 17:55:23 myhost systemd[7568]: Stopped target Default.
Mai 27 17:55:23 myhost systemd[7568]: Stopped target Basic System.
Mai 27 17:55:23 myhost systemd[7568]: Stopped target Paths.
Mai 27 17:55:23 myhost systemd[7568]: Stopped target Sockets.
Mai 27 17:55:23 myhost systemd[7568]: Closed GnuPG cryptographic agent and passphrase cache (restricted).
Mai 27 17:55:23 myhost systemd[7568]: Closed GnuPG network certificate management daemon.
Mai 27 17:55:23 myhost systemd[7568]: Closed GnuPG cryptographic agent (ssh-agent emulation).
Mai 27 17:55:23 myhost systemd[7568]: Closed GnuPG cryptographic agent and passphrase cache (access for web browsers).
Mai 27 17:55:23 myhost systemd[7568]: Closed D-Bus User Message Bus Socket.
Mai 27 17:55:23 myhost systemd[7568]: Closed GnuPG cryptographic agent and passphrase cache.
Mai 27 17:55:23 myhost systemd[7568]: Stopped target Timers.
Mai 27 17:55:23 myhost systemd[7568]: Reached target Shutdown.
Mai 27 17:55:23 myhost systemd[7568]: Starting Exit the Session...
Mai 27 17:55:23 myhost systemd[7568]: Received SIGRTMIN+24 from PID 7599 (kill).
Mai 27 17:55:23 myhost systemd[1]: Stopped User Manager for UID 1041.
Mai 27 17:55:23 myhost systemd[1]: Removed slice User Slice of test25.
Mai 27 17:55:27 myhost xrdp[7565]: [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
Mai 27 17:55:31 myhost xrdp[7565]: [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
Mai 27 17:55:35 myhost xrdp[7565]: [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
Mai 27 17:55:39 myhost xrdp[7565]: [WARN ] xrdp_mm_connect_chansrv: connect failed trying again...
Mai 27 17:55:39 myhost xrdp[7565]: [ERROR] xrdp_mm_connect_chansrv: error in trans_connect chan
Mai 27 17:55:39 myhost xrdp[7565]: [ERROR] SSL_shutdown: Failure in SSL library (protocol error?)
Mai 27 17:55:39 myhost guacd[7551]: RDP server closed/refused connection: Manually logged off.
Mai 27 17:55:39 myhost guacd[1665]: guacd[7551]: INFO:        RDP server closed/refused connection: Manually logged off.
Mai 27 17:55:39 myhost guacd[7551]: Internal RDP client disconnected
Mai 27 17:55:39 myhost guacd[1665]: guacd[7551]: INFO:        Internal RDP client disconnected
Mai 27 17:55:42 myhost guacd[7551]: User "@70deb7e4-06c4-42e4-85ed-6c611bbfd84e" disconnected (0 users remain)
Mai 27 17:55:42 myhost guacd[1665]: guacd[7551]: INFO:        User "@70deb7e4-06c4-42e4-85ed-6c611bbfd84e" disconnected (0 users remain)
Mai 27 17:55:42 myhost guacd[1665]: guacd[7551]: INFO:        Last user of connection "$5c1cc564-481f-431d-83ef-1eed18cd9824" disconnected
Mai 27 17:55:42 myhost guacd[7551]: Last user of connection "$5c1cc564-481f-431d-83ef-1eed18cd9824" disconnected
Mai 27 17:55:42 myhost guacd[1665]: Connection "$5c1cc564-481f-431d-83ef-1eed18cd9824" removed.
Mai 27 17:55:42 myhost guacd[1665]: guacd[1665]: INFO:        Connection "$5c1cc564-481f-431d-83ef-1eed18cd9824" removed.

@matt335672
Copy link
Member

Interesting - there's no logging at all from the session itself, which implies it didn't really get going.

I see from this line:-

Mai 27 17:55:23 myhost xrdp-sesman[7580]: [INFO ] Starting user requested window manager on display 10 with embeded arguments using a shell: /home/user/start.sh <snip>

that you're using a user-provided window manager.

Does your user test25 have read+execute permissions to /home/user/start.sh?

Assuming it does, we could get some more logging out of start.sh by adding something like the following to the start of it:-

#!/bin/sh

set -x

exec >$HOME/start.log 2>&1

@saddy001
Copy link
Author

saddy001 commented Jun 1, 2021

I see what's the problem, I had an error in start.sh under certain conditions. Thanks for investigating!

@saddy001 saddy001 closed this as completed Jun 1, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@saddy001 @matt335672