A pesquisa reversa de DNS do sshd é sempre um candidato quando você tem longos atrasos de login. Você poderia tentar se definir
UseDNS no
no /etc/ssh/sshd.conf (e reiniciando o sshd depois) corrige o problema.
Eu tenho um servidor que está agindo muito estranho e espero que você me ajude a descobrir o que está acontecendo. Aqui estão os fatos:
root e myuser
myuser do Putty (no Windows), a conexão levará alguns segundos e o prompt do cmd aparecerá imediatamente myuser do Cygwin (no Windows), a conexão levará alguns segundos, mas demora cerca de 40 segundos para o prompt cmd aparecer. O mesmo ocorre quando se conecta a partir de um script PHP ou mesmo com ssh de outro servidor linux na mesma rede OpenSSH_7.2p1, OpenSSL 1.0.2g , no PHP a biblioteca phpseclib e no outro servidor linux OpenSSH_5.3p1, OpenSSL 1.0.1e-fips
root produz os mesmos resultados Assim, a conexão ssh é estabelecida corretamente em ambos os casos (os logs sshd escrevem session opened for user myuser ), mas em um caso os prompts cmd aparecem imediatamente e no outro demoram demais (60 segundos).
Alguma idéia do que poderia causar o problema? Se você precisar de mais informações sobre mensagens de logs ou arquivos de configuração, me avise nos comentários.
UPDATE 1
A execução de strace ssh [email protected] gera o seguinte:
**lot of stuff**
18:20:10 read(3, "Dq02+76r51225462D74$
18:20:10 ioctl(0, TIOCGWINSZ, {ws_row=60, ws_col=237, ws_xpixel=0, ws_ypixel=0}) = 0
18:20:10 getsockopt(3, SOL_TCP, TCP_NODELAY, [0], [4]) = 0
18:20:10 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
18:20:10 getsockname(3, {sa_family=AF_INET, sin_port=htons(40713), sin_addr=inet_addr("190.9$
18:20:10 setsockopt(3, SOL_IP, IP_TOS, [16], 4) = 0
18:20:10 select(7, [3], [3], NULL, NULL) = 1 (out [3])
18:20:10 write(3, "?325762x74>2K65)5071Zu,I!3Hv1$
18:20:10 select(7, [3], [], NULL, NULL) = 1 (in [3])
18:20:10 read(3, "7736442506zl0X5i073f$
18:20:10 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
18:20:10 read(3, "J2546045<D\t5Y61!_107C2I2|\$
18:20:10 select(7, [3 4], [5], NULL, NULL) = 1 (out [5])
18:20:10 write(5, "Last login: Fri Mar 4 18:19:33 "..., 58) = 58
18:20:10 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
# Here is where it waits 60 seconds
18:21:10 read(3, ":357P6.u&5273162aN33353\$
18:21:10 select(7, [3 4], [5], NULL, NULL) = 1 (out [5])
18:21:10 write(5, "[?1034h[securitybox@wordpress10"..., 41) = 41
18:21:10 select(7, [3 4], [], NULL, NULL) = 1 (in [4])
18:21:14 read(4, "e", 16384) = 1
18:21:14 select(7, [3 4], [3], NULL, NULL) = 1 (out [3])
18:21:14 write(3, ":65J2w+3i041\vc024711o6$
18:21:14 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
18:21:14 read(3, "eS2U<65f53<J1%1hx&k3 0\n^-P"..., 8$
18:21:14 select(7, [3 4], [5], NULL, NULL) = 1 (out [5])
18:21:14 write(5, "e", 1) = 1
18:21:14 select(7, [3 4], [], NULL, NULL) = 1 (in [4])
18:21:14 read(4, "x", 16384) = 1
**more stuff**
UPDATE 2
Saiba que depois do Último login: , quando ele estiver desligado, você pode pressionar Ctrl + C e ele mostrará o prompt de comando imediatamente. Então, parece que há um processo que está demorando demais na inicialização.
UPDATE 3
Eu aumentei o nível de depuração no lado do servidor e aqui estão as saídas dos lates antes de aguardar e aguardar:
Mar 4 17:15:31 thisserver.hostname sshd[2279]: debug3: PAM: opening session
Mar 4 17:15:32 thisserver.hostname sshd[2279]: pam_unix(sshd:session): session opened for user securitybox by (uid=0)
Mar 4 17:15:32 thisserver.hostname sshd[2279]: User child is on pid 2301
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_request_receive entering
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: PAM: establishing credentials
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: permanently_set_uid: 10037/10037
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: set_newkeys: mode 0
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: set_newkeys: mode 1
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: Entering interactive session for SSH2.
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 4 setting O_NONBLOCK
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 6 setting O_NONBLOCK
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_init_dispatch_20
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: input_session_request
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: channel 0: new [server-session]
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: session_new: allocate (allocated 0 max 10)
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: session_unused: session id 0 unused
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_new: session 0
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_open: channel 0
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_open: session 0: link with channel 0
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_open: confirm session
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_global_request: rtype [email protected] want_reply 0
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: Wrote 40 bytes for a total of 2701
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_by_channel: session 0 channel 0
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_input_channel_req: session 0 req pty-req
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: Allocating pty.
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_request_send entering: type 26
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_pty_allocate: waiting for MONITOR_ANS_PTY
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_request_receive_expect entering: type 27
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: mm_request_receive entering
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: monitor_read: checking request 26
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_answer_pty entering
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug2: session_new: allocate (allocated 0 max 10)
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: session_unused: session id 0 unused
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug1: session_new: session 0
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: ssh_selinux_setup_pty: setting TTY context on /dev/pts/6
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: ssh_selinux_setup_pty: done
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_request_send entering: type 27
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_answer_pty: tty /dev/pts/6 ptyfd 4
Mar 4 17:15:32 thisserver.hostname sshd[2279]: debug3: mm_request_receive entering
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_pty_req: session 0 alloc /dev/pts/6
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: server_input_channel_req: channel 0 request shell reply 1
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_by_channel: session 0 channel 0
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug1: session_input_channel_req: session 0 req shell
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 3 setting TCP_NODELAY
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: channel 0: rfd 9 isatty
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug2: fd 9 setting O_NONBLOCK
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: fd 7 is O_NONBLOCK
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: Wrote 88 bytes for a total of 2789
Mar 4 17:15:32 thisserver.hostname sshd[2302]: debug1: Setting controlling tty using TIOCSCTTY.
Mar 4 17:15:32 thisserver.hostname sshd[2301]: debug3: Wrote 88 bytes for a total of 2877
Mar 4 17:15:32 thisserver.hostname sshd[2302]: debug3: Copy environment: SELINUX_ROLE_REQUESTED=
Mar 4 17:15:32 thisserver.hostname sshd[2302]: debug3: Copy environment: SELINUX_LEVEL_REQUESTED=
Mar 4 17:15:32 thisserver.hostname sshd[2302]: debug3: Copy environment: SELINUX_USE_CURRENT_RANGE=
Mar 4 17:15:32 thisserver.hostname sshd[2302]: debug3: channel 0: close_fds r -1 w -1 e -1
Depois de algum tempo, ao mesmo tempo em que o prompt aparece, ele imprime:
Mar 4 17:16:32 thisserver.hostname sshd[2301]: debug3: Wrote 72 bytes for a total of 2949
Lá você pode ver que demorou 60 segundos. sempre leva exatamente 60 segundos.
Aqui está a saída do mesmo log ao conectar usando o Putty (lembre-se de que o uso do Putty faz o prompt aparecer imediatamente).
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: PAM: opening session
Mar 4 17:44:45 thisserver.hostname sshd[5505]: pam_unix(sshd:session): session opened for user root by (uid=0)
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: set_newkeys: mode 0
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: cipher_init: set keylen (16 -> 32)
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: set_newkeys: mode 1
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: cipher_init: set keylen (16 -> 32)
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: Entering interactive session for SSH2.
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 4 setting O_NONBLOCK
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 5 setting O_NONBLOCK
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_init_dispatch_20
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_open: ctype session rchan 256 win 16384 max 16384
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: input_session_request
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: channel 0: new [server-session]
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: session_new: allocate (allocated 0 max 10)
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: session_unused: session id 0 unused
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_new: session 0
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_open: channel 0
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_open: session 0: link with channel 0
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_open: confirm session
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 52 bytes for a total of 3185
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_req: channel 0 request pty-req reply 1
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_by_channel: session 0 channel 0
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_input_channel_req: session 0 req pty-req
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: Allocating pty.
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_pty_req: session 0 alloc /dev/pts/7
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: ssh_selinux_setup_pty: setting TTY context on /dev/pts/7
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: ssh_selinux_setup_pty: done
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 36 bytes for a total of 3221
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: server_input_channel_req: channel 0 request shell reply 1
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_by_channel: session 0 channel 0
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug1: session_input_channel_req: session 0 req shell
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 3 setting TCP_NODELAY
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: channel 0: rfd 8 isatty
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug2: fd 8 setting O_NONBLOCK
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: fd 6 is O_NONBLOCK
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 88 bytes for a total of 3309
Mar 4 17:44:45 thisserver.hostname sshd[5508]: debug1: Setting controlling tty using TIOCSCTTY.
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 100 bytes for a total of 3409
Mar 4 17:44:45 thisserver.hostname sshd[5508]: debug1: PAM: reinitializing credentials
Mar 4 17:44:45 thisserver.hostname sshd[5508]: debug1: permanently_set_uid: 0/0
Mar 4 17:44:45 thisserver.hostname sshd[5508]: debug3: Copy environment: SELINUX_ROLE_REQUESTED=
Mar 4 17:44:45 thisserver.hostname sshd[5508]: debug3: Copy environment: SELINUX_LEVEL_REQUESTED=
Mar 4 17:44:45 thisserver.hostname sshd[5508]: debug3: Copy environment: SELINUX_USE_CURRENT_RANGE=
Mar 4 17:44:45 thisserver.hostname sshd[5508]: debug3: channel 0: close_fds r -1 w -1 e -1
Mar 4 17:44:45 thisserver.hostname sshd[5505]: debug3: Wrote 84 bytes for a total of 3493
UPDATE 4
Descobri que o processo está pendente na chamada do sistema:
select(7, [3 4], [], NULL, NULL
Esta foi a saída de strace -p $PID , em que $PID é o pid do programa ssh enquanto permeia a conexão.
A pesquisa reversa de DNS do sshd é sempre um candidato quando você tem longos atrasos de login. Você poderia tentar se definir
UseDNS no
no /etc/ssh/sshd.conf (e reiniciando o sshd depois) corrige o problema.
Tente aumentar os níveis de depuração no lado do servidor, em vez do cliente.
Parece que talvez algo na pilha do PAM esteja demorando (possivelmente é o que está fazendo pesquisas lentas, etc., em vez do próprio sshd). O registro detalhado no lado do servidor ssh deve informar a você qual módulo pam (se houver algum) está atrasando as coisas e geralmente há opções para ativar o registro detalhado desses módulos que podem ajudar.
Aproveitando a resposta da BeerSerc, usando a seguinte abordagem no UBUNTU LTS 14.05.5, obtive uma aparência mais rápida do prompt de comando depois de fornecer credenciais de nome de usuário e senha SSH com as seguintes alterações em meu sistema Linux:
...become root using su or preface the next two (2) lines with the sudo command...
#cd /etc/ssh
#vi sshd_config
...navigate to end of file, add following text...
# GL 2017-02-25 Turn off DNS lookups to speed up the appearance
# of the command prompt after SSH username and
# password have been supplied
UseDNS no
...save file and exit editor...
#/etc/init.d/ssh restart