Connexion ssh lente - L'activation de org.freedesktop.login1 a expiré

39

Sur l'un de mes serveurs, j'ai constaté un réel retard des connexions SSH.

Si vous vous connectez à l’aide des options ssh -vvv, le délai se produit à debug1: Entering interactive session.

extrait de connexion:

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

En utilisant la méthode décrite ici, j'ai généré une sortie strace et remarqué la ligne 14:09:53.676004 ppoll([{fd=5, events=POLLIN}], 1, {24, 999645000}, NULL, 8) = 1 ([{fd=5, revents=POLLIN}], left {0, 0}) <25.020764>qui prend 25 secondes.

extrait de la sortie 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>

J'ai remarqué une entrée dans les journaux d'authentification à l'heure pertinente:

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

Ne pas en savoir assez sur quoi chercher et pourquoi cela prend-il maintenant 25 secondes sur ce serveur particulier.

La journalctl -u systemd-logindcommande montre

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.

Émettre la commande systemctl restart systemd-logind.servicecorrige (pour l'instant probablement).

Qu'est-ce Activation of org.freedesktop.login1qu'il mentionne? Existe-t-il un moyen de ne pas avoir à redémarrer logind à l'avenir? Je prévois qu'avec le temps, ce problème se posera avec le reste des serveurs que je gère.

Je viens de remarquer que cela commence à se produire sur un autre serveur. 

$ 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 - journalctlsortie étendue .

EDIT2 - ajout du statut systemd-logind comme suggéré dans les commentaires lorsque remarqué que cela démarre sur un autre serveur.

MISE À JOUR - Cela commence à se produire pour le reste de mes serveurs Jessie. Suis-je le seul à en faire l'expérience? Il doit y avoir un correctif autre que le redémarrage de systemd-logind, est-ce que quelqu'un a des idées?

Il y a un rapport de bogue Debian sur ce 770135 .

ssh debian pam systemd Alasdair
la source
Il serait utile de voir la sortie de systemcts status systemd-logindavant redémarrage pour voir ce qui ne va pas avec elle (sortie, échec, peu importe). ppollest juste un médiateur qui attend la réponse de systemd afin que vous ne puissiez pas le blâmer.
Jakuje
il n'y a pas de systemctscommande
Alasdair
Désolé. systemctlbien sur
Jakuje
Je pensais que c'était ce que vous vouliez dire, mais je voulais être sûr. N'est-ce pas la même sortie que celle disponible dans la commandejournalctl -u systemd-logind
Alasdair le
il devrait afficher le journal, mais aussi le statut du service lui-même.
Jakuje

Réponses:

48

Cela se produit lorsque dbus est redémarré, mais que systemd-logind n'est pas redémarré. Il suffit de faire ce qui suit:

systemctl restart systemd-logind

La solution est à partir d'ici: https://major.io/2015/07/27/very-slow-ssh-logins-on-fedora-22/

asv
la source
1
Déjà mentionné dans la question, le rapport de bogue n'est toujours pas résolu, mais merci de le rétablir.
Alasdair
Remarque: cela peut également donner une "boucle de connexion" dans le lightdm greeter normal; même solution s'applique.
Unhammer
1

En utilisant:

systemctl restart systemd-logind

résout le problème que temporairement.

Une solution consiste à supprimer tous les .scopefichiers d'un travail cron, comme indiqué ici .

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

Le rapport de bogue systemd associé est ici: Fuite des unités de portée ralentissant les "fichiers d'unité de liste systemctl" et retardant les connexions .

Il semble qu’il s’agisse d’un bogue dbus: le décompte en vol en vol unix fd est résolu, ce qui est résolu dans la version dbus 1.11.10

Pour corriger définitivement ce bogue, il suffit d’attendre que cette version de dbus apparaisse dans votre distribution. Pour l’instant, Debian Stretch est à 1.10.18 dbus, Ubuntu 17.04 (Zesty) est à 1.10.10, CentOS 7 à dbus 1.6.12.

Ortomala Lokni
la source