Login ssh lambat - Aktivasi habis waktu org.freedesktop.login1

39

Pada salah satu server saya, saya perhatikan benar-benar menunda login SSH.

Menghubungkan menggunakan opsi ssh -vvv penundaan terjadi pada debug1: Entering interactive session.

ekstrak koneksi:

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 [email protected]
debug1: Entering interactive session.
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

menggunakan metode yang diuraikan di sini saya menghasilkan output strace dan memperhatikan garis 14:09:53.676004 ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000}, NULL, 8) = 1 ([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764>yang membutuhkan waktu 25 detik.

ekstrak dari output strace:

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>

Saya telah memperhatikan entri dalam auth log pada waktu yang relevan:

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

Tidak cukup mengetahui tentang ini apa yang ia coba jajak pendapat dan mengapa sekarang mengambil 25 detik di server khusus ini.

The journalctl -u systemd-logindperintah menunjukkan

Jul 20 11:33:06 click systemd-logind[19415]: Failed to abandon session scope: Transport endpoint is not connected
Jul 21 05:04:54 myhost systemd[1]: Started Login Service.
Jul 21 12:15:30 myhost systemd[1]: Started Login Service.
Jul 21 12:17:04 myhost systemd[1]: Started Login Service.
Jul 21 12:49:55 myhost systemd[1]: Started Login Service.
Jul 21 13:57:05 myhost systemd[1]: Started Login Service.
Jul 21 13:58:49 myhost systemd[1]: Started Login Service.
Jul 21 14:01:55 myhost systemd[1]: Started Login Service.
Jul 21 14:08:32 myhost systemd[1]: Started Login Service.
Jul 21 14:09:53 myhost systemd[1]: Started Login Service.
Jul 21 14:19:08 myhost systemd[1]: Started Login Service.
Jul 21 14:21:26 myhost systemd[1]: Started Login Service.
Jul 21 14:22:37 myhost systemd[1]: Started Login Service.
Jul 21 14:25:20 myhost systemd[1]: Started Login Service.
Jul 21 14:30:27 myhost systemd[1]: Started Login Service.
Jul 21 15:02:56 myhost systemd[1]: Started Login Service.

Mengeluarkan perintah systemctl restart systemd-logind.servicememperbaikinya (untuk saat ini mungkin).

Apa yang Activation of org.freedesktop.login1disebutkannya? Apakah ada cara saya bisa mencegah keharusan me-restart login di masa depan? Saya berharap seiring waktu saya akan memiliki masalah ini dengan sisa server yang saya kelola.

Hanya memperhatikan ini mulai terjadi di server lain. 

$ 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.

EDIT - journalctloutput diperluas .

EDIT2 - menambahkan status systemd-logind seperti yang disarankan dalam komentar ketika melihat ini dimulai pada server lain.

PEMBARUAN - Ini mulai terjadi pada seluruh server Jessie saya. Apakah saya satu-satunya yang mengalami ini? Pasti ada perbaikan selain memulai kembali systemd-logind, adakah yang punya ide?

Ada laporan bug Debian tentang 770135 ini .

ssh debian pam systemd Alasdair
sumber
Akan bermanfaat untuk melihat output systemcts status systemd-logindsebelum restart untuk melihat apa yang salah dengannya (keluar, gagal, apa pun). ppollhanyalah mediator yang sedang menunggu respons dari systemd sehingga Anda tidak dapat menyalahkannya.
Jakuje
tidak ada systemctsperintah
Alasdair
Maaf. systemctltentu saja
Jakuje
Saya pikir itu yang Anda maksudkan tetapi ingin memastikan. Apakah itu bukan output yang sama seperti yang tersedia dari perintahjournalctl -u systemd-logind
Alasdair
harus menunjukkan log, tetapi juga status layanan itu sendiri.
Jakuje

Jawaban:

48

Ini terjadi ketika dbus di-restart, tetapi systemd-logind tidak di-restart. Lakukan saja yang berikut ini:

systemctl restart systemd-logind

Solusinya adalah dari sini: https://major.io/2015/07/27/very-slow-ssh-logins-on-fedora-22/

asv
sumber
1
Sudah dinyatakan dalam pertanyaan, laporan bug masih belum terselesaikan, tapi terima kasih telah mengembalikannya.
Alasdair
Catatan: ini juga dapat memberikan "loop masuk" di penyambut lightdm biasa; solusi yang sama berlaku.
Unhammer
1

Menggunakan:

systemctl restart systemd-logind

menyelesaikan masalah hanya sementara.

Salah satu solusinya adalah menghapus semua .scopefile dari pekerjaan cron, seperti yang dinyatakan di sini .

* 2,14 * * * root /bin/rm -f /run/systemd/system/*.scope

Laporan bug systemd terkait ada di sini: Kebocoran unit lingkup memperlambat "systemctl list-unit-file" dan menunda login .

Tampaknya itu sebenarnya bug dbus: unix fd in-flight penghitungan rusak yang diselesaikan dalam dbus versi 1.11.10

Untuk memperbaiki bug ini secara permanen, Anda hanya harus menunggu versi dbus ini muncul di distribusi Anda. Untuk saat ini, Debian Stretch berada di dbus 1.10.18, Ubuntu 17.04 (Zesty) berada di 1.10.10, CentOS 7 di dbus 1.6.12.

Ortomala Lokni
sumber