openssh bugs - Oct 2024 - [Bug 3747] New: ssh with ldap user account slow every time, local accounts unaffected

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

            Bug ID: 3747
           Summary: ssh with ldap user account slow every time, local
                    accounts unaffected
           Product: Portable OpenSSH
           Version: 8.9p1
          Hardware: 68k
                OS: Mac OS X
            Status: NEW
          Severity: enhancement
          Priority: P5
         Component: sshd
          Assignee: unassigned-bugs at mindrot.org
          Reporter: craig.emery at arm.com

Created attachment 3841
  --> https://bugzilla.mindrot.org/attachment.cgi?id=3841&action=edit
A snippet of /var/log/auth.log when logging in as an LDAP user.

I have an Ubuntu install on arm64
openssh version 1:8.9p1_3ubuntu10 installed.

Whe I ssh to the machine with an authorized key in an LDAP account it
takes approx 17seconds to get a shell prompt.

When I do the same with the same key but to a simple local account,
it's under one second.

/var/log/auth.log shows ensure_minimum_time_since() "sleeping" for 3.5
seconds. This seems to happen more than once. And "going in" it says
we've already spent 7 seconds.

Going from the debug logs I can't find out why and why only when the
"target" user is an LDAP one.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

--- Comment #1 from Craig Emery <craig.emery at arm.com> ---
It's lines like this that stand out for me:

Oct 15 12:34:43 ip-10-248-139-188 sshd[501923]: debug3:
ensure_minimum_time_since: elapsed 5689.207ms, delaying 3656.119ms
(requested 9.126ms) [preauth]

Why would there be a 3656ms delay during a connection that has no
failures. No back off etc.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

Craig Emery <craig.emery at arm.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Priority|P5                          |P3
                 OS|Mac OS X                    |Linux
           Hardware|68k                         |ARM64
           Severity|enhancement                 |normal

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

--- Comment #2 from Craig Emery <craig.emery at arm.com> ---
? dpkg -s openssh-server
Package: openssh-server
Status: install ok installed
Priority: optional
Section: net
Installed-Size: 1441
Maintainer: Ubuntu Developers <ubuntu-devel-discuss at lists.ubuntu.com>
Architecture: arm64
Multi-Arch: foreign
Source: openssh
Version: 1:8.9p1-3ubuntu0.10

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

Darren Tucker <dtucker at dtucker.net> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |dtucker at dtucker.net

--- Comment #3 from Darren Tucker <dtucker at dtucker.net> ---
Firstly, since this is a vendor modified binary, ultimately they are
the ones that will need to help you, unless you or they can reproduce
the problem with an unmodified OpenSSH as available on openssh.com.

That said, looking through the debug log, the first time sink is:

Oct 15 12:34:37 ip-10-248-139-188 sshd[501923]: debug1: fd 5 clearing
O_NONBLOCK
Oct 15 12:34:43 ip-10-248-139-188 sshd[501923]: debug1:
/home/craeme02/.ssh/authorized_keys:1: matching key found: RSA
SHA256:EsGSIDs3cY1EdOy67jomy4+XxJYj+tqIT3TUo5wsHgo

6 seconds to read a file in the user's home directory.  Are these
automounted or something?

Oct 15 12:34:46 ip-10-248-139-188 sshd[501923]: debug1: fd 5 clearing
O_NONBLOCK
Oct 15 12:34:52 ip-10-248-139-188 sshd[501923]: debug1:
/home/craeme02/.ssh/authorized_keys:1: matching key found: RSA
SHA256:EsGSIDs3cY1EdOy67jomy4+XxJYj+tqIT3TUo5wsHgo

Another 6 seconds to read a file.

(In reply to Craig Emery from comment #1)
> It's lines like this that stand out for me:
> 
> Oct 15 12:34:43 ip-10-248-139-188 sshd[501923]: debug3:
> ensure_minimum_time_since: elapsed 5689.207ms, delaying 3656.119ms
> (requested 9.126ms) [preauth]
> 
> Why would there be a 3656ms delay during a connection that has no
> failures. No back off etc.
Once an authentication has taken some amount of time, sshd will try to
keep the amount of time consistent for other auth attempts to prevent
leaking information about user or authentication state via timing
attacks.  If some operations are slow that carries over to other ones. 
If you can fix whatever is causing the slowdowns those will reduce to
match.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

--- Comment #4 from Craig Emery <craig.emery at arm.com> ---
That's fair. :-)

(In reply to Darren Tucker from comment #3)
> Firstly, since this is a vendor modified binary, ultimately they are
> the ones that will need to help you, unless you or they can
> reproduce the problem with an unmodified OpenSSH as available on
> openssh.com.
> 
> That said, looking through the debug log, the first time sink is:
> 
> Oct 15 12:34:37 ip-10-248-139-188 sshd[501923]: debug1: fd 5
> clearing O_NONBLOCK
> Oct 15 12:34:43 ip-10-248-139-188 sshd[501923]: debug1:
> /home/craeme02/.ssh/authorized_keys:1: matching key found: RSA
> SHA256:EsGSIDs3cY1EdOy67jomy4+XxJYj+tqIT3TUo5wsHgo
> 
> 6 seconds to read a file in the user's home directory.  Are these
> automounted or something?
I think this will have been the first ever LDAP mount of the user home
directory.

JOOI: Is there a DB / file I can remove that deletes the history of how
long things previously took?

So going forward I can see quicker times?
> Oct 15 12:34:46 ip-10-248-139-188 sshd[501923]: debug1: fd 5
> clearing O_NONBLOCK
> Oct 15 12:34:52 ip-10-248-139-188 sshd[501923]: debug1:
> /home/craeme02/.ssh/authorized_keys:1: matching key found: RSA
> SHA256:EsGSIDs3cY1EdOy67jomy4+XxJYj+tqIT3TUo5wsHgo
> 
> Another 6 seconds to read a file.
> 
> (In reply to Craig Emery from comment #1)
> > It's lines like this that stand out for me:
> > 
> > Oct 15 12:34:43 ip-10-248-139-188 sshd[501923]: debug3:
> > ensure_minimum_time_since: elapsed 5689.207ms, delaying 3656.119ms
> > (requested 9.126ms) [preauth]
> > 
> > Why would there be a 3656ms delay during a connection that has no
> > failures. No back off etc.
> 
> Once an authentication has taken some amount of time, sshd will try
> to keep the amount of time consistent for other auth attempts to
> prevent leaking information about user or authentication state via
> timing attacks.  If some operations are slow that carries over to
> other ones.  If you can fix whatever is causing the slowdowns those
> will reduce to match.
-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

--- Comment #5 from Darren Tucker <dtucker at dtucker.net> ---
(In reply to Craig Emery from comment #4)
[...]
> I think this will have been the first ever LDAP mount of the user
> home directory.
> 
> JOOI: Is there a DB / file I can remove that deletes the history of
> how long things previously took?
There's no persistent state, it only exists in the context of the
running sshd.  It does compute a per (host, user) hash so that there's
some minimum time for any given pair, but that's only a few
milliseconds so in your case the delay measured at runtime will
dominate what you can see.
> So going forward I can see quicker times?
If the home directory remains mounted (or can be remounted faster due
to some kind of caching effect) then subsequent connection attempts
will be proportionally quicker.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |djm at mindrot.org

--- Comment #6 from Damien Miller <djm at mindrot.org> ---
I think the problem is the openssh version you're using:
> openssh version 1:8.9p1_3ubuntu10 installed.
In particular, this was fixed since then:

commit 01dbf3d46651b7d6ddf5e45d233839bbfffaeaec
Author: djm at openbsd.org <djm at openbsd.org>
Date:   Mon Aug 28 09:48:11 2023 +0000

    upstream: limit artificial login delay to a reasonable maximum (5s)

    and don't delay at all for the "none" authentication
mechanism.
Patch by
    Dmitry Belyavskiy in bz3602 with polish/ok dtucker@

    OpenBSD-Commit-ID: 85b364676dd84cf1de0e98fc2fbdcb1a844ce515

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

--- Comment #7 from Craig Emery <craig.emery at arm.com> ---
Thanks all.
I will try & install a newer version or do an Ubuntu dist upgrade to
achieve the same.
Really pleased with the replies & insights.
Cheers

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

Craig Emery <craig.emery at arm.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.

https://bugzilla.mindrot.org/show_bug.cgi?id=3747

--- Comment #8 from Craig Emery <craig.emery at arm.com> ---
We made a discovery.

The permission on my authhorized_keys file was not 600, it was 644.

When set to 600, the delay vanished.

We think sshd is seeing the group readable permissions & then using PAM
/ LDAP to see what group users can read it & that takes time.

It seems odd to me that sshd then seems to allow the keys in that file
to be trusted.
I though if the permissions weren't 600 the file & the keys therein
would blanket not be trusted.

But at least we figured out the root cause.

-- 
You are receiving this mail because:
You are watching someone on the CC list of the bug.
You are watching the assignee of the bug.