X2Go Bug report logs - #1260
high CPU usage with Fedora 27 and users that disconnect, Caja and Mate crash/coredump

Toggle useless messages

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

From: Robert Kudyba <rkudyba@fordham.edu>

To: submit@bugs.x2go.org

Subject: high CPU usage with Fedora 27 and users that disconnect, Caja and Mate crash/coredump

Date: Tue, 20 Feb 2018 10:46:43 -0500

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

Package: x2goserver-4.1.0.1-0.0x2go1.0.git20180218.1532.heuler.fc27.x86_64
Version: 4.1.0.1-0

We experience a high load after users disconnect. The logs the follow below
indicate that Caja and Mate crash. I have uploaded core files to:
1) Mate:
http://storm.cis.fordham.edu/~rkudyba/core.mate-notificati.6675.6ecbb92662c74928aaa33397e2281f5d.13324.1519094587000000.lz4
2) Caja http://storm.cis.fordham.edu/~rkudyba/
core.caja.6675.6ecbb92662c74928aaa33397e2281f5d.11928.1519007933000000.lz4


Here is the server load with just 1 X2Go suspended user session:
2 users,  load average: 3.74, 4.95, 5.18

Here are some of his processes:
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+
COMMAND
11914 ouruser
  20   0 20.488g 0.018t   7116 R  90.7 80.5   1542:41 mate-panel
11624 ouruser  20   0   48564   3812   2960 S   0.3  0.0  18:55.56
dbus-daemon
11932 ouruser  20   0  601340   8040   5768 S   0.3  0.0  22:01.75
wnck-applet
12338 ouruser  20   0  591444   6180   5436 S   0.3  0.0   7:40.26
notification-ar

Here is a ps:
ps -auwx | grep x2go
root      8749  0.1  0.0 183668 11428 ?        S    Feb19   3:01
/usr/bin/perl /usr/sbin/x2gocleansessions
root     11516  0.0  0.0 115996  1024 pts/0    S+   09:48   0:00 grep
--color=auto x2go
ouruser 11518  0.0  0.0 116572  2720 ?        Ss   Feb18   0:00 /bin/bash
/usr/bin/x2goruncommand 327 11426 ouruser-327-1519007899_stDMATE_dp32 59504
mate-session nosnd D
ouruser 11623  0.0  0.0  32340  1096 ?        S    Feb18   0:00
/usr/bin/dbus-run-session /etc/x2go/Xsession

And a systemctl status x2goserver
● x2goserver.service - X2Go Server Daemon
   Loaded: loaded (/usr/lib/systemd/system/x2goserver.service; enabled;
vendor preset: disabled)
   Active: active (running) since Mon 2018-02-19 02:16:54 EST; 1 day 7h ago
 Main PID: 8749 (x2gocleansessio)
    Tasks: 1 (limit: 4915)
   Memory: 15.5M
      CPU: 6h 42min 49.407s
   CGroup: /system.slice/x2goserver.service
           └─8749 /usr/bin/perl /usr/sbin/x2gocleansessions

Warning: Journal has been rotated since unit was started. Log output is
incomplete or unavailable.

rpm -q x2goserver
x2goserver-4.1.0.1-0.0x2go1.0.git20180218.1532.heuler.fc27.x86_64

Logs at the time the user logs in and disconnects:
Feb 18 21:38:15 ourserver systemd[1]: Started User Manager for UID 6675.
Feb 18 21:38:21 ourserver /usr/sbin/x2gocleansessions[30526]:
ouruser-327-1519007899_stDMATE_dp32: state file for this s
ession does not exist:
/tmp/.x2go-ouruser/C-ouruser-327-1519007899_stDMATE_dp32/state (this can be
ignored during s
ession startups)
Feb 18 21:38:23 ourserver /usr/bin/x2gostartagent[11435]: successfully
started X2Go Agent session with ID ouruser-327-15
19007899_stDMATE_dp32
Feb 18 21:38:26 ourserver /usr/bin/x2gosetkeyboard[11597]: Setting X
keyboard according to /u/ourserver/csga/ouruser/.x2go/C
-ouruser-327-1519007899_stDMATE_dp32/keyboard
Feb 18 21:38:26 ourserver /usr/bin/x2goruncommand[11617]: launching session
with Xsession-x2go mechanism, using STARTUP="
mate-session"
Feb 18 21:38:26 ourserver /usr/bin/x2goruncommand[11618]: dbus wrapper
available as /usr/bin/dbus-run-session
Feb 18 21:38:27 ourserver baloo_file[17852]: QObject::connect: invalid null
parameter
Feb 18 21:38:28 ourserver baloo_file[18750]: QObject::connect: invalid null
parameter
Feb 18 21:38:28 ourserver baloo_file[5557]: QObject::connect: invalid null
parameter
Feb 18 21:38:28 ourserver baloo_file[3418]: QObject::connect: invalid null
parameter
Feb 18 21:38:31 ourserver gnome-keyring-daemon[11896]: couldn't access
control socket: /run/user/6675/keyring/control: No such file or directory
Feb 18 21:38:31 ourserver mate-session[11631]: WARNING: GSIdleMonitor:
IDLETIME counter not found
Feb 18 21:38:31 ourserver mate-session[11631]: GLib-GObject-CRITICAL:
object GSIdleMonitor 0x7f73040054d0 finalized while still in-construction
Feb 18 21:38:31 ourserver mate-session[11631]: GLib-GObject-CRITICAL:
Custom constructor for class GSIdleMonitor returned NULL (which is
invalid). Please use GInitable instead.
Feb 18 21:38:36 ourserver gnome-keyring-daemon[11896]: The Secret Service
was already initialized
Feb 18 21:38:36 ourserver spice-vdagent[11943]: Cannot access vdagent
virtio channel /dev/virtio-ports/com.redhat.spice.0
Feb 18 21:38:37 ourserver gnome-keyring-daemon[11896]: The SSH agent was
already initialized
Feb 18 21:38:37 ourserver pulseaudio[12014]: [pulseaudio] core-util.c:
Failed to open configuration file
'/u/ourserver/csga/ouruser/.x2go/C-ouruser-327-1519007899_stDMATE_dp32/.pulse-client.conf':
No such file or directory
Feb 18 21:38:37 ourserver pulseaudio[11975]: [pulseaudio] core-util.c:
Failed to open configuration file
'/u/ourserver/csga/ouruser/.x2go/C-ouruser-327-1519007899_stDMATE_dp32/.pulse-client.conf':
No such file or directory
Feb 18 21:38:38 ourserver dbus-daemon[892]: [system] Activating service
name='org.freedesktop.problems' requested by ':1.14085' (uid=6675 pid=12070
comm="abrt-applet ") (using servicehelper)
Feb 18 21:38:38 ourserver dbus-daemon[892]: [system] Successfully activated
service 'org.freedesktop.problems'
Feb 18 21:38:39 ourserver pulseaudio[12159]: [pulseaudio] core-util.c:
Failed to open configuration file
'/u/ourserver/csga/ouruser/.x2go/C-ouruser-327-1519007899_stDMATE_dp32/.pulse-client.conf':
No such file or directory
Feb 18 21:38:39 ourserver dbus-daemon[892]: [system] Rejected send message,
2 matched rules; type="method_call", sender=":1.14100" (uid=6675 pid=12088
comm="/usr/bin/pulseaudio --start --log-target=syslog ")
interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects"
error name="(unset)" requested_reply="0" destination="org.bluez" (bus)
Feb 18 21:38:39 ourserver gnome-keyring-daemon[11896]: The PKCS#11
component was already initialized
Feb 18 21:38:40 ourserver pulseaudio[12088]: [pulseaudio] bluez5-util.c:
GetManagedObjects() failed: org.freedesktop.DBus.Error.AccessDenied:
Rejected send message, 2 matched rules; type="method_call",
sender=":1.14100" (uid=6675 pid=12088 comm="/usr/bin/pulseaudio --start
--log-target=syslog ") interface="org.freedesktop.DBus.ObjectManager"
member="GetManagedObjects" error name="(unset)" requested_reply="0"
destination="org.bluez" (bus)
Feb 18 21:38:41 ourserver caja[11928]: [N-A] Caja-Actions Tracker 1.8.3
initializing...
Feb 18 21:38:41 ourserver pulseaudio[12200]: [pulseaudio] pid.c: Daemon
already running.
Feb 18 21:38:41 ourserver caja[11928]: [N-A] Caja-Actions Menu Extender
1.8.3 initializing...
Feb 18 21:38:41 ourserver pulseaudio[12227]: [pulseaudio] pid.c: Daemon
already running.
Feb 18 21:38:41 ourserver dbus-daemon[892]: [system] Activating via
systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested
by ':1.14102' (uid=6675 pid=12179 comm="python3 /bin/blueman-applet ")
Feb 18 21:38:41 ourserver dbus-daemon[892]: [system] Activating via
systemd: service name='org.bluez' unit='dbus-org.blue
z.service' requested by ':1.14102' (uid=6675 pid=12179 comm="python3
/bin/blueman-applet ")
Feb 18 21:38:41 ourserver systemd[1]:
/usr/lib/systemd/system/bluetooth.service:22: Not an absolute path,
ignoring: @stat
edir@
Feb 18 21:38:41 ourserver systemd[1]:
/usr/lib/systemd/system/bluetooth.service:23: Not an absolute path,
ignoring: @conf
dir@
Feb 18 21:38:43 ourserver dbus-daemon[892]: [system] Activating via
systemd: service name='org.baseurl.DnfSystem' unit='d
nfdaemon.service' requested by ':1.14084' (uid=6675 pid=11942 comm="python3
/bin/dnfdragora-updater ")
Feb 18 21:38:43 ourserver systemd[1]: Starting Package management dnf
daemon...
Feb 18 21:38:43 ourserver dbus-daemon[892]: [system] Successfully activated
service 'org.baseurl.DnfSystem'
Feb 18 21:38:43 ourserver systemd[1]: Started Package management dnf daemon.
Feb 18 21:38:53 ourserver kernel: traps: caja[11928] trap int3
ip:7fbd51c6a771 sp:7fff3feea110 error:0 in libglib-2.0.so.
0.5400.3[7fbd51c1a000+111000]
Feb 18 21:38:54 ourserver systemd[1]: Started Process Core Dump (PID
12386/UID 0).
Feb 18 21:38:54 ourserver caja[12395]: [N-A] Caja-Actions Tracker 1.8.3
initializing...
Feb 18 21:38:54 ourserver caja[12395]: [N-A] Caja-Actions Menu Extender
1.8.3 initializing...
Feb 18 21:39:01 ourserver systemd-coredump[12387]: Process 11928 (caja) of
user 6675 dumped core.#012#012Stack trace of t
hread 11928:#012#0  0x00007fbd51c6a771 _g_log_abort
(libglib-2.0.so.0)#012#1  0x00007fbd51c6cda1 g_log_writer_default
(libglib-2.0.so.0)#012#2  0x00007fbd51c6b30e g_log_structured_array
(libglib-2.0.so.0)#012#3  0x00007fbd51c6b607 g_log_structured
(libglib-2.0.so.0)#012#4  0x00007fbd5334c1e1 _gdk_x11_display_error_event
(libgdk-3.so.0)#012#5  0x00007fbd53359783 gdk_x_error
(libgdk-3.so.0)#012#6  0x00007fbd51921e3a _XError (libX11.so.6)#012#7
0x00007fbd5191ed6b handle_error (libX11.so.6)#012#8  0x00007fbd5191ee15
handle_response (libX11.so.6)#012#9  0x00007fbd5191f745 _XEventsQueued
(libX11.so.6)#012#10 0x00007fbd51911240 XEventsQueued (libX11.so.6)#012#11
0x00007fbd527e6252 _cairo_xlib_shm_su0x00007fbd527e70fc
_cairo_xlib_surface_create_similar_shm (libcairo.so.2)#012#14
0x00007fbd527b3f13 cairo_surface_create_similar_image
(libcairo.so.2)#012#15 0x00007fbd53317e4c gdk_cairo_set_source_pixbuf
(libgdk-3.so.0)#012#16 0x00007fbd54885c22 mate_bg_create_surface
(libmate-desktop-2.so.17)#012#17 0x0000559937d3d24a
eel_background_ensure_realized (caja)#012#18 0x0000559937d3d3c8
eel_background_set_up_widget (caja)#012#19 0x0000559937d3d57e
background_changed_cb (caja)#012#20 0x00007fbd51c61577 g_idle_dispatch
(libglib-2.0.so.0)#012#21 0x00007fbd51c64b77 g_main_context_dispatch
(libglib-2.0.so.0)#012#22 0x00007fbd51c64f20 g_main_context_iterate.isra.23
(libglib-2.0.so.0)#012#23 0x00007fbd51c64fac g_main_context_iteration
(libglib-2.0.so.0)#012#24 0x00007fbd52221cad g_application_run
(libgio-2.0.so.0)#012#25 0x0000559937c5f500 main (caja)#012#26
0x00007fbd5056e00a __libc_start_main (libc.so.6)#012#27 0x0000559937c5f57a
_start (caja)#012#012Stack trace of thread 12181:#012#0  0x00007fbd5226759f
g_file_monitor_source_handle_event (libgio-2.0.so.0)#012#1
0x00007fbd5229393e ih_event_callback (libgio-2.0.so.0)#012#2
0x00007fbd52292d09 ip_event_dispatch.part.4 (libgio-2.0.so.0)#012#3
0x00007fbd52292f4e ip_event_callback (libgio-2.0.so.0)#012#4
0x00007fbd5229229a ik_source_dispatch (libgio-2.0.so.0)#012#5
0x00007fbd51c64b77 g_main_context_dispatch (libglib-2.0.so.0)#012#6
0x00007fbd51c64f20 g_main_context_iterate.isra.23 (libglib-2.0.so.0)#012#7
0x00007fbd51c64fac g_main_context_iteration (libglib-2.0.so.0)#012#8
0x00007fbd51c64ff1 glib_worker_main (libglib-2.0.so.0)#012#9
0x00007fbd51c8c486 g_thread_proxy (libglib-2.0.so.0)#012#10
0x00007fbd5093761b start_thread (libpthread.so.0)#012#11 0x00007fbd5066498f
__clone (libc.so.6)#012#012Stack trace of thread 12192:#012#0
0x00007fbd506583db __poll (libc.so.6)#012#1  0x00007fbd51c64e99
g_main_context_iterate.isra.23 (libglib-2.0.so.0)#012#2  0x00007fbd51c64fac
g_main_context_iteration (libglib-2.0.so.0)#012#3  0x00007fbd4079442d
dconf_gdbus_worker_thread (libdconfsettings.so)#012#4  0x00007fbd51c8c486
g_thread_proxy (libglib-2.0.so.0)#012#5  0x00007fbd5093761b start_thread
(libpthread.so.0)#012#6  0x00007fbd5066498f __clone
(libc.so.6)#012#012Stack trace of thread 12370:#012#0  0x00007fbd5065ebf9
syscall (libc.so.6)#012#1  0x00007fbd51caa62a g_cond_wait_until
(libglib-2.0.so.0)#012#2  0x00007fbd51c39381
g_async_queue_pop_intern_unlocked (libglib-2.0.so.0)#012#3
0x00007fbd51c8ce24 g_thread_pool_thread_proxy (libglib-2.0.so.0)#012#4
0x00007fbd51c8c486 g_thread_proxy (libglib-2.0.so.0)#012#5
0x00007fbd5093761b start_thread (libpthread.so.0)#012#6  0x00007fbd5066498f
__clone (libc.so.6)#012#012Stack trace of thread 12182:#012#0
0x00007fbd506583db __poll (libc.so.6)#012#1  0x00007fbd51c64e99
g_main_context_iterate.isra.23 (libglib-2.0.so.0)#012#2  0x00007fbd51c65232
g_main_loop_run (libglib-2.0.so.0)#012#3  0x00007fbd5224db56
gdbus_shared_thread_func (libgio-2.0.so.0)#012#4  0x00007fbd51c8c486
g_thread_proxy (libglib-2.0.so.0)#012#5  0x00007fbd5093761b start_thread
(libpthread.so.0)#012#6  0x00007fbd5066498f __clone (libc.so.6)
Feb 18 21:39:04 ourserver baloo_file[3418]: QObject::connect: invalid null
parameter
Feb 18 21:39:04 ourserver baloo_file[5557]: QObject::connect: invalid null
parameter
Feb 18 21:39:05 ourserver baloo_file[18750]: QObject::connect: invalid null
parameter
Feb 18 21:39:05 ourserver baloo_file[17852]: QObject::connect: invalid null
parameter
Feb 18 21:39:06 ourserver dbus-daemon[892]: [system] Failed to activate
service 'org.bluez': timed out (service_start_timeout=25000ms)
Feb 18 21:39:08 ourserver python3[12179]: detected unhandled Python
exception in '/bin/blueman-applet'
Feb 18 21:39:21 ourserver dbus-daemon[892]: [system] Activating service
name='org.mate.SettingsDaemon.DateTimeMechanism' requested by ':1.14131'
(uid=6675 pid=12336 comm="/usr/libexec/mate-panel/clock-applet ") (using
servicehelper)
Feb 18 21:39:21 ourserver dbus-daemon[892]: [system] Successfully activated
service 'org.mate.SettingsDaemon.DateTimeMechanism'
Feb 18 21:39:36 ourserver abrt-notification[12723]: Process 11928 (caja)
crashed in gdk_x_error()
Feb 18 21:39:36 ourserver abrt-server[12509]: Deleting problem directory
Python3-2018-02-18-21:39:08-12179 (dup of Python3-2018-02-15-18:40:16-3479)
Feb 18 21:39:37 ourserver abrt-notification[12735]: Process 3479
(blueman-applet) of user 6675 encountered an uncaught GLib.GError exception
Feb 18 21:41:02 ourserver automount[31776]: add_host_addrs: hostname lookup
failed: No address associated with hostname
Feb 18 21:41:43 ourserver PackageKit[15297]: search-file transaction
/12276_bcdacbee from uid 6675 finished with success after 408ms
Feb 18 21:45:50 ourserver baloo_file[5557]: QObject::connect: invalid null
parameter
Feb 18 21:45:51 ourserver baloo_file[17852]: QObject::connect: invalid null
parameter
Feb 18 21:45:51 ourserver baloo_file[3418]: QObject::connect: invalid null
parameter
Feb 18 21:45:51 ourserver baloo_file[18750]: QObject::connect: invalid null
parameter
Feb 18 21:46:01 ourserver /usr/bin/x2gosuspend-session[14346]: session with
ID ouruser-327-1519007899_stDMATE_dp32 has been suspended successfully
Feb 18 21:46:02 ourserver systemd-logind[1945]: Removed session 4273.
Feb 18 21:46:02 ourserver systemd[1]: Stopping User Manager for UID 6675...

I figured I'd include what I could get from a gdb on the Mate core file:
warning: core file may not match specified executable file.
Reading symbols from /usr/libexec/mate-notification-daemon...Reading
symbols from
/usr/lib/debug/usr/libexec/mate-notification-daemon-1.19.1-1.fc27.x86_64.debug...done.
done.
warning: Ignoring non-absolute filename: <linux-vdso.so.1>
Missing separate debuginfo for linux-vdso.so.1
Try: dnf --enablerepo='*debug*' install
/usr/lib/debug/.build-id/34/aef3552ea0558533a32c64cecbea32c5a96c52
Missing separate debuginfo for /lib64/libwayland-egl.so.1
Try: dnf --enablerepo='*debug*' install
/usr/lib/debug/.build-id/34/03db48ea562a74e13d645554fe90b7cbdb138f

warning: .dynamic section for "/lib64/libwayland-egl.so.1" is not at the
expected address (wrong library or version mismatch?)
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/usr/libexec/mate-notification-daemon'.
Program terminated with signal SIGTRAP, Trace/breakpoint trap.
#0  _g_log_abort (breakpoint=breakpoint@entry=1) at gmessages.c:554
554 }

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

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

From: Mihai Moldovan <ionic@ionic.de>

To: Robert Kudyba <rkudyba@fordham.edu>, 1260@bugs.x2go.org

Subject: Re: [X2Go-Dev] high CPU usage with Fedora 27 and users that disconnect, Caja and Mate crash/coredump

Date: Mon, 5 Mar 2018 08:51:00 +0100

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

Control: forwarded -1 https://github.com/ArcticaProject/nx-libs/issues/671
Control: severity -1 grave

* On 02/20/2018 04:46 PM, Robert Kudyba wrote:
> Package: x2goserver-4.1.0.1-0.0x2go1.0.git20180218.1532.heuler.fc27.x86_64
> Version: 4.1.0.1-0
> 
> We experience a high load after users disconnect. The logs the follow below
> indicate that Caja and Mate crash.

Can reproduce on Debian Unstable with current X2Go Stable packages.

Forwarded to https://github.com/ArcticaProject/nx-libs/issues/671



Mihai

[signature.asc (application/pgp-signature, attachment)]

Send a report that this bug log contains spam.