openssh bugs - Apr 2015 - [Bug 2375] New: Non-informative log messages, invalid log message priorities etc.

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

            Bug ID: 2375
           Summary: Non-informative log messages, invalid log message
                    priorities etc.
           Product: Portable OpenSSH
           Version: 6.9p1
          Hardware: All
                OS: All
            Status: NEW
          Severity: normal
          Priority: P5
         Component: sshd
          Assignee: unassigned-bugs at mindrot.org
          Reporter: jaak+mindrot at ristioja.ee

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.

-- 
You are receiving this mail because:
You are watching the assignee of the bug.

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.

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

Jaak Ristioja <jaak+mindrot at ristioja.ee> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
            Version|6.9p1                       |6.8p1

--- Comment #2 from Jaak Ristioja <jaak+mindrot at ristioja.ee> ---
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.

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

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

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |djm at mindrot.org

--- Comment #3 from Damien Miller <djm at mindrot.org> ---
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.

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

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

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED

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

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

Damien Miller <djm at mindrot.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |CLOSED

--- Comment #4 from Damien Miller <djm at mindrot.org> ---
Close RESOLVED bugs with the release of openssh-8.0

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