A running SSH service is being scanned and brute-forced, subject to all the "privileges" of running on a public IP address. For some random connection, only the following messages are logged to syslog: Apr 7 18:09:10 localhost sshd:20499:info Received disconnect from 77.233.89.158: 11: disconnected by user Apr 7 18:09:10 localhost sshd:20499:info Disconnected from 77.233.89.158 Apr 7 18:09:10 localhost sshd:20496:err error: mm_request_receive: socket closed If the system administrator has configured syslog to drop messages with informational priority, only the cryptic and rather useless "error: mm_request_receive: socket closed" remain. These contain no IP address of the client and seem useless from a systems administration point of view. I mean what kind of reasonable action is the sysadmin supposed to take on such error messages alone? It contains no information about whether the disconnect happened before, during or after authentication, or what was the IP address of the client etc. Additionally, the first and second info messages contain more-or-less the same information, so why can't there be one message instead? Second example: Apr 8 07:01:55/sshd/info: User root from 218.65.30.23 not allowed because not listed in AllowUsers Apr 8 07:01:55/sshd/info: input_userauth_request: invalid user root [preauth] The second message is again rather useless. It contains nothing useful in addition to the first message. It should have debug priority not info priority. Additionally, there's no good way to trace certain log messages to a client connection. Each log message related to a client connection should contain an unique client connection ID (client IP:port pair would be best). In summary, the logs produced by OpenSSH are difficult to read, contain duplicate, useless, incorrectly prioritized and untracable messages. Could this please be improved? PS: Are successful authentications without login (e.g. ForceCommand) even logged? PPS: bugzilla.mindrot.org provides an OpenSSH Version field for 6.9p1, but not for 6.8p1.
(In reply to Jaak Ristioja from comment #0) > A running SSH service is being scanned and brute-forced, subject to > all the "privileges" of running on a public IP address. For some > random connection, only the following messages are logged to syslog: > > Apr 7 18:09:10 localhost sshd:20499:info Received disconnect from > 77.233.89.158: 11: disconnected by user > Apr 7 18:09:10 localhost sshd:20499:info Disconnected from > 77.233.89.158 > Apr 7 18:09:10 localhost sshd:20496:err error: mm_request_receive: > socket closed > > If the system administrator has configured syslog to drop messages > with informational priority, only the cryptic and rather useless > "error: mm_request_receive: socket closed" remain. These contain no > IP address of the client and seem useless from a systems > administration point of view. I mean what kind of reasonable action > is the sysadmin supposed to take on such error messages alone? All of the logging should come from the same PID, in this example 20499. The mm_request_receive message is likely a bug that should be fixed, but I can't reproduce it with 6.9p1 on Linux. Can you? If so, on what platform? > It contains no information about whether the disconnect happened > before, during or after authentication, or what was the IP address > of the client etc. Additionally, the first and second info messages > contain more-or-less the same information, so why can't there be one > message instead? They are actually logging different things. The first is "I received a disconnection request packet and here is the reason it gave". The second is the TCP connection actually being disconnected. If you log only the first, you are completely blind to clients making TCP connections but not initiating the ssh protocol (eg port scanners, people trying to tie up all of your pre-authentication (ie MaxStartups) servers. If you log only the second then you miss the reason from the client. > Second example: > > Apr 8 07:01:55/sshd/info: User root from 218.65.30.23 not allowed > because not listed in AllowUsers > Apr 8 07:01:55/sshd/info: input_userauth_request: invalid user > root [preauth] > > The second message is again rather useless. It contains nothing > useful in addition to the first message. It should have debug > priority not info priority. Again, doing that will entirely omit that log message from for users denied for reasons other than AllowUsers. > Additionally, there's no good way to trace certain log messages to a > client connection. Each log message related to a client connection > should contain an unique client connection ID (client IP:port pair > would be best). These should all come from the same process ID. Does your syslog not log that? On which platform? > In summary, the logs produced by OpenSSH are difficult to read, > contain duplicate, useless, incorrectly prioritized and untracable > messages. Could this please be improved? > > PS: Are successful authentications without login (e.g. ForceCommand) > even logged? All authentications should be logged through the auth.c:auth_log() function. The ForceCommands themselves are also logged at LogLevel=verbose. > PPS: bugzilla.mindrot.org provides an OpenSSH Version field for > 6.9p1, but not for 6.8p1. Fixed. I take it from is comment you are actually running 6.8p1? On what platform?
Thank you for the explanations. Is there a document somewhere which explains how to interpret these and other OpenSSH log messages? I'm running net-misc/openssh-6.8_p1-r4 on Gentoo Linux. I have not configured all syslog services (e.g. syslog-ng) to log PIDs, because I didn't expect that to be useful information.
Between Darren's explanation and a few years of tweaks to logging, I think this bug can be closed. Please reopen (or better - file a new bug) if you have specific concerns about log messages.
Close RESOLVED bugs with the release of openssh-8.0