New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"pam_systemd(login:session): Failed to create session: Connection timed out" on boot (pam_systemd should use a much longer timeout for the OpenSession bus call, since it starts the --user systemd instance which might block for a long time) #2863

Closed
Sohalt opened this Issue Mar 18, 2016 · 26 comments

Comments

@Sohalt

Sohalt commented Mar 18, 2016

Submission type

  • Bug report
  • Request for enhancement (RFE)

systemd version the issue has been seen with

229

Used distribution

ArchLinux 64bit

In case of bug report: Expected behaviour you didn't see

normal execution of systemd-logind (setup of $XDG_SESSION, $XDG_VTNR, etc)

In case of bug report: Unexpected behaviour you saw

login on the tty takes unexpectedly long (I don't use a dm) and then drops me into the tty instead of starting Xorg. This is because $XDG_VTNR is not set and I start Xorg with [[ -z $DISPLAY && $XDG_VTNR -eq 1 ]] && startx ]]. The journal says login[608]: pam_systemd(login:session): Failed to create session: Connection timed out directly before login[608]: LOGIN ON tty1 BY sohalt.
When I switch to tty2 and log in there $XDG_VTNR is correctly set to 2. Switching back to tty1 logging out and logging in again also sets the correct variables on tty1.

In case of bug report: Steps to reproduce the problem

The problem only occurs when I enable a user service that starts Emacs in daemon mode and then don't log in immediately after the login prompt appears (i.e. wait ~10sec). When I disable the Emacs unit I can login without problems even after waiting some time.

@poettering

This comment has been minimized.

Member

poettering commented Apr 15, 2016

this suggests there's a problem with dbus/logind, so that pam_systemd can't properly communicate with logind.

Do you see anything relevant in the logs regarding this?

@uatach

This comment has been minimized.

uatach commented May 26, 2016

I'm having a similar problem, I also use systemd version 229, login takes a long time and sometimes user@ service fails

@whxvd

This comment has been minimized.

whxvd commented Jun 25, 2016

There is a simple way to reproduce the problem or a similar one. I am running an up to date Arch Linux for x86_64 with systemd 230. I ran into the problem with profile-sync-daemon (psd), which currently takes slightly more than 25 seconds to start on my computer.

Without psd the problem can be reproduced as follows:

  • Create ~/.config/systemd/user/sleep.service:
[Unit]
Description = Sleep for some time

[Service]
Type        = oneshot
ExecStart   = /usr/sbin/sleep 30

[Install]
WantedBy    = default.target
  • Enable:
systemctl --user enable sleep
  • Reboot.
  • Log in.

Then the journal contains something like:

Jun 25 22:53:08 tisch login[330]: pam_succeed_if(login:auth): requirement "user = w" was met by user "w"
Jun 25 22:53:08 tisch login[330]: pam_unix(login:session): session opened for user w by LOGIN(uid=0)
Jun 25 22:53:08 tisch systemd[1]: Created slice User Slice of w.
Jun 25 22:53:08 tisch systemd[1]: Starting User Manager for UID 1000...
Jun 25 22:53:08 tisch systemd-logind[308]: New session c1 of user w.
Jun 25 22:53:08 tisch systemd[1]: Started Session c1 of user w.
Jun 25 22:53:08 tisch systemd[401]: pam_unix(systemd-user:session): session opened for user w by (uid=0)
Jun 25 22:53:08 tisch systemd[401]: Starting D-Bus User Message Bus Socket.
Jun 25 22:53:08 tisch systemd[401]: Reached target Paths.
Jun 25 22:53:08 tisch systemd[401]: Listening on Sound System.
Jun 25 22:53:08 tisch systemd[401]: Reached target Timers.
Jun 25 22:53:08 tisch systemd[401]: Listening on D-Bus User Message Bus Socket.
Jun 25 22:53:08 tisch systemd[401]: Reached target Sockets.
Jun 25 22:53:08 tisch systemd[401]: Reached target Basic System.
Jun 25 22:53:08 tisch systemd[401]: Starting Sleep for some time...
Jun 25 22:53:08 tisch systemd[401]: Starting Update XDG user dir configuration...
Jun 25 22:53:09 tisch systemd[401]: Started Update XDG user dir configuration.
Jun 25 22:53:22 tisch systemd-timesyncd[298]: Synchronized to time server 91.198.10.4:123 (2.arch.pool.ntp.org).
Jun 25 22:53:33 tisch login[330]: pam_systemd(login:session): Failed to create session: Connection timed out
Jun 25 22:53:33 tisch login[330]: LOGIN ON tty1 BY w
Jun 25 22:53:38 tisch systemd[401]: Started Sleep for some time.
Jun 25 22:53:38 tisch systemd[401]: Reached target Default.
Jun 25 22:53:38 tisch systemd[401]: Startup finished in 30.487s.
Jun 25 22:53:38 tisch systemd[1]: Started User Manager for UID 1000.

The pam_systemd(login:session): Failed to create session: Connection timed out seems to always happen exactly 25 seconds after the authentication succeeds.

I see nothing about

dbus/logind, so that pam_systemd can't properly communicate with
logind.

@arvidjaar

This comment has been minimized.

Contributor

arvidjaar commented Jun 26, 2016

always happen exactly 25 seconds after the authentication succeeds

Yes, this is default timeout for D-Bus calls in sd-bus library. pam_systemd calls into logind via D-Bus and hits timeout.

It is not clear whether logind session must wait for user instance to complete launch. After all, user instance is entirely optional and may not even exist.

@Lekensteyn

This comment has been minimized.

Contributor

Lekensteyn commented Oct 8, 2016

I could reproduce the delay in this way on Arch Linux (systemd 231-4) in a QEMU VM:

[root@builder ~]# ps aux | grep -v '0:00 \['
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.4  0.0  52876  6472 ?        Ss   12:29   0:00 /sbin/init
root      2105  0.1  0.0  52624  6772 ?        Ss   12:30   0:00 /usr/lib/systemd/systemd-journald
root      2130  0.4  0.0  35908  3792 ?        Ss   12:30   0:00 /usr/lib/systemd/systemd-udevd
root      2199  0.0  0.0  38440  4528 ?        Ss   12:30   0:00 /usr/lib/systemd/systemd-logind
dbus      2206  0.0  0.0  32884  3176 ?        Ss   12:30   0:00 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
root      2209  0.0  0.0  90108  4172 ?        Ss   12:30   0:00 login -- root
root      2211  0.0  0.0  90108  4212 ?        Ss   12:30   0:00 login -- root
root      2256  0.0  0.0  52424  6088 ?        Ss   12:30   0:00 /usr/lib/systemd/systemd --user
root      2267  0.0  0.0  98456  1428 ?        S    12:30   0:00 (sd-pam)
root      2278  0.0  0.0  14112  3152 ttyS0    Ss   12:30   0:00 -bash
root      2288  0.0  0.0  14112  2528 tty1     Ss+  12:31   0:00 -bash
root      2294  0.0  0.0  32852  2748 ttyS0    R+   12:31   0:00 ps aux
root      2295  0.0  0.0   8996   924 ttyS0    S+   12:31   0:00 grep -v 0:00 \[
[root@builder ~]# journalctl -af
-- Logs begin at Sat 2016-10-08 12:30:39 CEST. --
Oct 08 12:30:44 builder systemd[2256]: Reached target Basic System.
Oct 08 12:30:44 builder systemd[2256]: Reached target Default.
Oct 08 12:30:44 builder systemd[2256]: Startup finished in 12ms.
Oct 08 12:30:44 builder systemd[1]: Started User Manager for UID 0.
Oct 08 12:30:44 builder login[2211]: DIALUP AT ttyS0 BY root
Oct 08 12:30:44 builder login[2211]: ROOT LOGIN ON ttyS0
Oct 08 12:31:19 builder login[2209]: pam_unix(login:session): session opened for user root by LOGIN(uid=0)
Oct 08 12:31:19 builder systemd-logind[2199]: New session c2 of user root.
Oct 08 12:31:19 builder systemd[1]: Started Session c2 of user root.
Oct 08 12:31:19 builder login[2209]: ROOT LOGIN ON tty1

(ttyS0 has journalctl running, just logged in to ttyS0). In tty1, invoke: echo > /proc/sysrq-trigger e (terminate all tasks).

[  155.223745] systemd[1]: Starting Journal Service...
[  155.227193] systemd[1]: systemd-udevd.service: Service has no hold-off time, scheduling restart.
[  155.232417] systemd[1]: Started Journal Service.

Arch Linux 4.8.1-1-ARCH (ttyS0)

builder login: root

(observe a long delay here)

Last login: Sat Oct  8 12:31:19 on tty1
[root@builder ~]# ps aux | grep -v '0:00 \['
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.3  0.0  52876  6604 ?        Ss   12:29   0:00 /sbin/init
root      2301  0.0  0.0  44424  5144 ?        Ss   12:31   0:00 /usr/lib/systemd/systemd-journald
root      2308  0.0  0.0  35112  3056 ?        Ss   12:31   0:00 /usr/lib/systemd/systemd-udevd
dbus      2309  0.0  0.0  32884  3124 ?        Ss   12:31   0:00 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
root      2322  0.0  0.0  38520  4552 ?        Ss   12:31   0:00 /usr/lib/systemd/systemd-logind
root      2345  0.0  0.0   6332  1476 tty1     Ss+  12:31   0:00 /sbin/agetty --noclear tty1 linux
root      2349  0.0  0.0  90104  4232 ?        Ss   12:31   0:00 login -- root
root      2366  0.0  0.0  14112  3152 ttyS0    Ss   12:32   0:00 -bash
root      2374  0.0  0.0  32852  2696 ttyS0    R+   12:32   0:00 ps aux
root      2375  0.0  0.0   8996   840 ttyS0    S+   12:32   0:00 grep -v 0:00 \[
[root@builder ~]# journalctl -af --since=12:31:19
-- Logs begin at Sat 2016-10-08 12:30:39 CEST. --
Oct 08 12:31:19 builder login[2209]: pam_unix(login:session): session opened for user root by LOGIN(uid=0)
Oct 08 12:31:19 builder systemd-logind[2199]: New session c2 of user root.
Oct 08 12:31:19 builder systemd[1]: Started Session c2 of user root.
Oct 08 12:31:19 builder login[2209]: ROOT LOGIN ON tty1
Oct 08 12:31:38 builder systemd-journald[2105]: Journal stopped
Oct 08 12:31:38 builder systemd-journald[2301]: System journal (/var/log/journal/) is 8.0M, max 639.0M, 631.0M free.
Oct 08 12:31:38 builder kernel: sysrq: SysRq : Terminate All Tasks
Oct 08 12:31:38 builder systemd-journald[2105]: Received SIGTERM.
Oct 08 12:31:38 builder systemd[1]: systemd-journald.service: Service has no hold-off time, scheduling restart.
Oct 08 12:31:38 builder systemd[1]: Stopped Flush Journal to Persistent Storage.
Oct 08 12:31:38 builder systemd[1]: Stopping Flush Journal to Persistent Storage...
Oct 08 12:31:38 builder systemd[1]: Stopped Journal Service.
Oct 08 12:31:38 builder systemd[1]: Starting Journal Service...
Oct 08 12:31:38 builder systemd[1]: systemd-udevd.service: Service has no hold-off time, scheduling restart.
Oct 08 12:31:38 builder systemd-journald[2301]: Journal started
Oct 08 12:31:38 builder systemd[2256]: Stopped target Default.
Oct 08 12:31:38 builder login[2209]: pam_unix(login:session): session closed for user root
Oct 08 12:31:38 builder systemd[2256]: Stopped target Basic System.
Oct 08 12:31:38 builder login[2211]: pam_unix(login:session): session closed for user root
Oct 08 12:31:38 builder systemd[2256]: Stopped target Timers.
Oct 08 12:31:38 builder systemd[2256]: Stopped target Sockets.
Oct 08 12:31:38 builder systemd[2256]: Closed D-Bus User Message Bus Socket.
Oct 08 12:31:38 builder systemd[2256]: Reached target Shutdown.
Oct 08 12:31:38 builder systemd[2256]: Stopped target Paths.
Oct 08 12:31:38 builder systemd[2256]: Starting Exit the Session...
Oct 08 12:31:38 builder systemd[2256]: Received SIGRTMIN+24 from PID 2300 (kill).
Oct 08 12:31:38 builder systemd[1]: Started Journal Service.
Oct 08 12:31:38 builder systemd[1]: Starting Flush Journal to Persistent Storage...
Oct 08 12:31:38 builder systemd[1]: Stopped udev Kernel Device Manager.
Oct 08 12:31:38 builder systemd[1]: Starting udev Kernel Device Manager...
Oct 08 12:31:38 builder systemd[1]: Started D-Bus System Message Bus.
Oct 08 12:31:38 builder systemd[1]: Failed to subscribe to NameOwnerChanged signal for 'org.freedesktop.login1': Device or resource busy
Oct 08 12:31:38 builder dbus[2309]: [system] Activating systemd to hand-off: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Oct 08 12:31:38 builder dbus[2309]: [system] Successfully activated service 'org.freedesktop.systemd1'
Oct 08 12:31:38 builder systemd[1]: Started udev Kernel Device Manager.
Oct 08 12:31:38 builder systemd[1]: Started Flush Journal to Persistent Storage.
Oct 08 12:31:38 builder systemd[1]: systemd-logind.service: Service has no hold-off time, scheduling restart.
Oct 08 12:31:38 builder systemd[1]: Stopped Login Service.
Oct 08 12:31:38 builder systemd[1]: Starting Login Service...
Oct 08 12:31:38 builder dbus[2309]: [system] Successfully activated service 'org.freedesktop.login1'
Oct 08 12:31:38 builder systemd-logind[2322]: New seat seat0.
Oct 08 12:31:38 builder systemd-logind[2322]: Watching system buttons on /dev/input/event0 (Power Button)
Oct 08 12:31:38 builder systemd-logind[2322]: New session c1 of user root.
Oct 08 12:31:38 builder systemd-logind[2322]: New session c2 of user root.
Oct 08 12:31:38 builder systemd[1]: Starting User Manager for UID 0...
Oct 08 12:31:38 builder systemd[2323]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Oct 08 12:31:38 builder systemd[1]: getty@tty1.service: Service has no hold-off time, scheduling restart.
Oct 08 12:31:38 builder systemd[1]: Stopped Getty on tty1.
Oct 08 12:31:38 builder systemd[1]: Started Getty on tty1.
Oct 08 12:31:38 builder systemd-logind[2322]: Removed session c1.
Oct 08 12:31:38 builder systemd-logind[2322]: Removed session c2.
Oct 08 12:31:38 builder systemd[2323]: Reached target Paths.
Oct 08 12:31:38 builder systemd[2323]: Reached target Timers.
Oct 08 12:31:38 builder systemd[2323]: Starting D-Bus User Message Bus Socket.
Oct 08 12:31:38 builder systemd[2323]: Listening on D-Bus User Message Bus Socket.
Oct 08 12:31:38 builder systemd[2323]: Reached target Sockets.
Oct 08 12:31:38 builder systemd[2323]: Reached target Basic System.
Oct 08 12:31:38 builder systemd[2323]: Reached target Default.
Oct 08 12:31:38 builder systemd[2323]: Startup finished in 16ms.
Oct 08 12:31:39 builder systemd[1]: Started User Manager for UID 0.
Oct 08 12:31:39 builder systemd[1]: serial-getty@ttyS0.service: Service hold-off time over, scheduling restart.
Oct 08 12:31:39 builder systemd[1]: Stopping User Manager for UID 0...
Oct 08 12:31:39 builder systemd[1]: Stopped Serial Getty on ttyS0.
Oct 08 12:31:39 builder systemd[2323]: Stopped target Default.
Oct 08 12:31:39 builder systemd[2323]: Stopped target Basic System.
Oct 08 12:31:39 builder systemd[2323]: Stopped target Timers.
Oct 08 12:31:39 builder systemd[2323]: Stopped target Paths.
Oct 08 12:31:39 builder systemd[2323]: Stopped target Sockets.
Oct 08 12:31:39 builder systemd[1]: Started Serial Getty on ttyS0.
Oct 08 12:31:39 builder systemd[2323]: Closed D-Bus User Message Bus Socket.
Oct 08 12:31:39 builder systemd[2323]: Reached target Shutdown.
Oct 08 12:31:39 builder systemd[2323]: Starting Exit the Session...
Oct 08 12:31:39 builder systemd[2323]: Received SIGRTMIN+24 from PID 2350 (kill).
Oct 08 12:31:39 builder systemd[2336]: pam_unix(systemd-user:session): session closed for user root
Oct 08 12:31:39 builder systemd[1]: Stopped User Manager for UID 0.
Oct 08 12:31:39 builder systemd[1]: Removed slice User Slice of root.
Oct 08 12:31:46 builder login[2349]: pam_unix(login:session): session opened for user root by LOGIN(uid=0)
Oct 08 12:31:46 builder systemd-logind[2322]: New session c1 of user root.
Oct 08 12:32:11 builder login[2349]: pam_systemd(login:session): Failed to create session: Connection timed out
Oct 08 12:32:11 builder login[2349]: DIALUP AT ttyS0 BY root
Oct 08 12:32:11 builder login[2349]: ROOT LOGIN ON ttyS0

[root@builder ~]# systemctl daemon-reexec
[  408.251686] systemd: 47 output lines suppressed due to ratelimiting
[root@builder ~]# ps aux | grep -v '0:00 \[' 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.1  0.0  52836  6432 ?        Ss   12:29   0:00 /usr/lib/systemd/systemd --system --deserialize 43
root      2301  0.0  0.0  44424  5144 ?        Ss   12:31   0:00 /usr/lib/systemd/systemd-journald
root      2308  0.0  0.0  35112  3056 ?        Ss   12:31   0:00 /usr/lib/systemd/systemd-udevd
dbus      2309  0.0  0.0  32884  3124 ?        Ss   12:31   0:00 /usr/bin/dbus-daemon --system --address=systemd: --nofork --nopidfile --systemd-activation
root      2345  0.0  0.0   6332  1476 tty1     Ss+  12:31   0:00 /sbin/agetty --noclear tty1 linux
root      2349  0.0  0.0  90104  4232 ?        Ss   12:31   0:00 login -- root
root      2366  0.0  0.0  14112  3192 ttyS0    Ss   12:32   0:00 -bash
root      2394  0.0  0.0  36320  4524 ?        Ss   12:36   0:00 /usr/lib/systemd/systemd-logind
root      2395  0.0  0.0  52424  5876 ?        Ss   12:36   0:00 /usr/lib/systemd/systemd --user
root      2403  0.0  0.0  98444  1492 ?        S    12:36   0:00 (sd-pam)
root      2413  0.0  0.0  32852  2756 ttyS0    R+   12:36   0:00 ps aux
root      2414  0.0  0.0   8996   844 ttyS0    S+   12:36   0:00 grep -v 0:00 \[
[root@builder ~]# journalctl -af --since=12:34:38
-- Logs begin at Sat 2016-10-08 12:30:39 CEST. --
Oct 08 12:34:38 builder systemd[1]: systemd-logind.service: Start operation timed out. Terminating.
Oct 08 12:34:38 builder systemd[1]: Failed to start Login Service.
Oct 08 12:34:38 builder systemd[1]: systemd-logind.service: Unit entered failed state.
Oct 08 12:34:38 builder systemd[1]: systemd-logind.service: Failed with result 'timeout'.
Oct 08 12:34:38 builder systemd[1]: systemd-logind.service: Service has no hold-off time, scheduling restart.
Oct 08 12:34:38 builder systemd[1]: Stopped Login Service.
Oct 08 12:34:38 builder systemd[1]: Starting Login Service...
Oct 08 12:34:38 builder systemd-logind[2381]: New seat seat0.
Oct 08 12:34:38 builder systemd-logind[2381]: Watching system buttons on /dev/input/event0 (Power Button)
Oct 08 12:34:38 builder systemd-logind[2381]: New session c1 of user root.
Oct 08 12:35:51 builder systemd[1]: Reexecuting.
Oct 08 12:35:51 builder kernel: systemd: 47 output lines suppressed due to ratelimiting
Oct 08 12:35:51 builder systemd[1]: systemd 231 running in system mode. (+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
Oct 08 12:35:51 builder systemd[1]: Detected virtualization qemu.
Oct 08 12:35:51 builder systemd[1]: Detected architecture x86-64.
Oct 08 12:36:08 builder systemd[1]: systemd-logind.service: Start operation timed out. Terminating.
Oct 08 12:36:08 builder systemd[1]: Failed to start Login Service.
Oct 08 12:36:08 builder systemd[1]: systemd-logind.service: Unit entered failed state.
Oct 08 12:36:08 builder systemd[1]: systemd-logind.service: Failed with result 'timeout'.
Oct 08 12:36:08 builder systemd[1]: systemd-logind.service: Service has no hold-off time, scheduling restart.
Oct 08 12:36:08 builder systemd[1]: Stopped Login Service.
Oct 08 12:36:08 builder systemd[1]: Starting Login Service...
Oct 08 12:36:08 builder systemd[1]: Started Login Service.
Oct 08 12:36:08 builder systemd-logind[2394]: New seat seat0.
Oct 08 12:36:08 builder systemd[1]: Created slice User Slice of root.
Oct 08 12:36:08 builder systemd[1]: Starting User Manager for UID 0...
Oct 08 12:36:08 builder systemd[1]: Started Session c1 of user root.
Oct 08 12:36:08 builder systemd-logind[2394]: Watching system buttons on /dev/input/event0 (Power Button)
Oct 08 12:36:08 builder systemd-logind[2394]: New session c1 of user root.
Oct 08 12:36:08 builder systemd[2395]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
Oct 08 12:36:08 builder systemd[2395]: Starting D-Bus User Message Bus Socket.
Oct 08 12:36:08 builder systemd[2395]: Reached target Timers.
Oct 08 12:36:08 builder systemd[2395]: Reached target Paths.
Oct 08 12:36:08 builder systemd[2395]: Listening on D-Bus User Message Bus Socket.
Oct 08 12:36:08 builder systemd[2395]: Reached target Sockets.
Oct 08 12:36:08 builder systemd[2395]: Reached target Basic System.
Oct 08 12:36:08 builder systemd[2395]: Reached target Default.
Oct 08 12:36:08 builder systemd[2395]: Startup finished in 11ms.
Oct 08 12:36:08 builder systemd[1]: Started User Manager for UID 0.
Oct 08 12:36:28 builder login[2345]: pam_unix(login:session): session opened for user root by LOGIN(uid=0)
Oct 08 12:36:28 builder systemd-logind[2394]: New session c2 of user root.
Oct 08 12:36:28 builder systemd[1]: Started Session c2 of user root.
Oct 08 12:36:28 builder login[2345]: ROOT LOGIN ON tty1
Oct 08 12:38:29 builder login[2345]: pam_unix(login:session): session closed for user root
Oct 08 12:38:29 builder systemd[1]: getty@tty1.service: Service has no hold-off time, scheduling restart.
Oct 08 12:38:29 builder systemd[1]: Stopped Getty on tty1.
Oct 08 12:38:29 builder systemd[1]: Started Getty on tty1.
Oct 08 12:38:29 builder systemd-logind[2394]: Removed session c2.
Oct 08 12:38:30 builder login[2432]: pam_unix(login:session): session opened for user root by LOGIN(uid=0)
Oct 08 12:38:30 builder systemd-logind[2394]: New session c3 of user root.
Oct 08 12:38:30 builder systemd[1]: Started Session c3 of user root.
Oct 08 12:38:30 builder login[2432]: ROOT LOGIN ON tty1

Somehow systemctl daemon-reexec helps in this case, but I also had cases where even daemon-reexec had no recovering effect. Killing the systemd --user instance is apparently also sufficient to introduce such delays.

@zabbal

This comment has been minimized.

zabbal commented Nov 3, 2016

Yes, this is default timeout for D-Bus calls in sd-bus library. pam_systemd calls into logind via D-Bus and hits timeout.

Is there a way to configure it in runtime?

It is not clear whether logind session must wait for user instance to complete launch. After all, user instance is entirely optional and may not even exist.

Currently it looks like single "bad" (takes more than 25s to start) unit kills entire user session which is definitely wrong. Even if unit is somewhat misbehaving (which is not the case - even 1min startup should not be an issue) it should have no affect on anything except the unit and its dependencies.

@tidux

This comment has been minimized.

tidux commented Jan 3, 2017

This is still present on systemd 232-6 on Arch x86_64 and thoroughly breaks desktop user sessions that rely on DBus.

@dasJ

This comment has been minimized.

Contributor

dasJ commented Jan 10, 2017

So why does this still need reporter feedback? I can reproduce the problem with the provided sleep.service and it really seems to be a systemd bug.

@FichteFoll

This comment has been minimized.

FichteFoll commented Jan 20, 2017

Took me hours to figure out what was causing my pam_systemd to time out and consequently any systemctl --user calls to fail. Turned out it was my --user mpd.service. I assume it takes ~30s to load my library during which it is still "starting up" and causing the timeout. This was also causing my first login to take 25s before I could do anything.

Is there a way to make it not wait for instances to start up?

@Sohalt

This comment has been minimized.

Sohalt commented Mar 5, 2017

So why does this still need reporter feedback? I can reproduce the problem with the provided sleep.service and it really seems to be a systemd bug.

Do you still need any info from me? I think the issue has pretty much been identified.

@poettering poettering changed the title from "pam_systemd(login:session): Failed to create session: Connection timed out" on boot to "pam_systemd(login:session): Failed to create session: Connection timed out" on boot (pam_systemd should use a much longer timeout for the OpenSession bus call, since it starts the --user systemd instance which might block for a long time) Mar 31, 2017

@lulcat

This comment has been minimized.

lulcat commented Jul 17, 2017

systemctl list-unit-files --user :(
Failed to list unit files: Process org.freedesktop.systemd1 exited with status 1

ye.. I can't precisely for the above reasons ,p but ok, if one has identified an update breaks one of the user files, at least I can figure this out. I got fed up with a lot of these systemd things (mainly arch , not systemd per se), so haven't bothered digging too much. Just moved on.

addendum. what seems like a total meltdown of the old system , was down to a simple user service.. wow. In my case it was a gpg and/or ssh agent user service.

@DirkSchmitt

This comment has been minimized.

DirkSchmitt commented Aug 2, 2017

I have here a similar issue with postgresql
The database is working - but the related user@128.service is failing.

systemd 233
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN default-hierarchy=hybrid

@underhillian

This comment has been minimized.

underhillian commented Aug 9, 2017

I had a similar issue involving a user service running upon login which requires 45 sec or so to complete.

In my case (where nothing else depends on my user service) I was able to resolve the issue by changing the service type from "oneshot" to "simple." I suspect this is related to the documented difference that for a oneshot service "it is expected that the process has to exit before systemd starts follow-up units" whereas for a simple service "systemd will immediately proceed starting follow-up units" but this is only a guess.

@rumpelsepp

This comment has been minimized.

rumpelsepp commented Aug 28, 2017

Same here on debian testing with systemd 234. I can't login into gnome after my laptop has been in suspend to RAM (happens randomly).

Aug 28 09:21:40 kronos gdm-password][27628]: pam_unix(gdm-password:session): session closed for user stefan
Aug 28 09:21:40 kronos /usr/lib/gdm3/gdm-wayland-session[27637]: Unable to register display with display manager
Aug 28 09:21:40 kronos /usr/lib/gdm3/gdm-wayland-session[27637]: Activated service 'org.freedesktop.systemd1' failed: Process org.freedesktop.systemd1 exited with status 1
Aug 28 09:21:40 kronos /usr/lib/gdm3/gdm-wayland-session[27637]: Activating service name='org.freedesktop.systemd1'
Aug 28 09:21:39 kronos gdm-password][27628]: pam_systemd(gdm-password:session): Cannot create session: Already occupied by a session
Aug 28 09:21:39 kronos gdm-password][27628]: pam_unix(gdm-password:session): session opened for user stefan by stefan(uid=0)
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos dbus[670]: [system] Rejected send message, 2 matched rules; type="error", sender=":1.3" (uid=0 pid=733 comm="/lib/systemd/systemd-logind ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.29" (uid=123 pid=1400 comm="/usr/bin/gnome-shell ")
Aug 28 09:21:33 kronos gdm3[1074]: GdmDisplay: display lasted 0,056869 seconds
Aug 28 09:21:33 kronos gdm-password][27477]: pam_unix(gdm-password:session): session closed for user stefan
Aug 28 09:21:33 kronos /usr/lib/gdm3/gdm-wayland-session[27608]: Unable to register display with display manager
Aug 28 09:21:33 kronos /usr/lib/gdm3/gdm-wayland-session[27608]: Activated service 'org.freedesktop.systemd1' failed: Process org.freedesktop.systemd1 exited with status 1
Aug 28 09:21:33 kronos /usr/lib/gdm3/gdm-wayland-session[27608]: Activating service name='org.freedesktop.systemd1'
Aug 28 09:21:32 kronos gdm-password][27477]: pam_systemd(gdm-password:session): Failed to create session: Connection timed out

Does anybody know what's going on here?

@ghost

This comment has been minimized.

ghost commented Aug 28, 2017

systemd 234
+PAM -AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN default-hierarchy=hybrid

Saw this issue while trying to install dunst on my machine.

It is not clear whether logind session must wait for user instance to complete launch. After all, user instance is entirely optional and may not even exist.

Okay, but in a world where people are increasingly relying on the user instance...

@tidux

This comment has been minimized.

tidux commented Aug 31, 2017

@sphaugh I've found that dunst works better when called from the WM's init/rc file, at least for me where I use it in Window Maker or Fluxbox.

@nh2

This comment has been minimized.

nh2 commented Oct 12, 2017

I'm getting this problem, but apparently not on a user session, but on sshd:session:

pam_systemd(sshd:session): Failed to create session: Connection timed out

It delays my first SSH session after boot for 25 seconds.

systemd 234
+PAM +AUDIT -SELINUX +IMA +APPARMOR -SMACK -SYSVINIT +UTMP -LIBCRYPTSETUP +GCRYPT -GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN default-hierarchy=hybrid

See NixOS/nixpkgs#30348 for details.


Is there a way to at least reduce this timeout as a temporary workaround?

@nh2

This comment has been minimized.

nh2 commented Oct 12, 2017

Possibly related?

Edit: Using dbus 1.11.20 didn't change anything for me.

@nh2

This comment has been minimized.

nh2 commented Oct 12, 2017

Is there a way to at least reduce this timeout as a temporary workaround?

To answer some of this myself:

Now, the above is probably obvious for somebody familiar with systemd code, but a more interesting question is:

Should this path even be taken when there's no dbus running on my machine? At least ps doesn't indicate so (on my NixOS server).

nh2 added a commit to nh2/systemd that referenced this issue Oct 12, 2017

nh2 added a commit to nh2/systemd that referenced this issue Oct 12, 2017

@nh2

This comment has been minimized.

nh2 commented Oct 12, 2017

Another suspicion: It might be an entropy issue (tip from @cleverca22):

And a corresponding issue in systemd:

pam_systemd's D-Bus call also times out
Login takes a long time

@nh2

This comment has been minimized.

nh2 commented Oct 12, 2017

Should this path even be taken when there's no dbus running on my machine? At least ps doesn't indicate so

Hmm, I suspect it had crashed? I do have a dbus service set up and on another reboot it's also back in ps.

@nh2

This comment has been minimized.

nh2 commented Oct 12, 2017

Here's a journalctl output for sshd and dbus with debugging enabled, with dbus 1.0.24 which per release notes has a fix for the entropy problem:

https://gist.github.com/nh2/80a57f08b6ee61754bfb52c1d0cee82e

@nh2

This comment has been minimized.

nh2 commented Oct 12, 2017

Am I supposed to see a CreateSession anywhere in the dbus debug output?

It is absent.

keszybz added a commit to keszybz/systemd that referenced this issue Oct 15, 2017

core: in --user mode, report READY=1 as soon as basic.target is reached
When a user logs in, systemd-pam will wait for the user manager instance to
report readiness. We don't need to wait for all the jobs to finish, it
is enough if the basic startup is done and the user manager is responsive.

systemd --user will now send out two READY=1 notifications:
- once with status "Reached basic.target"
- and later the normal one with "Startup finished in ..."
I think this is OK.

Also fixes #2863.
@nh2

This comment has been minimized.

nh2 commented Oct 16, 2017

OK, I've investigated a bit more now.

I found that the problem would only appear when I had an /etc/fstab entry with x-systemd.* options.

When I turned that entry to an equivalent .mount unit with the same options (see here nh2/nixops-gluster-example@67f59bf for an example of such transformation), the pam_systemd(login:session): Failed to create session: Connection timed out disappeared.

Do you have any idea why this could be?

Also, @keszybz do the investigations for your patch linked above explain this, or would they potentially hide this error source if it's a different one?

Also, I have a NixOS+nixops based deployment here that can reliably reproduce this bug. If a systemd developer would find that useful, I can show how to rund it, or set up a deployment and provide login to it.

@fsateler

This comment has been minimized.

Member

fsateler commented Oct 17, 2017

@nh2 your .mount unit does not appear to be equivalent. The linked commit has a typo: the requires = desp should read requires = deps ? Perhaps that is the key difference.

keszybz added a commit to keszybz/systemd that referenced this issue Oct 18, 2017

core: in --user mode, report READY=1 as soon as basic.target is reached
When a user logs in, systemd-pam will wait for the user manager instance to
report readiness. We don't need to wait for all the jobs to finish, it
is enough if the basic startup is done and the user manager is responsive.

systemd --user will now send out a READY=1 notification when either of two
conditions becomes true:
- basic.target/start job is gone,
- the initial transaction is done.

Also fixes #2863.

keszybz added a commit to keszybz/systemd that referenced this issue Oct 19, 2017

core: in --user mode, report READY=1 as soon as basic.target is reached
When a user logs in, systemd-pam will wait for the user manager instance to
report readiness. We don't need to wait for all the jobs to finish, it
is enough if the basic startup is done and the user manager is responsive.

systemd --user will now send out a READY=1 notification when either of two
conditions becomes true:
- basic.target/start job is gone,
- the initial transaction is done.

Also fixes #2863.
@nh2

This comment has been minimized.

nh2 commented Oct 22, 2017

@fsateler You're right about the typo (result of improper cleanup before pushing), but it doesn't make a difference (in fact nixops wouldn't let me deploy this with the typo, it points it out with error: undefined variable ‘desp’).

I've fixed the typo now (updated commit), the problem (commit before) and fix (the commit) remain (I have retested it right now, with this setup it takes me only 5 minutes to reproduce).

poettering added a commit that referenced this issue Oct 24, 2017

core: in --user mode, report READY=1 as soon as basic.target is reach…
…ed (#7102)

When a user logs in, systemd-pam will wait for the user manager instance to
report readiness. We don't need to wait for all the jobs to finish, it
is enough if the basic startup is done and the user manager is responsive.

systemd --user will now send out a READY=1 notification when either of two
conditions becomes true:
- basic.target/start job is gone,
- the initial transaction is done.

Also fixes #2863.

dm0- pushed a commit to dm0-/systemd that referenced this issue Oct 30, 2018

Merge pull request systemd#2863 from coreosbot/master-4.13.10
Upgrade Linux in master to 4.13.10
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment