su : Erreur système

[Dunatotatos]

Salut à tous,

J'ai ces derniers temps un souci étrange sur un VPS. Il arrive de temps en temps (une fois par semaine) de ne pas pouvoir me connecter au serveur. Après quelques tentatives, la connexion fonctionne, mais `su` échoue avec une "Erreur système". Je n'ai aucune idée d'où vient le problème...

Pour SSH, du côté client :

Code : Tout sélectionner

$ ssh Arche
Enter passphrase for key '/home/dunatotatos/.ssh/id_rsa': 
Connection to dunatotatos.com closed by remote host.
Connection to dunatotatos.com closed.

Et les logs correspondant du côté serveur :

Code : Tout sélectionner

Sep 28 17:05:59 dunatotatos sshd[24769]: Accepted publickey for ssh_user from XXX.XXX.XXX.XXX port 33925 ssh2: RSA SHA256:A0c1YlkiP/3Q8/R1qcM/NJ+udjzzXLPvcI8kxKLg+l0
Sep 28 17:05:59 dunatotatos sshd[24769]: pam_unix(sshd:session): session opened for user ssh_user by (uid=0)
Sep 28 17:05:59 dunatotatos sshd[24769]: pam_systemd(sshd:session): Failed to create session: Cannot allocate memory
Sep 28 17:05:59 dunatotatos sshd[24782]: PAM audit_open() failed: Cannot allocate memory
Sep 28 17:05:59 dunatotatos sshd[24769]: fatal: linux_audit_write_entry failed: Cannot allocate memory

La mention "Cannot allocate memory" me semble très étrange, étant donné que :

Code : Tout sélectionner

$ free -h
              total        used        free      shared  buff/cache   available
Mem:           8,0G        5,6G        1,6G        2,3G        843M        2,3G
Swap:          128M          0B        128M

Après une tentative fructueuse, je tente d'utiliser `su`, et rencontre un échec :

Code : Tout sélectionner

$ su
Mot de passe :
su: Erreur système

Et dans les /var/log/auth.log :

Code : Tout sélectionner

Sep 28 17:06:49 dunatotatos su[24929]: Successful su for root by ssh_user
Sep 28 17:06:49 dunatotatos su[24929]: + /dev/pts/2 ssh_user:root
Sep 28 17:06:49 dunatotatos su[24929]: PAM audit_open() failed: Ne peut allouer de la mémoire
Sep 28 17:06:49 dunatotatos su[24929]: pam_setcred: System error

Mais que se passe-t-il ?

[vohu]

ton disque n'est pas plein par hasard ?

[lol]

Hello,
Y'a quoi sur ce serveur comme "services"?
Bien entendu tu as regardé syslog, kern, etc., et tu n'as rien vu de bizarre?
C'est une machine qui tourne h24 depuis longtemps ou qui redémarre régulièrement?

[PascalHambourg]

ton disque n'est pas plein par hasard ?

Ou à court d'inodes ?

Code : Tout sélectionner

df -h ; df -iT

[Dunatotatos]

Merci pour vos réponses !
Non, le disque n'est pas plein.

Code : Tout sélectionner

# df -h
Sys. de fichiers  Taille Utilisé Dispo Uti% Monté sur
/dev/ploop10493p1   100G     51G   45G  53% /
tmpfs               820M    1,3M  818M   1% /run
tmpfs               5,0M       0  5,0M   0% /run/lock
devtmpfs             10M       0   10M   0% /dev
tmpfs               1,7G    264K  1,7G   1% /run/shm
cgroup               12K       0   12K   0% /sys/fs/cgroup
tmpfs               820M       0  820M   0% /run/user/1000
tmpfs               820M       0  820M   0% /run/user/0
tmpfs               820M       0  820M   0% /run/user/122
tmpfs               820M       0  820M   0% /run/user/65534
tmpfs               820M       0  820M   0% /run/user/1003
tmpfs               820M       0  820M   0% /run/user/1009
tmpfs               820M       0  820M   0% /run/user/106
tmpfs               820M       0  820M   0% /run/user/1007
tmpfs               820M       0  820M   0% /run/user/1008

Question log, rien n'est ajouté autre part que dans /var/log/auth.log. Très peu de redémarrages, mais son uptime actuel n'est que de 27 jours.
Et elle héberge pas mal de services (DNS, mail, apache, 3 sites Django, davical, un walkie, et surtout gitlab très gourmand en ressources diverses).

J'attends la prochaine occurence du problème pour verifier les inodes. Je suis complètement passé à côté de cette possibilité. Pour le moment, tout semble nominal.

Code : Tout sélectionner

# df -iT                                                                                                                                                                                                                                                                                                                                                                                                                                                      
Sys. de fichiers  Type      Inœuds IUtil.  ILibre IUti% Monté sur                                                                                                                                                                                                                                                                                                                                                                                                                            
/dev/ploop10493p1 ext4     6619136 430716 6188420    7% /                                                                                                                                                                                                                                                                                                                                                                                                                                    
tmpfs             tmpfs    1048576    469 1048107    1% /run                                                                                                                                                                                                                                                                                                                                                                                                                                 
tmpfs             tmpfs    1048576      5 1048571    1% /run/lock                                                                                                                                                                                                                                                                                                                                                                                                                            
devtmpfs          devtmpfs 1048576     63 1048513    1% /dev                                                                                                                                                                                                                                                                                                                                                                                                                                 
tmpfs             tmpfs    1048576     36 1048540    1% /run/shm                                                                                                                                                                                                                                                                                                                                                                                                                             
cgroup            tmpfs    1048576      4 1048572    1% /sys/fs/cgroup                                                                                                                                                                                                                                                                                                                                                                                                                       
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/1000                                                                                                                                                                                                                                                                                                                                                                                                                       
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/0                                                                                                                                                                                                                                                                                                                                                                                                                          
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/122                                                                                                                                                                                                                                                                                                                                                                                                                        
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/65534                                                                                                                                                                                                                                                                                                                                                                                                                      
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/1003                                                                                                                                                                                                                                                                                                                                                                                                                       
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/1009                                                                                                                                                                                                                                                                                                                                                                                                                       
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/106                                                                                                                                                                                                                                                                                                                                                                                                                        
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/1007                                                                                                                                                                                                                                                                                                                                                                                                                       
tmpfs             tmpfs    1048576      1 1048575    1% /run/user/1008

[Dunatotatos]

Problème similaire ce soir. Les inodes n'ont pas de problème, la sortie de `df -iT` est similaire à la sortie du message précédent.
Je ne comprends pas...

[vohu]

Problème de disque ou RAM sur la machine ? Tu peux toujours demander à OVH de vérifier s'ils ont remarqué quelque chose sur le serveur

[MicP]

Bonjour

En faisant une recherche avec :

Code : Tout sélectionner

pam_systemd(sshd:session): Failed to create session: Cannot allocate memory

on retrouve plusieurs fils non résolus.

Mais la réinstallation de systemd aurait résolu le problème dans celui-ci :

[Dunatotatos]

Ah tiens, ça devient intéressant !
Il s'avère que cet machine a été mise à jour depuis une ancienne Debian (Wheezy, il me semble), et n'utilise pas systemd, mais init.d. J'ai récemment tenté de migrer vers systemd. L'opération s'est conclue par un cuisant échec. J'ai donc annulé mes modifications, et il serait bien possible que la première occurence du problème discuté ici soit apparue juste après.

Je vais re-tenter une migration vers systemd et voir ce qu'il se passe.

Ou peut-être plus simplement réinstaller un Debian fraîche...

[Dunatotatos]

Pour ceux que ça intéresserait, je cherche tout de même à tracer le problème pour en trouver la cause. J'ai épluché les logs après que le problème se soit reproduit aujourd'hui (Oct 11).

J'ai détecté le souci après une connexion SSH à 12:43:46 (heure du serveur) quand ping6 n'a pas voulu fonctionner :

Code : Tout sélectionner

$ ping6 xx:xx:xx:xx:xx:xx:xx:xx
socket: Aucun espace tampon disponible

Puis l'habituel su (à 12:44:02)

Code : Tout sélectionner

$ su
Mot de passe :
su: Erreur système

Voici un extrait des logs.
auth.log:

Code : Tout sélectionner

Oct 11 12:44:02 dunatotatos su[11417]: Successful su for root by ssh_user
Oct 11 12:44:02 dunatotatos su[11417]: + /dev/pts/2 ssh_user:root
Oct 11 12:44:02 dunatotatos su[11417]: pam_unix(su:session): session opened for user root by ssh_user(uid=1000)
Oct 11 12:44:02 dunatotatos su[11417]: pam_systemd(su:session): Failed to create session: Cannot allocate memory
Oct 11 12:44:02 dunatotatos su[11417]: PAM audit_open() failed: Ne peut allouer de la mémoire
Oct 11 12:44:02 dunatotatos su[11417]: pam_open_session: System error

Je vois des erreurs similaires qui traînent d'il y a 3 jours, lorsque un `git push` a échoué :

Code : Tout sélectionner

Oct  7 04:23:41 dunatotatos su[8366]: Successful su for nobody by root
Oct  7 04:23:41 dunatotatos su[8366]: + ??? root:nobody
Oct  7 04:23:41 dunatotatos su[8366]: pam_unix(su:session): session opened for user nobody by (uid=0)
Oct  7 04:23:41 dunatotatos su[8366]: pam_systemd(su:session): Failed to create session: Input/output error
Oct  7 04:23:41 dunatotatos su[8366]: pam_unix(su:session): session closed for user nobody

daemon.log (et syslog)

Code : Tout sélectionner

Oct 11 12:44:02 dunatotatos dbus[1384]: [system] Activating service name='org.freedesktop.systemd1' (using servicehelper)
Oct 11 12:44:02 dunatotatos dbus[1384]: [system] Failed to activate service org.freedesktop.systemd1: Could not create full-duplex pipe
Oct 11 12:44:02 dunatotatos dbus[1384]: [system] dbus-daemon transaction failed (OOM), sending error to sender uid=0 pid=2629 comm="/lib/systemd/systemd-logind "

error.log

Code : Tout sélectionner

Oct 11 09:51:55 dunatotatos sshd[1638]: error: reexec socketpair: Cannot allocate memory
Oct 11 09:59:40 dunatotatos sslh[17780]: sprintaddr:getnameinfo: Temporary failure in name resolution
Oct 11 10:28:18 dunatotatos sslh[22278]: sprintaddr:getnameinfo: Temporary failure in name resolution
Oct 11 11:04:01 dunatotatos CRON[27890]: PAM audit_open() failed: Ne peut allouer de la mémoire
Oct 11 11:04:01 dunatotatos CRON[27890]: Erreur système
Oct 11 11:05:01 dunatotatos CRON[28035]: PAM audit_open() failed: Ne peut allouer de la mémoire
Oct 11 11:05:01 dunatotatos CRON[28035]: Erreur système
Oct 11 11:05:02 dunatotatos postfix/sendmail[28044]: fatal: inet_addr_local[getifaddrs]: getifaddrs: Cannot allocate memory
Oct 11 11:05:02 dunatotatos CRON[28036]: PAM audit_open() failed: Ne peut allouer de la mémoire
Oct 11 11:05:40 dunatotatos sshd[1638]: error: reexec socketpair: Cannot allocate memory
Oct 11 11:45:01 dunatotatos CRON[2008]: PAM audit_open() failed: Ne peut allouer de la mémoire
Oct 11 11:45:01 dunatotatos CRON[2008]: Erreur système
Oct 11 12:22:18 dunatotatos sslh[7845]: sprintaddr:getnameinfo: Temporary failure in name resolution
Oct 11 12:22:25 dunatotatos postfix/sendmail[7813]: fatal: root(0): unable to execute /usr/sbin/postdrop -r: Cannot allocate memory
Oct 11 12:43:46 dunatotatos postfix/trivial-rewrite[11378]: fatal: inet_addr_local[getifaddrs]: getifaddrs: Cannot allocate memory
Oct 11 12:44:02 dunatotatos su[11417]: pam_systemd(su:session): Failed to create session: Cannot allocate memory
Oct 11 12:44:02 dunatotatos su[11417]: PAM audit_open() failed: Ne peut allouer de la mémoire
Oct 11 12:44:02 dunatotatos su[11417]: pam_open_session: System error
Oct 11 12:44:18 dunatotatos su[11456]: pam_systemd(su:session): Failed to create session: Cannot allocate memory
Oct 11 12:44:48 dunatotatos sslh[11620]: sprintaddr:getnameinfo: Temporary failure in name resolution

RAM, disk space et inodes ne sont de loin pas plein.

Je ne peux pas me résoudre à réinstaller l'OS en totalité sans chercher l'origine du problème. Et je trouverai !

[piratebab]

un coup c'est de la mémoire, une autre fois des i/o, c'est étrange ton truc

[PascalHambourg]

Peut-être l'épuisement d'une "ressource" limitée du noyau (nombre de fichiers ou sockets ouverts, tampons...) ?
Peut-être plus d'infos dans /proc/meminfo.

[Dunatotatos]

Peut-être l'épuisement d'une "ressource" limitée du noyau (nombre de fichiers ou sockets ouverts, tampons...) ?

C'est bien ce que je suspecte. Reste à trouver quelles ressource...

Le problème se produit en ce moment, et voici le contenu de /proc/meminf:

Code : Tout sélectionner

MemTotal:        8388608 kB
MemFree:         2342488 kB
Cached:           216940 kB
Buffers:               0 kB
Active:          2759116 kB
Inactive:         749196 kB
Active(anon):    2647692 kB
Inactive(anon):   643680 kB
Active(file):     111424 kB
Inactive(file):   105516 kB
Unevictable:        8364 kB
Mlocked:           25336 kB
SwapTotal:        131072 kB
SwapFree:         131072 kB
Dirty:               108 kB
Writeback:             0 kB
AnonPages:       3291372 kB
Shmem:           2394288 kB
Slab:             135104 kB
SReclaimable:      62480 kB
SUnreclaim:        72624 kB

Je n'y vois rien qui cloche, surtout quand je compare au même contenu quand je ne rencontre pas le souci :

Code : Tout sélectionner

MemTotal:        8388608 kB
MemFree:         2219748 kB
Cached:           385768 kB
Buffers:               0 kB
Active:          2675828 kB
Inactive:         961644 kB
Active(anon):    2607520 kB
Inactive(anon):   644184 kB
Active(file):      68308 kB
Inactive(file):   317460 kB
Unevictable:        8364 kB
Mlocked:           25336 kB
SwapTotal:        131072 kB
SwapFree:         131072 kB
Dirty:                20 kB
Writeback:             0 kB
AnonPages:       3251704 kB
Shmem:           2394280 kB
Slab:             128668 kB
SReclaimable:      57480 kB
SUnreclaim:        71188 kB

EDIT : Le nombre de Inactive (file) est triplé par rapport à une situation sans problème. Tiendrait-on le coupable ?

EDIT2 : Je n'arrive pas à comprendre à quoi correspond cette entrée de Inactive (file)... Je cherche.

[Dunatotatos]

J'ai trouvé ça :

Code : Tout sélectionner

Inactive(file) — The amount of file cache memory, in kibibytes, that is newly loaded from the disk, or is a candidate for reclaiming.

ici : https://www.lynxbee.com/analysing-linux ... info-file/

Reste à trouver un moyen de tracer cet usage par processus. Je ne sais pas comment...

[piratebab]

si c'est via un appel systeme, strace sur les candidats potentiels.

[Dunatotatos]

Ça va être délicat. Je ne lance rien à la main, et la plupart des services créent des forks (et surtout gitlab, que je suspecte plus que tout autre).

[piratebab]

normalement les inactives sont ceux qui peuvent étre relachés du cache, ça ne devrais pas poser de problème.
Ce serait plutot les actives qui sont plus critiques

[PascalHambourg]

Le nombre de Inactive (file) est triplé par rapport à une situation sans problème.

C'est plutôt l'inverse, non ? Je ne pense pas que ce soit pertinent, surtout vu la quantité en jeu.

Je n'arrive pas à comprendre à quoi correspond cette entrée de Inactive (file)

C'est la mémoire allouée à des pages de cache de fichiers qui n'ont pas été accédées récemment, qui ont plus de chances d'être évincées en cas de besoin.
La mémoire marquée "active" correspond aux pages accédées récemment, qui ont moins de chances d'être évincées.
La mémoire marquée (anon) correspond aux données des processus ("anonyme" car ne corrspondant pas à des fichiers).

A la réflexion je ne pense pas qu'on trouvera de réponse dans /proc/meminfo.

[Dunatotatos]

C'est plutôt l'inverse, non ?

Ah oui, zut...

Et merci pour l'explication.

Je tenterai un strace sur une commande qui foire dès que je rencontre à nouveau le problème.

[Dunatotatos]

Je n'ai pas réussi à avoir un strace d'une commande qui échoue, mais voici ce que `atop` me retourne quelques secondes après que le problème ne soit apparu. Je ne sais pas pourquoi la ligne MEM est en rouge, mais des personnes plus éduquées que moi pourront certainement m'éclairer.