[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16564202#comment-16564202
]
Bryan Turner commented on SSHD-838:
-----------------------------------
{quote}this may make the stack trace un-readable... - it is much easier to read
if each line is separate
{quote}
I probably wouldn't do it quite like that patch either, I think. But then, I
wouldn't have {{LoggingUtils.logExceptionStackTrace}} in the first place. That
utility feels a lot like fighting the logging framework, to me. Is there a
reason not to just pass the exception object through to SLF4J like "normal"?
I've never seen a library that logs its exceptions frame by frame.
Changing the code from this:
{code:java}
log.warn("Caught {} while accepting incoming connection from {}: {}",
exc.getClass().getSimpleName(), address, exc.getMessage());
LoggingUtils.logExceptionStackTrace(log, Level.WARNING, exc);
{code}
to this:
{code:java}
log.warn("Caught an exception while accepting incoming connection from {}",
address, exc);
{code}
would change the logging from:
{noformat}
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor Caught MissingAttachedSessionException
while accepting incoming connection from /0:0:0:0:0:0:0:0:7997: No session
attached to Nio2Session[local=/1.1.1.1:7997, remote=/1.1.1.1:12938]
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.session.helpers.AbstractSession.getSession(AbstractSession.java:335)
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.session.helpers.AbstractSession.getSession(AbstractSession.java:318)
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.sessionClosed(AbstractSessionIoHandler.java:45)
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2Acceptor$AcceptCompletionHandler.onCompleted(Nio2Acceptor.java:205)
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2Acceptor$AcceptCompletionHandler.onCompleted(Nio2Acceptor.java:174)
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
java.security.AccessController.doPrivileged(Native Method)
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
{noformat}
to this:
{noformat}
2018-07-31 17:55:59,961 WARN [sshd-SshServer[5696675c]-nio2-thread-4]
o.a.sshd.common.io.nio2.Nio2Acceptor Caught an exception while accepting
incoming connection from /0:0:0:0:0:0:0:0:7997
org.apache.sshd.common.session.helpers.MissingAttachedSessionException: No
session attached to Nio2Session[local=/1.1.1.1:7997, remote=/1.1.1.1:12938]
at
org.apache.sshd.common.session.helpers.AbstractSession.getSession(AbstractSession.java:335)
at
org.apache.sshd.common.session.helpers.AbstractSession.getSession(AbstractSession.java:318)
at
org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.sessionClosed(AbstractSessionIoHandler.java:45)
at
org.apache.sshd.common.io.nio2.Nio2Acceptor$AcceptCompletionHandler.onCompleted(Nio2Acceptor.java:205)
at
org.apache.sshd.common.io.nio2.Nio2Acceptor$AcceptCompletionHandler.onCompleted(Nio2Acceptor.java:174)
at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
at java.security.AccessController.doPrivileged(Native Method)
at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
{noformat}
In my opinion, the latter is significantly _easier_ to read, because the stack
trace flows uninterrupted from line to line without all the logger details
repeated before each frame. It also means we'd get the complete stack, rather a
truncated one, and that, if there's a cause chain on the caught exception, we'd
see all the causes too. It _also_ puts the logging behavior significantly more
under the _application's_ control; with whatever logging framework is
underpinning SLF4J, the application can configure how exceptions should be
logged. Bitbucket Server, for example, uses a custom exception appender which
filters stack traces to eliminate some common frames that tend to be
uninteresting when debugging.
{quote}as previously stated, there is something wrong with the system
{quote}
I'm not sure that's true. This message happens when a remote user Ctrl+C's a
process (typically a {{git clone}} or {{git fetch}}, in our case) "early"
enough to terminate the connection before the handshake completes. It's not
that hard to do, especially when you're traversing a cross-geo WAN link to get
to the server (e.g. Australia to a US East AWS zone). In cases where a client
disconnects before completing the handshake, that doesn't seem like a
server-side problem. And producing logging this vocal about such cases is
likely to cause confusion.
{quote}BTW, there is a simple solution to this issue - in your logging
configuration (e.g., log4j, logback) set the threshold level for messages
originating from Nio2Acceptor as ERROR and then you won't see these warnings .
Of course, you might not see other warning originating from it that are of
interest.
{quote}
That's a poor solution, and for exactly the reason you mention. The warning
logged in {{onCompleted}} when the session can't be closed, for example, seems
like something we'd want to see, if it ever happened, because that seems likely
to produce a resource leak. Switching the entire class over to error level
would lose those messages.
{quote}Another solution is to employ log analysis tools (there are many out
there) and "teach" them what warnings/errors interest your solution
{quote}
Our logs aren't just for _us_, as the developers of the product; Bitbucket
Server is installed on thousands of servers worldwide, so our logs are also for
administrators we'll never even meet. Before they could "teach" their log
analysis tools (which presupposes they're even using any) that these warnings
aren't significant, they'd first need to find that out themselves. That's most
likely to take the form of a support case. And when those cases do arise, the
most common response administrators make after being told a given warning or
error is benign, is to ask why it's being logged in the first place then.
Is there any way we can work together to adjust this logging so that it's not
so "strong", for lack of a better term, when it's most likely nothing but a
client disconnecting early?
Best regards,
Bryan Turner
> Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
> ------------------------------------------------------------------------
>
> Key: SSHD-838
> URL: https://issues.apache.org/jira/browse/SSHD-838
> Project: MINA SSHD
> Issue Type: Improvement
> Affects Versions: 2.0.0
> Reporter: jpalacios
> Priority: Minor
> Attachments: sshd-nio-acceptor-logging.patch
>
>
> As discussed in [SSHD-833|https://issues.apache.org/jira/browse/SSHD-833], it
> appears that when a client disconnects before the handshake completes there's
> some pretty loud logging coming from the
> {{Nio2Acceptor.AcceptCompletionHandler#okToReaccept}}.
> The entire message is logged at {{WARN}} level. Also, several lines from the
> stack trace are logged individually at the same level.
> We feel this much logging at {{WARN}} level will be too much noise for system
> administrators who might think there's something wrong with the system. We
> propose:
> # Changing the log level to {{DEBUG}} / {{FINE}}
> # Logging the stacktrace in a single message
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
