Note: This started as a "How to debug", tutorial, but ended up being the solution that helped me on an Ubuntu 16.04 LTS server.
TLDR: Run landscape-sysinfo
and check if that command takes a long time to finish; it's the system information printout on a new SSH login. If that's the case, you may be able to disable the execution of /etc/update-motd.d/50-landscape-sysinfo
, which does call that command, by chmod -x
-ing it. Note that this command isn't available on all systems, the landscape-common
package installs it.
Start a second ssh server on another port on the machine that has the problem, do so in debug mode, which won't make it fork and will print out debug messages:
sudo /usr/sbin/sshd -ddd -p 44321
connect to that server from another machine in verbose mode:
ssh -vvv -p 44321 username@server
My client outputs the following lines right before starting to sleep:
debug1: Entering interactive session.
debug1: pledge: network
Googling that isn't really helpful, but the server logs are better:
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
I noticed that when I change UsePAM yes
to UsePAM no
then this issue is resolved.
Not related to UseDNS
or any other setting, only UsePAM
affects this problem on my system.
I have no clue why, and I'm also not leaving UsePAM
at no
, because I do not know which the side-effects are, but this lets me continue investigating.
So please don't consider this to be an answer, but a first step to start finding out what's wrong.
So I continued investigating, and ran sshd
with strace
(sudo strace /usr/sbin/sshd -ddd -p 44321
). This yielded the following:
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
The line /etc/update-motd.d
made me suspicious, apparently the process waits for the result of the stuff that is in /etc/update-motd.d
So I cd
'd into /etc/update-motd.d
and ran a sudo chmod -x *
in order to inhibit PAM to run all the files which generate this dynamic Message Of The Day
, which includes system load and if packages need to be upgraded, and this solved the issue.
This is a server based on an "energy-efficient" N3150 CPU which has a lot of work to do 24/7, so I think that collecting all this motd-data was just too much for it.
I may start to enable scripts in that folder selectively, to see which are less harmful, but specially calling landscape-sysinfo
is very slow, and 50-landscape-sysinfo
does call that command. I think that is the one which causes the biggest delay.
After reenabling most of the files I came to the conclusion that
50-landscape-sysinfo
and 99-esm
were the cause for my troubles. 50-landscape-sysinfo
took about 5 seconds to execute and 99-esm
about 3 seconds. All the remaining files about 2 seconds altogether.
Neither 50-landscape-sysinfo
and 99-esm
are crucial. 50-landscape-sysinfo
prints out interesting system stats (and also if you're low on space!), and 99-esm
prints out messages related to Ubuntu Extended Security Maintenance
Finally you can create a script with echo '/usr/bin/landscape-sysinfo' > info.sh && chmod +x info.sh
and get that printout upon request.