Opmerking: Dit begon als een “Hoe te debuggen”, tutorial, maar eindigde als de oplossing die me hielp op een Ubuntu 16.04 LTS server.
TLDR : Voer landscape-sysinfo uit en controleer of het lang duurt voordat dat commando klaar is; het is de systeeminformatie die wordt afgedrukt bij een nieuwe SSH login. Merk op dat dit commando niet op alle systemen beschikbaar is, het landscape-common pakket installeert het. (“Maar wacht, er is meer…”)
Start een tweede ssh server op een andere poort op de machine die het probleem heeft, doe dit in debug mode, waardoor het niet fork en debug boodschappen zal uitdraaien:
sudo /usr/sbin/sshd -ddd -p 44321
maak verbinding met die server vanaf een andere machine in verbose mode:
ssh -vvv -p 44321 username@server
Mijn client geeft de volgende regels af vlak voordat hij begint te slapen:
debug1: Entering interactive session.
debug1: pledge: network
Googlen helpt niet echt, maar de serverlogs zijn beter:
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
Ik heb gemerkt dat als ik UsePAM yes verander in UsePAM no dan is dit probleem opgelost.
Niet gerelateerd aan UseDNS of een andere instelling, alleen UsePAM heeft invloed op dit probleem op mijn systeem.
Ik heb geen idee waarom, en ik laat UsePAM ook niet op no staan, omdat ik niet weet wat de neveneffecten zijn, maar dit laat me verder onderzoek doen.
Dus beschouw dit alstublieft niet als een antwoord, maar als een eerste stap om uit te zoeken wat er mis is.
Dus ging ik verder met het onderzoek, en liep sshd met strace (sudo strace /usr/sbin/sshd -ddd -p 44321). Dit leverde het volgende op:
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
De regel /etc/update-motd.d maakte me achterdochtig, blijkbaar wacht het proces op het resultaat van de dingen die in /etc/update-motd.d
staan, dus ik cd‘d in /etc/update-motd.d en liep een sudo chmod -x * om PAM te remmen om alle bestanden uit te voeren die deze dynamische Message Of The Day genereren, waaronder systeembelasting en of pakketten geüpgrade moeten worden, en dit loste het probleem op.
Dit is een server gebaseerd op een “energiezuinige” N3150 CPU die 24/7 veel werk te doen heeft, dus ik denk dat het verzamelen van al deze motd-data gewoon te veel was voor hem.
Ik ga misschien selectief scripts in die map aanzetten, om te zien welke minder schadelijk zijn, maar speciaal het aanroepen van landscape-sysinfo is erg traag, en 50-landscape-sysinfo roept dat commando wel aan. Ik denk dat dat degene is die de grootste vertraging veroorzaakt.
Na het opnieuw aanroepen van de meeste bestanden kwam ik tot de conclusie dat50-landscape-sysinfo en 99-esm de oorzaak van mijn problemen waren. 50-landscape-sysinfo deed er ongeveer 5 seconden over om uit te voeren en 99-esm ongeveer 3 seconden. Alle andere bestanden samen ongeveer 2 seconden.
Noch 50-landscape-sysinfo en 99-esm zijn cruciaal. 50-landscape-sysinfo drukt interessante systeem statistieken af (en ook als je weinig ruimte hebt!), en 99-esm drukt berichten af die gerelateerd zijn aan Ubuntu Extended Security Maintenance
Tenslotte kun je een script maken met echo '/usr/bin/landscape-sysinfo' > info.sh && chmod +x info.sh en die afdruk op verzoek krijgen.