Dotaz: xrdp - OpenSuse 13.2

[Pavel Čejka]

Přílohy:

• 2015-11-04_xrdp_01_login.png (10172 bytů)
• 2015-11-04_xrdp_02_chybova_hlaska.png (8217 bytů)

Mám instalované OpenSuse 13.2 ve virtuálu (qemu, libvirt). K němu přistupuji na nějaké lokální IP adrese routované strojem, na kterém virtuál běží atd... potud ok.

K virtuálu se připojím SSH, X (mám povolené naslouchání ... takže funguje X :1 -query 192.168.10.101), VNC skrz xinetd, nejenom tím VNC, co poskytuje virtualizér.

Rád bych se připojoval RDP protokolem, protože XRDP pro každé připojení vytvoří samostatnou persistentní session.

Jednou - při prvním pokusu - se mi to povedlo, pak jsem OpenSuse aktualizoval (normální update Yastem), párkrát rebootoval a od té doby to nefunguje. Vrtám se v tom už tak dlouho, že není šance poznat, jaký byl stav v okamžiku funkčnosti.

Firewall je aktuálně zcela vypnutý, nic není blokováno, vše je schované v lokální síti.

Verze balíčků

xrdp 0.9.0git.1420692256
xorg-x11-Xvnc 1.4.1
x11vnc 0.9.13

Dost mne u toho irituje journalctl ... ale nějak jsem se prokousal k tomu, že xrdp s vnc alespoň něco posílají do logu, takže to aktuálně při pokusu o přihlášení (které skončí hláškou viz screenshot) hlásí toto (pomocí journalctl -f):

lis 04 18:58:55 virtpc01 XRDP[1449]: (1449)(-1222187264)[INFO ] An established connection closed to endpoint: 192.168.0.5:34134 - socket: 8
lis 04 18:58:55 virtpc01 XRDP[1449]: (1449)(-1222187264)[DEBUG] xrdp_mm_module_cleanup
lis 04 18:58:55 virtpc01 XRDP[1449]: (1449)(-1222187264)[ERROR] Listening socket is in wrong state we terminate listener
lis 04 18:58:57 virtpc01 XRDP[1228]: (1228)(-1222187264)[INFO ] A connection received from: 192.168.0.5 port 34178
lis 04 18:58:57 virtpc01 XRDP[1228]: (1228)(-1222187264)[INFO ] An established connection closed to endpoint: 192.168.0.5:34178 - socket: 8
lis 04 18:58:57 virtpc01 XRDP[2986]: (2986)(-1222187264)[INFO ] An established connection closed to endpoint: NULL:NULL - socket: 7
lis 04 18:58:57 virtpc01 XRDP[2986]: (2986)(-1222187264)[CORE ] WARNING: Invalid x.509 certificate path defined, default path will be used: /etc/xrdp/cert.pem
lis 04 18:58:57 virtpc01 XRDP[2986]: (2986)(-1222187264)[WARN ] Invalid X.509 certificate path defined, default path will be used: /etc/xrdp/key.pem
lis 04 18:58:57 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] xrdp_00000baa_wm_login_mode_event_00000001
lis 04 18:58:57 virtpc01 XRDP[2986]: (2986)(-1222187264)[WARN ] local keymap file for 0x10405 found and dosen't match built in keymap, using local keymap file
lis 04 19:00:01 virtpc01 cron[2987]: pam_unix(crond:session): session opened for user root by (uid=0)
lis 04 19:00:01 virtpc01 CRON[2987]: pam_unix(crond:session): session closed for user root
lis 04 19:01:05 virtpc01 XRDP-sesman[1258]: (1258)(-1221637824)[INFO ] A connection received from: 127.0.0.1 port 44130
lis 04 19:01:05 virtpc01 XRDP-sesman[1258]: (1258)(-1221637824)[INFO ] scp thread on sck 8 started successfully
lis 04 19:01:05 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] returnvalue from xrdp_mm_connect 0
lis 04 19:01:05 virtpc01 XRDP-sesman[1258]: (1258)(-1222116544)[INFO ] ++ reconnected session: username pavelcejka, display :10.0, session_pid 1451, ip 192.168.0.5:34178 - socket: 8
lis 04 19:01:05 virtpc01 XRDP-sesman[1258]: (1258)(-1222116544)[INFO ] An established connection closed to endpoint: 127.0.0.1:44130 - socket: 8
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] VNC Error after security negotiation
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] VNC error before sending share flag
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] VNC error before receiving server init
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] VNC error before receiving pixel format
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] VNC error before receiving name length
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] VNC error before receiving name
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[INFO ] An established connection closed to endpoint: NULL:NULL - socket: 12
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] xrdp_mm_module_cleanup
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[DEBUG] VNC mod_exit
lis 04 19:01:08 virtpc01 XRDP[2986]: (2986)(-1222187264)[INFO ] An established connection closed to endpoint: 127.0.0.1:3350 - socket: 11

Certifikát tam je, hláška je zřejmě jen varování, že cesta k němu není uvedená explicitně v xrdp.ini, což není (a ani při prvním funkčním pokusu nebyla).

Domnívám se, že skutečná chyba nastává před "VNC Error after security negotiation", ale problém je, že se mi k tomu nedaří najít vůbec nic. Resp. různými pokusy najdu desítku diskuzí, znichž část je trochu o něčem jiném a zbylé nekončí řešením, příp. řešení není použitelné, některé spoustu let staré.

Zajímavé taky je, že po nepovedeném pokusu o přihlášení skončí vnc jako zombie, dokud neprovedu restart xrdp.

 1228 ?        S      0:00 /usr/sbin/xrdp
 2986 ?        S      0:00  \_ /usr/sbin/xrdp
 1258 ?        S      0:00 /usr/sbin/xrdp-sesman
 1451 ?        S      0:00  \_ /usr/sbin/xrdp-sessvc 1453 1452
 1452 ?        S      0:00      \_ /usr/sbin/xrdp-sesman
 1455 ?        S      0:00      |   \_ /usr/bin/ck-launch-session /usr/bin/dbus-launch --sh-syntax --exit-with-session /usr/bin/ssh-agent /usr/bin/gpg-agent --sh --daemon --keep-display --write-env-file /home/pavelcejka/.gnupg/agent.info
 1593 ?        Sl     0:00      |       \_ /usr/bin/lxsession -s LXDE -e LXDE
 1598 ?        Ss     0:00      |           \_ /usr/bin/ssh-agent /usr/bin/gpg-agent --sh --daemon --keep-display --write-env-file /home/pavelcejka/.gnupg/agent.info-virtpc01:10.0 /etc/X11/xinit/xinitrc
 1599 ?        Ss     0:00      |           \_ /usr/bin/gpg-agent --sh --daemon --keep-display --write-env-file /home/pavelcejka/.gnupg/agent.info-virtpc01:10.0 /etc/X11/xinit/xinitrc
 1453 ?        Z      0:00      \_ [Xvnc] <defunct>
 1486 ?        Sl     0:00      \_ xrdp-chansrv

v logu /var/log/xrdp

[20151104-18:48:01] [DEBUG] xrdp_mm_module_cleanup
[20151104-18:48:01] [INFO ] An established connection closed to endpoint: 127.0.0.1:3350 - socket: 11
[20151104-18:48:37] [DEBUG] returnvalue from xrdp_mm_connect 0
[20151104-18:48:40] [DEBUG] VNC Error after security negotiation
[20151104-18:48:40] [DEBUG] VNC error before sending share flag
[20151104-18:48:40] [DEBUG] VNC error before receiving server init
[20151104-18:48:40] [DEBUG] VNC error before receiving pixel format
[20151104-18:48:40] [DEBUG] VNC error before receiving name length
[20151104-18:48:40] [DEBUG] VNC error before receiving name
[20151104-18:48:40] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 12
[20151104-18:48:40] [DEBUG] xrdp_mm_module_cleanup
[20151104-18:48:40] [DEBUG] VNC mod_exit
[20151104-18:48:40] [INFO ] An established connection closed to endpoint: 127.0.0.1:3350 - socket: 11
[20151104-18:58:55] [INFO ] An established connection closed to endpoint: 192.168.0.5:34134 - socket: 8
[20151104-18:58:55] [DEBUG] xrdp_mm_module_cleanup
[20151104-18:58:55] [ERROR] Listening socket is in wrong state we terminate listener
[20151104-18:58:57] [INFO ] A connection received from: 192.168.0.5 port 34178
[20151104-18:58:57] [INFO ] An established connection closed to endpoint: 192.168.0.5:34178 - socket: 8
[20151104-18:58:57] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 7
[20151104-18:58:57] [CORE ] WARNING: Invalid x.509 certificate path defined, default path will be used: /etc/xrdp/cert.pem
[20151104-18:58:57] [WARN ] Invalid X.509 certificate path defined, default path will be used: /etc/xrdp/key.pem
[20151104-18:58:57] [DEBUG] xrdp_00000baa_wm_login_mode_event_00000001
[20151104-18:58:57] [WARN ] local keymap file for 0x10405 found and dosen't match built in keymap, using local keymap file
[20151104-19:01:05] [DEBUG] returnvalue from xrdp_mm_connect 0
[20151104-19:01:08] [DEBUG] VNC Error after security negotiation
[20151104-19:01:08] [DEBUG] VNC error before sending share flag
[20151104-19:01:08] [DEBUG] VNC error before receiving server init
[20151104-19:01:08] [DEBUG] VNC error before receiving pixel format
[20151104-19:01:08] [DEBUG] VNC error before receiving name length
[20151104-19:01:08] [DEBUG] VNC error before receiving name
[20151104-19:01:08] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 12
[20151104-19:01:08] [DEBUG] xrdp_mm_module_cleanup
[20151104-19:01:08] [DEBUG] VNC mod_exit
[20151104-19:01:08] [INFO ] An established connection closed to endpoint: 127.0.0.1:3350 - socket: 11

v logu /var/log/xrdp-sesman

[20151104-18:26:58] [INFO ] Xorg :11 -config xrdp/xorg.conf -logfile /dev/null -noreset -ac -nolisten tcp  
[20151104-18:27:07] [ERROR] X server for display 11 startup timeout
[20151104-18:27:08] [INFO ] starting xrdp-sessvc - xpid=6585 - wmpid=6584
[20151104-18:27:08] [ERROR] X server for display 11 startup timeout
[20151104-18:27:08] [ERROR] another Xserver might already be active on display 11 - see log
[20151104-18:27:08] [DEBUG] aborting connection...
[20151104-18:27:08] [INFO ] ++ terminated session:  username pavelcejka, display :11.0, session_pid 6583, ip 192.168.0.5:34071 - socket: 8
[20151104-18:30:20] [INFO ] A connection received from: 127.0.0.1 port 47014
[20151104-18:30:20] [INFO ] scp thread on sck 8 started successfully
[20151104-18:30:21] [INFO ] ++ reconnected session: username pavelcejka, display :10.0, session_pid 6482, ip 192.168.0.5:34091 - socket: 8
[20151104-18:30:21] [INFO ] An established connection closed to endpoint: 127.0.0.1:47014 - socket: 8
[20151104-18:42:41] [INFO ] shutting down sesman 1
[20151104-18:42:42] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 7
[20151104-18:42:42] [INFO ] shutting down sesman 1
[20151104-18:43:17] [WARN ] [init:46] libscp initialized
[20151104-18:43:17] [CORE ] starting sesman with pid 1258
[20151104-18:43:17] [INFO ] listening...
[20151104-18:44:15] [INFO ] A connection received from: 127.0.0.1 port 44080
[20151104-18:44:15] [INFO ] scp thread on sck 8 started successfully
[20151104-18:44:16] [INFO ] ++ created session (access granted): username pavelcejka, ip 192.168.0.5:34134 - socket: 8
[20151104-18:44:16] [INFO ] starting Xvnc session...
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 10
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 9
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 9
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: 127.0.0.1:44080 - socket: 8
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 5
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 6
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 7
[20151104-18:44:16] [INFO ] An established connection closed to endpoint: 127.0.0.1:44080 - socket: 8
[20151104-18:44:16] [ERROR] env_set_user: error creating .vnc dir
[20151104-18:44:16] [INFO ] Xvnc :10 -geometry 1840x1100 -depth 16 -rfbauth /home/pavelcejka/.vnc/sesman_pavelcejka_passwd -bs -ac -nolisten tcp -localhost -dpi 96 -depth 16  
[20151104-18:44:16] [INFO ] starting xrdp-sessvc - xpid=1453 - wmpid=1452
[20151104-18:44:27] [INFO ] A connection received from: 127.0.0.1 port 44112
[20151104-18:44:27] [INFO ] scp thread on sck 8 started successfully
[20151104-18:44:28] [INFO ] ++ created session (access granted): username pavelcejka, ip 192.168.0.5:34134 - socket: 8
[20151104-18:44:28] [INFO ] starting Xorg session...
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 10
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 9
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 9
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: 127.0.0.1:44112 - socket: 8
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 5
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 6
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: NULL:NULL - socket: 7
[20151104-18:44:28] [INFO ] An established connection closed to endpoint: 127.0.0.1:44112 - socket: 8
[20151104-18:44:28] [INFO ] Xorg :11 -config xrdp/xorg.conf -logfile /dev/null -noreset -ac -nolisten tcp  
[20151104-18:44:38] [ERROR] X server for display 11 startup timeout
[20151104-18:44:38] [INFO ] starting xrdp-sessvc - xpid=1628 - wmpid=1627
[20151104-18:44:38] [ERROR] X server for display 11 startup timeout
[20151104-18:44:38] [ERROR] another Xserver might already be active on display 11 - see log
[20151104-18:44:38] [DEBUG] aborting connection...
[20151104-18:44:38] [INFO ] ++ terminated session:  username pavelcejka, display :11.0, session_pid 1626, ip 192.168.0.5:34134 - socket: 8
[20151104-18:48:36] [INFO ] A connection received from: 127.0.0.1 port 44113
[20151104-18:48:36] [INFO ] scp thread on sck 8 started successfully
[20151104-18:48:37] [INFO ] ++ reconnected session: username pavelcejka, display :10.0, session_pid 1451, ip 192.168.0.5:34134 - socket: 8
[20151104-18:48:37] [INFO ] An established connection closed to endpoint: 127.0.0.1:44113 - socket: 8
[20151104-19:01:05] [INFO ] A connection received from: 127.0.0.1 port 44130
[20151104-19:01:05] [INFO ] scp thread on sck 8 started successfully
[20151104-19:01:05] [INFO ] ++ reconnected session: username pavelcejka, display :10.0, session_pid 1451, ip 192.168.0.5:34178 - socket: 8
[20151104-19:01:05] [INFO ] An established connection closed to endpoint: 127.0.0.1:44130 - socket: 8

Otázka je, co s tím?

Dá se nějak vnc přinutit, aby bylo ukecanější? Dá se nějak zjistit, proč vlastně vnc selhalo? Vlastní log nemá, v systémovém logu nic nevidím. Přehlíd jsem něco?

Na otázku zatím nikdo bohužel neodpověděl.