Suddenly (probably after installing systemd updates this morning) it takes 30 seconds or so for an NIS user to login via ssh and I see this nonsense show up in the log:
Jan 16 14:53:33 tomh systemd-logind[811]: New session 11 of user tom. Jan 16 14:53:33 tomh systemd[1]: Failed to mount /userland. Jan 16 14:53:33 tomh systemd-logind[811]: Session 11 logged out. Waiting for processes to exit. Jan 16 14:53:33 tomh systemd-logind[811]: Removed session 11. Jan 16 14:53:34 tomh systemd[3119]: Listening on Sound System. Jan 16 14:53:34 tomh systemd[3119]: Starting D-Bus User Message Bus Socket. Jan 16 14:53:34 tomh systemd[3119]: Listening on Multimedia System. Jan 16 14:53:34 tomh systemd[3119]: Reached target Paths. Jan 16 14:53:34 tomh systemd[3119]: Started Mark boot as successful after the user session has run 2 minutes. Jan 16 14:53:34 tomh systemd[3119]: Reached target Timers. Jan 16 14:53:34 tomh systemd[3119]: Listening on D-Bus User Message Bus Socket. Jan 16 14:53:34 tomh systemd[3119]: Reached target Sockets. Jan 16 14:53:34 tomh systemd[3119]: Reached target Basic System. Jan 16 14:53:34 tomh systemd[3119]: Starting Sound Service... Jan 16 14:53:34 tomh dbus-daemon[822]: [system] Rejected send message, 2 matched rules; type="method_call", sender=":1.90" (uid=2304 pid=3129 comm="/usr/bin/pulseaudio --daemonize=no ") interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" error name="(unset)" requested_reply="0" destination="org.bluez" (bus) Jan 16 14:53:34 tomh systemd[3119]: Started D-Bus User Message Bus. Jan 16 14:53:34 tomh dbus-daemon[3157]: [session uid=2304 pid=3157] Activating service name='org.gnome.GConf' requested by ':1.1' (uid=2304 pid=3156 comm="/usr/libexec/pulse/gconf-helper ") Jan 16 14:53:34 tomh dbus-daemon[3157]: [session uid=2304 pid=3157] Successfully activated service 'org.gnome.GConf' Jan 16 14:53:34 tomh systemd[3119]: Started Sound Service. Jan 16 14:53:34 tomh pulseaudio[3129]: E: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.AccessDenied: Rejected send message, 2 matched rules; type="method_call", sender=":1.90" (uid=2304 pid=3129 comm="/usr/bin/pulseaudio --daemonize=no ") interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" error name="(unset)" requested_reply="0" destination="org.bluez" (bus) Jan 16 14:53:34 tomh systemd[3119]: Reached target Default. Jan 16 14:53:34 tomh systemd[3119]: Startup finished in 690ms. Jan 16 14:53:44 tomh systemd[3119]: Stopping D-Bus User Message Bus... Jan 16 14:53:44 tomh systemd[3119]: Stopped target Default. Jan 16 14:53:44 tomh systemd[3119]: Stopping Sound Service... Jan 16 14:53:44 tomh systemd[3119]: Stopped D-Bus User Message Bus. Jan 16 14:53:44 tomh systemd[3119]: Stopped Sound Service. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Basic System. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Paths. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Timers. Jan 16 14:53:44 tomh systemd[3119]: Stopped Mark boot as successful after the user session has run 2 minutes. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Sockets. Jan 16 14:53:44 tomh systemd[3119]: Closed Multimedia System. Jan 16 14:53:44 tomh systemd[3119]: Closed D-Bus User Message Bus Socket. Jan 16 14:53:44 tomh systemd[3119]: Closed Sound System. Jan 16 14:53:44 tomh systemd[3119]: Reached target Shutdown. Jan 16 14:53:44 tomh systemd[3119]: Starting Exit the Session... Jan 16 14:53:44 tomh systemd[3119]: Received SIGRTMIN+24 from PID 3179 (kill).
Most of the delay follows that last message. Any idea how to make NIS login work fast again?
If I login as a local user the only message I see is:
Jan 16 15:01:20 tomh systemd-logind[811]: New session 23 of user tweety.
and the login is immediate.
Just to confirm: the NIS user hasn't got a local /etc/passwd entry?
This may not be related to your issue, but I've tripped over systemd failing at NIS recently (not Fedora), and the fix was to make sure nscd was installed. Apparently systemd thinks it can speak NIS, but actually it can't (well, not correctly). By redirecting through ncsd (which happens automatically) our problem went away.
For us it was a local console GUI login aborting soon after login, as systemd's login manager process crashed.
Anyway, installing nscd is trivial and I would be interested to know if it changes the behaviour for you.
Cheers, Cameron Simpson cs@cskk.id.au
On 16Jan2019 15:02, Tom Horsley horsley1953@gmail.com wrote:
Suddenly (probably after installing systemd updates this morning) it takes 30 seconds or so for an NIS user to login via ssh and I see this nonsense show up in the log:
Jan 16 14:53:33 tomh systemd-logind[811]: New session 11 of user tom. Jan 16 14:53:33 tomh systemd[1]: Failed to mount /userland. Jan 16 14:53:33 tomh systemd-logind[811]: Session 11 logged out. Waiting for processes to exit. Jan 16 14:53:33 tomh systemd-logind[811]: Removed session 11. Jan 16 14:53:34 tomh systemd[3119]: Listening on Sound System. Jan 16 14:53:34 tomh systemd[3119]: Starting D-Bus User Message Bus Socket. Jan 16 14:53:34 tomh systemd[3119]: Listening on Multimedia System. Jan 16 14:53:34 tomh systemd[3119]: Reached target Paths. Jan 16 14:53:34 tomh systemd[3119]: Started Mark boot as successful after the user session has run 2 minutes. Jan 16 14:53:34 tomh systemd[3119]: Reached target Timers. Jan 16 14:53:34 tomh systemd[3119]: Listening on D-Bus User Message Bus Socket. Jan 16 14:53:34 tomh systemd[3119]: Reached target Sockets. Jan 16 14:53:34 tomh systemd[3119]: Reached target Basic System. Jan 16 14:53:34 tomh systemd[3119]: Starting Sound Service... Jan 16 14:53:34 tomh dbus-daemon[822]: [system] Rejected send message, 2 matched rules; type="method_call", sender=":1.90" (uid=2304 pid=3129 comm="/usr/bin/pulseaudio --daemonize=no ") interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" error name="(unset)" requested_reply="0" destination="org.bluez" (bus) Jan 16 14:53:34 tomh systemd[3119]: Started D-Bus User Message Bus. Jan 16 14:53:34 tomh dbus-daemon[3157]: [session uid=2304 pid=3157] Activating service name='org.gnome.GConf' requested by ':1.1' (uid=2304 pid=3156 comm="/usr/libexec/pulse/gconf-helper ") Jan 16 14:53:34 tomh dbus-daemon[3157]: [session uid=2304 pid=3157] Successfully activated service 'org.gnome.GConf' Jan 16 14:53:34 tomh systemd[3119]: Started Sound Service. Jan 16 14:53:34 tomh pulseaudio[3129]: E: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.DBus.Error.AccessDenied: Rejected send message, 2 matched rules; type="method_call", sender=":1.90" (uid=2304 pid=3129 comm="/usr/bin/pulseaudio --daemonize=no ") interface="org.freedesktop.DBus.ObjectManager" member="GetManagedObjects" error name="(unset)" requested_reply="0" destination="org.bluez" (bus) Jan 16 14:53:34 tomh systemd[3119]: Reached target Default. Jan 16 14:53:34 tomh systemd[3119]: Startup finished in 690ms. Jan 16 14:53:44 tomh systemd[3119]: Stopping D-Bus User Message Bus... Jan 16 14:53:44 tomh systemd[3119]: Stopped target Default. Jan 16 14:53:44 tomh systemd[3119]: Stopping Sound Service... Jan 16 14:53:44 tomh systemd[3119]: Stopped D-Bus User Message Bus. Jan 16 14:53:44 tomh systemd[3119]: Stopped Sound Service. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Basic System. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Paths. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Timers. Jan 16 14:53:44 tomh systemd[3119]: Stopped Mark boot as successful after the user session has run 2 minutes. Jan 16 14:53:44 tomh systemd[3119]: Stopped target Sockets. Jan 16 14:53:44 tomh systemd[3119]: Closed Multimedia System. Jan 16 14:53:44 tomh systemd[3119]: Closed D-Bus User Message Bus Socket. Jan 16 14:53:44 tomh systemd[3119]: Closed Sound System. Jan 16 14:53:44 tomh systemd[3119]: Reached target Shutdown. Jan 16 14:53:44 tomh systemd[3119]: Starting Exit the Session... Jan 16 14:53:44 tomh systemd[3119]: Received SIGRTMIN+24 from PID 3179 (kill).
Most of the delay follows that last message. Any idea how to make NIS login work fast again?
If I login as a local user the only message I see is:
Jan 16 15:01:20 tomh systemd-logind[811]: New session 23 of user tweety.
and the login is immediate.
On Thu, 17 Jan 2019 09:29:07 +1100 Cameron Simpson wrote:
Just to confirm: the NIS user hasn't got a local /etc/passwd entry?
Definitely no local /etc/passwd entry.
Anyway, installing nscd is trivial and I would be interested to know if it changes the behaviour for you.
Nope, same behavior, and I noticed something new as well:
All systemctl commands now seem to hang for about the same amount of time (enable, disable, etc).
It is like it is a dbus problem (but if dbus was broken, you'd think it would never finish, not just hang).
If I turn on ssh -vvv debugging, it hangs after this output:
Authenticated to tomh ([10.134.30.143]:22). debug1: channel 0: new [client-session] debug3: ssh_session2_open: channel_new: 0 debug2: channel 0: send open debug3: send packet: type 90 debug1: Requesting no-more-sessions@openssh.com debug3: send packet: type 80 debug1: Entering interactive session. debug1: pledge: exec
Then eventually spews more debug output and logs in.
On 16Jan2019 19:47, Tom Horsley horsley1953@gmail.com wrote:
On Thu, 17 Jan 2019 09:29:07 +1100 Cameron Simpson wrote:
Just to confirm: the NIS user hasn't got a local /etc/passwd entry?
Definitely no local /etc/passwd entry.
Anyway, installing nscd is trivial and I would be interested to know if it changes the behaviour for you.
Nope, same behavior, and I noticed something new as well: All systemctl commands now seem to hang for about the same amount of time (enable, disable, etc).
It is like it is a dbus problem (but if dbus was broken, you'd think it would never finish, not just hang).
Yeah.
ISTR that the TCP connection timeout is about 30s. Can you "netstat -anp | grep SYN" during the delay and see if somethings trying a TCP connection to something now answering?
Cheers, Cameron Simpson cs@cskk.id.au
On Thu, 17 Jan 2019 15:31:36 +1100 Cameron Simpson wrote:
ISTR that the TCP connection timeout is about 30s. Can you "netstat -anp | grep SYN" during the delay and see if somethings trying a TCP connection to something now answering?
That didn't detect anything, so I used the big hammer of running strace on sshd and following all the pids and I see it connect fd 4 to /run/dbus/system_bus_socket
[pid 3275] connect(4, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 29) = 0
Then this happens a tad later:
[pid 3275] recvmsg(4, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
This poll is apparently where things hang. I see fd 4 is connected just above to /run/dbus/system_bus_socket
[pid 3275] ppoll([{fd=4, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999872000}, NULL, 8) = 0 (Timeout)
As soon as this stuff starts showing up in the trace, the login completes.
[pid 3275] openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = 7 ...
An lsof shows that pid 1 (systemd) does have the socket open:
systemd 1 root 145u unix 0x00000000caf35a01 0t0 17299 /run/dbus/system_bus_socket type=STREAM
So it looks like systemd is just sometimes speechless (which would explain the systemctl commands hanging as well).
On Wed, Jan 16, 2019 at 3:03 PM Tom Horsley horsley1953@gmail.com wrote:
Suddenly (probably after installing systemd updates this morning) it takes 30 seconds or so for an NIS user to login via ssh and I see this nonsense show up in the log:
It may not be related, but I also did an update Wednesday morning, and was greeted on Thursday morning with 3 ABRTs and complaints of a tainted kernel and a message that there were more updates, which included a new kernel and a whole passel of utilities, so checking for an update might be in order.
-- Ted Roche Ted Roche & Associates, LLC http://www.tedroche.com
On Thu, 17 Jan 2019 10:01:33 -0500 Tom Horsley wrote:
So it looks like systemd is just sometimes speechless (which would explain the systemctl commands hanging as well).
I just did a dnf downgrade systemd to arrive at these old versions:
systemd-239-3.fc29.x86_64 systemd-libs-239-3.fc29.x86_64
And the delay is gone. I submitted this bug:
-
Cameron Simpson -
Ted Roche -
Tom Horsley