Mailing List Archive

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
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
Do you have a controlmaster set up?
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
> Do you have a controlmaster set up?

Do you mean the ssh client option ControlMaster ("Enables the sharing of multiple sessions over a single network connection") ?
I cannot control what options the clients use.

In sshd_config I have not set MaxSessions ("Specifies the maximum number of open sessions permitted per network connection. The default is 10.")
so it should default to 10.

Does this answer your question?
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
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
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Aw: Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
> 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.
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: Aw: Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
>> 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.)

_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
> 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.....

Thanks very much!

I just had a sshd session with PID 32322 which lacked the debug log message.

The strace (exactly the command you stated above) looks for me like the debug log messages are written to /dev/log
But I am no strace reading expert. Does this strace look healthy like the logging to /dev/log works for the debug log messages?

32322 08:19:16.727870 poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 2, -1 <unfinished ...>
32322 08:19:16.727919 <... poll resumed> ) = 2 ([{fd=6, revents=POLLIN}, {fd=7, revents=POLLIN}])
32322 08:19:16.727965 read(7, <unfinished ...>
32322 08:19:16.728010 <... read resumed> "\0\0\1\245", 4) = 4
32322 08:19:16.728065 read(7, <unfinished ...>
32322 08:19:16.728112 <... read resumed> "\0\0\0\6\0\0\1\235MACs ctos: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-
128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@op"..., 421) = 421
32322 08:19:16.728206 getpid( <unfinished ...>
32322 08:19:16.728252 <... getpid resumed> ) = 32322
32322 08:19:16.728305 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0 <unfinished ...>
32322 08:19:16.728363 <... socket resumed> ) = 4
32322 08:19:16.728457 connect(4, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110 <unfinished ...>
32322 08:19:16.728514 <... connect resumed> ) = 0
32322 08:19:16.728548 sendto(4, "<151>May 11 08:19:16 sftpd[32322]: debug2: MACs ctos: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@o
penssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-et"..., 466, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
32322 08:19:16.728594 <... sendto resumed> ) = 466
32322 08:19:16.728656 close(4 <unfinished ...>
32322 08:19:16.728710 <... close resumed> ) = 0
32322 08:19:16.728747 poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 2, -1) = 2 ([{fd=6, revents=POLLIN}, {fd=7, revents=POLLIN}])
32322 08:19:16.728838 read(7, <unfinished ...>
32322 08:19:16.728918 <... read resumed> "\0\0\1\245", 4) = 4
32322 08:19:16.728995 read(7, <unfinished ...>
32322 08:19:16.729032 <... read resumed> "\0\0\0\6\0\0\1\235MACs stoc: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@openssh.com,umac-
128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-ripemd160-etm@op"..., 421) = 421
32322 08:19:16.729115 getpid( <unfinished ...>
32322 08:19:16.729204 <... getpid resumed> ) = 32322
32322 08:19:16.729243 socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0 <unfinished ...>
32322 08:19:16.729298 <... socket resumed> ) = 4
32322 08:19:16.729360 connect(4, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110 <unfinished ...>
32322 08:19:16.729435 <... connect resumed> ) = 0
32322 08:19:16.729521 sendto(4, "<151>May 11 08:19:16 sftpd[32322]: debug2: MACs stoc: hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@o
penssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-et"..., 466, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
32322 08:19:16.729614 <... sendto resumed> ) = 466
32322 08:19:16.729650 close(4) = 0
32322 08:19:16.729734 poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 2, -1) = 2 ([{fd=6, revents=POLLIN}, {fd=7, revents=POLLIN}])
32322 08:19:16.729802 read(7, <unfinished ...>
32322 08:19:16.729834 <... read resumed> "\0\0\0004", 4) = 4
32322 08:19:16.729867 read(7, <unfinished ...>
32322 08:19:16.729899 <... read resumed> "\0\0\0\6\0\0\0,compression ctos: none,zlib@openssh.com,zlib", 52) = 52
32322 08:19:16.729976 getpid( <unfinished ...>

> 1) Do you have a per-client configuration in your sshd_config?
> Look for a "Match" block, also in included files.
no

> 2) Is syslog-ng configured to relay the data? If yes, and using UDP,
> some log entries might simply be missing because of congestion.
Yes local syslog-ng filters the relevant debug messages (facility local2) and sends them via UDP to a remote syslog-ng server.

_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
> I just had a sshd session with PID 32322 which lacked the debug log
> message.
>
> The strace (exactly the command you stated above) looks for me like
> the debug log messages are written to /dev/log
> But I am no strace reading expert. Does this strace look healthy like
> the logging to /dev/log works for the debug log messages?

> 32322 08:19:16.728548 sendto(4, "<151>May 11 08:19:16 sftpd[32322]:
> debug2: MACs ctos:
> hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@o
> penssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-et"...,
> 466, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
> 32322 08:19:16.729521 sendto(4, "<151>May 11 08:19:16 sftpd[32322]:
> debug2: MACs stoc:
> hmac-md5-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64-etm@o
> penssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-et"...,
> 466, MSG_NOSIGNAL, NULL, 0 <unfinished ...>

If one of these messages didn't arrive in your logfile, then UDP packet
loss
looks like a good explanation.

>> 2) Is syslog-ng configured to relay the data? If yes, and using UDP,
>> some log entries might simply be missing because of congestion.
> Yes local syslog-ng filters the relevant debug messages (facility
> local2) and sends them via UDP to a remote syslog-ng server.

My "man rsyslog.conf" says

omrelp
Output module for the reliable RELP protocol (prevents message loss)

Even TCP can lose messages: the ones in transmit when a connection
breaks.
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
> 2) Is syslog-ng configured to relay the data? If yes, and using UDP,
> some log entries might simply be missing because of congestion.

I log locally, the syslog-ng config is plain simple:

source s_src {
system(); # this is /dev/log on Linux
internal(); # this is only for error messages from syslog-ng itself
};

filter f_local2 { facility(local2); }; # sshd is configured with "SyslogFacility local2"

filter f_ssh_auth_wanted {
not level(debug)
or message("^debug2: MACs ctos: ")
or message("^debug1: kex: client->server cipher: ")
or message("^debug2: KEX algorithms: ")
or message("^debug2: host key algorithms: ")
or message("^debug1: kex: host key algorithm: ")
or message("^debug2: ciphers ctos: ");
};

destination d_ssh_auth {
file("/var/log/app/ssh/auth.log" flush_lines(10) );
};

log {
source(s_src);
filter(f_local2);
filter(f_ssh_auth_wanted);
destination(d_ssh_auth);
};

# delete all other unwanted sshd debug messages (no destination = no action = "delete")
log {
source(s_src);
filter(f_local2);
flags(final);
};

I have no clue why the debug messages that match on the filter (e.g. "debug2: host key algorithms: ssh-rsa,ssh-dss [preauth]") are only logged _sometimes_ in /var/log/app/ssh/auth.log and not together with every "Accepted password" log entry.
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev
Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user [ In reply to ]
> Gesendet: Dienstag, 10. Mai 2022 um 03:21 Uhr
> Von: "Damien Miller" <djm@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.
_______________________________________________
openssh-unix-dev mailing list
openssh-unix-dev@mindrot.org
https://lists.mindrot.org/mailman/listinfo/openssh-unix-dev