Forum Linux.debian/ubuntu Commande su très très lente

Posté par Chris K. le 24 septembre 2013 à 17:20. Licence CC By‑SA.

Étiquettes :

sept.

2013

Bonjour à tous,

Je sèche avec une machine qui met environ 30 secondes à faire un su depuis root vers un autre utilisateur.
Dans l'autre sens la demande de mot de passe est instantanée mais l'ouverture du shell mets le même temps.

Dans le strace de la commande su j'ai un :

25.024613 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5
 0.000020 open("/proc/self/loginuid", O_WRONLY|O_TRUNC|O_NOFOLLOW) = 5
 4.255104 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5

Je précise que :
- L'ouverture du fichier /etc/passwd par un éditeur ou un cat est instantanée
- Les droits sont corrects et il n'y a pas de d'acls
- Pareil pour /bin/bash. Même problème en passant le shell sur /bin/sh
- La configuration PAM à l'air tout à fait correcte et est conforme au fichier d'origine du package

C'est une Debian Wheezy avec un noyau 3.2.0-4-amd64 et tout est à jour.

Quelqu'un aurait-il une piste ?

Merci d'avance :).

# Commentaire supprimé

Posté par Anonyme le 24 septembre 2013 à 17:41. Évalué à 2.

Ce commentaire a été supprimé par l’équipe de modération.

[^] # Re: Je n'appelerais pas cela une piste...

Posté par Chris K. le 24 septembre 2013 à 18:32. Évalué à 1.

Oui c'est bien possible car avec cat j'ai ceci pour open :

0.000065 open("/etc/passwd", O_RDONLY) = 3

[^] # Re: Je n'appelerais pas cela une piste...

Posté par Chris K. le 24 septembre 2013 à 18:48. Évalué à 1.

Je me répond à moi même je suis surtout passé à coté du plus important, AMHA, l'appel poll juste avant qui part en timeout :

0.000040 poll([{fd=4, events=POLLIN}], 1, 25000) = 0 (Timeout)
25.024613 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5

Ne sachant pas exactement à quoi cela correspond je retourne à mes recherches….

[^] # Commentaire supprimé

Posté par Anonyme le 24 septembre 2013 à 19:29. Évalué à 3.

Ce commentaire a été supprimé par l’équipe de modération.

[^] # Re: Je n'appelerais pas cela une piste...

Posté par Chris K. le 25 septembre 2013 à 01:02. Évalué à 1.

C'est bien poll qui prend son temps, voici le trace presque complet (strace -T -r -o trace-t.log su mon_user) :

     0.000015 close(4)                  = 0 <0.000003>
 0.000014 munmap(0x7f434decf000, 4096) = 0 <0.000006>
 0.000019 stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000004>
 0.000027 open("/etc/pam.d/common-account", O_RDONLY) = 4 <0.000005>
 0.000019 fstat(4, {st_mode=S_IFREG|0644, st_size=1208, ...}) = 0 <0.000004>
 0.000022 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434decf000 <0.000004>
 0.000020 read(4, "#\n# /etc/pam.d/common-account - "..., 4096) = 1208 <0.000005>
 0.000027 read(4, "", 4096)         = 0 <0.000004>
 0.000015 close(4)                  = 0 <0.000004>
 0.000015 munmap(0x7f434decf000, 4096) = 0 <0.000006>
 0.000018 stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000005>
 0.000027 open("/etc/pam.d/common-password", O_RDONLY) = 4 <0.000005>
 0.000019 fstat(4, {st_mode=S_IFREG|0644, st_size=1480, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434decf000 <0.000004>
 0.000016 read(4, "#\n# /etc/pam.d/common-password -"..., 4096) = 1480 <0.000006>
 0.000033 open("/lib/x86_64-linux-gnu/security/pam_gnome_keyring.so", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000006>
 0.000029 open("/lib/security/pam_gnome_keyring.so", O_RDONLY) = 5 <0.000005>
 0.000020 read(5, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0` \0\0\0\0\0\0"..., 832) = 832 <0.000004>
 0.000019 fstat(5, {st_mode=S_IFREG|0644, st_size=42296, ...}) = 0 <0.000003>
 0.000027 mmap(NULL, 2137584, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 5, 0) = 0x7f434a5d7000 <0.000006>
 0.000018 mprotect(0x7f434a5e1000, 2093056, PROT_NONE) = 0 <0.000007>
 0.000019 mmap(0x7f434a7e0000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 5, 0x9000) = 0x7f434a7e0000 <0.000005>
 0.000020 close(5)                  = 0 <0.000003>
 0.000046 read(4, "", 4096)         = 0 <0.000003>
 0.000016 close(4)                  = 0 <0.000003>
 0.000014 munmap(0x7f434decf000, 4096) = 0 <0.000006>
 0.000019 stat("/etc/pam.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000004>
 0.000027 open("/etc/pam.d/common-session", O_RDONLY) = 4 <0.000005>
 0.000019 fstat(4, {st_mode=S_IFREG|0644, st_size=1235, ...}) = 0 <0.000003>
 0.000022 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434decf000 <0.000004>
 0.000017 read(4, "#\n# /etc/pam.d/common-session - "..., 4096) = 1235 <0.000006>
 0.000042 read(4, "", 4096)         = 0 <0.000004>
 0.000016 close(4)                  = 0 <0.000004>
 0.000014 munmap(0x7f434decf000, 4096) = 0 <0.000006>
 0.000017 read(3, "", 4096)         = 0 <0.000003>
 0.000015 close(3)                  = 0 <0.000004>
 0.000014 munmap(0x7f434ded0000, 4096) = 0 <0.000005>
 0.000019 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3 <0.000005>
 0.000019 lseek(3, 0, SEEK_CUR)     = 0 <0.000003>
 0.000015 fstat(3, {st_mode=S_IFREG|0644, st_size=2497, ...}) = 0 <0.000003>
 0.000022 mmap(NULL, 2497, PROT_READ, MAP_SHARED, 3, 0) = 0x7f434ded0000 <0.000004>
 0.000016 lseek(3, 2497, SEEK_SET)  = 2497 <0.000003>
 0.000023 munmap(0x7f434ded0000, 2497) = 0 <0.000005>
 0.000015 close(3)                  = 0 <0.000003>
 0.000018 rt_sigaction(SIGINT, {SIG_IGN, [INT], SA_RESTORER|SA_RESTART, 0x7f434d54a4f0}, {SIG_DFL, [], 0}, 8) = 0 <0.000008>
 0.000035 rt_sigaction(SIGQUIT, {SIG_IGN, [QUIT], SA_RESTORER|SA_RESTART, 0x7f434d54a4f0}, {SIG_DFL, [], 0}, 8) = 0 <0.000004>
 0.000028 time(NULL)                = 1380063549 <0.000003>
 0.000014 getuid()                  = 0 <0.000008>
 0.000024 getuid()                  = 0 <0.000003>
 0.000018 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3 <0.000005>
 0.000019 lseek(3, 0, SEEK_CUR)     = 0 <0.000003>
 0.000014 fstat(3, {st_mode=S_IFREG|0644, st_size=2497, ...}) = 0 <0.000003>
 0.000022 mmap(NULL, 2497, PROT_READ, MAP_SHARED, 3, 0) = 0x7f434ded0000 <0.000004>
 0.000016 lseek(3, 2497, SEEK_SET)  = 2497 <0.000003>
 0.000022 munmap(0x7f434ded0000, 2497) = 0 <0.000004>
 0.000015 close(3)                  = 0 <0.000003>
 0.000031 open("/etc/shadow", O_RDONLY|O_CLOEXEC) = 3 <0.000006>
 0.000021 lseek(3, 0, SEEK_CUR)     = 0 <0.000003>
 0.000014 fstat(3, {st_mode=S_IFREG|0640, st_size=1609, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 1609, PROT_READ, MAP_SHARED, 3, 0) = 0x7f434ded0000 <0.000004>
 0.000018 lseek(3, 1609, SEEK_SET)  = 1609 <0.000003>
 0.000023 munmap(0x7f434ded0000, 1609) = 0 <0.000006>
 0.000016 close(3)                  = 0 <0.000004>
 0.000018 time(NULL)                = 1380063549 <0.000003>
 0.000017 rt_sigaction(SIGINT, {SIG_DFL, [INT], SA_RESTORER|SA_RESTART, 0x7f434d54a4f0}, {SIG_IGN, [INT], SA_RESTORER|SA_RESTART, 0x7f434d54a4f0}, 8) = 0 <0.000004>
 0.000027 rt_sigaction(SIGQUIT, {SIG_DFL, [QUIT], SA_RESTORER|SA_RESTART, 0x7f434d54a4f0}, {SIG_IGN, [QUIT], SA_RESTORER|SA_RESTART, 0x7f434d54a4f0}, 8) = 0 <0.000003>
 0.000037 time([1380063549])        = 1380063549 <0.000004>
 0.000020 open("/etc/localtime", O_RDONLY) = 3 <0.000006>
 0.000019 fstat(3, {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0 <0.000003>
 0.000022 fstat(3, {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0 <0.000003>
 0.000022 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434ded0000 <0.000004>
 0.000017 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\f\0\0\0\f\0\0\0\0"..., 4096) = 2945 <0.000006>
 0.000022 lseek(3, -1863, SEEK_CUR) = 1082 <0.000003>
 0.000014 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\r\0\0\0\r\0\0\0\0"..., 4096) = 1863 <0.000004>
 0.000025 close(3)                  = 0 <0.000003>
 0.000015 munmap(0x7f434ded0000, 4096) = 0 <0.000006>
 0.000029 socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 3 <0.000008>
 0.000020 connect(3, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0 <0.000006>
 0.000025 sendto(3, "<86>Sep 25 00:59:09 su[3318]: Su"..., 65, MSG_NOSIGNAL, NULL, 0) = 65 <0.000031>
 0.000053 open("/etc/login.defs", O_RDONLY) = 4 <0.000006>
 0.000020 fstat(4, {st_mode=S_IFREG|0644, st_size=10185, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434ded0000 <0.000004>
 0.000016 read(4, "#\n# /etc/login.defs - Configurat"..., 4096) = 4096 <0.000006>
 0.000037 read(4, " issuing \n# the \"mesg y\" command"..., 4096) = 4096 <0.000004>
 0.000033 read(4, "set to MD5 , MD5-based algorithm"..., 4096) = 1993 <0.000004>
 0.000024 read(4, "", 4096)         = 0 <0.000003>
 0.000016 close(4)                  = 0 <0.000003>
 0.000014 munmap(0x7f434ded0000, 4096) = 0 <0.000006>
 0.000027 time([1380063549])        = 1380063549 <0.000004>
 0.000021 sendto(3, "<86>Sep 25 00:59:09 su[3318]: + "..., 57, MSG_NOSIGNAL, NULL, 0) = 57 <0.000015>
 0.000036 setgid(1001)              = 0 <0.000005>
 0.000019 open("/proc/sys/kernel/ngroups_max", O_RDONLY) = 4 <0.000013>
 0.000030 read(4, "65536\n", 31)    = 6 <0.000006>
 0.000017 close(4)                  = 0 <0.000003>
 0.000017 socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4 <0.000012>
 0.000025 connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000009>
 0.000029 close(4)                  = 0 <0.000005>
 0.000016 socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 4 <0.000005>
 0.000016 connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) <0.000007>
 0.000025 close(4)                  = 0 <0.000004>
 0.000023 open("/etc/group", O_RDONLY|O_CLOEXEC) = 4 <0.000005>
 0.000020 lseek(4, 0, SEEK_CUR)     = 0 <0.000003>
 0.000014 fstat(4, {st_mode=S_IFREG|0644, st_size=1092, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 1092, PROT_READ, MAP_SHARED, 4, 0) = 0x7f434ded0000 <0.000004>
 0.000016 lseek(4, 1092, SEEK_SET)  = 1092 <0.000003>
 0.000028 fstat(4, {st_mode=S_IFREG|0644, st_size=1092, ...}) = 0 <0.000003>
 0.000023 munmap(0x7f434ded0000, 1092) = 0 <0.000006>
 0.000015 close(4)                  = 0 <0.000004>
 0.000016 setgroups(1, [1001])      = 0 <0.000004>
 0.000022 open("/etc/security/pam_env.conf", O_RDONLY) = 4 <0.000006>
 0.000021 fstat(4, {st_mode=S_IFREG|0644, st_size=2980, ...}) = 0 <0.000004>
 0.000026 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434ded0000 <0.000005>
 0.000017 read(4, "#\n# This is the configuration fi"..., 4096) = 2980 <0.000006>
 0.000025 read(4, "", 4096)         = 0 <0.000004>
 0.000014 close(4)                  = 0 <0.000003>
 0.000014 munmap(0x7f434ded0000, 4096) = 0 <0.000006>
 0.000018 open("/etc/environment", O_RDONLY) = 4 <0.000006>
 0.000019 fstat(4, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434ded0000 <0.000004>
 0.000015 read(4, "", 4096)         = 0 <0.000004>
 0.000015 close(4)                  = 0 <0.000003>
 0.000014 munmap(0x7f434ded0000, 4096) = 0 <0.000004>
 0.000017 open("/etc/security/pam_env.conf", O_RDONLY) = 4 <0.000005>
 0.000019 fstat(4, {st_mode=S_IFREG|0644, st_size=2980, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434ded0000 <0.000004>
 0.000015 read(4, "#\n# This is the configuration fi"..., 4096) = 2980 <0.000005>
 0.000023 read(4, "", 4096)         = 0 <0.000004>
 0.000014 close(4)                  = 0 <0.000003>
 0.000014 munmap(0x7f434ded0000, 4096) = 0 <0.000005>
 0.000024 open("/etc/default/locale", O_RDONLY) = 4 <0.000006>
 0.000019 fstat(4, {st_mode=S_IFREG|0644, st_size=52, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f434ded0000 <0.000004>
 0.000016 read(4, "#  File generated by update-loca"..., 4096) = 52 <0.000006>
 0.000021 read(4, "", 4096)         = 0 <0.000004>
 0.000014 close(4)                  = 0 <0.000003>
 0.000014 munmap(0x7f434ded0000, 4096) = 0 <0.000005>
 0.000019 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4 <0.000005>
 0.000018 lseek(4, 0, SEEK_CUR)     = 0 <0.000003>
 0.000015 fstat(4, {st_mode=S_IFREG|0644, st_size=2497, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 2497, PROT_READ, MAP_SHARED, 4, 0) = 0x7f434ded0000 <0.000004>
 0.000015 lseek(4, 2497, SEEK_SET)  = 2497 <0.000003>
 0.000022 munmap(0x7f434ded0000, 2497) = 0 <0.000004>
 0.000015 close(4)                  = 0 <0.000004>
 0.000020 getuid()                  = 0 <0.000003>
 0.000018 access("/var/run/utmpx", F_OK) = -1 ENOENT (No such file or directory) <0.000006>
 0.000022 open("/var/run/utmp", O_RDONLY|O_CLOEXEC) = 4 <0.000006>
 0.000018 lseek(4, 0, SEEK_SET)     = 0 <0.000005>
 0.000023 alarm(0)                  = 0 <0.000003>
 0.000015 rt_sigaction(SIGALRM, {0x7f434d627690, [], SA_RESTORER, 0x7f434d54a4f0}, {SIG_DFL, [], 0}, 8) = 0 <0.000004>
 0.000026 alarm(10)                 = 0 <0.000004>
 0.000020 fcntl(4, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0 <0.000006>
 0.000029 read(4, "\10\0\0\0\362\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000005>
 0.000024 read(4, "\2\0\0\0\0\0\0\0~\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000004>
 0.000019 read(4, "\1\0\0\0002N\0\0~\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000003>
 0.000020 read(4, "\10\0\0\0\205\10\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000004>
 0.000019 read(4, "\6\0\0\0f\27\0\0tty1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000004>
 0.000020 read(4, "\6\0\0\0h\27\0\0tty3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000003>
 0.000020 read(4, "\6\0\0\0j\27\0\0tty5\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000004>
 0.000019 read(4, "\6\0\0\0k\27\0\0tty6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000003>
 0.000020 read(4, "\6\0\0\0g\27\0\0tty2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000004>
 0.000019 read(4, "\6\0\0\0i\27\0\0tty4\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000003>
 0.000020 read(4, "\7\0\0\0'\333\0\0pts/1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000004>
 0.000023 read(4, "\10\0\0\0\2462\0\0pts/2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000004>
 0.000019 read(4, "\7\0\0\0\205\337\0\0pts/3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 384) = 384 <0.000003>
 0.000020 fcntl(4, F_SETLKW, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0 <0.000004>
 0.000017 alarm(0)                  = 10 <0.000004>
 0.000014 rt_sigaction(SIGALRM, {SIG_DFL, [], SA_RESTORER, 0x7f434d54a4f0}, NULL, 8) = 0 <0.000004>
 0.000022 close(4)                  = 0 <0.000003>
 0.000014 getuid()                  = 0 <0.000003>
 0.000019 time([1380063549])        = 1380063549 <0.000003>
 0.000020 sendto(3, "<86>Sep 25 00:59:09 su[3318]: pa"..., 100, MSG_NOSIGNAL, NULL, 0) = 100 <0.000017>
 0.000039 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4 <0.000005>
 0.000019 lseek(4, 0, SEEK_CUR)     = 0 <0.000004>
 0.000015 fstat(4, {st_mode=S_IFREG|0644, st_size=2497, ...}) = 0 <0.000003>
 0.000023 mmap(NULL, 2497, PROT_READ, MAP_SHARED, 4, 0) = 0x7f434ded0000 <0.000005>
 0.000016 lseek(4, 2497, SEEK_SET)  = 2497 <0.000003>
 0.000021 munmap(0x7f434ded0000, 2497) = 0 <0.000005>
 0.000016 close(4)                  = 0 <0.000003>
 0.000020 getresuid([0], [0], [0])  = 0 <0.000003>
 0.000017 getresgid([1001], [1001], [1001]) = 0 <0.000003>
 0.000039 socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC, 0) = 4 <0.000006>
 0.000019 connect(4, {sa_family=AF_FILE, path="/var/run/dbus/system_bus_socket"}, 33) = 0 <0.000010>
 0.000026 fcntl(4, F_GETFL)         = 0x2 (flags O_RDWR) <0.000004>
 0.000015 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000003>
 0.000022 geteuid()                 = 0 <0.000003>
 0.000019 getsockname(4, {sa_family=AF_FILE, NULL}, [2]) = 0 <0.000003>
 0.000057 poll([{fd=4, events=POLLOUT}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}]) <0.000004>
 0.000027 sendto(4, "\0", 1, MSG_NOSIGNAL, NULL, 0) = 1 <0.000005>
 0.000020 sendto(4, "AUTH EXTERNAL 30\r\n", 18, MSG_NOSIGNAL, NULL, 0) = 18 <0.000004>
 0.000022 poll([{fd=4, events=POLLIN}], 1, -1) = 1 ([{fd=4, revents=POLLIN}]) <0.000004>
 0.000020 read(4, "OK 897353d5a09c45991d5e51fb520c0"..., 2048) = 37 <0.000004>
 0.000024 poll([{fd=4, events=POLLOUT}], 1, -1) = 1 ([{fd=4, revents=POLLOUT}]) <0.000004>
 0.000019 sendto(4, "NEGOTIATE_UNIX_FD\r\n", 19, MSG_NOSIGNAL, NULL, 0) = 19 <0.000005>
 0.000019 poll([{fd=4, events=POLLIN}], 1, -1) = 1 ([{fd=4, revents=POLLIN}]) <0.000004>
 0.000018 read(4, "AGREE_UNIX_FD\r\n", 2048) = 15 <0.000004>
 0.000020 poll([{fd=4, events=POLLOUT}], 1, -1) = 1 ([{fd=4, revents=POLLOUT}]) <0.000003>
 0.000025 sendto(4, "BEGIN\r\n", 7, MSG_NOSIGNAL, NULL, 0) = 7 <0.000005>
 0.000019 poll([{fd=4, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=4, revents=POLLOUT}]) <0.000004>
 0.000019 sendmsg(4, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\0\0\0\0\1\0\0\0n\0\0\0\1\1o\0\25\0\0\0/org/fre"..., 128}, {"", 0}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 128 <0.000005>
 0.000038 poll([{fd=4, events=POLLIN}], 1, 25000) = 1 ([{fd=4, revents=POLLIN}]) <0.008384>
 0.008415 recvmsg(4, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\v\0\0\0\1\0\0\0=\0\0\0\6\1s\0\6\0\0\0:1.783\0\0"..., 2048}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 262 <0.000006>
 0.000047 recvmsg(4, 0x7fff31780700, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) <0.000003>
 0.000047 sendmsg(4, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\304\0\0\0\2\0\0\0\273\0\0\0\1\1o\0#\0\0\0/org/fre"..., 208}, {"\274\0\0\0\0\0\0\0\t\0\0\0unix-user\0\1i\0\0\0\0\351\3\0\0"..., 196}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 404 <0.000006>
 0.000038 poll([{fd=4, events=POLLIN}], 1, 25000) = 0 (Timeout) <25.006077>
25.006150 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000010>
 0.000034 lseek(5, 0, SEEK_CUR)     = 0 <0.000004>
 0.000016 fstat(5, {st_mode=S_IFREG|0644, st_size=2497, ...}) = 0 <0.000004>
 0.000026 mmap(NULL, 2497, PROT_READ, MAP_SHARED, 5, 0) = 0x7f434ded0000 <0.000007>
 0.000029 lseek(5, 2497, SEEK_SET)  = 2497 <0.000003>
 0.000027 munmap(0x7f434ded0000, 2497) = 0 <0.000008>
 0.000020 close(5)                  = 0 <0.000005>
 0.000021 open("/proc/self/loginuid", O_WRONLY|O_TRUNC|O_NOFOLLOW) = 5 <0.000012>
 0.000030 write(5, "1001", 4)       = 4 <0.000022>
 0.000046 close(5)                  = 0 <0.000006>
 0.000028 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f434dea89d0) = 3360 <0.000124>
 0.000156 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1], NULL, 8) = 0 <0.000004>
 0.000027 rt_sigaction(SIGTERM, {0x4036f0, [], SA_RESTORER, 0x7f434d54a4f0}, NULL, 8) = 0 <0.000003>
 0.000022 rt_sigprocmask(SIG_UNBLOCK, [ALRM TERM], NULL, 8) = 0 <0.000003>
 0.000017 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED, NULL) = 3360 <4.441088>
 4.441156 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000008>
 0.000033 lseek(5, 0, SEEK_CUR)     = 0 <0.000004>
 0.000017 fstat(5, {st_mode=S_IFREG|0644, st_size=2497, ...}) = 0 <0.000004>
 0.000029 mmap(NULL, 2497, PROT_READ, MAP_SHARED, 5, 0) = 0x7f434ded0000 <0.000032>
 0.000059 lseek(5, 2497, SEEK_SET)  = 2497 <0.000005>
 0.000051 munmap(0x7f434ded0000, 2497) = 0 <0.000007>
 0.000022 close(5)                  = 0 <0.000005>
 0.000046 getuid()                  = 0 <0.000005>
 0.000025 time([1380063578])        = 1380063578 <0.000004>
 0.000043 sendto(3, "<86>Sep 25 00:59:38 su[3318]: pa"..., 85, MSG_NOSIGNAL, NULL, 0) = 85 <0.000008>
 0.000041 close(4)                  = 0 <0.000010>
 0.000058 munmap(0x7f434c8db000, 2101312) = 0 <0.000013>

[^] # Re: Je n'appelerais pas cela une piste...

Posté par tatrefthekiller le 25 septembre 2013 à 00:36. Évalué à 1.

Il faut chercher quelques lignes plus haut un descripteur de fichier (fd) égal à 4. Sachant que sous Linux ça peut être aussi du réseau par ex :

socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4

Moi je parie sur un timeout DNS :-)
- [^] # Re: Je n'appelerais pas cela une piste...
  
  Posté par Chris K. le 25 septembre 2013 à 01:15. Évalué à 2.
  
  Bingo… a priori d’après ce que j'ai pu voir rapidement c'est en rapport avec l'ouverture d'un socket vers nscd qui… n'est pas installé. Si quelqu'un de plus habitué à strace peut confirmer.
  
  Après ne connaissant pas ce service et ne l'ayant jamais installé pourquoi diable va t il essayer de se connecter à ce truc c'est une toute autre question.
  
  En tout cas merci à tout le monde pour le coup de main.

# Truc sur le réseau ?

Posté par benoar le 24 septembre 2013 à 18:15. Évalué à 3.

Ce genre de timeout, ça ressemble à quelque chose lié au réseau. Pourrais-tu tu faire un tcpdump voir si tu vois quelque chose ?

Je parle tcpdump avant le « reste » car je ne vois pas trop comment tu aurais pu faire des changements de config qui arrivent à ça, vu que normalement su n'y touche pas trop (autant sudo fait de la résolution de nom, mais pas su, je crois), mais aussi car vu comme c'est louche, ça pourrait être dû à quelque chose que tu ne contrôle pas (rootkit ?…).
- [^] # Re: Truc sur le réseau ?
  
  Posté par Chris K. le 24 septembre 2013 à 18:50. Évalué à 1.
  
  Ce genre de timeout, ça ressemble à quelque chose lié au réseau
  
  Je suis aussi partit sur cette piste et j'ai vérifié quelques petits trucs comme la présence de localhost et localhost.localdomain qui pointent bien vers 127.0.0.1 dans /etc/hosts mais je n'ai rien trouvé de spécial.
  
  Pour tcpdump ca va être coton car la machine est en utilisation (elle ne présente absolument aucun autre soucis) et il y a beaucoup de traffic… il va falloir que trouve un moyen de filtrer tout ça.
  
  Franchement si c'est un rootkit ce sera le plus beau que je n'ai jamais vu car les vérification des signatures md5 des fichiers sont OK, il n'y a pas d'activité suspecte à aucun niveau (logs, fichiers, …) et les vérification avec rkhunter/chkrootkit et unhide sont normales.
  
  Bref je pense plus pour une ânerie du coté du réseau avec ce fameux poll…
  - [^] # Re: Truc sur le réseau ?
    
    Posté par NeoX le 24 septembre 2013 à 20:17. Évalué à 4.
    
    au hasard, ton root est local, ton user est sur un annuaire ldap/ad
    
    du coup su - est rapide car tu cherches en local
    su - le_userest plus lent car y a une recherche dans l'annuaire, annuaire qui fait peut-etre un reverse lookup de ta machine, etc
    - [^] # Re: Truc sur le réseau ?
      
      Posté par Chris K. le 25 septembre 2013 à 00:20. Évalué à 1.
      
      Non non je l'aurai tout de même précisé ^{^.} Pas d'annuaire et su est lent dans tous les cas de figure…
      - [^] # Re: Truc sur le réseau ?
        
        Posté par NeoX le 25 septembre 2013 à 07:41. Évalué à 3.
        
        donc dans les deux cas :
        
        la demande de mot de passe est instantanée mais l'ouverture du shell mets le même temps.
        
        faut regarder les fichiers de configuration du shell
        y a peut-etre des actions qui prennent du temps.
        
        /etc/profile
        /etc/bashrc
        ~/.profile
        ~/.bashrc
        
        etc
        
        [^] # Re: Truc sur le réseau ?
        
        Posté par Chris K. le 25 septembre 2013 à 20:39. Évalué à 1. Dernière modification le 25 septembre 2013 à 20:40.
        
        J'ai également pensé à cela mais lors d'une ouverture de session par ssh le chargement du shell est instantané. J'ai également changé le shell de l'utilisateur et le temps de réponse est toujours très long.
        
        [^] # Re: Truc sur le réseau ?
        
        Posté par NeoX le 25 septembre 2013 à 20:42. Évalué à 2.
        
        ca le fait pour un utilisateur ou pour tous ?
        
        [^] # Re: Truc sur le réseau ?
        
        Posté par Chris K. le 25 septembre 2013 à 21:28. Évalué à 1.
        
        Absolument tous oui, je pense que la piste nscd est effectivement la bonne. J'ai n'ai malheureusement pas encore eu le temps de la creuser.
        
        Merci en tout cas.
        Je vous tiens au courant de la suite.
# DBUSquer le problème

Posté par ecid le 27 septembre 2013 à 10:47. Évalué à 2.
Bonjour,

Voici mon analyse, pour ce qu'elle vaut:

Connexion à /var/run/dbus/system_bus_socket
```
socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC, 0) = 4 <0.000006>
connect(4, {sa_family=AF_FILE, path="/var/run/dbus/system_bus_socket"}, 33) = 0 <0.000010>
```
La négotiation ne prend pas de temps, on envoie et reçoit (le buffer par défaut de strace ne permet pas logguer l'ensemble des messages, on ne voit pas donc pas quelle "ressource" est demandée [ord.freedesktop…]

La "ressource" demandée n'est pas disponible/ne répond pas:
```
0.000047 recvmsg(4, 0x7fff31780700, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) 
```
On essaie une foie encore [flag EAGAIN] et on "poll" avec un timeout de 25000ms. Comme rien ne se passe, on ouvre /etc/passwd une fois ces 25s passées:
```
0.000038 poll([{fd=4, events=POLLIN}], 1, 25000) = 0 (Timeout) <25.006077>
25.006150 open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 5 <0.000010>
```
Voilà pour les 25s de perdues. Reste encore les 4 à 5 secondes restantes:

Après avoir fermé /etc/passwd, on clone le process:
```
0.000028 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,     child_tidptr=0x7f434dea89d0) = 3360 <0.000124>
```
Un peu plus loin, on attend que ce process fils se termine en utilisant wait4(). Cela prend 4.4s
```
0.000017 wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED, NULL) = 3360 ****<4.441088>****
```
Reste à savoir quelle ressource est demandée via dbus et ce que fait le process fils pour qu'il faille attendre encore 4.4s

Encore du strace en perspective.

Suivre le flux des commentaires

Note : les commentaires appartiennent à celles et ceux qui les ont postés. Nous n’en sommes pas responsables.