Estou executando um servidor em casa com o Ubuntu 14.04. Eu tenho dois usuários na máquina, digamos user1 e user2 , cada um capaz de ssh na caixa. Enquanto user1 efetua login muito rapidamente, user2 leva cerca de 20 segundos para efetuar login. O mesmo comportamento acontece independentemente de qual usuário está efetuando login de qualquer máquina em particular.
Fazer login como user2 com ssh -v mostra que a pausa principal acontece após essa mensagem:
debug1: Sending environment.
Os arquivos .bashrc para os dois usuários são idênticos. (Um diff neles não produz saída.) O mesmo para os arquivos .profile para user1 e user2 .
No servidor, há uma linha em /etc/ssh/sshd_config com AllowUsers user1 user2 . Esse mesmo arquivo já tem UseDNS no . (Eu só mencionei isso porque a maioria das páginas eu encontrei enquanto procurava por uma solução mencionada para adicionar aquela linha.)
Este problema começou há apenas uma semana; Eu não tive tais problemas nos últimos dois anos que eu tenho usado a máquina.
Por um capricho, criei um novo usuário, user3 , dei acesso ao usuário ssh editando sshd_config apropriadamente e o login para o novo usuário é rápido. Então, parece ser algo sobre a maneira como o user2 está configurado. Mas o que?
Onde devo procurar a causa raiz do atraso para o login em user2 ?
EDIT: Abaixo estão os resultados de tail -f /var/log/auth.log quando user2 efetua login:
Jun 21 11:27:10 topo sshd[18386]: Connection from re.mo.te.ip port XXXXX on se.rv.er.ip port XX
Jun 21 11:27:21 topo sshd[18386]: Accepted password for user2 from re.mo.te.ip port XXXXX ssh2
Jun 21 11:27:21 topo sshd[18386]: pam_unix(sshd:session): session opened for user user2 by (uid=0)
Jun 21 11:27:21 topo systemd-logind[3347]: New session 25 of user user2.
Jun 21 11:28:03 topo sshd[18386]: User child is on pid XXXXX
Jun 21 11:28:03 topo sshd[18455]: Starting session: shell on pts/6 for user2 from re.mo.te.ip port XXXXX
Anote os carimbos de hora. O atraso ocorre após a última mensagem aqui. Nenhuma mensagem aparece no auth.log uma vez que user2 está finalmente logado.
EDIT: Abaixo estão alguns resultados de strace -f -p <sshd pid> -o out.tx -tt onde há atrasos.
22733 12:59:10.414388 open("/usr/lib/python2.7/dist-packages/twisted/python/compat.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:10.840303 open("/usr/lib/python2.7/dist-packages/twisted/python/compat.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:11.264716 open("/usr/lib/python2.7/dist-packages/twisted/python/compatmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:11.717471 open("/usr/lib/python2.7/dist-packages/twisted/python/compat.py", O_RDONLY) = 4
22733 12:59:12.660275 fstat(4, {st_mode=S_IFREG|0644, st_size=11146, ...}) = 0
...
22733 12:59:12.661502 open("/usr/lib/python2.7/dist-packages/twisted/python/__future__.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:13.212844 open("/usr/lib/python2.7/dist-packages/twisted/python/__future__.so", O_RDONLY) = -1 ENOENT (No such file or directory)
...
22733 12:59:14.441963 open("/usr/bin/dis.py", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:14.900322 open("/usr/bin/dis.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:15.401750 stat("/usr/lib/python2.7/dis", 0x7ffcb599ddd0) = -1 ENOENT (No such file or directory)
...
22733 12:59:17.315288 open("/usr/lib/python2.7/dist-packages/twisted/internet/termios.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:17.967173 open("/usr/lib/python2.7/dist-packages/twisted/internet/termiosmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:18.511526 open("/usr/lib/python2.7/dist-packages/twisted/internet/termios.py", O_RDONLY) = -1 ENOENT (No such file or directory)
...
22733 12:59:25.993287 open("/usr/lib/python2.7/dist-packages/landscape/monitor/time.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:26.612018 open("/usr/lib/python2.7/dist-packages/landscape/monitor/time.so", O_RDONLY) = -1 ENOENT (No such file or directory)
...
22733 12:59:29.688166 open("/proc/37/stat", O_RDONLY) = 9
22733 12:59:30.239695 fstat(9, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
...
22733 12:59:30.240450 open("/proc/uptime", O_RDONLY) = 10
22733 12:59:31.634404 fstat(10, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
...
22733 12:59:34.287758 open("/proc/557/stat", O_RDONLY) = 9
22733 12:59:34.851662 fstat(9, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
...
22758 12:59:39.500397 open(".", O_RDONLY) = 3
22758 12:59:40.377193 fchdir(3) = 0
22758 12:59:40.377312 newfstatat(AT_FDCWD, "/var/lib/apt//lists/", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_SYMLINK_NOFOLLOW) = 0
22758 12:59:40.377378 open(".", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_DIRECTORY|O_NOFOLLOW) = 4
22758 12:59:40.878676 fchdir(4) = 0
...
22759 12:59:41.680427 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
22759 12:59:42.249796 read(3, "7ELFdebug1: Sending environment.
Jun 21 11:27:10 topo sshd[18386]: Connection from re.mo.te.ip port XXXXX on se.rv.er.ip port XX
Jun 21 11:27:21 topo sshd[18386]: Accepted password for user2 from re.mo.te.ip port XXXXX ssh2
Jun 21 11:27:21 topo sshd[18386]: pam_unix(sshd:session): session opened for user user2 by (uid=0)
Jun 21 11:27:21 topo systemd-logind[3347]: New session 25 of user user2.
Jun 21 11:28:03 topo sshd[18386]: User child is on pid XXXXX
Jun 21 11:28:03 topo sshd[18455]: Starting session: shell on pts/6 for user2 from re.mo.te.ip port XXXXX
22733 12:59:10.414388 open("/usr/lib/python2.7/dist-packages/twisted/python/compat.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:10.840303 open("/usr/lib/python2.7/dist-packages/twisted/python/compat.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:11.264716 open("/usr/lib/python2.7/dist-packages/twisted/python/compatmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:11.717471 open("/usr/lib/python2.7/dist-packages/twisted/python/compat.py", O_RDONLY) = 4
22733 12:59:12.660275 fstat(4, {st_mode=S_IFREG|0644, st_size=11146, ...}) = 0
...
22733 12:59:12.661502 open("/usr/lib/python2.7/dist-packages/twisted/python/__future__.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:13.212844 open("/usr/lib/python2.7/dist-packages/twisted/python/__future__.so", O_RDONLY) = -1 ENOENT (No such file or directory)
...
22733 12:59:14.441963 open("/usr/bin/dis.py", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:14.900322 open("/usr/bin/dis.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:15.401750 stat("/usr/lib/python2.7/dis", 0x7ffcb599ddd0) = -1 ENOENT (No such file or directory)
...
22733 12:59:17.315288 open("/usr/lib/python2.7/dist-packages/twisted/internet/termios.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:17.967173 open("/usr/lib/python2.7/dist-packages/twisted/internet/termiosmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:18.511526 open("/usr/lib/python2.7/dist-packages/twisted/internet/termios.py", O_RDONLY) = -1 ENOENT (No such file or directory)
...
22733 12:59:25.993287 open("/usr/lib/python2.7/dist-packages/landscape/monitor/time.x86_64-linux-gnu.so", O_RDONLY) = -1 ENOENT (No such file or directory)
22733 12:59:26.612018 open("/usr/lib/python2.7/dist-packages/landscape/monitor/time.so", O_RDONLY) = -1 ENOENT (No such file or directory)
...
22733 12:59:29.688166 open("/proc/37/stat", O_RDONLY) = 9
22733 12:59:30.239695 fstat(9, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
...
22733 12:59:30.240450 open("/proc/uptime", O_RDONLY) = 10
22733 12:59:31.634404 fstat(10, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
...
22733 12:59:34.287758 open("/proc/557/stat", O_RDONLY) = 9
22733 12:59:34.851662 fstat(9, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
...
22758 12:59:39.500397 open(".", O_RDONLY) = 3
22758 12:59:40.377193 fchdir(3) = 0
22758 12:59:40.377312 newfstatat(AT_FDCWD, "/var/lib/apt//lists/", {st_mode=S_IFDIR|0755, st_size=12288, ...}, AT_SYMLINK_NOFOLLOW) = 0
22758 12:59:40.377378 open(".", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_DIRECTORY|O_NOFOLLOW) = 4
22758 12:59:40.878676 fchdir(4) = 0
...
22759 12:59:41.680427 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
22759 12:59:42.249796 read(3, "7ELF%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%>%pre%%pre%%pre%%pre%P %pre%%pre%%pre%%pre%%pre%"..., 832) = 832
...
22759 12:59:46.019309 open("/etc/lsb-release", O_RDONLY|O_CLOEXEC) = 64
22759 12:59:46.948115 fstat(64, {st_mode=S_IFREG|0644, st_size=105, ...}) = 0
...
22786 12:59:50.251281 open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
22786 12:59:50.970074 fcntl(1, F_GETFD) = 0
...
22785 12:59:53.338632 select(10, [3 4 6], [], NULL, NULL) = 1 (in [3])
22785 12:59:53.771002 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
%pre%%pre%%pre%%pre%%pre%%pre%%pre%>%pre%%pre%%pre%%pre%P %pre%%pre%%pre%%pre%%pre%"..., 832) = 832
...
22759 12:59:46.019309 open("/etc/lsb-release", O_RDONLY|O_CLOEXEC) = 64
22759 12:59:46.948115 fstat(64, {st_mode=S_IFREG|0644, st_size=105, ...}) = 0
...
22786 12:59:50.251281 open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
22786 12:59:50.970074 fcntl(1, F_GETFD) = 0
...
22785 12:59:53.338632 select(10, [3 4 6], [], NULL, NULL) = 1 (in [3])
22785 12:59:53.771002 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
Muito disso parece relacionado a bibliotecas python. No entanto, eles também são carregados quando user1 efetua login, apenas sem essas pausas de 0.5s.