Uwaga: To zaczęło się jako “Jak debugować”, samouczek, ale skończyło się na rozwiązaniu, które pomogło mi na serwerze Ubuntu 16.04 LTS.
TLDR : Uruchom landscape-sysinfo i sprawdź, czy to polecenie długo się kończy; jest to wydruk informacji systemowych przy nowym logowaniu SSH. Zauważ, że ta komenda nie jest dostępna na wszystkich systemach, pakiet landscape-common ją instaluje. (“But wait, there’s more…”)
Uruchom drugi serwer ssh na innym porcie na maszynie, która ma problem, zrób to w trybie debug, co nie spowoduje jego rozwidlenia i wydrukuje komunikaty debug:
sudo /usr/sbin/sshd -ddd -p 44321
Połącz się z tym serwerem z innej maszyny w trybie verbose:
ssh -vvv -p 44321 username@server
Mój klient wypisuje następujące linie tuż przed rozpoczęciem snu:
debug1: Entering interactive session.
debug1: pledge: network
Googlowanie tego nie jest zbyt pomocne, ale logi serwera są lepsze:
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
Zauważyłem, że gdy zmienię UsePAM yes na UsePAM no wtedy ten problem zostaje rozwiązany.
Nie jest to związane z UseDNS lub jakimkolwiek innym ustawieniem, tylko UsePAM ma wpływ na ten problem w moim systemie.
Nie mam pojęcia dlaczego, a także nie zostawiam UsePAM na no, ponieważ nie wiem, jakie są skutki uboczne, ale to pozwala mi kontynuować badania.
Więc proszę nie traktuj tego jako odpowiedzi, ale jako pierwszy krok do rozpoczęcia poszukiwania tego, co jest nie tak.
Więc kontynuowałem dochodzenie i uruchomiłem sshd z strace (sudo strace /usr/sbin/sshd -ddd -p 44321). Dało to następujące wyniki:
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
Linia /etc/update-motd.d wzbudziła moje podejrzenia, najwyraźniej proces czeka na wynik rzeczy, które znajdują się w /etc/update-motd.d
Tak więc cd‘d do /etc/update-motd.d i uruchomiłem sudo chmod -x * w celu zablokowania PAM do uruchomienia wszystkich plików, które generują to dynamiczne Message Of The Day, co obejmuje obciążenie systemu i jeśli pakiety wymagają aktualizacji, a to rozwiązało problem.
Jest to serwer oparty na “energooszczędnym” procesorze N3150, który ma dużo pracy 24/7, więc myślę, że zbieranie tych wszystkich danych motd było dla niego po prostu zbyt dużym obciążeniem.
Może zacznę selektywnie włączać skrypty w tym folderze, aby zobaczyć, które są mniej szkodliwe, ale specjalnie wywoływanie landscape-sysinfo jest bardzo powolne, a 50-landscape-sysinfo wywołuje tę komendę. Myślę, że to właśnie ona powoduje największe opóźnienia.
Po ponownym włączeniu większości plików doszedłem do wniosku, że50-landscape-sysinfo i 99-esm były przyczyną moich kłopotów. 50-landscape-sysinfo potrzebował około 5 sekund na wykonanie, a 99-esm około 3 sekund. Wszystkie pozostałe pliki około 2 sekund łącznie.
Ani 50-landscape-sysinfo, ani 99-esm nie są kluczowe. 50-landscape-sysinfo wypisuje interesujące statystyki systemowe (a także jeśli masz mało miejsca!), a 99-esm wypisuje komunikaty związane z Ubuntu Extended Security Maintenance
W końcu możesz stworzyć skrypt z echo '/usr/bin/landscape-sysinfo' > info.sh && chmod +x info.sh i uzyskać ten wydruk na żądanie.