Subject: Bug#763: Bug Report: Slow startup time with x2go server on Debian 7 Wheezy

From: Matt Weatherford <[email-masked]>
Date: Thu, 22 Jan 2015 15:40:45 -0800

Package: 4.0.1.18-0x2go1+git20141006.949+wheezy.main.1

Windows 2012R2,  x86-64 client version:  4.0.3.1  with debug 
(x2goclient-4.0.3.1-20141214-debug-setup)

Debian Wheezy (7.8) - x2go package Server Versions:
root@ars:~# apt-show-versions | grep x2go
libnx-x11/wheezy uptodate 2:3.5.0.28-0x2go1+git20141113.546+wheezy.main.1
libxcomp3/wheezy uptodate 2:3.5.0.28-0x2go1+git20141113.546+wheezy.main.1
libxcompext3/wheezy uptodate 2:3.5.0.28-0x2go1+git20141113.546+wheezy.main.1
libxcompshad3/wheezy uptodate 
2:3.5.0.28-0x2go1+git20141113.546+wheezy.main.1
nxagent/wheezy uptodate 2:3.5.0.28-0x2go1+git20141113.546+wheezy.main.1
x2go-keyring/wheezy uptodate 2012.07.23+wheezy~main~17~build1
x2goagent/wheezy uptodate 2:3.5.0.28-0x2go1+git20141113.546+wheezy.main.1
x2goserver/wheezy uptodate 4.0.1.18-0x2go1+git20141006.949+wheezy.main.1
x2goserver-extensions/wheezy uptodate 
4.0.1.18-0x2go1+git20141006.949+wheezy.main.1
x2goserver-xsession/wheezy uptodate 
4.0.1.18-0x2go1+git20141006.949+wheezy.main.1
root@ars:~#
root@ars:~# uname -a
Linux ars 3.2.0-4-amd64 #1 SMP Debian 3.2.65-1+deb7u1 x86_64 GNU/Linux
root@ars:~#
root@ars:~# grep -i x2go /etc/apt/sources.list
root@ars:~# grep -i x2go /etc/apt/sources.list.d/*
/etc/apt/sources.list.d/x2go_repo.list:# x2go_repo
/etc/apt/sources.list.d/x2go_repo.list:deb 
http://packages.x2go.org/debian wheezy main
/etc/apt/sources.list.d/x2go_repo.list:deb-src 
http://packages.x2go.org/debian wheezy main
root@ars:~#

Summary:

x2go windows client starts fine, open a connection to Ars
On server, log shows a long pause (2 -3 minutes) at:
"x2golistsessions has been called with options: --all-servers"

Session does finally start up fine though

Here are the logs on the server side (debug option on, from syslog)

root@ars:~#
root@ars:~#
root@ars:~# Jan 22 15:27:38 ars automount[3023]: set_tsd_user_vars: 
failed to get group info from getgrgid_r
Jan 22 15:27:38 ars /usr/bin/x2golistsessions[2051]: x2golistsessions 
has been called with no option
Jan 22 15:27:40 ars /usr/bin/x2gostartagent: x2gostartagent called with 
options: 800x600 adsl 16m-jpeg-9 unix-kde-depth_32 us auto 1 D MATE both
Jan 22 15:27:40 ars /usr/bin/x2gostartagent: client announced itself as 
,,128.208.105.87''
Jan 22 15:27:40 ars /usr/bin/x2gosessionlimit[2079]: x2gosessionlimit 
has been called
Jan 22 15:27:40 ars /usr/bin/x2golistsessions[2082]: x2golistsessions 
has been called with options: --all-servers

root@ars:~# ### long pause here, at least 2 minutes  ###
root@ars:~#
root@ars:~#
root@ars:~# Jan 22 15:29:32 ars /usr/bin/x2gostartagent: In While loop 
near line 156 - x2gogetdisplays
Jan 22 15:29:32 ars /usr/lib/x2go/x2gogetdisplays[2633]: db_getdisplays 
called, server: ars; return value:
Jan 22 15:29:32 ars /usr/lib/x2go/x2gogetports[2643]: db_getports 
called, server: ars; return value:
Jan 22 15:29:32 ars /usr/lib/x2go/x2goinsertsession[2676]: 
db_insertsession called, session ID: mbw-50-1421969372_stDMATE_dp32, 
server: ars, session ID: mbw-50-1421969372_stDMATE_dp32
Jan 22 15:29:32 ars /usr/bin/x2gostartagent: In Loop near line 192 - 
SSH_PORT
Jan 22 15:29:32 ars /usr/lib/x2go/x2gogetports[2689]: db_getports 
called, server: ars; return value:
Jan 22 15:29:33 ars /usr/lib/x2go/x2goinsertport[2703]: db_insertport 
called, session ID: mbw-50-1421969372_stDMATE_dp32, server: ars, SSH 
port: 30001
Jan 22 15:29:33 ars /usr/bin/x2gostartagent: In Loop near line 192 - 
SSH_PORT
Jan 22 15:29:33 ars /usr/lib/x2go/x2gogetports[2715]: db_getports 
called, server: ars; return value: |30001|
Jan 22 15:29:33 ars /usr/lib/x2go/x2goinsertport[2729]: db_insertport 
called, session ID: mbw-50-1421969372_stDMATE_dp32, server: ars, SSH 
port: 30002
Jan 22 15:29:33 ars /usr/bin/x2gostartagent: In Loop near line 192 - 
SSH_PORT
Jan 22 15:29:34 ars /usr/lib/x2go/x2gogetports[2741]: db_getports 
called, server: ars; return value: |30001| |30002|
Jan 22 15:29:34 ars /usr/lib/x2go/x2goinsertport[2755]: db_insertport 
called, session ID: mbw-50-1421969372_stDMATE_dp32, server: ars, SSH 
port: 30003
Jan 22 15:29:34 ars /usr/bin/x2gofeature: x2gofeature called with 
options: X2GO_RUN_EXTENSIONS
Jan 22 15:29:34 ars 
/usr/share/x2go/x2gofeature.d/x2goserver-extensions.features: 
x2goserver-extensions.features called with options: X2GO_RUN_EXTENSIONS
Jan 22 15:29:34 ars /usr/sbin/x2gocleansessions[3109]: 
mbw-50-1421969372_stDMATE_dp32: state file for this session does not 
exist: /tmp/.x2go-mbw/C-mbw-50-1421969372_stDMATE_dp32/state (this can 
be ignored during session startups)
Jan 22 15:29:34 ars /usr/bin/x2goserver-run-extensions: 
x2goserver-run-extensions called with options: 
mbw-50-1421969372_stDMATE_dp32 pre-start
Jan 22 15:29:34 ars /usr/bin/x2gostartagent: successfully started X2Go 
agent session with ID mbw-50-1421969372_stDMATE_dp32
Jan 22 15:29:34 ars /usr/bin/x2gofeature: x2gofeature called with 
options: X2GO_RUN_EXTENSIONS
Jan 22 15:29:34 ars 
/usr/share/x2go/x2gofeature.d/x2goserver-extensions.features: 
x2goserver-extensions.features called with options: X2GO_RUN_EXTENSIONS
Jan 22 15:29:34 ars /usr/bin/x2goserver-run-extensions: 
x2goserver-run-extensions called with options: 
mbw-50-1421969372_stDMATE_dp32 post-start
Jan 22 15:29:35 ars /usr/lib/x2go/x2gocreatesession[2919]: 
db_createsession called, session ID: mbw-50-1421969372_stDMATE_dp32, 
cookie: dbff79275061d36931e594964be21d9e, client: 128.208.105.87, pid: 
2886, graphics port: 30001, sound port: 30002, file sharing port: 30003
Jan 22 15:29:40 ars /usr/bin/x2goruncommand: x2goruncommand called with 
options: 50 2886 mbw-50-1421969372_stDMATE_dp32 30002 mate-session nosnd D
Jan 22 15:29:40 ars /usr/bin/x2goruncommand: exporting 
LD_LIBRARY_PATH=/usr/lib/nx/X11/Xinerama:/usr/lib/nx/X11
Jan 22 15:29:40 ars /usr/bin/x2gofeature: x2gofeature called with 
options: X2GO_RUN_EXTENSIONS
Jan 22 15:29:40 ars 
/usr/share/x2go/x2gofeature.d/x2goserver-extensions.features: 
x2goserver-extensions.features called with options: X2GO_RUN_EXTENSIONS
Jan 22 15:29:40 ars /usr/bin/x2goserver-run-extensions: 
x2goserver-run-extensions called with options: 
mbw-50-1421969372_stDMATE_dp32 pre-runcommand
Jan 22 15:29:40 ars /usr/bin/x2goruncommand: running command 
/usr/bin/mate-session
Jan 22 15:29:40 ars /usr/bin/x2gosetkeyboard: x2gosetkeyboard called 
with options:
Jan 22 15:29:40 ars /usr/bin/x2gofeature: x2gofeature called with 
options: X2GO_XSESSION
Jan 22 15:29:40 ars /usr/bin/x2gosetkeyboard: Waiting for 
/homes/mbw/.x2go/C-mbw-50-1421969372_stDMATE_dp32/keyboard to appear
Jan 22 15:29:40 ars 
/usr/share/x2go/x2gofeature.d/x2goserver-extensions.features: 
x2goserver-extensions.features called with options: X2GO_XSESSION
Jan 22 15:29:40 ars /usr/share/x2go/x2gofeature.d/x2goserver.features: 
x2goserver.features called with options: X2GO_XSESSION
Jan 22 15:29:40 ars 
/usr/share/x2go/x2gofeature.d/x2goserver-xsession.features: 
x2goserver-xsession.features called with options: X2GO_XSESSION
Jan 22 15:29:40 ars /usr/bin/x2goruncommand: launching session with 
Xsession-x2go mechanism, using STARTUP="mate-session"
Jan 22 15:29:40 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/20x11-common_process-args
Jan 22 15:29:40 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/30x11-common_xresources
Jan 22 15:29:40 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/35x11-common_xhost-local
Jan 22 15:29:41 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/40x11-common_xsessionrc
Jan 22 15:29:41 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/50x11-common_determine-startup
Jan 22 15:29:41 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/75dbus_dbus-launch
Jan 22 15:29:41 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/90consolekit
Jan 22 15:29:41 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/90x11-common_ssh-agent
Jan 22 15:29:41 ars /etc/x2go/Xsession: executing 
/etc/x2go/Xsession.d/99x11-common_start
Jan 22 15:29:41 ars /usr/bin/x2gosetkeyboard: Setting X keyboard 
according to /homes/mbw/.x2go/C-mbw-50-1421969372_stDMATE_dp32/keyboard
Jan 22 15:29:41 ars mate-session[3330]: WARNING: GSIdleMonitor: IDLETIME 
counter not found
Jan 22 15:29:42 ars automount[3023]: set_tsd_user_vars: failed to get 
group info from getgrgid_r
Jan 22 15:29:42 ars automount[3023]: set_tsd_user_vars: failed to get 
group info from getgrgid_r
Jan 22 15:29:42 ars automount[3023]: key "home4" not found in map source(s).
Jan 22 15:29:42 ars automount[3023]: set_tsd_user_vars: failed to get 
group info from getgrgid_r
Jan 22 15:29:47 ars dbus[3111]: [system] Activating service 
name='org.mate.SettingsDaemon.DateTimeMechanism' (using servicehelper)
Jan 22 15:29:47 ars dbus[3111]: [system] Successfully activated service 
'org.mate.SettingsDaemon.DateTimeMechanism'

Debug Logs from Windows Client:

x2go-INFO-1> "Starting x2goclient..."
x2go-WARNING-1> "Can't load translator: :/x2goclient_en_us"
x2go-WARNING-2> "Can't load translator: :/qt_en_US"
x2go-DEBUG-onmainwindow.cpp:9755> Getting Xorg settings.
x2go-INFO-3> "Started  x2goclient."
x2go-DEBUG-onmainwindow.cpp:490> "$HOME=C:/Users/mbw"
x2go-DEBUG-onmainwindow.cpp:2104> Reading 3 sessions from config file.
x2go-DEBUG-onmainwindow.cpp:9497> Starting win servers...
x2go-DEBUG-onmainwindow.cpp:9833> "C:/Users/mbw/.x2go/etc/sshd_config 
created."
x2go-DEBUG-onmainwindow.cpp:9266> got localhost
x2go-DEBUG-onmainwindow.cpp:9288> Port is free: 7022
x2go-DEBUG-onmainwindow.cpp:9889> Creating desktop: x2go_mbw
x2go-INFO-8> "Starting connection to server: ars.csde.washington.edu:22"
x2go-DEBUG-onmainwindow.cpp:2683> Start new ssh connection to 
server:"ars.csde.w
ashington.edu":"22" krbLogin: false
x2go-DEBUG-onmainwindow.cpp:2778> SSH connection established.
x2go-DEBUG-onmainwindow.cpp:3038> Continue normal x2go session
x2go-DEBUG-onmainwindow.cpp:3382> ""
x2go-DEBUG-onmainwindow.cpp:3769> Fullscreen: false
x2go-DEBUG-onmainwindow.cpp:9266> got localhost
x2go-DEBUG-onmainwindow.cpp:9288> Port is free: 6000
x2go-DEBUG-onmainwindow.cpp:9354> using internal X: true
x2go-DEBUG-onmainwindow.cpp:9377> WxH:"800"x"600"
x2go-DEBUG-onmainwindow.cpp:9382> "-multiwindow -notrayicon -clipboard"
x2go-DEBUG-onmainwindow.cpp:9419> Running "C:/Program Files 
(x86)/x2goclient\vcx
srv\vcxsrv.exe" "-multiwindow -notrayicon -clipboard :0"
x2go-DEBUG-onmainwindow.cpp:3901> Executing remote command: "X2GODPI=96 
x2gostar
tagent 800x600 adsl 16m-jpeg-9 unix-kde-depth_32 us auto 1 D MATE both"
x2go-DEBUG-onmainwindow.cpp:9266> got localhost
x2go-DEBUG-onmainwindow.cpp:9294> Port already used: 6000
x2go-DEBUG-onmainwindow.cpp:9448> X is started.
x2go-DEBUG-onmainwindow.cpp:9799> All winservers are started.
x2go-DEBUG-onmainwindow.cpp:4705> Agent output: "50
dbff79275061d36931e594964be21d9e
2886
mbw-50-1421969372_stDMATE_dp32
30001
30002
30003
"
x2go-DEBUG-onmainwindow.cpp:9614> PulseAudio Version Line: "pulseaudio 5.0"
x2go-DEBUG-onmainwindow.cpp:9628> PulseAudio >= 3.0 Detected. x2goclient 
will te
ll PulseAudio to use .pulse-cookie.
x2go-DEBUG-onmainwindow.cpp:9266> got localhost
x2go-DEBUG-onmainwindow.cpp:9288> Port is free: 4713
x2go-DEBUG-onmainwindow.cpp:9266> got localhost
x2go-DEBUG-onmainwindow.cpp:9288> Port is free: 4714
x2go-DEBUG-onmainwindow.cpp:9642> pulse template: 
"C:/Users/mbw/X2GO~1/pulse/tmp
"
x2go-DEBUG-onmainwindow.cpp:9652> pulse tmp file: 
"C:/Users/mbw/X2GO~1/pulse/tmp
.Hp5996"
x2go-DEBUG-onmainwindow.cpp:9726> Starting pulse\pulseaudio.exe 
"--exit-idle-tim
e=-1 -n -F C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\config.pa 
--log-level=debug --ve
rbose --log-target=file:C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\pulse.log" 
working
dir: "C:\PROGRA~2\X2GOCL~1\pulse"
x2go-DEBUG-onmainwindow.cpp:9733> Connected timer.
x2go-DEBUG-onmainwindow.cpp:9266> got localhost
x2go-DEBUG-onmainwindow.cpp:9288> Port is free: 31001
x2go-DEBUG-onmainwindow.cpp:9266> got localhost
x2go-DEBUG-onmainwindow.cpp:9294> Port already used: 6000
x2go-DEBUG-onmainwindow.cpp:5315> "Starting NX proxy, command: nxproxy 
-S nx/nx,
options=/cygdrive/C/Users/mbw/X2GO~1/S-MBW-~3/options:50"
Object::connect: No such slot ONMainWindow::slotSndTunOk(int)
x2go-DEBUG-onmainwindow.cpp:5638> Proxy wrote on stderr: "
NXPROXY - Version 3.5.0

Copyright (C) 2001, 2010 NoMachine.
See http://www.nomachine.com/ for more information.

Info: Proxy running in client mode with pid '3340'.
Session: Starting session at 'Thu Jan 22 15:29:39 2015'.
Info: Connecting to remote host 'localhost:31001'.
Info: Connection to remote proxy 'localhost:31001' established.
Info: Connection with remote proxy completed.
Warning: Unrecognized session type 'unix-kde-depth_32'. Assuming agent 
session.
"
x2go-DEBUG-onmainwindow.cpp:10184> "Searching proxy win: 
X2GO-mbw-50-1421969372_
stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:11727> "Searching window with title: 
X2GO-mbw-50-142
1969372_stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:5638> Proxy wrote on stderr: "Warning: 
Failed to rea
d data from the X auth command.
Warning: Generated a fake cookie for X authentication.
Info: Using ADSL link parameters 512/24/1/0.
Info: Using cache parameters 4/4096KB/8192KB/8192KB.
Info: Using pack method '16m-jpeg-9' with session 'unix-kde-depth_32'.
Info: Using ZLIB data compression 1/1/32.
Info: Using ZLIB stream compression 4/4.
Info: No suitable cache file found.
Info: Forwarding X11 connections to display 'localhost:0'.
Session: Session started at 'Thu Jan 22 15:29:39 2015'.
Info: Established X server connection.
"
x2go-DEBUG-onmainwindow.cpp:7702> "ssh-keygen -t rsa -b 1024 -N -f 
C:/Users/mbw
/X2GO~1/ssh/gen/key.gq5996 -q"
cygwin warning:
   MS-DOS style path detected: C:/Users/mbw/X2GO~1/ssh/gen/key.gq5996
   Preferred POSIX equivalent is: 
/cygdrive/c/Users/mbw/X2GO~1/ssh/gen/key.gq5996

   CYGWIN environment variable option "nodosfilewarning" turns off this 
warning.
   Consult the user's guide for more details about POSIX paths:
     http://cygwin.com/cygwin-ug-net/using.html#using-pathnames
x2go-DEBUG-onmainwindow.cpp:7709> ssh-keygen succeeded.
x2go-DEBUG-onmainwindow.cpp:7527> Key created on: 
"C:/Users/mbw/X2GO~1/ssh/gen/k
ey.gq5996"
x2go-DEBUG-onmainwindow.cpp:8961> Starting fs tunnel for: 
"mbw-50-1421969372_stD
MATE_dp32"
x2go-DEBUG-onmainwindow.cpp:8962> fs port: "30003"
x2go-DEBUG-onmainwindow.cpp:10184> "Searching proxy win: 
X2GO-mbw-50-1421969372_
stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:11727> "Searching window with title: 
X2GO-mbw-50-142
1969372_stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:5638> Proxy wrote on stderr: "Info: Using 
shared mem
ory parameters 0/0K.
"
x2go-DEBUG-onmainwindow.cpp:9745> Restarting pulse\pulseaudio.exe 
"--exit-idle-t
ime=-1 -n -F C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\config.pa 
--log-level=debug --
verbose --log-target=file:C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\pulse.log"
x2go-DEBUG-onmainwindow.cpp:10184> "Searching proxy win: 
X2GO-mbw-50-1421969372_
stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:11727> "Searching window with title: 
X2GO-mbw-50-142
1969372_stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:10184> "Searching proxy win: 
X2GO-mbw-50-1421969372_
stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:11727> "Searching window with title: 
X2GO-mbw-50-142
1969372_stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:10184> "Searching proxy win: 
X2GO-mbw-50-1421969372_
stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:11727> "Searching window with title: 
X2GO-mbw-50-142
1969372_stDMATE_dp32"
x2go-DEBUG-onmainwindow.cpp:10190> "Proxy win found: 459712"
x2go-DEBUG-onmainwindow.cpp:10250> Maximize proxy win: false
x2go-DEBUG-onmainwindow.cpp:9745> Restarting pulse\pulseaudio.exe 
"--exit-idle-t
ime=-1 -n -F C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\config.pa 
--log-level=debug --
verbose --log-target=file:C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\pulse.log"
x2go-DEBUG-onmainwindow.cpp:9745> Restarting pulse\pulseaudio.exe 
"--exit-idle-t
ime=-1 -n -F C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\config.pa 
--log-level=debug --
verbose --log-target=file:C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\pulse.log"
x2go-DEBUG-onmainwindow.cpp:9745> Restarting pulse\pulseaudio.exe 
"--exit-idle-t
ime=-1 -n -F C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\config.pa 
--log-level=debug --
verbose --log-target=file:C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\pulse.log"
x2go-DEBUG-onmainwindow.cpp:9745> Restarting pulse\pulseaudio.exe 
"--exit-idle-t
ime=-1 -n -F C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\config.pa 
--log-level=debug --
verbose --log-target=file:C:\Users\mbw\X2GO~1\pulse\tmp.Hp5996\pulse.log"