openssh unix dev - May 2022 - LogLevel debug2 handshake logging only on some logins, not on every login of a user

Running Ubuntu 18.04.1 LTS with package openssh-server 7.6p1-4ubuntu0.5

In /etc/ssh/sshd_config is set LogLevel DEBUG2.

I get the debug2 log message of the client MACs offering part of handshake:

May  3 18:51:05 10.10.10.10 sshd[14300]: debug2: MACs ctos:
hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]

and afterwards in the same second the login log entry for user "abc"
login from IP 1.2.3.4 with the same sshd PID, so I guess this login message
belongs to the first debug2 log entry:

May  3 18:51:05 10.10.10.10 sshd[14300]: Accepted password for abc from 1.2.3.4
port 51294 ssh2

But I get the according (same PID, roughly same second) debug2 handshake log
entry not for every Accepted password log entry, only for a small fraction of
logins.

E.g. I observe a user logging in 2525 times on a day, but I can see the
according debug2: MACs ctos: log entry (same PID, roughly same time) only for
155 of those logins.

This happens accross all user logins, so it is not user specific.

Is this a bug or a feature? Is there some handshake info cache, so full
handshake is not done (or logged) on every login? How can I achieve that for
every login the debug2 handshake log entry is made?

Hildegard

Do you have a controlmaster set up?

On Mon, 9 May 2022, Hildegard Meier wrote:
> Running Ubuntu 18.04.1 LTS with package openssh-server
> 7.6p1-4ubuntu0.5
>
> In /etc/ssh/sshd_config is set LogLevel DEBUG2.
>
> I get the debug2 log message of the client MACs offering part of
> handshake:
>
> May 3 18:51:05 10.10.10.10 sshd[14300]: debug2: MACs ctos:
> hmac-sha1,hmac-sha1-96,hmac-md5 [preauth]
>
> and afterwards in the same second the login log entry for user
"abc"
> login from IP 1.2.3.4 with the same sshd PID, so I guess this login
> message belongs to the first debug2 log entry:
>
> May 3 18:51:05 10.10.10.10 sshd[14300]: Accepted password for abc from
> 1.2.3.4 port 51294 ssh2
>
> But I get the according (same PID, roughly same second) debug2
> handshake log entry not for every Accepted password log entry, only
> for a small fraction of logins.
>
> E.g. I observe a user logging in 2525 times on a day, but I can see
> the according debug2: MACs ctos: log entry (same PID, roughly same
> time) only for 155 of those logins.
>
> This happens accross all user logins, so it is not user specific.
>
> Is this a bug or a feature? Is there some handshake info cache, so
> full handshake is not done (or logged) on every login? How can I
> achieve that for every login the debug2 handshake log entry is made?
If configured to log at debug2, then sshd should log this line at least
once for every accepted password.

I'd suggest the next steps in figuring this out are:

1) verifying that sshd is actually doing this (maybe via strace or
similar?)

2) verifying that syslogd isn't eating the log entries after sshd
sends them. Some syslogd implementations do coalesce similar or
identical messages (e.g. replacing them with "last message repeated
N times")

Hope this helps.

-d