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.

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

Desktop wont start and vnc or tiger vnc wont show cli or desktop by default #3615

Closed
krishnasen2401 opened this issue Jun 19, 2020 · 30 comments
Labels
ARMbaby Buster External bug 🐞 For bugs which are not caused by DietPi. Solution available 🥂 Definite solution has been done
Milestone

Comments

@krishnasen2401
Copy link

krishnasen2401 commented Jun 19, 2020

Creating a bug report/issue

Required Information

Additional Information (if applicable)

  • Software title | ( LXDE)
  • Was the software title installed freshly or updated/migrated? Freshly Installed
  • Can this issue be replicated on a fresh installation of DietPi? Yes

Steps to reproduce

  1. Login via cli (attached to montior)
  2. startx or sudo startx

Expected behaviour

Should Display a Desktop Environment may it be lxde or mate

Actual behaviour

dietpi@DietPi:/etc/X11$ sudo startx
X.Org X Server 1.20.4
X Protocol Version 11, Revision 0
Build Operating System: Linux 4.15.0-48-generic armv8l Raspbian
Current Operating System: Linux DietPi 4.19.118-v7l+ #1311 SMP Mon Apr 27 14:26:42 BST 2020 armv7l
Kernel command line: coherent_pool=1M 8250.nr_uarts=0 cma=64M snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 bcm2708_fb.fbwidth=0 bcm2708_fb.fbheight=0 bcm2708_fb.fbswap=1 smsc95xx.macaddr=DC:A6:32:87:00:37 vc_mem.m
em_base=0x3ec00000 vc_mem.mem_size=0x40000000  console=tty1 root=PARTUUID=2fed7fee-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait quiet net.ifnames=0
Build Date: 05 June 2019  12:49:54PM
xorg-server 2:1.20.4-1+rpt1 (https://www.debian.org/support) 
Current version of pixman: 0.36.0
        Before reporting problems, check http://wiki.x.org
        to make sure that you have the latest version.
Markers: (--) probed, (**) from config file, (==) default setting,
        (++) from command line, (!!) notice, (II) informational,
        (WW) warning, (EE) error, (NI) not implemented, (??) unknown.
(==) Log file: "/var/log/Xorg.0.log", Time: Fri Jun 19 15:45:29 2020
(==) Using config directory: "/etc/X11/xorg.conf.d"
(==) Using system config directory "/usr/share/X11/xorg.conf.d"
(EE) 
Fatal server error:
(EE) no screens found(EE) 
(EE) 
Please consult the The X.Org Foundation support 
         at http://wiki.x.org
 for help. 
(EE) Please also check the log file at "/var/log/Xorg.0.log" for additional information.
(EE) 
(EE) Server terminated with error (1). Closing log file.
xinit: giving up
xinit: unable to connect to X server: Connection refused
xinit: server error

Also in vncview unless i give address as ip:1 it wont be displayed same with windows rdp server just a bluescreen

@Joulinar
Copy link
Collaborator

Joulinar commented Jun 19, 2020

Hi,

many thanks for your report. As I see you have 2 issues:

  1. using startx as non-root user.
  1. VNC not reachable
  • by design VNC should be running on port 5901 (setting SOFTWARE_VNCSERVER_DISPLAY_INDEX=1 inside /boot/dietpi.txt)
  • basically you could verify it by executing ss -alnp | grep LISTEN
  • Therefore you would need to specify :1 on your VNC client

@krishnasen2401
Copy link
Author

I have tried via sudo startx and

1.sudo su
2.startx

Login via root also same result

@Joulinar
Copy link
Collaborator

pls can you copy content of /var/log/Xorg.0.log

@krishnasen2401
Copy link
Author

log.txt
here is log file

@MichaIng
Copy link
Owner

How did you install the desktop and did you choose/enable a VC4 OpenGL overlay (e.g. via dietpi-config)?
GPU memory split has been increased to at least 32M?

@krishnasen2401
Copy link
Author

krishnasen2401 commented Jun 20, 2020

Have installed via dietpi-software and raise GPU to 64mb as of now its working via root user for attached display and ip:1 via vnc but for xrdp display(via xvnc)
IMG_20200620_073433

@Joulinar
Copy link
Collaborator

@MichaIng
Copy link
Owner

Btw great find to disable the Xorg login method in /etc/xrdp/xrdp.ini. Since Stretch this requires a dedicated driver: https://packages.debian.org/buster/xorgxrdp
But I never got mouse and keyboard working with this, neither in VM nor on PC nor on RPi: #3022
Now I found a related issue on xorgxrdp repo: neutrinolabs/xorgxrdp#164
Until this has been reliably sorted, we could prevent future users from running into it by disabling the Xorg connection method, although we clearly state in online docs that Xvnc is required.

Would be actually nice if we could get it running since this would likely reduce overhead and could increase RDP performance. At least it sounds like an overhead to wrap RDP around VNC.
@krishnasen2401 basically this includes a hint that you could use VNC directly, which performs MUCH more fluent than XRDP (over VNC). I use this old tiny portable TightVNC viewer on Windows: https://www.tightvnc.com/download/1.3.10/tightvnc-1.3.10_x86_viewer.zip
If there is no strong reason to use XRDP, give a VNC viewer a try and compare to XRDP once got it working. On my machines the difference is huge 😉!

@krishnasen2401
Copy link
Author

I followed according xrdp I use it in my laptop whereas for other devices like android phone I vnc but for linux system it seems xorg can be port forwarded using ssh will try that I guess

@Joulinar
Copy link
Collaborator

@MichaIng
there are quite some challenges around VNC atm. On some platforms VNC server is crashing once disconnecting the client. This is a Debian bug. I described it as well on the forum post. A patch was released on SID repro this week. Not sure how long it will take into Buster.

Next to this, xrdp session manager is always trying to use a different port than VNC server is running on. Therefore it's needed to pin VNC server port within xrdp.ini. I did not find a working solution totgehet with session manager until now.

@MichaIng
Copy link
Owner

I followed according xrdp I use it in my laptop whereas for other devices like android phone I vnc but for linux system it seems xorg can be port forwarded using ssh will try that I guess

Ah yes X over SSH is another alternative I used in the past, although only for single X applications, not a whole desktop. But one requires am X server on the client machine then.

there are quite some challenges around VNC atm. On some platforms VNC server is crashing once disconnecting the client. This is a Debian bug. I described it as well on the forum post. A patch was released on SID repro this week. Not sure how long it will take into Buster.

Next to this, xrdp session manager is always trying to use a different port than VNC server is running on. Therefore it's needed to pin VNC server port within xrdp.ini. I did not find a working solution totgehet with session manager until now.

Nasty, since both of this was not an issue when I tested it last time. Ongoing issues with XRDP (on Debian) it seems. I was already close to remove it from our software list, only some backported fixes made me stay with it. But if there is now more such need to workaround this or that I'm wondering if it's worth the effort, especially since one can run VNC on the same port (if required to fulfil firewall rules) with much better performance and a large amount clients for all platforms.

However the first one is a VNC issue, so these need to be worked around definitely.

@MichaIng MichaIng added the External bug 🐞 For bugs which are not caused by DietPi. label Jun 20, 2020
@MichaIng MichaIng added this to the v6.31 milestone Jun 20, 2020
@MichaIng MichaIng added Workaround available 🆗 Workaround is available/has been implemented, but a definite solution should be found when possible. and removed Raspberry Pi Raspberry Pi 4 labels Jun 20, 2020
@MichaIng
Copy link
Owner

I added the workaround for the libunwind8 bug on ARMs, it is an issue on ARMv8 as well: 49f960a
Initial report: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=932499
Changelog: bc21cfb

I'll run some tests about XRDP default VNC port. This was never necessary before, "-1" simply worked and if there is some auto-detection or socket-based connection behind it, this is actually preferred.

@MichaIng
Copy link
Owner

MichaIng commented Jun 25, 2020

Tested XRDP on VM and was not able to reproduce any issue without changing the Xvnc port option, it connects fine OOTB 🤔. Probably the libunwind8 bug and server crash was the actual reason why port could not be auto-estimated? Could you guys try it with reverting to port=-1?

@Joulinar
Copy link
Collaborator

Joulinar commented Jun 25, 2020

ok I did a test on my RPi3B+ as well as VM. First I switched to actual DEV branch. I know you still working on 6.31 but would like to test the fix.

RPi3B+
There seems to be an issue with the fix. As far as I can see you put the workaround into the following line FP_BINARY='/usr/bin/tigervncserver'

It looks like this now

FP_BINARY='LD_PRELOAD=/lib/arm-linux-gnueabihf/libgcc_s.so.1 /usr/bin/tigervncserver'

however this will lead to VNC Server not being able to start.

● vncserver.service - Manage VNC Server (DietPi)
   Loaded: loaded (/etc/systemd/system/vncserver.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Fri 2020-06-26 01:04:38 CEST; 1s ago
  Process: 1713 ExecStart=/usr/local/bin/vncserver start (code=exited, status=1/FAILURE)
 Main PID: 1713 (code=exited, status=1/FAILURE)

Jun 26 01:04:38 DietPi3 systemd[1]: Started Manage VNC Server (DietPi).
Jun 26 01:04:38 DietPi3 systemd[1713]: pam_unix(login:session): session opened for user root by (uid=0)
Jun 26 01:04:38 DietPi3 vncserver[1713]: /usr/local/bin/vncserver: line 36: LD_PRELOAD=/lib/arm-linux-gnueabihf/libgcc_s.so.1: No such file or directory
Jun 26 01:04:38 DietPi3 systemd[1]: vncserver.service: Main process exited, code=exited, status=1/FAILURE
Jun 26 01:04:38 DietPi3 systemd[1]: vncserver.service: Failed with result 'exit-code'.

I need to move the workaround down to the line I copied in the forum. I guess it needs to be in front of the executable

LD_PRELOAD=/lib/arm-linux-gnueabihf/libgcc_s.so.1 $BINARY_FP :${DISPLAY:-1} -geometry ${WIDTH:-1280}'x'${HEIGHT:-720} -depth ${DEPTH:-16} || exit 1

This way VNC server is able to start.

Next problem is the server port. On my RPi, session manager is trying to connect on 5911

picture1

DietPi VM

all working fine, VNC Server is running and session manager is going to use correct port 5901

So it makes a difference if you use RPi or VM 🤔

BTW: Will do some test with RealVNC as well to check if the fix is needed there as well.

@MichaIng
Copy link
Owner

MichaIng commented Jun 26, 2020

Fixed LD_PRELOAD: 2039bcf
Variables cannot be assigned via variable expansion 😢.

So it makes a difference if you use RPi or VM 🤔

Very strange, I'll try to replicate on RPi. The annoying thing about it is that default port is 5900 + display number. So we'd need inform user anyway to adjust this together with the VNC display set via dietpi.txt... setting it to 5900 when using shared mode etc...

... ahh and now I see that indeed XRDP tries to connect to display 11: "login successful for display 11"
Is it probably not detecting the existing VNC session and trying to open a new one? RealVNC by default runs a daemon that opens a new virtual VNC session for every client that connects, which basically totally makes sense. Probably XRDP (on RPi for some reason) is trying this but TigerVNC has no such listening daemon, at least I am not aware of one. Probably XRDP on Raspbian/RPi has even be adjusted to work with RealVNC... I'll have a closer look.


EDIT: There is an RPi build, but it is very outdated and would only be installed on Jessie systems: http://archive.raspberrypi.org/debian/pool/main/x/xrdp/

apt policy xrdp/dpkg -l xrdp

@MichaIng
Copy link
Owner

Issue confirmed with wrong VNC port chosen by XRDP on RPi. In my case it attempted to connect to display 10 and accordingly port 5910, probably not 11 because its headless and nothing is using display 0? Not sure how exactly derives its choice...

@Joulinar
Copy link
Collaborator

for me it was 10 if VNC server was not running. Not sure how session manager is doing it. But could it be an option to use the variable from dietpi.txt inside xrdp.ini to specify the port use?

@MichaIng
Copy link
Owner

MichaIng commented Jun 26, 2020

🈴 (12642)(1996301680)[ERROR] Cannot read private key file /etc/xrdp/key.pem: Permission denied

# ls -Al /etc/xrdp/key.pem
lrwxrwxrwx 1 root root 38 Jun 26 12:49 /etc/xrdp/key.pem -> /etc/ssl/private/ssl-cert-snakeoil.key
# ls -Al /etc/ssl/private/ssl-cert-snakeoil.key
-rw-r----- 1 root ssl-cert 1704 Jun 26 12:48 /etc/ssl/private/ssl-cert-snakeoil.key

XRDP runs as "xrdp" hence has no access to certs by default. Not sure why it is linked by default at all, however not required and moving a real cert into place (with correct permissions) does not solve anything.

(12645)(1995587104)[INFO ] Xvnc :10

Its indeed not the port that is chosen wrong, but the display.

But could it be an option to use the variable from dietpi.txt inside xrdp.ini to specify the port use?

Config files do not allow variables. Of course we can derive the port our self based on dietpi.txt entry and hack it inside xrdp.ini but whenever user changes display or switch to shared desktop mode, it will be broken. So I would prefer to fix the wrong display connection attempt in the first place.


/etc/xrdp/sesman.ini

[Sessions]
;; X11DisplayOffset - x11 display number offset
; Type: integer
; Default: 10
X11DisplayOffset=10
  • There we have the display offset, however this is default, changing it to "1" leads to connection to display "2" somehow, setting it to "0" leads to display 0 connection failure...

@MichaIng
Copy link
Owner

When setting the port manually to 5901, xrdp seems to behave fundamentally different, here with forced port from service start until successful client connection:

Jun 26 14:47:16 Building-ARMv7-Buster systemd[1]: Starting xrdp session manager...
Jun 26 14:47:16 Building-ARMv7-Buster xrdp-sesman[12840]: (12840)(1995824672)[DEBUG] libscp initialized
Jun 26 14:47:16 Building-ARMv7-Buster xrdp-sesman[12840]: (12840)(1995824672)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:47:16 Building-ARMv7-Buster xrdp-sesman[12840]: (12840)(1995824672)[DEBUG] Testing if xrdp-sesman can listen on 127.0.0.1 port 3350.
Jun 26 14:47:16 Building-ARMv7-Buster xrdp-sesman[12840]: (12840)(1995824672)[DEBUG] Closed socket 1 (AF_INET 127.0.0.1:3350)
Jun 26 14:47:16 Building-ARMv7-Buster xrdp-sesman[12841]: (12841)(1995824672)[INFO ] starting xrdp-sesman with pid 12841
Jun 26 14:47:16 Building-ARMv7-Buster systemd[1]: Started xrdp session manager.
Jun 26 14:47:16 Building-ARMv7-Buster systemd[1]: Starting xrdp daemon...
Jun 26 14:47:16 Building-ARMv7-Buster xrdp-sesman[12841]: (12841)(1995824672)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:47:16 Building-ARMv7-Buster xrdp-sesman[12841]: (12841)(1995824672)[INFO ] listening to port 3350 on 127.0.0.1
Jun 26 14:47:16 Building-ARMv7-Buster xrdp[12850]: (12850)(1995752816)[DEBUG] Testing if xrdp can listen on 0.0.0.0 port 3389.
Jun 26 14:47:16 Building-ARMv7-Buster xrdp[12850]: (12850)(1995752816)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:47:16 Building-ARMv7-Buster xrdp[12850]: (12850)(1995752816)[DEBUG] Closed socket 7 (AF_INET 0.0.0.0:3389)
Jun 26 14:47:16 Building-ARMv7-Buster systemd[1]: xrdp.service: Can't open PID file /run/xrdp/xrdp.pid (yet?) after start: No such file or directory
Jun 26 14:47:17 Building-ARMv7-Buster systemd[1]: Started xrdp daemon.
Jun 26 14:47:18 Building-ARMv7-Buster xrdp[12851]: (12851)(1995752816)[INFO ] starting xrdp with pid 12851
Jun 26 14:47:18 Building-ARMv7-Buster xrdp[12851]: (12851)(1995752816)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:47:18 Building-ARMv7-Buster xrdp[12851]: (12851)(1995752816)[INFO ] listening to port 3389 on 0.0.0.0
-------------- Client login happens here ----------------------
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12851]: (12851)(1995752816)[INFO ] Socket 12: AF_INET connection received from 192.168.1.10 port 51076
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12851]: (12851)(1995752816)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12854]: (12854)(1995752816)[DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12854]: (12854)(1995752816)[INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12854]: (12854)(1995752816)[INFO ] Using default X.509 key file: /etc/xrdp/key.pem
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12854]: (12854)(1995752816)[DEBUG] TLSv1.3 enabled
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12854]: (12854)(1995752816)[DEBUG] TLSv1.2 enabled
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12854]: (12854)(1995752816)[DEBUG] Security layer: requested 11, selected 1
Jun 26 14:47:58 Building-ARMv7-Buster xrdp[12854]: (12854)(1995752816)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12851]: (12851)(1995752816)[INFO ] Socket 12: AF_INET connection received from 192.168.1.10 port 51077
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12851]: (12851)(1995752816)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] Using default X.509 key file: /etc/xrdp/key.pem
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] TLSv1.3 enabled
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] TLSv1.2 enabled
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] Security layer: requested 11, selected 1
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] connected client computer name: MICHA
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] adding channel item name rdpdr chan_id 1004 flags 0x80800000
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] adding channel item name rdpsnd chan_id 1005 flags 0xc0000000
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] adding channel item name cliprdr chan_id 1006 flags 0xc0a00000
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] adding channel item name drdynvc chan_id 1007 flags 0xc0800000
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] TLS connection established from 192.168.1.10 port 51077: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_00003237_wm_login_mode_event_00000001
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] Loading keymap file /etc/xrdp/km-00000407.ini
Jun 26 14:47:59 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[WARN ] local keymap file for 0x00000407 found and doesn't match built in keymap, using local keymap file
Jun 26 14:48:04 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC started connecting
Jun 26 14:48:04 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC connecting to 127.0.0.1 5901
Jun 26 14:48:04 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC tcp connected
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC security level is 2 (1 = none, 2 = standard)
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC password ok
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC sending share flag
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC receiving server init
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC receiving pixel format
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC receiving name length
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC receiving name
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC sending pixel format
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC sending encodings
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC sending framebuffer update request
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC sending cursor
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: VNC connection complete, connected ok
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_wm_log_msg: connected ok
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] return value from xrdp_mm_connect 0
Jun 26 14:48:05 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] CLIPRDR_FORMAT_ANNOUNCE - status 0 length 144
Jun 26 14:48:10 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:48:10 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] xrdp_mm_module_cleanup
Jun 26 14:48:10 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] VNC mod_exit
Jun 26 14:48:10 Building-ARMv7-Buster xrdp[12855]: (12855)(1995752816)[DEBUG] Closed socket 18 (AF_INET 127.0.0.1:35000)
  • This is btw inside a systemd-nspawn container on RPi but Debian system, as I wanted to rule out any library/package influence.
  • No xrdp-sesman invocation anymore after service start, hence all this display number settings etc is obsolete, no Xvnc :<display_number> call is done.

With port set to default -1:

Jun 26 14:54:45 Building-ARMv7-Buster systemd[1]: Starting xrdp session manager...
Jun 26 14:54:45 Building-ARMv7-Buster xrdp-sesman[12868]: (12868)(1995886112)[DEBUG] libscp initialized
Jun 26 14:54:45 Building-ARMv7-Buster xrdp-sesman[12868]: (12868)(1995886112)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:54:45 Building-ARMv7-Buster xrdp-sesman[12868]: (12868)(1995886112)[DEBUG] Testing if xrdp-sesman can listen on 127.0.0.1 port 3350.
Jun 26 14:54:45 Building-ARMv7-Buster xrdp-sesman[12868]: (12868)(1995886112)[DEBUG] Closed socket 1 (AF_INET 127.0.0.1:3350)
Jun 26 14:54:45 Building-ARMv7-Buster systemd[1]: Started xrdp session manager.
Jun 26 14:54:45 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] starting xrdp-sesman with pid 12869
Jun 26 14:54:45 Building-ARMv7-Buster systemd[1]: Starting xrdp daemon...
Jun 26 14:54:45 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:54:45 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] listening to port 3350 on 127.0.0.1
Jun 26 14:54:45 Building-ARMv7-Buster xrdp[12878]: (12878)(1996236144)[DEBUG] Testing if xrdp can listen on 0.0.0.0 port 3389.
Jun 26 14:54:45 Building-ARMv7-Buster xrdp[12878]: (12878)(1996236144)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:54:45 Building-ARMv7-Buster xrdp[12878]: (12878)(1996236144)[DEBUG] Closed socket 7 (AF_INET 0.0.0.0:3389)
Jun 26 14:54:45 Building-ARMv7-Buster systemd[1]: xrdp.service: Can't open PID file /run/xrdp/xrdp.pid (yet?) after start: No such file or directory
Jun 26 14:54:46 Building-ARMv7-Buster systemd[1]: Started xrdp daemon.
Jun 26 14:54:47 Building-ARMv7-Buster xrdp[12879]: (12879)(1996236144)[INFO ] starting xrdp with pid 12879
Jun 26 14:54:47 Building-ARMv7-Buster xrdp[12879]: (12879)(1996236144)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:54:47 Building-ARMv7-Buster xrdp[12879]: (12879)(1996236144)[INFO ] listening to port 3389 on 0.0.0.0
-------------- Client login happens here ----------------------
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12879]: (12879)(1996236144)[INFO ] Socket 12: AF_INET connection received from 192.168.1.10 port 51114
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12879]: (12879)(1996236144)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12882]: (12882)(1996236144)[DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12882]: (12882)(1996236144)[INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12882]: (12882)(1996236144)[INFO ] Using default X.509 key file: /etc/xrdp/key.pem
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12882]: (12882)(1996236144)[DEBUG] TLSv1.3 enabled
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12882]: (12882)(1996236144)[DEBUG] TLSv1.2 enabled
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12882]: (12882)(1996236144)[DEBUG] Security layer: requested 11, selected 1
Jun 26 14:55:34 Building-ARMv7-Buster xrdp[12882]: (12882)(1996236144)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12879]: (12879)(1996236144)[INFO ] Socket 12: AF_INET connection received from 192.168.1.10 port 51115
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12879]: (12879)(1996236144)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] Closed socket 11 (AF_INET 0.0.0.0:3389)
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] Using default X.509 key file: /etc/xrdp/key.pem
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] TLSv1.3 enabled
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] TLSv1.2 enabled
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] Security layer: requested 11, selected 1
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] connected client computer name: MICHA
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] adding channel item name rdpdr chan_id 1004 flags 0x80800000
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] adding channel item name rdpsnd chan_id 1005 flags 0xc0000000
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] adding channel item name cliprdr chan_id 1006 flags 0xc0a00000
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] adding channel item name drdynvc chan_id 1007 flags 0xc0800000
Jun 26 14:55:35 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] TLS connection established from 192.168.1.10 port 51115: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384
Jun 26 14:55:36 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_00003253_wm_login_mode_event_00000001
Jun 26 14:55:36 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] Loading keymap file /etc/xrdp/km-00000407.ini
Jun 26 14:55:36 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[WARN ] local keymap file for 0x00000407 found and doesn't match built in keymap, using local keymap file
Jun 26 14:55:40 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_wm_log_msg: connecting to sesman ip 127.0.0.1 port 3350
Jun 26 14:55:40 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] IPv6 not supported, falling back to IPv4
-------------- Here xrdp-sesman jumps in ----------------------
Jun 26 14:55:40 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] A connection received from 127.0.0.1 port 42720
Jun 26 14:55:41 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] xrdp_wm_log_msg: sesman connect ok
Jun 26 14:55:41 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_wm_log_msg: sending login info to session manager, please wait...
Jun 26 14:55:41 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] return value from xrdp_mm_connect 0
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] ++ created session (access granted): username root, ip 192.168.1.10:51115 - socket: 12
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] starting Xvnc session...
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[DEBUG] Closed socket 9 (AF_INET 0.0.0.0:5910)
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[DEBUG] Closed socket 9 (AF_INET 0.0.0.0:6010)
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[DEBUG] Closed socket 9 (AF_INET 0.0.0.0:6210)
Jun 26 14:55:41 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] xrdp_wm_log_msg: login successful for display 10
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[INFO ] calling auth_start_session from pid 12884
Jun 26 14:55:41 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_wm_log_msg: VNC started connecting
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12884]: pam_unix(xrdp-sesman:session): session opened for user root by (uid=0)
Jun 26 14:55:41 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_wm_log_msg: VNC connecting to 127.0.0.1 5910
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[DEBUG] Closed socket 8 (AF_INET 127.0.0.1:3350)
Jun 26 14:55:41 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[INFO ] IPv6 not supported, falling back to IPv4
Jun 26 14:55:41 Building-ARMv7-Buster systemd-logind[11778]: New session c6 of user root.
Jun 26 14:55:41 Building-ARMv7-Buster systemd[1]: Started Session c6 of user root.
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[DEBUG] Closed socket 7 (AF_INET 127.0.0.1:3350)
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[DEBUG] Closed socket 8 (AF_INET 127.0.0.1:3350)
Jun 26 14:55:41 Building-ARMv7-Buster xrdp-sesman[12886]: (12886)(1995886112)[INFO ] Xvnc :10 -auth .Xauthority -geometry 1920x1200 -depth 32 -rfbauth /root/.vnc/sesman_passwd-root@Building-ARMv7-Buster:10 -bs -nolisten tcp -localhost -dpi 96
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] VNC error 1 after security negotiation
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] VNC error before sending share flag
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] VNC error before receiving server init
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] VNC error before receiving pixel format
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] VNC error before receiving name length
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] VNC error before receiving name
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_wm_log_msg: VNC error - problem connecting
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] Closed socket 19 (AF_INET 127.0.0.1:37044)
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_wm_log_msg: some problem
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_mm_module_cleanup
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] VNC mod_exit
Jun 26 14:55:44 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] Closed socket 18 (AF_INET 127.0.0.1:42720)
Jun 26 14:55:50 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] Closed socket 12 (AF_INET 192.168.1.2:3389)
Jun 26 14:55:50 Building-ARMv7-Buster xrdp[12883]: (12883)(1996236144)[DEBUG] xrdp_mm_module_cleanup
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[ERROR] X server for display 10 startup timeout
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[CORE ] waiting for window manager (pid 12885) to exit
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12885]: (12885)(1995886112)[ERROR] X server for display 10 startup timeout
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12885]: (12885)(1995886112)[ERROR] another Xserver might already be active on display 10 - see log
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12885]: (12885)(1995886112)[DEBUG] aborting connection...
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[CORE ] window manager (pid 12885) did exit, cleaning up session
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[INFO ] calling auth_stop_session and auth_end from pid 12884
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: pam_unix(xrdp-sesman:session): session closed for user root
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[DEBUG] cleanup_sockets:
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[DEBUG] cleanup_sockets: deleting /var/run/xrdp/sockdir/xrdp_chansrv_socket_10
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12884]: (12884)(1995886112)[DEBUG] cleanup_sockets: deleting /var/run/xrdp/sockdir/xrdpapi_10
Jun 26 14:55:51 Building-ARMv7-Buster xrdp-sesman[12869]: (12869)(1995886112)[INFO ] ++ terminated session:  username root, display :10.0, session_pid 12884, ip 192.168.1.10:51115 - socket: 12
Jun 26 14:55:51 Building-ARMv7-Buster systemd-logind[11778]: Session c6 logged out. Waiting for processes to exit.
Jun 26 14:55:51 Building-ARMv7-Buster systemd[1]: session-c6.scope: Succeeded.
Jun 26 14:55:51 Building-ARMv7-Buster systemd-logind[11778]: Removed session c6.
  • So with port=-1 xrdp-sesman seems to start a new VNC session via Xvnc call on a display number with +10 offset from the existing one(s) on related port with own geometry (overriding dietpi.txt settings as well) and tries to connect to it, which obviously fails.
  • With port=5901, xrdp-sesman is not invoked but xrdp connects to the already running VNC session which is what we actually want.

Now lets see how VM/x86_64 behaves...

@Joulinar
Copy link
Collaborator

Joulinar commented Jun 26, 2020

btw I checked the new fix implementation and it's working for xrdp + tiger vnc. Means vnc server is not crashing anymore on logoff.

I guess it would not be needed to start a new VNC session as we already have one running 🤔

EDIT:
One question. Does the VNC fix applies for TigerVNC only. Or does it get active on RealVNC as well? Because my RealVNC server crashed as soon as I hit the logout button inside the VNC session.

@MichaIng
Copy link
Owner

I guess it would not be needed to start a new VNC session as we already have one running 🤔

Exactly. A running session started with set screen dimensions on set display index (or local shared session) that the VNC in only "attaching" to and detaching from is what the intention is. Actually I like the way how RealVNC aims it, to have no X session running but start a fresh one for every client connection. We break this somehow be manually starting one with our service for RealVNC as well. But this is another topic to have a closer look by times...

One question. Does the VNC fix applies for TigerVNC only. Or does it get active on RealVNC as well? Because my RealVNC server crashed as soon as I hit the logout button inside the VNC session.

Ah, I thought it is a TigerVNC-only issue, not for RealVNC the fix is not applied. Does it fix things for RealVNC just the same (will test as well)? To apply it for both would be even easier, then we can hardcode it into the service script without variable checks and such.

@Joulinar
Copy link
Collaborator

well, not sure if the same fix could be applied for RealVNC as well. During my test I noticed VNC server crashing as soon as I hit the logoff button

before

root@DietPi3:~# ps -ef|grep vnc
root       377     1  0 00:14 ?        00:00:00 /usr/bin/vncserver-x11-serviced -fg
root       380     1  0 00:14 ?        00:00:00 /usr/bin/vncserver-virtuald -fg
root       395   377  0 00:14 ?        00:00:00 /usr/bin/vncserver-x11-core -service
root      2345     1  0 01:22 ?        00:00:00 /usr/bin/vncserver-virtual :1 -geometry 1280x720 -depth 16
root      2347  2345  5 01:22 ?        00:00:00 /usr/bin/Xvnc-core :1 -auth /root/.Xauthority -pn -geometry 1280x720 -depth 16
root      2365  2345  0 01:22 ?        00:00:00 /bin/sh /etc/vnc/xstartup
root      2433     1  8 01:22 ?        00:00:00 /usr/bin/vncserverui virtual 19
root      2452  2433  2 01:22 ?        00:00:00 /usr/bin/vncserverui -statusicon 5
root      2488  1795  0 01:22 pts/1    00:00:00 grep vnc

after

root@DietPi3:~# ps -ef|grep vnc
root       377     1  0 00:14 ?        00:00:00 /usr/bin/vncserver-x11-serviced -fg
root       380     1  0 00:14 ?        00:00:00 /usr/bin/vncserver-virtuald -fg
root       395   377  0 00:14 ?        00:00:00 /usr/bin/vncserver-x11-core -service
root      2519  1795  0 01:23 pts/1    00:00:00 grep vnc
root@DietPi3:~#

@MichaIng
Copy link
Owner

MichaIng commented Jun 27, 2020

RealVNC

Is it really a "crash" or is it probably stopped on purpose? As said vncserver-virtuald is actually aimed to listed and start a new vncserver-virtual on every client connection. Does connecting via VNC client (instead or RDP) works that way?

XRDP on x86_64

Jun 27 01:52:15 VM-Buster systemd[1]: Starting xrdp session manager...
Jun 27 01:52:15 VM-Buster xrdp-sesman[6871]: (6871)(140154949354944)[DEBUG] libscp initialized
Jun 27 01:52:15 VM-Buster xrdp-sesman[6871]: (6871)(140154949354944)[DEBUG] Testing if xrdp-sesman can listen on 127.0.0.1 port 3350.
Jun 27 01:52:15 VM-Buster xrdp-sesman[6871]: (6871)(140154949354944)[DEBUG] Closed socket 1 (AF_INET6 ::ffff:127.0.0.1 port 3350)
Jun 27 01:52:15 VM-Buster systemd[1]: Started xrdp session manager.
Jun 27 01:52:15 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[INFO ] starting xrdp-sesman with pid 6872
Jun 27 01:52:15 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[INFO ] listening to port 3350 on 127.0.0.1
Jun 27 01:52:15 VM-Buster systemd[1]: Starting xrdp daemon...
Jun 27 01:52:15 VM-Buster xrdp[6881]: (6881)(139906538833728)[DEBUG] Testing if xrdp can listen on 0.0.0.0 port 3389.
Jun 27 01:52:15 VM-Buster xrdp[6881]: (6881)(139906538833728)[DEBUG] Closed socket 7 (AF_INET6 :: port 3389)
Jun 27 01:52:15 VM-Buster systemd[1]: xrdp.service: Can't open PID file /run/xrdp/xrdp.pid (yet?) after start: No such file or directory
Jun 27 01:52:16 VM-Buster systemd[1]: Started xrdp daemon.
Jun 27 01:52:17 VM-Buster xrdp[6882]: (6882)(139906538833728)[INFO ] starting xrdp with pid 6882
Jun 27 01:52:17 VM-Buster xrdp[6882]: (6882)(139906538833728)[INFO ] listening to port 3389 on 0.0.0.0
--------- Here client login happens -------------
Jun 27 01:52:56 VM-Buster xrdp[6882]: (6882)(139906538833728)[INFO ] Socket 12: AF_INET6 connection received from ::ffff:192.168.1.10 port 57548
Jun 27 01:52:56 VM-Buster xrdp[6882]: (6882)(139906538833728)[DEBUG] Closed socket 12 (AF_INET6 ::ffff:192.168.1.22 port 3389)
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[DEBUG] Closed socket 11 (AF_INET6 :: port 3389)
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[INFO ] Using default X.509 key file: /etc/xrdp/key.pem
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[ERROR] Cannot read private key file /etc/xrdp/key.pem: Permission denied
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[DEBUG] TLSv1.3 enabled
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[DEBUG] TLSv1.2 enabled
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[DEBUG] Security layer: requested 11, selected 0
Jun 27 01:52:56 VM-Buster xrdp[6887]: (6887)(139906538833728)[DEBUG] Closed socket 12 (AF_INET6 ::ffff:192.168.1.22 port 3389)
Jun 27 01:52:58 VM-Buster xrdp[6882]: (6882)(139906538833728)[INFO ] Socket 12: AF_INET6 connection received from ::ffff:192.168.1.10 port 57549
Jun 27 01:52:58 VM-Buster xrdp[6882]: (6882)(139906538833728)[DEBUG] Closed socket 12 (AF_INET6 ::ffff:192.168.1.22 port 3389)
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] Closed socket 11 (AF_INET6 :: port 3389)
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] Using default X.509 certificate: /etc/xrdp/cert.pem
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] Using default X.509 key file: /etc/xrdp/key.pem
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[ERROR] Cannot read private key file /etc/xrdp/key.pem: Permission denied
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] TLSv1.3 enabled
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] TLSv1.2 enabled
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] Security layer: requested 0, selected 0
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] connected client computer name: MICHA
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] adding channel item name rdpdr chan_id 1004 flags 0x80800000
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] adding channel item name rdpsnd chan_id 1005 flags 0xc0000000
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] adding channel item name cliprdr chan_id 1006 flags 0xc0a00000
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] adding channel item name drdynvc chan_id 1007 flags 0xc0800000
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] Non-TLS connection established from ::ffff:192.168.1.10 port 57549: encrypted with standard RDP security
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_00001ae8_wm_login_mode_event_00000001
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] Loading keymap file /etc/xrdp/km-00000407.ini
Jun 27 01:52:58 VM-Buster xrdp[6888]: (6888)(139906538833728)[WARN ] local keymap file for 0x00000407 found and doesn't match built in keymap, using local keymap file
Jun 27 01:53:03 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: connecting to sesman ip 127.0.0.1 port 3350
Jun 27 01:53:03 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[INFO ] A connection received from ::ffff:127.0.0.1 port 53684
Jun 27 01:53:03 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] xrdp_wm_log_msg: sesman connect ok
Jun 27 01:53:03 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: sending login info to session manager, please wait...
Jun 27 01:53:03 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] return value from xrdp_mm_connect 0
Jun 27 01:53:03 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[INFO ] ++ created session (access granted): username root, ip ::ffff:192.168.1.10:57549 - socket: 12
Jun 27 01:53:03 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[INFO ] starting Xvnc session...
Jun 27 01:53:03 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[DEBUG] Closed socket 9 (AF_INET6 :: port 5910)
Jun 27 01:53:03 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[DEBUG] Closed socket 9 (AF_INET6 :: port 6010)
Jun 27 01:53:03 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[DEBUG] Closed socket 9 (AF_INET6 :: port 6210)
Jun 27 01:53:03 VM-Buster xrdp-sesman[6872]: (6872)(140154949354944)[DEBUG] Closed socket 8 (AF_INET6 ::ffff:127.0.0.1 port 3350)
Jun 27 01:53:03 VM-Buster xrdp[6888]: (6888)(139906538833728)[INFO ] xrdp_wm_log_msg: login successful for display 10
Jun 27 01:53:03 VM-Buster xrdp-sesman[6889]: (6889)(140154949354944)[INFO ] calling auth_start_session from pid 6889
Jun 27 01:53:03 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC started connecting
Jun 27 01:53:03 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC connecting to 127.0.0.1 5910
Jun 27 01:53:03 VM-Buster xrdp-sesman[6889]: pam_unix(xrdp-sesman:session): session opened for user root by (uid=0)
Jun 27 01:53:03 VM-Buster systemd-logind[6295]: New session c1 of user root.
Jun 27 01:53:03 VM-Buster systemd[1]: Started Session c1 of user root.
Jun 27 01:53:03 VM-Buster xrdp-sesman[6889]: (6889)(140154949354944)[DEBUG] Closed socket 7 (AF_INET6 ::ffff:127.0.0.1 port 3350)
Jun 27 01:53:03 VM-Buster xrdp-sesman[6889]: (6889)(140154949354944)[DEBUG] Closed socket 8 (AF_INET6 ::ffff:127.0.0.1 port 3350)
Jun 27 01:53:03 VM-Buster xrdp-sesman[6891]: (6891)(140154949354944)[INFO ] Xvnc :10 -auth .Xauthority -geometry 1920x1200 -depth 32 -rfbauth /root/.vnc/sesman_passwd-root@VM-Buster:10 -bs -nolisten tcp -localhost -dpi 96
Jun 27 01:53:04 VM-Buster xrdp-sesman[6889]: (6889)(140154949354944)[CORE ] waiting for window manager (pid 6890) to exit
Jun 27 01:53:04 VM-Buster dbus-daemon[6924]: [session uid=0 pid=6922] Activating service name='org.freedesktop.systemd1' requested by ':1.0' (uid=0 pid=6930 comm="dbus-update-activation-environment --verbose --sys")
Jun 27 01:53:04 VM-Buster dbus-daemon[6924]: [session uid=0 pid=6922] Activated service 'org.freedesktop.systemd1' failed: Process org.freedesktop.systemd1 exited with status 1
Jun 27 01:53:04 VM-Buster polkitd(authority=local)[6527]: Registered Authentication Agent for unix-session:c1 (system bus name :1.17 [lxpolkit], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Jun 27 01:53:04 VM-Buster dbus-daemon[6924]: [session uid=0 pid=6922] Activating service name='ca.desrt.dconf' requested by ':1.3' (uid=0 pid=6956 comm="light-locker ")
Jun 27 01:53:04 VM-Buster dbus-daemon[6924]: [session uid=0 pid=6922] Successfully activated service 'ca.desrt.dconf'
Jun 27 01:53:04 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC tcp connected
Jun 27 01:53:04 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC security level is 2 (1 = none, 2 = standard)
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC password ok
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC sending share flag
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC receiving server init
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC receiving pixel format
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC receiving name length
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC receiving name
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC sending pixel format
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC sending encodings
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC sending framebuffer update request
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC sending cursor
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: VNC connection complete, connected ok
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_wm_log_msg: connected ok
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_mm_connect_chansrv: chansrv connect successful
Jun 27 01:53:05 VM-Buster kernel: fuse init (API version 7.27)
Jun 27 01:53:05 VM-Buster systemd[1]: Mounting FUSE Control File System...
Jun 27 01:53:05 VM-Buster systemd[1]: Mounted FUSE Control File System.
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] Closed socket 16 (AF_INET6 ::ffff:127.0.0.1 port 53684)
Jun 27 01:53:05 VM-Buster kernel: traps: light-locker[6956] trap int3 ip:7f6bf9dd1c75 sp:7ffda7ed60c0 error:0 in libglib-2.0.so.0.5800.3[7f6bf9d99000+7e000]
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] VNC got clip data
Jun 27 01:53:05 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] VNC got clip data
Jun 27 01:53:11 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] Closed socket 12 (AF_INET6 ::ffff:192.168.1.22 port 3389)
Jun 27 01:53:11 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] xrdp_mm_module_cleanup
Jun 27 01:53:11 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] VNC mod_exit
Jun 27 01:53:11 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] Closed socket 17 (AF_INET6 ::ffff:127.0.0.1 port 40932)
Jun 27 01:53:11 VM-Buster xrdp[6888]: (6888)(139906538833728)[DEBUG] Closed socket 18 (AF_UNIX)
Jun 27 01:53:11 VM-Buster systemd[6451]: root-thinclient_drives.mount: Succeeded.
Jun 27 01:53:11 VM-Buster systemd[1]: root-thinclient_drives.mount: Succeeded.
  • VNC connecting to 127.0.0.1 5910 ! Same port as on ARM with port=-1!
  • Xvnc :10 -auth .Xauthority -geometry 1920x1200 -depth 32 ! New VNC session is started with different default geometry, not matching dietpi.txt entries. However while this fails on ARM, this succeeds on x86_64.
  • The X session stays active after logout and will be resumed on next RDP login, as long as one does not hit "logout", which all works reasonable.
  • This means and just verified that no running VNC session is required. So if we start one, we end up with two concurrent X sessions.

The two concurrent X sessions might be even the issue here, at least worth to try systemctl stop vncserver.


So basically we need to decide how we want it:

  • Decouple VNC from XRDP and aim to have XRDP start its own VNC/X sessions on demand?
  • Have XRDP connecting to the same VNC session that we start with our vncserver.service?

Actually the second solution sounds more consequent, so XRDP is just another client connector to the same sessions, making it more lightweight if there is anyway an X session running in the background all the time. We could remove the username input (obsolete, unused, like on VNC login, always root) and create/name our own login method (still Xvnc of course) on the top of the list. Downside is, similar to our VNC implementation, that one always attaches to a root user desktop session, no other user login possible. For this one would need to switch to a different login method and at best disable our vncserver service to avoid doubled session.

The way TigerVNC is invoked, it blocks logouts btw, to avoid the X/VNC session from closing. Otherwise one would need to restart it manually. On RealVNC this seems to be not the case which @Joulinar might be the issue you face? Do you actually logout or just close the VNC/RDP client? Probably RealVNC has some auto-logout/session-close feature that could be disabled to align it with TigerVNC.


Actually I like ondemand session spawning like XRDP and RealVNC by default do it. Will check if there is any such possibility with TigerVNC and test a bid. However this is likely something for next release as I want to finish v6.31 before Juli.

@MichaIng
Copy link
Owner

Loooooooool, same error with XRDP when starting Xvnc then with VNC directly... Same solution with preloading to override libunwind...

2020-06-27 15:05:36 root@Building-ARMv7-Buster:~# Xvnc :1

Xvnc TigerVNC 1.9.0 - built Jan 23 2020 18:03:00
Copyright (C) 1999-2018 TigerVNC Team and many others (see README.rst)
See http://www.tigervnc.org for information on TigerVNC.
Underlying X server release 12004000, The X.Org Foundation


Sat Jun 27 15:05:42 2020
 vncext:      VNC extension running!
terminate called after throwing an instance of 'network::SocketException'
terminate called recursively
(EE)
(EE) Backtrace:
(EE)
(EE)
Fatal server error:
(EE) Caught signal 6 (Aborted). Server aborting
(EE)
Aborted
2020-06-27 15:05:42 root@Building-ARMv7-Buster:~# LD_PRELOAD=/lib/arm-linux-gnueabihf/libgcc_s.so.1 Xvnc :1

Xvnc TigerVNC 1.9.0 - built Jan 23 2020 18:03:00
Copyright (C) 1999-2018 TigerVNC Team and many others (see README.rst)
See http://www.tigervnc.org for information on TigerVNC.
Underlying X server release 12004000, The X.Org Foundation


Sat Jun 27 15:05:45 2020
 vncext:      VNC extension running!
 vncext:      Listening for VNC connections on all interface(s), port 5901
 vncext:      created VNC server for screen 0
^C
Sat Jun 27 15:05:52 2020
 ComparingUpdateTracker: 0 pixels in / 0 pixels out
 ComparingUpdateTracker: (1:nan ratio)

@MichaIng
Copy link
Owner

Actually instead of hacking the LD_PRELOAD into all services, what we need is applying it for the Xvnc (Xtigervnc) binary directly. I cannot find a way to achieve this currently...

...
found a solution:

apt install patchelf
patchelf --remove-needed libgcc_s.so.1 /usr/bin/Xtigervnc
patchelf --add-needed libgcc_s.so.1 /usr/bin/Xtigervnc

This has the same effect as having the libgcc_s.so.1 preloaded with every binary call, as removing and re-adding this library will place it to the top of the list.

This program also allows to remove libunwind from the list, but this breaks execution as there are other functions of it called which are not provided by libgcc_s or others. So without recompiling, reordering the loaded libraries is the only change. Will patch this inside.

@MichaIng
Copy link
Owner

I just verified that XRDP does not support RealVNC:

Checked and verified that RealVNC auto-spawn of X sessions is an enterprise feature, not available by default and likely only working in combination with RealVNC client:

So basically there is no point for us to enable this service. When users do/have an enterprise subscription they'll know what to do. The vncserver-x11-serviced can be started/stopped by our service/script instead of having systemd doing that on boot. So control can be done via single service/script instead of having to take care multiple ones.

@MichaIng
Copy link
Owner

Final fix and better RealVNC integration: f96ad09

Whether to have XRDP by default connecting to a running virtual VNC session or spawning an own one is a matter of future discussion. For now at least things are running again as before (in case of RealVNC slightly better).

@Joulinar
Copy link
Collaborator

Well done Micha. Quite a lot of time spent on such a small bug.

@MichaIng
Copy link
Owner

MichaIng commented Jun 27, 2020

Part of the time I took the chance to have closer look on some other things I was never really happy with on our VNC integration. Still much to do and decisions to make until I am 100% satisfied on it 😅, but many things about how both VNC servers and XRDP work, what's possible and what's not, became clear today. Best basis for further tuning at a later time 😃.

Updated online docs: https://dietpi.com/phpbb/viewtopic.php?p=4149#p4149

MichaIng added a commit that referenced this issue Jun 28, 2020
+ CHANGELOG | XRDP: The TigerVNC bug affected as well XRDP connections which have been resolved in the same turn: #3615 (comment)
@MichaIng MichaIng mentioned this issue Jun 28, 2020
@MichaIng
Copy link
Owner

Patch has been merged into Debian Buster branch: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=932499

@MichaIng MichaIng added Solution available 🥂 Definite solution has been done and removed Workaround available 🆗 Workaround is available/has been implemented, but a definite solution should be found when possible. labels Sep 11, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
ARMbaby Buster External bug 🐞 For bugs which are not caused by DietPi. Solution available 🥂 Definite solution has been done
Projects
None yet
Development

No branches or pull requests

3 participants