X2Go Bug report logs - #763
Bug Report: Slow startup time with x2go server on Debian 7 Wheezy

Reply or subscribe to this bug.

Toggle useless messages

Message #5 received at submit@bugs.x2go.org (full text, mbox, reply):

From: Matt Weatherford <mbw@u.washington.edu>

To: submit@bugs.x2go.org, Stefan Baur <postmaster@stefanbaur.de>

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

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"

Message #14 received at 763@bugs.x2go.org (full text, mbox, reply):

From: Blake Leverett <bleverett@gmail.com>

To: 763@bugs.x2go.org

Subject: I also have huge startup delays

Date: Wed, 18 Jul 2018 10:23:07 -0600

[Message part 1 (text/plain, inline)]

I have the same problem.  x2go works, but it takes 2-3 minutes from
starting the session until the remote session window appears.  Works fine
otherwise.

This bug should probably be marked as critical, as it makes x2go barely
useable for some use cases.  My me it's a bit annoying, but not that big of
a deal.

I am running Gentoo Linux, x2go client 4.1.1.0, x2go server 4.0.1.22.

[Message part 2 (text/html, inline)]

Message #19 received at 763@bugs.x2go.org (full text, mbox, reply):

From: Blake Leverett <bleverett@gmail.com>

To: 763@bugs.x2go.org

Subject: Fixed by upgrading x2goserver to 4.1.0.0

Date: Wed, 18 Jul 2018 10:36:44 -0600

[Message part 1 (text/plain, inline)]

I upgraded to x2go server 4.1.0.0 and the problem is gone, for me at least.

[Message part 2 (text/html, inline)]

Send a report that this bug log contains spam.