[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16575093#comment-16575093
]
Goldstein Lyor commented on SSHD-838:
-
I believe 2.1.0 will be the next release in view of several structural changes
(not just this one). We have not set even a tentative release date yet - we
usually wait for enough changes to accumulate (when that will be or what
"enough" means is still a fluid definition... :)). My current intent is to aim
for a release sometime in mid-Sep. perhaps early Oct. 2018...
{quote}
Best regards, and thanks again for all your support
{quote}
We are always open for improvements - especially when persuasive justification
can be provided - as in this case.
> 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
>Assignee: Goldstein Lyor
>Priority: Major
> Labels: important, listener, logging
> Fix For: 2.0.1
>
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16573267#comment-16573267
]
Bryan Turner commented on SSHD-838:
---
[~lgoldstein],
Thanks for such rapid turnaround! The new interface looks great. Since it's new
functionality, will you be releasing it as 2.1.0? Seems a little odd for a
patch release to introduce a new public SPI. Any thoughts on when a release
will be cut with it?
Once this change is released, I'll get Bitbucket Server upgraded. At that
point, I think we'll make SSHD's own NIO factory our default, instead of Mina.
We've been holding off due to these warnings coming from our production server
where we've been testing the changeover.
Best regards, and thanks again for all your support!
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
>Assignee: Goldstein Lyor
>Priority: Major
> Labels: important, listener, logging
> Fix For: 2.0.1
>
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565817#comment-16565817
]
Goldstein Lyor commented on SSHD-838:
-
{quote}
That said, though, I want to be respectful of your time, because I'm not sure I
personally have the time to devote to building that change, and jpalacios is
about to leave on vacation
{quote}
I was not implying that you should come up with the code change - I feel I
understand the requirements and agree with the valid arguments you have made.
All I ask is that since your project seems to make use of this library, we
could leverage your experience with it and if possible to map the locations
where in your experience there is "loud" logging (as you have put it) so I can
have a better idea as to how to craft the suggested solution and where to
employ it.
{quote}
and I don't want to assume you have the time to build it either.
{quote}
I am rather busy in the near future, but since I believe this is an important
issue I will try to find some time for it (don't know when though). Please
track this issue and if you don't see any progress within the next few weeks,
please don't hesitate to inquire - just so we can be sure it does not fall
between the cracks...
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565804#comment-16565804
]
Bryan Turner commented on SSHD-838:
---
My thanks and sincere appreciation, [~lgoldstein].
{quote}
Perhaps a possible solution is to define some "events" that can be signalled
via a ConnectionEventListener before the session is established and let the
user decide how to log them - e.g., connection requested, connection
established, connection accepted, connection terminated + reason (OK or
exception), etc For backward compatibility, if no event listener is
registered then the code will just log the event as it currently does (i.e.,
WARNING + stack trace)...
Once the session is established, all events associated with it should be
signalled via the SessionListener. In this context, please see if there are
other such exceptions/warnings that are signalled via logging and could
potentially be signalled via either the ConnectionEventListener or the
SessionListener.
{quote}
The approach itself sounds good to me. Bitbucket Server is already implementing
its own {{SessionListener}}, so implementing a {{ConnectionListener}} (or
whatever name is used) would be a logical enhancement, and allow us to
customize the behavior to fit our needs. That said, though, I want to be
respectful of your time, because I'm not sure I personally have the time to
devote to _building_ that change, and [~jpalacios] is about to leave on
vacation, and I don't want to assume you have the time to build it either.
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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565783#comment-16565783
]
ASF GitHub Bot commented on SSHD-838:
-
Github user bturner closed the pull request at:
https://github.com/apache/mina-sshd/pull/65
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565735#comment-16565735
]
Goldstein Lyor commented on SSHD-838:
-
After reviewing your arguments I was persuaded and have adopted your suggested
patch (with a minor change) - see [this
commit|https://github.com/apache/mina-sshd/commit/f17bf3852e27b67f86fbd0d4091e788deb4202ba].
What remains now is the connection event listen...
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565706#comment-16565706
]
Goldstein Lyor commented on SSHD-838:
-
{quote}I humbly ask...please don't move your logging in this direction{quote}
Will take this under advisement...
What about the {{ConnectionEventListener}} solution I suggested ?
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565685#comment-16565685
]
Bryan Turner commented on SSHD-838:
---
{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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565509#comment-16565509
]
Goldstein Lyor commented on SSHD-838:
-
{quote}
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.
{quote}
But that is a *client* side event - how can the *server* distinguish between
such (let's say) "acceptable" incomplete handshakes from "unacceptable" ones.
If there indeed is a problem and we always log it as DEBUG level, we might
never know about "unacceptable" handshakes...
{quote}
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?
{quote}
Perhaps a possible solution is do define some "events" that can be signalled
via a {{ConnectionEventListener}} before the session is established and let the
user decide how to log them - e.g., connection requested, connection
established, connection accepted, connection terminated + reason (OK or
exception), etc For backward compatibility, if no event listener is
registered then the code will just log the event as it currently does (i.e.,
WARNING + stack trace)...
Once the session is established, all events associated with it should be
signalled via the {{SessionListener}}. In this context, please see if there are
other such exceptions/warnings that are signalled via logging and could
potentially be signalled via either the {{ConnectionEventListener}} or the
{{SessionListener}}.
What do you think ... ?
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16565499#comment-16565499
]
Goldstein Lyor commented on SSHD-838:
-
{quote}
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"?
{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}
LoggingUtils.logExceptionStackTrace appears to only be used in 2 places in the
entire codebase
{quote}
This utility is relatively new and we did not retro fit older code.
{quote}
how about removing logExceptionStackTrace
{quote}
If anything, I am considering replacing all code that passes the exception
directly to the logging framework with this call.
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16564284#comment-16564284
]
Bryan Turner commented on SSHD-838:
---
{{LoggingUtils.logExceptionStackTrace}} appears to only be used in [2 places in
the entire
codebase|https://github.com/apache/mina-sshd/search?q=logExceptionStackTrace_q=logExceptionStackTrace].
In all the other places where exceptions are logged, they're passed through
directly to SLF4J. Setting aside the _level_ consideration for the moment, how
about removing {{logExceptionStackTrace}} and making the two call sites log the
exception directly? To help move the discussion forward, I've opened [pull
request #65|https://github.com/apache/mina-sshd/pull/65] with a minimal change.
The log levels and messages are unchanged; only how the exceptions are logged
is different.
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16564283#comment-16564283
]
ASF GitHub Bot commented on SSHD-838:
-
GitHub user bturner opened a pull request:
https://github.com/apache/mina-sshd/pull/65
SSHD-838 Remove LoggingUtils.logExceptionStackTrace.
- Removed LoggingUtils.logExceptionStackTrace and its related helpers
- Updated call sites in Nio2Acceptor and Nio2Session to log exceptions by
passing them directly to SLF4J
You can merge this pull request into a Git repository by running:
$ git pull https://github.com/bturner/mina-sshd
SSHD-838-remove-logexceptionstacktrace
Alternatively you can review and apply these changes as the patch at:
https://github.com/apache/mina-sshd/pull/65.patch
To close this pull request, make a commit to your master/trunk branch
with (at least) the following in the commit message:
This closes #65
commit 4abe76d65227723a91c2073da42eafaa1ef9f5e0
Author: Bryan Turner
Date: 2018-07-31T19:47:20Z
SSHD-838 Remove LoggingUtils.logExceptionStackTrace.
- Removed LoggingUtils.logExceptionStackTrace and its related helpers
- Updated call sites in Nio2Acceptor and Nio2Session to log exceptions
by passing them directly to SLF4J
> 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)
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=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
[jira] [Commented] (SSHD-838) Lower the log level in Nio2Acceptor.AcceptCompletionHandler#okToReaccept
[
https://issues.apache.org/jira/browse/SSHD-838?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16563999#comment-16563999
]
Goldstein Lyor commented on SSHD-838:
-
Please publish this as Github PR as it makes it easier to review and comment...
Specifically there are 2 requests:
* Lower the log level - we will need to consider this against the possible
benefit of such "loudness" - WARNING(s) are intended to indicate and draw
attention to abnormal conditions in the system and I am inclined to believe that
{quote}when a client disconnects before the handshake completes{quote} this
falls well within this definition. I am not against lowering the level of the
stack trace, but will have to think hard about the warning that the condition
occurred.
* {quote}Logging the stacktrace in a single message{quote} this may make the
stack trace un-readable... - it is much easier to read if each line is separate
* {quote}too much noise for system administrators who might think there's
something wrong with the system{quote} - as previously stated, there *is*
something wrong with the system and IMO many administrators would like to know.
This is a general project and we cannot accommodate everyone, so we make
choices that we think will satisfy the most users.
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.
Another solution is to employ log analysis tools (there are many out there) and
"teach" them what warnings/errors interest *your* solution and which do not
(which might be different than what *my* solution or other users' solution
might consider warnings/errors of interest).
> 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: Bug
>Affects Versions: 2.0.0
>Reporter: jpalacios
>Priority: Major
> 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)
