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

[Hildegard Meier]

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