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

> 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.

>> 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.
Use a command like

	strace -f -tt -s 200 -o /tmp/logfile.txt -p <pid of sshd>

Then you'd have to verify what gets written in the logfile to the data
in your syslog.....

Also, everything the users do is in the logfile -- that might make
that approach unsuitable as well.

> 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.
1)  Do you have a per-client configuration in your sshd_config?
	Look for a "Match" block, also in included files.

2)  Is syslog-ng configured to relay the data? If yes, and using UDP,
	some log entries might simply be missing because of congestion.

3)  I'd be happy to take a look at a log file (send it privately);
	if you're not happy about that, I'd fully understand.
	(I don't have a script ready to anonymize such log files, sadly -
	and TBH, changing the one I have for HTTP access logs right now is
	too much effort, and might also go wrong.)