[Bug 2375] Non-informative log messages, invalid log message priorities etc.

[bugzilla-daemon at mindrot.org]

https://bugzilla.mindrot.org/show_bug.cgi?id=2375

Darren Tucker <dtucker at zip.com.au> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |dtucker at zip.com.au

--- Comment #1 from Darren Tucker <dtucker at zip.com.au> ---
(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?

-- 
You are receiving this mail because:
You are watching the assignee of the bug.
You are watching someone on the CC list of the bug.