LogLevel debug2 handshake logging only on some logins, not on every login of a user

[Damien Miller]

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