mina-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bryan Turner (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
Date Wed, 01 Aug 2018 17:36:00 GMT

    [ https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16565685#comment-16565685
] 

Bryan Turner edited comment on SSHD-838 at 8/1/18 5:35 PM:
-----------------------------------------------------------

{quote}
If anything, I am considering replacing all code that passes the exception directly to the
logging framework with this call.
{quote}

That's _extremely_ concerning to me.

{quote}
The reason for it is that when passing the exception directly to the logging framework it
logs the entire stack trace - which is often very long and tedious. Usually, logging the top
(or bottom - depending how you look at it) 6-8 frames provides enough "hints" as to the call
flow to let the user know what went wrong.
{quote}

That doesn't feel like a decision a _library_ should make. The few frames being logged may
be "enough hints" for an SSHD developer, but they completely eliminate most, if not all, frames
related to the _application_. That means I have to reproduce the failure myself (which isn't
always possible), or otherwise guess my way through to how the SSHD code relates to _my_ code.
What call in _my_ application led to the calls in SSHD that failed?

By using SLF4J "normally", the decisions are left to the application developer. If the _application_
doesn't want the full trace, they can eliminate some or all of it by configuring Logback/Log4J
accordingly\-\-something Bitbucket Server, for example, _does_. We trim our own stack frames\-\-we
don't need (or want) the libraries we use to do it for us, because our goals aren't always
the same. For the _library_, the goal is to facilitate its maintainers' ability to get useful
(_to them_) details when failures are reported, while avoiding "long and tedious" extra information
that makes resolution slower. For the _application_, the goal is to facilitate troubleshooting
_customer-raised issues_, which requires more complete context. Is the problem in the library?
Or is the problem in how we _set up or use_ the library? When SSH-related issues come through
our support, _very, very few_ of them get forwarded to the wider SSHD community. Instead,
we debug them ourselves and we [often|https://github.com/apache/mina-sshd/pull/1] [provide|https://github.com/apache/mina-sshd/pull/2]
[fixes|https://github.com/apache/mina-sshd/pull/3] ([and more examples|https://issues.apache.org/jira/browse/SSHD-163?jql=project%20%3D%20SSHD%20AND%20reporter%20%3D%20pepoirot%20]).

Further, there are shortcomings with the _structure_ of {{logExceptionStackTrace}}'s output:
* You're dropping the cause(s), which are often more useful for debugging a failure than the
various exceptions that wrap them
* All of the frames are separate log messages, which means:
** They each are prefixed with logger details, making the frames themselves significantly
harder to scan
** Systems that are connected to a LaaS (logging-as-a-service) framework end up with all of
the frames in separate events. Searching for a message and then seeing the trace becomes more
complicated

I humbly ask...please don't move your logging in this direction. As a system which uses Mina
SSHD heavily, it's a very undesirable change for Bitbucket Server. If you do make this change,
though, please, please add a way to turn it off and log exceptions normally again.

Best regards,
Bryan Turner


was (Author: bturner):
{quote}
If anything, I am considering replacing all code that passes the exception directly to the
logging framework with this call.
{quote}

That's _extremely_ concerning to me.

{quote}
The reason for it is that when passing the exception directly to the logging framework it
logs the entire stack trace - which is often very long and tedious. Usually, logging the top
(or bottom - depending how you look at it) 6-8 frames provides enough "hints" as to the call
flow to let the user know what went wrong.
{quote}

That doesn't feel like a decision a _library_ should make. The few frames being logged may
be "enough hints" for an SSHD developer, but they completely eliminate most, if not all, frames
related to the _application_. That means I have to reproduce the failure myself (which isn't
always possible), or otherwise guess my way through to how the SSHD code relates to _my_ code.
What call in _my_ application led to the calls in SSHD that failed?

By using SLF4J "normally", the decisions are left to the application developer. If the _application_
doesn't want the full trace, they can eliminate some or all of it by configuring Logback/Log4J
accordingly--something Bitbucket Server, for example, _does_. We trim our own stack frames--we
don't need (or want) the libraries we use to do it for us, because our goals aren't always
the same. For the _library_, the goal is to facilitate its maintainers' ability to get useful
(_to them_) details when failures are reported, while avoiding "long and tedious" extra information
that makes resolution slower. For the _application_, the goal is to facilitate troubleshooting
_customer-raised issues_, which requires more complete context. Is the problem in the library?
Or is the problem in how we _set up or use_ the library? When SSH-related issues come through
our support, _very, very few_ of them get forwarded to the wider SSHD community. Instead,
we debug them ourselves and we [often|https://github.com/apache/mina-sshd/pull/1] [provide|https://github.com/apache/mina-sshd/pull/2]
[fixes|https://github.com/apache/mina-sshd/pull/3] ([and more examples|https://issues.apache.org/jira/browse/SSHD-163?jql=project%20%3D%20SSHD%20AND%20reporter%20%3D%20pepoirot%20]).

Further, there are shortcomings with the _structure_ of {{logExceptionStackTrace}}'s output:
* You're dropping the cause(s), which are often more useful for debugging a failure than the
various exceptions that wrap them
* All of the frames are separate log messages, which means:
** They each are prefixed with logger details, making the frames themselves significantly
harder to scan
** Systems that are connected to a LaaS (logging-as-a-service) framework end up with all of
the frames in separate events. Searching for a message and then seeing the trace becomes more
complicated

I humbly ask...please don't move your logging in this direction. As a system which uses Mina
SSHD heavily, it's a very undesirable change for Bitbucket Server. If you do make this change,
though, please, please add a way to turn it off and log exceptions normally again.

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)

Mime
View raw message