User session started before user login, why?

kokoko3k · 2022-04-28 11:42:10

Hi use a script that sends me notifications via kdialog and notify-send.
As per wiki, "Systemd provides a script in /etc/X11/xinit/xinitrc.d/50-systemd-user.sh to import those variables into the systemd user session on X launch. "
That file is present and executable.
I use plasma and sddm with autologin.

Errors on interacting with X

koko@Gozer# systemctl --user status check.hosts
● check.hosts.service - Tiene aggiornata una lista con lo stato di alcuni host controllati
     Loaded: loaded (/home/koko/.config/systemd/user/check.hosts.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2022-04-28 12:47:55 CEST; 47min ago
   Main PID: 795 (check_hosts.sh)
      Tasks: 2 (limit: 19035)
     Memory: 1.8M
        CPU: 4.083s
     CGroup: /user.slice/user-1012.slice/user@1012.service/app.slice/check.hosts.service
             ├─  795 /bin/bash /home/koko/scripts/check_hosts/check_hosts.sh
             └─36382 sleep 60

apr 28 12:48:49 Gozer check_hosts.sh[795]: Init SlimertVpn
apr 28 12:49:01 Gozer check_hosts.sh[795]: SlimertVpn Down
apr 28 12:49:01 Gozer check_hosts.sh[795]: Init www.google.it:80
apr 28 12:49:02 Gozer check_hosts.sh[795]: Init RouterCasa:8981
apr 28 12:50:24 Gozer check_hosts.sh[795]: PitVpn Up
apr 28 12:50:26 Gozer check_hosts.sh[795]: MammatVpn Up
apr 28 13:00:24 Gozer check_hosts.sh[795]: Proxy:3128 Down
apr 28 13:00:24 Gozer kdialog[12575]: This application failed to start because no Qt platform plugin could be initialized. Reinstalling the application may fix this problem.
                                      
                                      Available platform plugins are: eglfs, linuxfb, minimal, minimalegl, offscreen, vnc, wayland-egl, wayland, wayland-xcomposite-egl, wayland-xcomposite-glx, xcb.
apr 28 13:00:26 Gozer check_hosts.sh[795]: /home/koko/scripts/check_hosts/check_hosts.sh: riga 43: 12568 Annullato               timeout 3600 kdialog --sorry "$NOW:\n$HOST_LOCAL Down" --title "Check Host:"

No DISPLAY or XAUTHORITY set:

koko@Gozer# strings /proc/795/environ
HOME=/home/koko
KWIN_DRM_NO_AMS=1
KWIN_TRIPLE_BUFFER=0
LANG=it_IT.utf8
LANGUAGE=it_IT.UTF-8
LC_COLLATE=C
LOGNAME=koko
MAIL=/var/spool/mail/koko
PATH=/usr/local/bin:/usr/bin
QT_GRAPHICSSYSTEM=raster
QT_LOGGING_RULES=*=false
SAL_USE_VCLPLUGIN=gtk
SHELL=/bin/bash
SYSTEMD_EXEC_PID=795
USER=koko
XDG_DATA_DIRS=/home/koko/.local/share/flatpak/exports/share:/var/lib/flatpak/exports/share:/usr/local/share/:/usr/share/
XDG_DESKTOP_DIR=/home/koko/Desktop
XDG_RUNTIME_DIR=/run/user/1012
__GLVND_DISALLOW_PATCHING=1
__GLX_VENDOR_LIBRARY_NAME=amber
__GL_ExperimentalPerfStrategy=1
DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1012/bus
MANAGERPID=717
INVOCATION_ID=f36ab0913e1e43a88aa136943b98be63
JOURNAL_STREAM=8:24861

From the following, given the errors on the .desktop files, I assume that the user service has been started *after* the graphical session.

koko@Gozer# journalctl -b --user
apr 28 12:47:55 Gozer systemd-xdg-autostart-generator[746]: /home/koko/.config/autostart/jdsp-gui.desktop:13: Unknown key name 'TerminalOptions' in section 'Desktop Entry', ignoring.
apr 28 12:47:55 Gozer systemd-xdg-autostart-generator[746]: /home/koko/.config/autostart/higgins.desktop:15: Unknown key name 'TerminalOptions' in section 'Desktop Entry', ignoring.
apr 28 12:47:55 Gozer systemd-xdg-autostart-generator[746]: Exec binary 'start-pulseaudio-kde' does not exist: No such file or directory
apr 28 12:47:55 Gozer systemd-xdg-autostart-generator[746]: Not generating service for XDG autostart app-pulseaudio\x2dkde.desktop.ori@autostart.service, error parsing Exec= line: No such file or directory
apr 28 12:47:55 Gozer systemd-xdg-autostart-generator[746]: Exec binary 'start-pulseaudio-x11' does not exist: No such file or directory
apr 28 12:47:55 Gozer systemd-xdg-autostart-generator[746]: Not generating service for XDG autostart app-pulseaudio.desktop.ori@autostart.service, error parsing Exec= line: No such file or directory
apr 28 12:47:55 Gozer systemd[717]: Queued start job for default target Main User Target.
apr 28 12:47:55 Gozer systemd[717]: Created slice User Application Slice.
apr 28 12:47:55 Gozer systemd[717]: Started Notifiche mattutine.
apr 28 12:47:55 Gozer systemd[717]: Reached target Paths.
apr 28 12:47:55 Gozer systemd[717]: Reached target Timers.
apr 28 12:47:55 Gozer systemd[717]: Starting D-Bus User Message Bus Socket...
apr 28 12:47:55 Gozer systemd[717]: Listening on GnuPG network certificate management daemon.
apr 28 12:47:55 Gozer systemd[717]: Listening on GCR ssh-agent wrapper.
apr 28 12:47:55 Gozer systemd[717]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
apr 28 12:47:55 Gozer systemd[717]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
apr 28 12:47:55 Gozer systemd[717]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
apr 28 12:47:55 Gozer systemd[717]: Listening on GnuPG cryptographic agent and passphrase cache.
apr 28 12:47:55 Gozer systemd[717]: Listening on p11-kit server.
apr 28 12:47:55 Gozer systemd[717]: Listening on PipeWire PulseAudio.
apr 28 12:47:55 Gozer systemd[717]: Listening on PipeWire Multimedia System Socket.
apr 28 12:47:55 Gozer systemd[717]: Listening on D-Bus User Message Bus Socket.
apr 28 12:47:55 Gozer systemd[717]: Reached target Sockets.
apr 28 12:47:55 Gozer systemd[717]: Reached target Basic System.
apr 28 12:47:55 Gozer systemd[717]: Started Beep quando l'ups dei server si sta scaricando.
apr 28 12:47:55 Gozer systemd[717]: Started Tiene aggiornata una lista con lo stato di alcuni host controllati. # <-<-<-<-<-<-<----- USER SERVICE I'M TALKING ABOUT
apr 28 12:47:55 Gozer systemd[717]: Started rimuove ",Regular" da kdeglobals per far vedere lo stile Bold....
apr 28 12:47:55 Gozer systemd[717]: Started telegram shell bot.
apr 28 12:47:55 Gozer check_hosts.sh[795]: Init Infservbio
apr 28 12:47:55 Gozer systemd[717]: Started unison sync a pi.
apr 28 12:47:55 Gozer systemd[717]: Starting Update XDG user dir configuration...
apr 28 12:47:55 Gozer systemd[717]: Finished Update XDG user dir configuration.
apr 28 12:47:55 Gozer systemd[717]: Reached target Main User Target.
apr 28 12:47:55 Gozer systemd[717]: Startup finished in 237ms.

...but if i manually restart it from the graphical session, all is good:

koko@Gozer# systemctl --user restart check.hosts

koko@Gozer# systemctl --user status check.hosts|grep PID
   Main PID: 39306 (check_hosts.sh)

koko@Gozer# strings /proc/39306/environ|grep 'XAUTHORITY\|DISPLAY'
DISPLAY=:0
XAUTHORITY=/home/koko/.Xauthority

Is it a race condition? How to debug?

Thanks!

Last edited by kokoko3k (2022-04-28 12:34:49)

kokoko3k · 2022-04-28 12:02:01

I manually modified /etc/X11/xinit/xinitrc.d/50-systemd-user.sh to include a: touch /tmp/50-systemd-user.executed and rebooted.
Indeed the file was there, so it get executed.

koko@Gozer# ls -la --full-time /tmp/50-systemd-user.executed 
-rw-r--r-- 1 koko koko 0 2022-04-28 13:57:22.951445800 +0200 /tmp/50-systemd-user.executed

koko@Gozer# systemctl --user status check.hosts |grep since
     Active: active (running) since Thu 2022-04-28 13:57:21 CEST; 3min 48s ago

So... the user service starts before /etc/X11/xinit/xinitrc.d/50-systemd-user.sh

edit
I restarted without logging in as the user, but as root, and i verified that the user services are running, so somehow an user session is started, even if loginctl|grep koko returns nothing.

Here it is (I'm UID 1012):

root@Gozer# journalctl -b|grep "session opened for user koko" -B50 -A10
apr 28 14:12:07 Gozer dnsmasq[637]: DBus support enabled: connected to system bus
apr 28 14:12:07 Gozer dnsmasq[637]: using nameserver 192.168.117.243#53 for domain #omissis#
apr 28 14:12:07 Gozer dnsmasq[637]: reading /etc/resolv.conf
apr 28 14:12:07 Gozer dnsmasq[637]: using nameserver 192.168.117.243#53 for domain #omissis#
apr 28 14:12:07 Gozer dnsmasq[637]: ignoring nameserver 127.0.0.1 - local interface
apr 28 14:12:07 Gozer dnsmasq[637]: using nameserver 1.1.1.1#53
apr 28 14:12:07 Gozer dnsmasq[637]: using nameserver 8.8.8.8#53
apr 28 14:12:07 Gozer dnsmasq[637]: using nameserver #omissis##53
apr 28 14:12:07 Gozer dnsmasq[637]: using nameserver #omissis##53
apr 28 14:12:07 Gozer dnsmasq[637]: read /etc/hosts - 53 addresses
apr 28 14:12:07 Gozer systemd[1]: Started User Login Management.
apr 28 14:12:07 Gozer systemd-udevd[269]: Using default interface naming scheme 'v250'.
apr 28 14:12:07 Gozer systemd[1]: Created slice Slice /system/netctl.
apr 28 14:12:07 Gozer systemd[1]: Created slice User Slice of UID 0.
apr 28 14:12:07 Gozer systemd[1]: Created slice User Slice of UID 1012.
apr 28 14:12:07 Gozer systemd[1]: Starting Networking for netctl profile ##Omissis#
apr 28 14:12:07 Gozer systemd[1]: Started Simple Desktop Display Manager.
apr 28 14:12:07 Gozer systemd[1]: Starting User Runtime Directory /run/user/0...
apr 28 14:12:07 Gozer systemd[1]: Starting User Runtime Directory /run/user/1012...
apr 28 14:12:07 Gozer rc.local[693]: 604 (process ID) old priority 0, new priority 19
apr 28 14:12:07 Gozer tor[688]: Apr 28 14:12:07.993 [notice] Tor 0.4.6.10 running on Linux with Libevent 2.1.12-stable, OpenSSL 1.1.1n, Zlib 1.2.12, Liblzma 5.2.5, Libzstd 1.5.2 and Glibc 2.35 as libc.
apr 28 14:12:07 Gozer tor[688]: Apr 28 14:12:07.993 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://support.torproject.org/faq/staying-anonymous/
apr 28 14:12:07 Gozer tor[688]: Apr 28 14:12:07.997 [notice] Read configuration file "/etc/tor/torrc".
apr 28 14:12:08 Gozer systemd[1]: Finished User Runtime Directory /run/user/0.
apr 28 14:12:08 Gozer systemd[1]: Finished User Runtime Directory /run/user/1012.
apr 28 14:12:08 Gozer systemd[1]: Starting User Manager for UID 0...
apr 28 14:12:08 Gozer systemd[1]: Starting User Manager for UID 1012...
apr 28 14:12:08 Gozer tor[688]: Configuration was valid
apr 28 14:12:08 Gozer network[691]: Starting network profile 'wifi_unina'...
apr 28 14:12:08 Gozer tor[704]: Apr 28 14:12:08.016 [notice] Tor 0.4.6.10 running on Linux with Libevent 2.1.12-stable, OpenSSL 1.1.1n, Zlib 1.2.12, Liblzma 5.2.5, Libzstd 1.5.2 and Glibc 2.35 as libc.
apr 28 14:12:08 Gozer tor[704]: Apr 28 14:12:08.016 [notice] Tor can't help you if you use it wrong! Learn how to be safe at https://support.torproject.org/faq/staying-anonymous/
apr 28 14:12:08 Gozer tor[704]: Apr 28 14:12:08.016 [notice] Read configuration file "/etc/tor/torrc".
apr 28 14:12:08 Gozer tor[704]: Apr 28 14:12:08.017 [notice] Opening Socks listener on 127.0.0.1:9050
apr 28 14:12:08 Gozer tor[704]: Apr 28 14:12:08.017 [notice] Opened Socks listener connection (ready) on 127.0.0.1:9050
apr 28 14:12:08 Gozer Tor[704]: We compiled with OpenSSL 101010ef: OpenSSL 1.1.1n  15 Mar 2022 and we are running with OpenSSL 101010ef: 1.1.1n. These two versions should be binary compatible.
apr 28 14:12:08 Gozer Tor[704]: Tor 0.4.6.10 running on Linux with Libevent 2.1.12-stable, OpenSSL 1.1.1n, Zlib 1.2.12, Liblzma 5.2.5, Libzstd 1.5.2 and Glibc 2.35 as libc.
apr 28 14:12:08 Gozer Tor[704]: Tor can't help you if you use it wrong! Learn how to be safe at https://support.torproject.org/faq/staying-anonymous/
apr 28 14:12:08 Gozer Tor[704]: Read configuration file "/etc/tor/torrc".
apr 28 14:12:08 Gozer Tor[704]: Opening Socks listener on 127.0.0.1:9050
apr 28 14:12:08 Gozer Tor[704]: Opened Socks listener connection (ready) on 127.0.0.1:9050
apr 28 14:12:08 Gozer Tor[704]: Parsing GEOIP IPv4 file /usr/share/tor/geoip.
apr 28 14:12:08 Gozer kernel: Generic FE-GE Realtek PHY r8169-0-300:00: attached PHY driver (mii_bus:phy_addr=r8169-0-300:00, irq=MAC)
apr 28 14:12:08 Gozer dbus-daemon[592]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.5' (uid=0 pid=703 comm="(systemd)")
apr 28 14:12:08 Gozer dbus-daemon[592]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
apr 28 14:12:08 Gozer systemd[703]: pam_systemd_home(systemd-user:account): systemd-homed is not available: Unit dbus-org.freedesktop.home1.service not found.
apr 28 14:12:08 Gozer systemd[703]: pam_warn(systemd-user:setcred): function=[pam_sm_setcred] flags=0x8002 service=[systemd-user] terminal=[] user=[koko] ruser=[<unknown>] rhost=[<unknown>]
apr 28 14:12:08 Gozer systemd[702]: pam_warn(systemd-user:setcred): function=[pam_sm_setcred] flags=0x8002 service=[systemd-user] terminal=[] user=[root] ruser=[<unknown>] rhost=[<unknown>]
apr 28 14:12:08 Gozer dbus-daemon[592]: [system] Activating via systemd: service name='org.freedesktop.ColorManager' unit='colord.service' requested by ':1.6' (uid=0 pid=586 comm="/usr/bin/cupsd -l")
apr 28 14:12:08 Gozer systemd[1]: Starting Manage, Install and Generate Color Profiles...
apr 28 14:12:08 Gozer systemd[702]: pam_unix(systemd-user:session): session opened for user root(uid=0) by (uid=0)
apr 28 14:12:08 Gozer systemd[703]: pam_unix(systemd-user:session): session opened for user koko(uid=1012) by (uid=0)
apr 28 14:12:08 Gozer systemd[703]: pam_env(systemd-user:session): deprecated reading of user environment enabled
apr 28 14:12:08 Gozer systemd[702]: pam_env(systemd-user:session): deprecated reading of user environment enabled
apr 28 14:12:08 Gozer sddm[692]: Initializing...
apr 28 14:12:08 Gozer sddm[692]: Starting...
apr 28 14:12:08 Gozer sddm[692]: Logind interface found
apr 28 14:12:08 Gozer Tor[704]: Parsing GEOIP IPv6 file /usr/share/tor/geoip6.
apr 28 14:12:08 Gozer sddm[692]: Adding new display on vt 7 ...
apr 28 14:12:08 Gozer dbus-daemon[592]: [system] Successfully activated service 'org.freedesktop.ColorManager'
apr 28 14:12:08 Gozer systemd[1]: Started Manage, Install and Generate Color Profiles.
apr 28 14:12:08 Gozer sddm[692]: Loading theme configuration from ""

I've no clue why it is started :-)

Last edited by kokoko3k (2022-04-28 12:31:33)

Arch Linux

#1 2022-04-28 11:42:10

User session started before user login, why?

#2 2022-04-28 12:02:01

Re: User session started before user login, why?

Board footer