Solved Slow SSH login

Hi all,

I am having an odd situation where my SSH sessions take ages to reach the prompt. For example it takes 30 seconds to run the below:
Code:
$ time ssh root@techanalysis "echo ok"
ok

real    0m30,422s
user    0m0,142s
sys    0m0,000s

The same command when run with the IP address is much faster:

Code:
time ssh root@192.168.42.154 "echo ok"
ok

real    0m0,239s
user    0m0,055s
sys    0m0,000s

This tells me that it most likely is an issue with DNS resolution. However testing with "drill" and other commands using the DNS name gives me instant responses, so there is something specific about SSH + DNS that is causing this issue. The machines are connected together via a switch and are on the same network, so there should be no routing or FW issues.

Anyone got any idea?
 
If this is on 14.x, it may be due to ObscureKeystrokeTiming setting. This was added to openssh.
I get around it by adding the following line to my .ssh/config file for the different hosts:

ObscureKeystrokeTiming "no"

You should be able to add that option on the ssh command line to test.
 
Most likely you are missing rDNS record, try to add UseDNS no in /etc/ssh/sshd_config then reload the sshd and test again.
This did not help, still takes 30 seconds to launch.

If this is on 14.x, it may be due to ObscureKeystrokeTiming setting. This was added to openssh.
I get around it by adding the following line to my .ssh/config file for the different hosts:

ObscureKeystrokeTiming "no"

You should be able to add that option on the ssh command line to test.
No dice, I get: /etc/ssh/sshd_config: line 124: Bad configuration option: ObscureKeystrokeTiming.
The version of sshd it is currently running is OpenSSH_9.5p1, OpenSSL 3.0.12 24 Oct 2023. Perhaps this version does not have that option?
Also I should note that I am connecting using a pubkey rather than username/password type login, not sure if the "ObscureKeystrokeTiming" would affect that?

EDIT: I now realise you meant to add it to my client config, which I did as so:
Host *
ObscureKeystrokeTiming "no"

While that is a valid config option, it unfortunately did not help, still takes 30 seconds to launch.

Run the ssh server in interactive / debug mode.

Done, results below:

Code:
debug1: sshd version OpenSSH_9.5, OpenSSL 3.0.12 24 Oct 2023
debug1: private host key #0: ssh-rsa SHA256:XXXX
debug1: private host key #1: ecdsa-sha2-nistp256 XXXX
debug1: private host key #2: ssh-ed25519 SHA256:XXXX
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-d'
debug1: rexec_argv[2]='-f'
debug1: rexec_argv[3]='/etc/ssh/sshd_config'
debug1: madvise(): Operation not permitted
debug1: Bind to port 22 on 0.0.0.0.
Server listening on 0.0.0.0 port 22.
---------- [ ~30 second pause] ------------
debug1: fd 4 clearing O_NONBLOCK
debug1: Server will not fork when running in debugging mode.
debug1: rexec start in 4 out 4 newsock 4 pipe -1 sock 7
debug1: sshd version OpenSSH_9.5, OpenSSL 3.0.12 24 Oct 2023
debug1: private host key #0: ssh-rsa SHA256:XXXX
debug1: private host key #1: ecdsa-sha2-nistp256 SHA256:XXXX
debug1: private host key #2: ssh-ed25519 SHA256:XXXX
debug1: inetd sockets after dupping: 3, 3
debug1: res_init()
Connection from 192.168.42.55 port 10384 on 192.168.42.154 port 22
debug1: Local version string SSH-2.0-OpenSSH_9.5 FreeBSD-20231004
debug1: Remote protocol version 2.0, remote software version OpenSSH_9.5
debug1: Fssh_compat_banner: match: OpenSSH_9.5 pat OpenSSH* compat 0x04000000
debug1: permanently_set_uid: 22/22 [preauth]
debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug1: kex: algorithm: [EMAIL]sntrup761x25519-sha512@openssh.com[/EMAIL] [preauth]
debug1: kex: host key algorithm: ssh-ed25519 [preauth]
debug1: kex: client->server cipher: [EMAIL]chacha20-poly1305@openssh.com[/EMAIL] MAC: <implicit> compression: none [preauth]
debug1: kex: server->client cipher: [EMAIL]chacha20-poly1305@openssh.com[/EMAIL] MAC: <implicit> compression: none [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
debug1: Fssh_ssh_packet_send2_wrapped: resetting send seqnr 3 [preauth]
debug1: rekey out after 134217728 blocks [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: Sending SSH2_MSG_EXT_INFO [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug1: Fssh_ssh_packet_read_poll2: resetting read seqnr 3 [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: rekey in after 134217728 blocks [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user root service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug1: PAM: initializing for "root"
debug1: PAM: setting PAM_RHOST to "192.168.42.55"
debug1: userauth-request for user root service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug1: userauth_pubkey: publickey test pkalg rsa-sha2-512 pkblob RSA SHA256:XXXX [preauth]
debug1: trying public key file /root/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: /root/.ssh/authorized_keys:1: matching key found: RSA SHA256:XXXX
debug1: /root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Accepted key RSA SHA256:afEeqvdrY0bIf1L3pEUJK8hG0GEnqTlRXsnVOLcif1Y found at /root/.ssh/authorized_keys:1
Postponed publickey for root from 192.168.42.55 port 10384 ssh2 [preauth]
debug1: userauth-request for user root service ssh-connection method [EMAIL]publickey-hostbound-v00@openssh.com[/EMAIL] [preauth]
debug1: attempt 2 failures 0 [preauth]
debug1: trying public key file /root/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: /root/.ssh/authorized_keys:1: matching key found: RSA SHA256:XXXX
debug1: /root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Accepted key RSA SHA256:XXXXX found at /root/.ssh/authorized_keys:1
debug1: auth_activate_options: setting new authentication options
debug1: do_pam_account: called
Accepted publickey for root from 192.168.42.55 port 10384 ssh2: RSA SHA256:XXXX
debug1: monitor_child_preauth: user root authenticated by privileged process
debug1: auth_activate_options: setting new authentication options [preauth]
debug1: monitor_read_log: child log fd closed
debug1: PAM: establishing credentials
debug1: rekey in after 134217728 blocks
debug1: rekey out after 134217728 blocks
debug1: Fssh_ssh_packet_set_postauth: called
debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Entering interactive session for SSH2.
debug1: server_init_dispatch
debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768
debug1: input_session_request
debug1: channel 0: new session [server-session] (inactive timeout: 0)
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_global_request: rtype [EMAIL]no-more-sessions@openssh.com[/EMAIL] want_reply 0
debug1: server_input_channel_req: channel 0 request exec reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req exec
Starting session: command for root from 192.168.42.55 port 10384 id 0
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 26472
debug1: session_exit_message: session 0 channel 0 pid 26472 exit 0
debug1: session_exit_message: release channel 0
Received disconnect from 192.168.42.55 port 10384:11: disconnected by user
Disconnected from user root 192.168.42.55 port 10384
debug1: do_cleanup
debug1: PAM: cleanup
debug1: PAM: closing session
debug1: PAM: deleting credentials

Unfortunately I did not see any particular errors, it reached the "Server listening on 0.0.0.0 port 22.", then when I ran the ssh client command it just sat there for 30 seconds, after which the rest of the lines blazed past at high speed.
 
I just ran the ssh client in debug mode as well and I found that it waits in two points, for approx 15 seconds each:
Code:
ssh -vvv root@techanalysis "echo ok"
OpenSSH_9.5p1, OpenSSL 3.0.12 24 Oct 2023
debug1: Reading configuration data /home/user/.ssh/config
debug1: /home/user/.ssh/config line 22: Applying options for *
debug1: Reading configuration data /etc/ssh/ssh_config
----------- [ ~15 second pause ] ----------
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/home/user/.ssh/known_hosts'
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/home/user/.ssh/known_hosts2'
debug2: resolving "techanalysis.cosmos.lnet" port 22
debug3: resolve_host: lookup techanalysis.cosmos.lnet:22
----------- [ ~15 second pause ] ----------
debug3: ssh_connect_direct: entering
debug1: Connecting to techanalysis.cosmos.lnet [192.168.42.154] port 22.


The rest of the log messages fly by, so those are not the cause of the slow down. My ssh config is blank except for the ObscureKeystrokeTiming "no" mentioned above, so I am running on defaults.
 
EDIT: never mind, this wouldn't cause differences between hostname and IP. I missed this nuance while responding.

This may be due to the speed at which your public key can be verified (and even sent) on the host.

Simply put: if you create a very complex key, it'll take much longer for the host to respond. I'd test it out by connecting twice to monitor the second connection from the host out. If the sshd program is using a lot of cpu cycles while the connection is taking place, you know that's the reason.
Another thing you can test is to add a second very simple public key or preferably enable username/password temporarily. If that works immediately then the verification of the key is what's taking up time.
 
Note you must restart (or reload) the sshd service for edits in sshd_config to take.

It looks like one pause is while looking up the host on your (client) machine. Does host techanalysis.cosmos.lnet execute quickly?

The other pause seems to be while parsing /etc/ssh/ssh_config ? Anything non-standard enabled in there?

Both these pauses appear to be before reaching out to the remote side, but you can verify that by trying to connect to the wrong port, for example, and seeing if you have the same pauses in the client.
 
This tells me that it most likely is an issue with DNS resolution. However testing with "drill" and other commands using the DNS name gives me instant responses, so there is something specific about SSH + DNS that is causing this issue.

What's in /etc/resolv.conf on the client?
 
You could also add this to the end of your ~/.ssh/config (ref. ssh_config(5)):

Code:
Host techanalysis*
    Hostname 192.168.42.154

As long as that is a static IP if you can’t figure out why the DNS resolution for the ssh client is being slow.
 
What's in /etc/resolv.conf on the client?

# Generated by resolvconf
search cosmos.lnet
nameserver 192.168.42.167

42.167 is a local dnsmasq daemon. It caches remote DNS while reading in local addresses from /etc/hosts.

Note you must restart (or reload) the sshd service for edits in sshd_config to take.
Noted and done in each config change.

It looks like one pause is while looking up the host on your (client) machine. Does host techanalysis.cosmos.lnet execute quickly?
Actually it doesn't...

$time host techanalysis
techanalysis.cosmos.lnet has address 192.168.42.154
;; connection timed out; no servers could be reached

real 0m10,018s
user 0m0,007s
sys 0m0,000s

It gets the address quickly, but then it sits for a good 10 seconds before it says "no servers could be reached".

The other pause seems to be while parsing /etc/ssh/ssh_config ? Anything non-standard enabled in there?
Nope, ssh_config is all commented out, so running defaults

Both these pauses appear to be before reaching out to the remote side, but you can verify that by trying to connect to the wrong port, for example, and seeing if you have the same pauses in the client.
I get the same delay on an invalid port.

the "host" test above indicates the issue may well be with my DNS rather than SSH itself. I find it odd that it resolves the IP address correctly, then sits and waits for 10 seconds before giving the ;; connection timed out; no servers could be reached message. It acts like there are multiple nameservers in my local /etc/resolv.conf, some of which are unreachable. However there is only a single one (local, reachable and fast) as mentioned at the top of my post.

I will investigate the dnsmasq configuration and see if there is anything odd going on in there. I have made no changes to dnsmasq in over a year, but I did update the machine to Freebsd 14 recently, so perhaps there has been a change in the default software behaviour.
 
You could also add this to the end of your ~/.ssh/config (ref. ssh_config(5)):

Code:
Host techanalysis*
    Hostname 192.168.42.154

As long as that is a static IP if you can’t figure out why the DNS resolution for the ssh client is being slow.

With this change, ‘ssh techanalysis’ should avoid the local DNS resolution. Now if your DNS is misbehaving at your dns server, and you have UseDNS yes in the sshd_config, you’ll still get a delay at that point.
 
What about IPv6? I'm thinking the client has IPv6, and techanalysis.osmos.lnet also resolves to an IPv6 address. But the host at techanalysis.osmos.lnet is only accessible on IPv4. Or maybe the techanalysis.osmos.lnet host has a local firewall that only allows IPv4, or sshd(8) is only bound to its IPv4 address. The client tries to connect to the IPv6 address, times out (30 second delay), then retries the connection on IPv4, which succeeds.

So I'm wondering if ping techanalysis works, and if it tries to ping an IPv6 or IPv4 address. You could also try ssh -4 techanalysis. Depending on the outcome you might need to remove the AAAA record for techanalysis.osmos.lnet, or fix the firewall to also allow IPv6, or bind sshd(8) to both IPv4 and IPv6.
 
Well, this took me down a rabbit hole...

My setup is such that my main DNS server is 42.167, which hosts statically assigned DNS names in /etc/hosts, handled by dnsmasq. It in turn uses 42.1 as its upstream server, which is my ADSL router. That hosts DHCP and the dynamic DNS entries (generated by DHCP), as well as caching of Internet DNS.

Effectively my DNS was split between two systems, one for fixed IPs and one dynamic. When I disabled 42.1 on dnsmasq, the 30 second delay vanished (along with internet and dynamic DNS). After much debugging I could not work out why there was such a delay, nor why now all of a sudden it was a problem.

As I could not remember why I built the system this way all those years ago I decided to move all the DHCP and DNS to dnsmasq and disable the ADSL router DHCP/DNS (which promptly broke everything).

I then discovered why I did it this way: dnsmasq is in a jail and its DHCP server does not work in jails (See https://forums.freebsd.org/threads/dnsmasq-server-in-jail-dns-works-dhcp-doesnt.52775/ ) so I used the router as the DHCP server, which necessitated the chained DNS to make sure all machine entries were resolvable.

As 10 years later dnsmasq still does not work properly in a jail I don't expect it will start working soon, so I ended up moving all the static allocations into the ADSL router instead (which was slow and painful via its web interface). With only the router as my DNS server the problem seems to have completely gone away now, so happy to mark this as solved.
 
It's the default for OpenSSH, and has been for quite some time.

Code:
     UseDNS  Specifies whether sshd(8) should look up the remote host name,
             and to check that the resolved host name for the remote IP
             address maps back to the very same IP address.

             If this option is set to no, then only addresses and not host
             names may be used in ~/.ssh/authorized_keys from and sshd_config
             Match Host directives.  The default is “yes”.
sshd_config(5)
 
It's the default for OpenSSH, and has been for quite some time.

Code:
     UseDNS  Specifies whether sshd(8) should look up the remote host name,
             and to check that the resolved host name for the remote IP
             address maps back to the very same IP address.

             If this option is set to no, then only addresses and not host
             names may be used in ~/.ssh/authorized_keys from and sshd_config
             Match Host directives.  The default is “yes”.
sshd_config(5)
You're looking at the FreeBSD manpage...

See:
- https://man.openbsd.org/sshd_config
- https://github.com/openssh/openssh-portable/blob/master/sshd_config.5#L1976
 
Hi, I think I have the same issue. 15-20s wait when ssh into my FreeBSD backup server, Don't think DNS is involved though.

I ssh from a laptop into my ubuntu file server. It has 2 nics, so I ssh again out the second to the backup server, it's behind the server. Ubuntu is set up as a bridge, with static ip backing out to the Freebsd. I can get into the FBSD box ok just pauses for ? 15 seconds every time. using ssh -v from ubuntu I find the wait happens after line `debug1: Local version string SSH-2.0-OpenSSH_8.9p1 Ubuntu-3ubuntu0.11` is posted to screen and before the next line: `debug1: Remote protocol version 2.0, remote software version OpenSSH_9.3 FreeBSD-20230316` is posted to the screen.

I don't think I have any weird settings on FBSD:
Code:
backman@bub02:~ $ cat /etc/ssh/sshd_config | grep -i dns
#UseDNS yes
backman@bub02:~ $ cat /etc/ssh/sshd_config |grep -v "^#" | grep -v "^$"
AuthorizedKeysFile      .ssh/authorized_keys
Subsystem       sftp    /usr/libexec/sftp-server
backman@bub02:~ $ ps aux | grep -i network
backman 23433   0.0  0.1 12816  2388  0  S+   05:31       0:00.00 grep -i network
backman@bub02:~ $ exit

It happens if I try `ssh -c aes128-cbc backman@192.168.177.2` or if I try `ssh -o Compression=no backman@192.168.177.2`, it happens with passwordless keys, and passwords.

I think my FBSD network settings are ok,

Code:
backman@bub02:~ $ ifconfig
re0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=8209b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,WOL_MAGIC,LINKSTATE>
        ether 00:25:22:cc:fd:1e
        inet 192.168.177.2 netmask 0xffffff00 broadcast 192.168.177.255
        media: Ethernet autoselect (1000baseT <full-duplex>)
        status: active
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
        options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
        inet6 ::1 prefixlen 128
        inet6 fe80::1%lo0 prefixlen 64 scopeid 0x2
        inet 127.0.0.1 netmask 0xff000000
        groups: lo
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
backman@bub02:~ $ netstat -rn
Routing tables

Internet:
Destination        Gateway            Flags     Netif Expire
default            192.168.177.1      UGS         re0
127.0.0.1          link#2             UH          lo0
192.168.177.0/24   link#1             U           re0
192.168.177.2      link#1             UHS         lo0

Internet6:
Destination                       Gateway                       Flags     Netif Expire
::/96                             ::1                           URS         lo0
::1                               link#2                        UHS         lo0
::ffff:0.0.0.0/96                 ::1                           URS         lo0
fe80::/10                         ::1                           URS         lo0
fe80::%lo0/64                     link#2                        U           lo0
fe80::1%lo0                       link#2                        UHS         lo0
ff02::/16                         ::1                           URS         lo0
backman@bub02:~ $

Coming over the the ubuntu box, I set it up as a bridge (not done this before probably and error..)
Code:
chris@nas04:~$ ip route show
default via 192.168.178.1 dev enp3s0 proto dhcp src 192.168.178.52 metric 100
172.17.0.0/16 dev docker0 proto kernel scope link src 172.17.0.1 linkdown
192.168.177.0/24 dev br0 proto kernel scope link src 192.168.177.1
192.168.178.0/24 dev enp3s0 proto kernel scope link src 192.168.178.52 metric 100
192.168.178.1 dev enp3s0 proto dhcp scope link src 192.168.178.52 metric 100
chris@nas04:~$ sudo cat /etc/netplan/00-installer-config.yaml
[sudo] password for chris:
# This is the network config written by 'subiquity'
network:
  ethernets:
    enp3s0:
      dhcp4: true
    enp4s0:
      dhcp4: false
  bridges:
    br0:
      interfaces: [enp4s0]
      addresses: [192.168.177.1/24]
  version: 2
chris@nas04:~$

For info, my isp router uses lan 192.168.178.0/24, so the laptop is 192.168.178.101, the ubuntu lan nic is 192.168.178.52, and the ubuntu nic facing FBSD is 192.168.177.1, so the FreeBSD box nic is 192.168.177.2.

I can update and upgrade FreeBSD through the ubuntu server fine. I think the problem is where ssh from ubuntu tries to establish 'Remote Protocol Version' from the FreeBSD backup box. Can anyone comment?

I am trying to setup zfs replication from one box to the other. the delay is making the 'zfs receive' fail.

Ok fixed it, kind of. Bit surprised, can't explain it.

when I first set it up, I could get out to update. I must have not made the change boot-surviving. I tried `# pkg udate` but could not get out over the ubuntu box. I had not adding routing, and not modified firewall rules. Added routing=1 and a few firewall rules and the ssh time disappeared. Now ssh instant

Code:
infra@nas04:/home/chris$ sudo sysctl -w net.ipv4.ip_forward=1
net.ipv4.ip_forward = 1
infra@nas04:/home/chris$ sudo iptables -t nat -A POSTROUTING -s 192.168.177.0/24 -o enp3s0 -j MASQUERADE
infra@nas04:/home/chris$ sudo iptables -A FORWARD -i br0 -o enp3s0 -j ACCEPT
infra@nas04:/home/chris$ sudo iptables -A FORWARD -i enp3s0 -o br0 -m state --state RELATED,ESTABLISHED -j ACCEPT
infra@nas04:/home/chris$ sudo sh -c 'iptables-save > /etc/iptables.rules'
infra@nas04:/home/chris$ ssh backman@192.168.177.2

Not sure what is happening here. all ssh expressions use ip addresses. should not need DNS. This little backup extension is all static ip, so no DHCP on bootup. So SSH is using some sort of ip query, but will time-out if no reply?
 
Check sshd -T | grep usedns on the destination (FreeBSD) system. It is likely yes. (Note that #UseDNS Yes in the installed sshd_config is an indicator that the default value is yes.)

If it cannot reverse-lookup (times out) your incoming IP address, that will cause a delay in the ssh connection.

UseDNS yes lets you do things like say “this key can only be used from foo.bar.com” rather than a fixed IP address. To enforce this, sshd needs to (reverse) DNS lookup the name corresponding to the IP of the connecting system.

You can uncomment the line in sshd_config and set it to no (and reload / restart sshd), but note that no match blocks or authorized_keys lines can use hostnames in that state. (Likely not an issue, but important to understand.)

And finally, when in doubt, remember the DNS haiku:

It's not DNS
There's no way it's DNS
It was DNS
- SSBroski
 
Also in my case, disabling UseDNS solved the problem about slow ssh logins.

But Emacs in TRAMP mode was still very laggy in processing remote files. I solved this last problem creating on the sshd server side the directory /var/db/entropy. It is required by the utility /usr/libexec/save-entropy and the error message was showed in /var/log/messages.
 
Back
Top