Nota: Isto começou como um “Como depurar”, tutorial, mas acabou por ser a solução que me ajudou num Ubuntu 16.04 servidor LTS.
TLDR* : Executar landscape-sysinfo e verificar se esse comando leva muito tempo a terminar; é a impressão da informação do sistema num novo login SSH. Note-se que este comando não está disponível em todos os sistemas, o pacote landscape-common instala-o. (“Mas espera, há mais…”)
Iniciar um segundo servidor ssh noutra porta da máquina que tenha o problema, fazê-lo em modo de depuração, o que não o fará fork e imprimirá mensagens de depuração:
sudo /usr/sbin/sshd -ddd -p 44321
ligar a esse servidor a partir de outra máquina em modo verboso:
ssh -vvv -p 44321 username@server
O meu cliente emite as seguintes linhas mesmo antes de começar a dormir:
debug1: Entering interactive session.
debug1: pledge: network
Googling que não é realmente útil, mas os registos do servidor são melhores:
debug3: mm_send_keystate: Finished sending state [preauth]
debug1: monitor_read_log: child log fd closed
debug1: PAM: establishing credentials
debug3: PAM: opening session
---- Pauses here ----
debug3: PAM: sshpam_store_conv called with 1 messages
User child is on pid 28051
Notei que quando mudo UsePAM yes para UsePAM no então esta questão está resolvida.
Não relacionado com UseDNS ou qualquer outra configuração, apenas UsePAM afecta este problema no meu sistema.
não faço ideia porquê, e também não vou deixar UsePAM em no, porque não sei quais são os efeitos secundários, mas isto permite-me continuar a investigar.
Portanto, por favor não considere isto como uma resposta, mas como um primeiro passo para começar a descobrir o que está errado.
Assim, continuei a investigar, e corri sshd com strace (sudo strace /usr/sbin/sshd -ddd -p 44321). Isto produziu o seguinte:
sendto(4, "<87>Nov 20 20:35:21 sshd[2234]: "..., 110, MSG_NOSIGNAL, NULL, 0) = 110
close(5) = 0
stat("/etc/update-motd.d", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
umask(022) = 02
rt_sigaction(SIGINT, {SIG_IGN, [], SA_RESTORER, 0x7f15dce784b0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGQUIT, {SIG_IGN, [], SA_RESTORER, 0x7f15dce784b0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
clone(child_stack=0, flags=CLONE_PARENT_SETTID|SIGCHLD, parent_tidptr=0x7ffde6152d2c) = 2385
wait4(2385, # BLOCKS RIGHT HERE, BEFORE THE REST IS PRINTED OUT # [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 2385
A linha /etc/update-motd.d fez-me suspeitar, aparentemente o processo espera pelo resultado do material que está em /etc/update-motd.d
Então eu cd‘d into /etc/update-motd.d e corri um sudo chmod -x * para inibir o PAM de correr todos os ficheiros que geram esta dinâmica Message Of The Day, o que inclui a carga do sistema e se os pacotes precisam de ser actualizados, e isto resolveu o problema.
Este é um servidor baseado num CPU N3150 “energeticamente eficiente” que tem muito trabalho para fazer 24/7, por isso penso que recolher todos estes dados motd era demasiado para ele.
Posso começar a activar os scripts nessa pasta selectivamente, para ver quais são menos nocivos, mas especialmente chamar landscape-sysinfo é muito lento, e 50-landscape-sysinfo chama esse comando. Penso que é o que causa o maior atraso.
Depois de reactivar a maioria dos ficheiros cheguei à conclusão de que 50-landscape-sysinfo e 99-esm foram a causa dos meus problemas. 50-landscape-sysinfo levou cerca de 5 segundos a executar e 99-esm cerca de 3 segundos. Todos os restantes ficheiros demoraram cerca de 2 segundos no total.
nem 50-landscape-sysinfo e 99-esm são cruciais. 50-landscape-sysinfo imprime estatísticas interessantes do sistema (e também se tiver pouco espaço!), e 99-esm imprime mensagens relacionadas com Ubuntu Extended Security Maintenance
Finalmente, pode criar um guião com echo '/usr/bin/landscape-sysinfo' > info.sh && chmod +x info.sh e obter essa impressão a pedido.