Bug#770135: systemd: Stalls just after debug1: Entering interactive session.

Mon Aug 3 17:06:55 BST 2015

This is a multi-part MIME message sent by reportbug.

--===============0015788417291632402==
MIME-Version: 1.0
Content-Transfer-Encoding: 8bit
Content-Type: text/plain; charset="UTF-8"
Content-Disposition: inline

Package: systemd
Version: 215-17+deb8u1
Followup-For: Bug #770135

Dear Maintainer,

*** Reporter, please consider answering these questions, where
appropriate ***

   * What led up to the situation?
   * What exactly did you do (or not do) that was effective (or
     ineffective)?
   * What was the outcome of this action?
   * What outcome did you expect instead?

*** End of the template - remove these template lines ***

-- Package-specific info:

-- System Information:
ebian Release: 8.1
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 3.16.0-4-amd64 (SMP w/8 CPU cores)
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages systemd depends on:
ii  acl             2.2.52-2
ii  adduser         3.113+nmu3
ii  initscripts     2.88dsf-59
ii  libacl1         2.2.52-2
ii  libaudit1       1:2.4-1+b1
ii  libblkid1       2.25.2-6
ii  libc6           2.19-18
ii  libcap2         1:2.24-8
ii  libcap2-bin     1:2.24-8
ii  libcryptsetup4  2:1.6.6-5
ii  libgcrypt20     1.6.3-2
ii  libkmod2        18-3
ii  liblzma5        5.1.1alpha+20120614-2+b3
ii  libpam0g        1.1.8-3.1
ii  libselinux1     2.3-2
ii  libsystemd0     215-17+deb8u1
ii  mount           2.25.2-6
ii  sysv-rc         2.88dsf-59
ii  udev            215-17+deb8u1
ii  util-linux      2.25.2-6

Versions of packages systemd recommends:
ii  dbus            1.8.18-0+deb8u1
ii  libpam-systemd  215-17+deb8u1

Versions of packages systemd suggests:
pn  systemd-ui  <none>

Connecting using the ssh -vvv options the delay occurs at debug1:
Entering interactive session.

extract of connection:

debug1: Authentication succeeded (publickey).
Authenticated to IP_REDACTED ([IP_REDACTED]:22).
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Requesting no-more-sessions at openssh.com
debug1: Entering interactive session.
[[[STALL]]]
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug3: packet_set_tos: set IP_TOS 0x10
debug2: client_session2_setup: id 0
debug2: channel 0: request pty-req confirm 1

using the method outlined
http://www.depesz.com/2010/12/13/a-tale-of-slow-ssh-connections/  I
generated strace output and noticed the line 14:09:53.676004
ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000}, NULL, 8) = 1
([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764> which takes 25
seconds.

extract of strace output:

14:09:53.675567 clock_gettime(CLOCK_MONOTONIC, {4662549, 999741404}) =
0 <0.000024>
14:09:53.675651 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{"l\4\1\1\n\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0",
24}], msg_controll
en=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24 <0.000024>
14:09:53.675744 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{"/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0"..., 146}],
msg_controllen
=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 146 <0.000025>
14:09:53.675842 recvmsg(5, 0x7ffe0ff1dfa0,
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource
temporarily unavailab
le) <0.000023>
14:09:53.675925 clock_gettime(CLOCK_MONOTONIC, {4662550, 96075}) = 0
<0.000024>
14:09:53.676004 ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000},
NULL, 8) = 1 ([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764>
14:10:18.696865 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{"l\3\1\0013\0\0\0\3\0\0\0m\0\0\0\6\1s\0\5\0\0\0", 24}],
msg_controllen=0,     msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24 <0.000017>
14:10:18.696944 recvmsg(5, {msg_name(0)=NULL,
msg_iov(1)=[{":1.10\0\0\0\4\1s\0#\0\0\0org.freedesktop."..., 155}],
msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC},
MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 155 <0.000018>

I have noticed an entry in the auth logs at the relevant time:

Jul 21 14:10:18 click sshd[8165]: pam_systemd(sshd:session): Failed to
create session: Activation of org.freedesktop.login1 timed out

extract of sudo service systemd-logind status:

systemd-logind.service - Login Service
   Loaded: loaded (/lib/systemd/system/systemd-logind.service; static)
   Active: active (running) since Tue 2015-06-16 14:10:57 BST; 1
months 12 days ago
     Docs: man:systemd-logind.service(8)
           man:logind.conf(5)
           http://www.freedesktop.org/wiki/Software/systemd/logind
           http://www.freedesktop.org/wiki/Software/systemd/multiseat
 Main PID: 1701 (systemd-logind)
   Status: "Processing requests..."
   CGroup: /system.slice/systemd-logind.service
           └─1701 /lib/systemd/systemd-logind

Jul 28 13:16:21 myhost systemd[1]: Started Login Service.
Jul 28 13:16:47 myhost systemd[1]: Started Login Service.
Jul 28 16:09:23 myhost systemd[1]: Started Login Service.
Jul 28 16:09:49 myhost systemd[1]: Started Login Service.
Jul 28 16:10:15 myhost systemd[1]: Started Login Service.
Jul 28 16:10:41 myhost systemd[1]: Started Login Service.
Jul 28 22:50:19 myhost systemd[1]: Started Login Service.
Jul 29 05:00:15 myhost systemd[1]: Started Login Service.
Jul 29 11:00:20 myhost systemd[1]: Started Login Service.
Jul 29 11:09:56 myhost systemd[1]: Started Login Service.

Can confim the command:
systemctl restart dbus.service
prompts this delay in ssh login and is only resolved by the command:
systemctl restart

--===============0015788417291632402==