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

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

> 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?)
Could someone please lead me how exactly to do this? I would be really glad to
check if sshd really always sends the debug log to syslog-ng for every
"Accepted password" line,
to pin this issue down.
> 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")
I use syslog-ng 3.13.2.
There are no lines like "last message repeated N times".
I just checked with an account (I named it here "example_user") that
logged in 47 times yesterday from IP 1.2.3.4.
In 46 cases I see only the log like this (line number prefix by me):

1 May 10 12:02:37 myserver sshd[30844]: Connection from 1.2.3.4 port 29292 on
10.10.10.10 port 2222
2 May 10 12:02:37 myserver sshd[30749]: Accepted password for <another
user> from <another ip> port 65354 ssh2
3 May 10 12:02:37 myserver sshd[30749]: User child is on pid 30846
4 May 10 12:02:37 myserver sshd[30847]: Connection from <another ip> port
21078 on 10.10.10.10 port 2222
5 May 10 12:02:37 myserver sshd[30847]: Did not receive identification string
from <another ip> port 21078
6 May 10 12:02:37 myserver sshd[30753]: Accepted password for <another
user> from <another ip> port 65356 ssh2
7 May 10 12:02:37 myserver sshd[30753]: User child is on pid 30848
8 May 10 12:02:37 myserver sshd[30844]: Accepted password for example_user from
1.2.3.4 port 29292 ssh2
9 May 10 12:02:37 myserver sshd[30844]: User child is on pid 30849

You see we have pretty much traffic on the server (660 thousand logins
yesterday, so roughly 8 logins/s in 24h average), sessions are overlapping in
the same second.
So lines 1,8,9 belong together (same PID 30844), and then there are three other
sessions logged between line 1 and 8:
Lines 2,3 (PID 30749) are the last log lines from a session established before.
Lines 4,5 (PID 30847) are from another new session
Lines 6,7 (PID 30753) are the last log lines from a session established before.

The log looks like this in 46 cases yesterday, and only in one case I see the
debug log lines (e.g. "debug1: kex: host key algorithm: ssh-rsa
[preauth]") between the
"Connection from" and "Accepted password" log lines, for the
session (same PID).
There are also not only some lines missing some times, the log just misses all
of the session corresponding debug log lines, or all are there.

I need this debug log to see what SSH ciphers the clients use, because we want
to disable insecure old ciphers and want to know which customers would be
affected by the disabling first because in some cases they could not login
anymore and we want to inform them in advance of the change.

> Gesendet: Dienstag, 10. Mai 2022 um 03:21 Uhr
> Von: "Damien Miller" <djm at mindrot.org>
> I'd suggest the next steps in figuring this out are:
>
> 1) verifying that sshd is actually doing this (maybe via strace or
> similar?)
I startet sshd with "-E /var/log/app/ssh/debug.log"
and in that log vor every "Accepted password" message there is one
corresponding debug log message,
so that log is as expected, unfortunately without timestamps, PIDs etc.
> 2) verifying that syslogd isn't eating the log entries after sshd
> sends them.
If the same log entries like that are written with "-E
/var/log/app/ssh/debug.log" are written to /dev/log (what seems to be
according to the strace), I think the eating of the debug log messages could be
a systemd issue (because /dev/log is a symlink to /run/systemd/journal/dev-log
nowadays),
or a syslog-ng issue. The non-debug messages are continiously logged as
expected.

I tried dozens of configuration tweeks with syslog-ng local file logging,
without any change of behavior.