Philipp Marek
2022-May-11 05:57 UTC
Aw: Re: LogLevel debug2 handshake logging only on some logins, not on every login of a user
>> 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.)
Hildegard Meier
2022-May-11 06:55 UTC
LogLevel debug2 handshake logging only on some logins, not on every login of a user
> 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 at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac- 128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-ripemd160-etm at 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 at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at o penssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at 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 at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at openssh.com,umac- 128-etm at openssh.com,hmac-sha2-256-etm at openssh.com,hmac-sha2-512-etm at openssh.com,hmac-ripemd160-etm at 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 at openssh.com,hmac-sha1-etm at openssh.com,umac-64-etm at o penssh.com,umac-128-etm at openssh.com,hmac-sha2-256-etm at 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 at 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.
Hildegard Meier
2022-May-11 11:38 UTC
LogLevel debug2 handshake logging only on some logins, not on every login of a user
> 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.