This is an automated email from the ASF dual-hosted git repository. lgoldstein pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/mina-sshd.git
commit c39dd0d890dfe241681941aeceff7025b6c64ea2 Author: Lyor Goldstein <lgoldst...@apache.org> AuthorDate: Sun Apr 12 21:11:50 2020 +0300 [SSHD-977] Use consistent logging policy of caught exceptions details --- CHANGES.md | 4 +- .../agent/common/DefaultAgentForwardSupport.java | 8 +- .../apache/sshd/agent/local/AgentServerProxy.java | 2 +- .../java/org/apache/sshd/client/SshClient.java | 8 +- .../apache/sshd/client/channel/ChannelSession.java | 25 ++--- .../client/session/ClientConnectionService.java | 8 +- .../sshd/common/channel/AbstractChannel.java | 27 ++--- .../common/channel/BufferedIoOutputStream.java | 50 ++++----- .../common/channel/ChannelAsyncOutputStream.java | 5 +- .../sshd/common/channel/ChannelOutputStream.java | 12 +-- .../common/forward/DefaultForwardingFilter.java | 12 +-- .../apache/sshd/common/io/nio2/Nio2Service.java | 10 +- .../apache/sshd/common/io/nio2/Nio2Session.java | 50 ++++----- .../session/helpers/AbstractConnectionService.java | 15 ++- .../common/session/helpers/AbstractSession.java | 20 ++-- .../session/helpers/AbstractSessionIoHandler.java | 9 +- .../sshd/common/session/helpers/SessionHelper.java | 113 +++++++++------------ .../session/helpers/SessionTimeoutListener.java | 4 + .../sshd/server/session/AbstractServerSession.java | 10 +- .../sshd/server/session/ServerUserAuthService.java | 29 +++--- .../sshd/server/x11/DefaultX11ForwardSupport.java | 36 ++++--- .../apache/sshd/common/io/mina/MinaAcceptor.java | 4 +- .../apache/sshd/common/io/mina/MinaConnector.java | 4 +- .../subsystem/sftp/SftpDirEntryIterator.java | 4 +- .../subsystem/sftp/fs/SftpFileSystemProvider.java | 5 +- .../subsystem/sftp/impl/SimpleSftpClientImpl.java | 32 +++--- .../sftp/AbstractSftpSubsystemHelper.java | 23 ++--- .../sshd/server/subsystem/sftp/SftpSubsystem.java | 8 +- 28 files changed, 252 insertions(+), 285 deletions(-) diff --git a/CHANGES.md b/CHANGES.md index f978527..7c0747d 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -29,4 +29,6 @@ where the former validate the messages and deal with the idle timeout, and the l * [SSHD-970](https://issues.apache.org/jira/browse/SSHD-970) - `transferTo` function of `SftpRemotePathChannel` will loop if count parameter is greater than file size -* [SSHD-972](https://issues.apache.org/jira/browse/SSHD-972) - Add support for peers using OpenSSH "security key" key types \ No newline at end of file +* [SSHD-972](https://issues.apache.org/jira/browse/SSHD-972) - Add support for peers using OpenSSH "security key" key types + +* [SSHD-977](https://issues.apache.org/jira/browse/SSHD-977) - Apply consistent logging policy to caught exceptions \ No newline at end of file diff --git a/sshd-core/src/main/java/org/apache/sshd/agent/common/DefaultAgentForwardSupport.java b/sshd-core/src/main/java/org/apache/sshd/agent/common/DefaultAgentForwardSupport.java index 9af4a84..38b3fd2 100644 --- a/sshd-core/src/main/java/org/apache/sshd/agent/common/DefaultAgentForwardSupport.java +++ b/sshd-core/src/main/java/org/apache/sshd/agent/common/DefaultAgentForwardSupport.java @@ -65,12 +65,10 @@ public class DefaultAgentForwardSupport extends AbstractCloseable implements Age return agentId; } catch (Throwable t) { + log.error("initialize({}) failed ({}) to create server: {}", + session, t.getClass().getSimpleName(), t.getMessage()); if (log.isDebugEnabled()) { - log.debug("initialize({}) failed ({}) to create server: {}", - session, t.getClass().getSimpleName(), t.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("initialize(" + session + ") server creation failure details", t); + log.error("initialize(" + session + ") server creation failure details", t); } if (t instanceof IOException) { throw (IOException) t; diff --git a/sshd-core/src/main/java/org/apache/sshd/agent/local/AgentServerProxy.java b/sshd-core/src/main/java/org/apache/sshd/agent/local/AgentServerProxy.java index 24a34cd..8a9c0af 100644 --- a/sshd-core/src/main/java/org/apache/sshd/agent/local/AgentServerProxy.java +++ b/sshd-core/src/main/java/org/apache/sshd/agent/local/AgentServerProxy.java @@ -52,7 +52,7 @@ public class AgentServerProxy extends AbstractLoggingBean implements SshAgentSer return channel.getAgent(); } catch (Throwable t) { if (log.isDebugEnabled()) { - log.debug("createClient(" + service.getSession() + ")[" + getId() + ")" + log.warn("createClient(" + service.getSession() + ")[" + getId() + ")" + " failed (" + t.getClass().getSimpleName() + ")" + " to create client: " + t.getMessage()); } diff --git a/sshd-core/src/main/java/org/apache/sshd/client/SshClient.java b/sshd-core/src/main/java/org/apache/sshd/client/SshClient.java index 477d7c7..fee16ad 100644 --- a/sshd-core/src/main/java/org/apache/sshd/client/SshClient.java +++ b/sshd-core/src/main/java/org/apache/sshd/client/SshClient.java @@ -442,12 +442,10 @@ public class SshClient extends AbstractFactoryManager implements ClientFactoryMa "Failed to receive closure confirmation within " + maxWait + " millis"); } } catch (IOException e) { - if (log.isDebugEnabled()) { - log.debug(e.getClass().getSimpleName() + " while stopping client: " + e.getMessage()); - } + log.warn(e.getClass().getSimpleName() + " while stopping client: " + e.getMessage()); - if (log.isTraceEnabled()) { - log.trace("Stop exception details", e); + if (log.isDebugEnabled()) { + log.warn("Stop exception details", e); } } finally { // clear the attributes since we close stop the client diff --git a/sshd-core/src/main/java/org/apache/sshd/client/channel/ChannelSession.java b/sshd-core/src/main/java/org/apache/sshd/client/channel/ChannelSession.java index 6612079..2a162c5 100644 --- a/sshd-core/src/main/java/org/apache/sshd/client/channel/ChannelSession.java +++ b/sshd-core/src/main/java/org/apache/sshd/client/channel/ChannelSession.java @@ -156,13 +156,11 @@ public class ChannelSession extends AbstractClientChannel { pumperService.shutdownNow(); } catch (Exception e) { - // we log it as DEBUG since it is relatively harmless + // we log it as WARN since it is relatively harmless + log.warn("doCloseImmediately({}) failed {} to shutdown stream pumper: {}", + this, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("doCloseImmediately({}) failed {} to shutdown stream pumper: {}", - this, e.getClass().getSimpleName(), e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("doCloseImmediately(" + this + ") stream pumper shutdown error details", e); + log.warn("doCloseImmediately(" + this + ") stream pumper shutdown error details", e); } } finally { pumper = null; @@ -172,6 +170,7 @@ public class ChannelSession extends AbstractClientChannel { } protected void pumpInputStream() { + boolean debugEnabled = log.isDebugEnabled(); try { Session session = getSession(); Window wRemote = getRemoteWindow(); @@ -186,7 +185,7 @@ public class ChannelSession extends AbstractClientChannel { while (!closeFuture.isClosed()) { int len = securedRead(in, maxChunkSize, buffer, 0, buffer.length); if (len < 0) { - if (log.isDebugEnabled()) { + if (debugEnabled) { log.debug("pumpInputStream({}) EOF signalled", this); } sendEof(); @@ -200,17 +199,15 @@ public class ChannelSession extends AbstractClientChannel { } } - if (log.isDebugEnabled()) { + if (debugEnabled) { log.debug("pumpInputStream({}) close future closed", this); } } catch (Exception e) { if (!isClosing()) { - if (log.isDebugEnabled()) { - log.debug("pumpInputStream({}) Caught {} : {}", - this, e.getClass().getSimpleName(), e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("pumpInputStream(" + this + ") caught exception details", e); + log.error("pumpInputStream({}) Caught {} : {}", + this, e.getClass().getSimpleName(), e.getMessage()); + if (debugEnabled) { + log.error("pumpInputStream(" + this + ") caught exception details", e); } close(false); } diff --git a/sshd-core/src/main/java/org/apache/sshd/client/session/ClientConnectionService.java b/sshd-core/src/main/java/org/apache/sshd/client/session/ClientConnectionService.java index 8911cc5..a727cb2 100644 --- a/sshd-core/src/main/java/org/apache/sshd/client/session/ClientConnectionService.java +++ b/sshd-core/src/main/java/org/apache/sshd/client/session/ClientConnectionService.java @@ -142,12 +142,10 @@ public class ClientConnectionService return true; } catch (IOException | RuntimeException | Error e) { session.exceptionCaught(e); + log.warn("sendHeartBeat({}) failed ({}) to send heartbeat #{} request={}: {}", + session, e.getClass().getSimpleName(), heartbeatCount, heartbeatRequest, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("sendHeartBeat({}) failed ({}) to send heartbeat #{} request={}: {}", - session, e.getClass().getSimpleName(), heartbeatCount, heartbeatRequest, e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("sendHeartBeat(" + session + ") exception details", e); + log.warn("sendHeartBeat(" + session + ") exception details", e); } return false; diff --git a/sshd-core/src/main/java/org/apache/sshd/common/channel/AbstractChannel.java b/sshd-core/src/main/java/org/apache/sshd/common/channel/AbstractChannel.java index 4a393b0..27bff8a 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/channel/AbstractChannel.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/channel/AbstractChannel.java @@ -276,7 +276,7 @@ public abstract class AbstractChannel this, e.getClass().getSimpleName(), handler.getClass().getSimpleName(), req, wantReply, e.getMessage()); if (debugEnabled) { - log.debug("handleRequest(" + this + ") request=" + req + log.warn("handleRequest(" + this + ") request=" + req + "[want-reply=" + wantReply + "] processing failure details", e); } @@ -444,14 +444,12 @@ public abstract class AbstractChannel log.warn("signalChannelOpenFailure({}) failed ({}) to inform listener of open failure={}: {}", this, ignored.getClass().getSimpleName(), reason.getClass().getSimpleName(), ignored.getMessage()); if (log.isDebugEnabled()) { - log.debug("doInit(" + this + ") inform listener open failure details", ignored); - } + log.warn("doInit(" + this + ") inform listener open failure details", ignored); - if (log.isTraceEnabled()) { Throwable[] suppressed = ignored.getSuppressed(); if (GenericUtils.length(suppressed) > 0) { for (Throwable s : suppressed) { - log.trace("signalChannelOpenFailure(" + this + ") suppressed channel open failure signalling", s); + log.warn("signalChannelOpenFailure(" + this + ") suppressed channel open failure signalling", s); } } } @@ -477,7 +475,7 @@ public abstract class AbstractChannel log.warn("notifyStateChanged({})[{}] {} while signal channel state change: {}", this, hint, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("notifyStateChanged(" + this + ")[" + hint + "] channel state signalling failure details", e); + log.warn("notifyStateChanged(" + this + ")[" + hint + "] channel state signalling failure details", e); } } finally { synchronized (futureLock) { @@ -633,13 +631,11 @@ public abstract class AbstractChannel } }); } catch (IOException e) { - if (debugEnabled) { - log.debug("close({})[immediately={}] {} while writing SSH_MSG_CHANNEL_CLOSE packet on channel: {}", - channel, immediately, e.getClass().getSimpleName(), e.getMessage()); - } + log.warn("close({})[immediately={}] {} while writing SSH_MSG_CHANNEL_CLOSE packet on channel: {}", + channel, immediately, e.getClass().getSimpleName(), e.getMessage()); - if (log.isTraceEnabled()) { - log.trace("close(" + channel + ")[immediately=" + immediately + "] packet write failure details", e); + if (log.isDebugEnabled()) { + log.warn("close(" + channel + ")[immediately=" + immediately + "] packet write failure details", e); } channel.close(true); } @@ -730,13 +726,12 @@ public abstract class AbstractChannel Throwable e = GenericUtils.peelException(err); log.warn("signalChannelClosed({}) {} while signal channel closed: {}", this, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("signalChannelClosed(" + this + ") channel closed signalling failure details", e); - } - if (log.isTraceEnabled()) { + log.warn("signalChannelClosed(" + this + ") channel closed signalling failure details", e); + Throwable[] suppressed = e.getSuppressed(); if (GenericUtils.length(suppressed) > 0) { for (Throwable s : suppressed) { - log.trace("signalChannelClosed(" + this + ") suppressed closed channel signalling failure", s); + log.warn("signalChannelClosed(" + this + ") suppressed closed channel signalling failure", s); } } } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/channel/BufferedIoOutputStream.java b/sshd-core/src/main/java/org/apache/sshd/common/channel/BufferedIoOutputStream.java index 1cb75aa..d39c1f5 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/channel/BufferedIoOutputStream.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/channel/BufferedIoOutputStream.java @@ -52,7 +52,7 @@ public class BufferedIoOutputStream extends AbstractInnerCloseable implements Io @Override public IoWriteFuture writePacket(Buffer buffer) throws IOException { if (isClosing()) { - throw new EOFException("Closed"); + throw new EOFException("Closed - state=" + state); } IoWriteFutureImpl future = new IoWriteFutureImpl(getId(), buffer); @@ -71,36 +71,40 @@ public class BufferedIoOutputStream extends AbstractInnerCloseable implements Io return; } - out.writePacket(future.getBuffer()).addListener(new SshFutureListener<IoWriteFuture>() { - @Override - public void operationComplete(IoWriteFuture f) { - if (f.isWritten()) { - future.setValue(Boolean.TRUE); - } else { - future.setValue(f.getException()); + out.writePacket(future.getBuffer()).addListener( + new SshFutureListener<IoWriteFuture>() { + @Override + public void operationComplete(IoWriteFuture f) { + if (f.isWritten()) { + future.setValue(Boolean.TRUE); + } else { + future.setValue(f.getException()); + } + finishWrite(future); } - finishWrite(); - } + }); + } - @SuppressWarnings("synthetic-access") - private void finishWrite() { - writes.remove(future); - currentWrite.compareAndSet(future, null); - try { - startWriting(); - } catch (IOException e) { - log.error("finishWrite({}) failed ({}) re-start writing", out, e.getClass().getSimpleName()); - } + protected void finishWrite(IoWriteFutureImpl future) { + writes.remove(future); + currentWrite.compareAndSet(future, null); + try { + startWriting(); + } catch (IOException e) { + log.error("finishWrite({}) failed ({}) re-start writing: {}", + out, e.getClass().getSimpleName(), e.getMessage()); + if (log.isDebugEnabled()) { + log.error("finishWrite(" + out + ") exception details", e); } - }); + } } @Override protected Closeable getInnerCloseable() { return builder() - .when(getId(), writes) - .close(out) - .build(); + .when(getId(), writes) + .close(out) + .build(); } @Override diff --git a/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelAsyncOutputStream.java b/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelAsyncOutputStream.java index e2f1ebd..a2066b3 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelAsyncOutputStream.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelAsyncOutputStream.java @@ -78,7 +78,10 @@ public class ChannelAsyncOutputStream extends AbstractCloseable implements IoOut packetWriter.close(); } catch (IOException e) { log.error("preClose({}) Failed ({}) to pre-close packet writer: {}", - this, e.getClass().getSimpleName(), e.getMessage()); + this, e.getClass().getSimpleName(), e.getMessage()); + if (log.isDebugEnabled()) { + log.error("preClose(" + this + ") packet writer close exception details", e); + } } } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelOutputStream.java b/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelOutputStream.java index a5168ee..4d04dea 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelOutputStream.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/channel/ChannelOutputStream.java @@ -138,10 +138,8 @@ public class ChannelOutputStream extends OutputStream implements java.nio.channe log.trace("write({}) len={} - available={}", this, l, available); } } catch (IOException e) { - if (debugEnabled) { - log.debug("write({}) failed ({}) to wait for space of len={}: {}", - this, e.getClass().getSimpleName(), l, e.getMessage()); - } + log.error("write({}) failed ({}) to wait for space of len={}: {}", + this, e.getClass().getSimpleName(), l, e.getMessage()); if ((e instanceof WindowClosedException) && (!closedState.getAndSet(true))) { if (debugEnabled) { @@ -198,11 +196,11 @@ public class ChannelOutputStream extends OutputStream implements java.nio.channe log.trace("flush({}) len={}, available={}", this, total, available); } } catch (IOException e) { + log.error("flush({}) failed ({}) to wait for space of len={}: {}", + this, e.getClass().getSimpleName(), total, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("flush({}) failed ({}) to wait for space of len={}: {}", - this, e.getClass().getSimpleName(), total, e.getMessage()); + log.error("flush(" + this + ") wait for space len=" + total + " exception details", e); } - throw e; } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/forward/DefaultForwardingFilter.java b/sshd-core/src/main/java/org/apache/sshd/common/forward/DefaultForwardingFilter.java index 5be03e1..a31cacf 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/forward/DefaultForwardingFilter.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/forward/DefaultForwardingFilter.java @@ -702,9 +702,9 @@ public class DefaultForwardingFilter } } catch (Error e) { log.warn("localPortForwardingRequested({})[{}] failed ({}) to consult forwarding filter: {}", - session, local, e.getClass().getSimpleName(), e.getMessage()); + session, local, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("localPortForwardingRequested(" + this + ")[" + local + "] filter consultation failure details", e); + log.warn("localPortForwardingRequested(" + session + ")[" + local + "] filter consultation failure details", e); } throw new RuntimeSshException(e); } @@ -974,7 +974,7 @@ public class DefaultForwardingFilter } return (InetSocketAddress) GenericUtils.head(after); } catch (IOException bindErr) { - Set<SocketAddress> after = acceptor.getBoundAddresses(); + Collection<SocketAddress> after = acceptor.getBoundAddresses(); if (GenericUtils.isEmpty(after)) { close(); } @@ -1123,11 +1123,9 @@ public class DefaultForwardingFilter @Override public void exceptionCaught(IoSession session, Throwable cause) throws Exception { session.setAttribute(TcpipForwardingExceptionMarker.class, cause); + log.warn("exceptionCaught({}) {}: {}", session, cause.getClass().getSimpleName(), cause.getMessage()); if (debugEnabled) { - log.debug("exceptionCaught({}) {}: {}", session, cause.getClass().getSimpleName(), cause.getMessage()); - } - if (traceEnabled) { - log.trace("exceptionCaught(" + session + ") caught exception details", cause); + log.warn("exceptionCaught(" + session + ") caught exception details", cause); } session.close(true); } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Service.java b/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Service.java index 066df84..73c4863 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Service.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Service.java @@ -114,13 +114,11 @@ public abstract class Nio2Service extends AbstractInnerCloseable implements IoSe throw new SocketTimeoutException("Failed to receive closure confirmation within " + maxWait + " millis"); } } catch (IOException e) { - if (log.isDebugEnabled()) { - log.debug("dispose({}) {} while stopping service: {}", - this, e.getClass().getSimpleName(), e.getMessage()); - } + log.warn("dispose({}) {} while stopping service: {}", + this, e.getClass().getSimpleName(), e.getMessage()); - if (log.isTraceEnabled()) { - log.trace("dispose(" + this + ") Stop exception details", e); + if (log.isDebugEnabled()) { + log.warn("dispose(" + this + ") Stop exception details", e); } } } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Session.java b/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Session.java index aaeab26..d683015 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Session.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/io/nio2/Nio2Session.java @@ -138,23 +138,18 @@ public class Nio2Session extends AbstractCloseable implements IoSession { public void suspend() { AsynchronousSocketChannel socket = getSocket(); - boolean debugEnabled = log.isDebugEnabled(); try { socket.shutdownInput(); } catch (IOException e) { - if (debugEnabled) { - log.debug("suspend({}) failed ({}) to shutdown input: {}", - this, e.getClass().getSimpleName(), e.getMessage()); - } + log.warn("suspend({}) failed ({}) to shutdown input: {}", + this, e.getClass().getSimpleName(), e.getMessage()); } try { socket.shutdownOutput(); } catch (IOException e) { - if (debugEnabled) { - log.debug("suspend({}) failed ({}) to shutdown output: {}", - this, e.getClass().getSimpleName(), e.getMessage()); - } + log.warn("suspend({}) failed ({}) to shutdown output: {}", + this, e.getClass().getSimpleName(), e.getMessage()); } } @@ -194,13 +189,11 @@ public class Nio2Session extends AbstractCloseable implements IoSession { handler.exceptionCaught(this, exc); } catch (Throwable e) { Throwable t = GenericUtils.peelException(e); - if (log.isDebugEnabled()) { - log.debug("exceptionCaught({}) Exception handler threw {}, closing the session: {}", - this, t.getClass().getSimpleName(), t.getMessage()); - } + log.warn("exceptionCaught({}) Exception handler threw {}, closing the session: {}", + this, t.getClass().getSimpleName(), t.getMessage()); - if (log.isTraceEnabled()) { - log.trace("exceptionCaught(" + this + ") exception handler failure details", t); + if (log.isDebugEnabled()) { + log.warn("exceptionCaught(" + this + ") exception handler failure details", t); } } } @@ -263,12 +256,11 @@ public class Nio2Session extends AbstractCloseable implements IoSession { if (debugEnabled) { log.debug("doCloseImmediately({}) socket={} closed", this, socket); } - } catch (IOException e) { log.info("doCloseImmediately({}) {} caught while closing socket={}: {}", this, e.getClass().getSimpleName(), socket, e.getMessage()); if (debugEnabled) { - log.debug("doCloseImmediately(" + this + ") socket=" + socket + " close failure details", e); + log.info("doCloseImmediately(" + this + ") socket=" + socket + " close failure details", e); } } @@ -279,13 +271,10 @@ public class Nio2Session extends AbstractCloseable implements IoSession { try { handler.sessionClosed(this); } catch (Throwable e) { - if (debugEnabled) { - log.debug("doCloseImmediately({}) {} while calling IoHandler#sessionClosed: {}", - this, e.getClass().getSimpleName(), e.getMessage()); - } - - if (log.isTraceEnabled()) { - log.trace("doCloseImmediately(" + this + ") IoHandler#sessionClosed failure details", e); + log.warn("doCloseImmediately({}) {} while calling IoHandler#sessionClosed: {}", + this, e.getClass().getSimpleName(), e.getMessage()); + if (log.isDebugEnabled()) { + log.warn("doCloseImmediately(" + this + ") IoHandler#sessionClosed failure details", e); } } @@ -457,8 +446,10 @@ public class Nio2Session extends AbstractCloseable implements IoSession { try { socket.write(buffer, null, completionHandler); } catch (Throwable t) { + log.warn("handleCompletedWriteCycle({}) {} while writing to socket len={}: {}", + this, t.getClass().getSimpleName(), writeLen, t.getMessage()); if (log.isDebugEnabled()) { - log.debug("handleCompletedWriteCycle(" + this + ") Exception caught while writing " + writeLen + " bytes", t); + log.warn("handleCompletedWriteCycle(" + this + ") Exception caught while writing " + writeLen + " bytes", t); } future.setWritten(); finishWrite(future); @@ -485,8 +476,7 @@ public class Nio2Session extends AbstractCloseable implements IoSession { this, exc.getClass().getSimpleName(), writeLen, exc.getMessage()); } - boolean traceEnabled = log.isTraceEnabled(); - if (traceEnabled) { + if (log.isTraceEnabled()) { log.trace("handleWriteCycleFailure(" + this + ") len=" + writeLen + " failure details", exc); } future.setException(exc); @@ -496,10 +486,8 @@ public class Nio2Session extends AbstractCloseable implements IoSession { try { finishWrite(future); } catch (RuntimeException e) { - if (traceEnabled) { - log.trace("handleWriteCycleFailure({}) failed ({}) to finish writing: {}", - this, e.getClass().getSimpleName(), e.getMessage()); - } + log.warn("handleWriteCycleFailure({}) failed ({}) to finish writing: {}", + this, e.getClass().getSimpleName(), e.getMessage()); } } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractConnectionService.java b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractConnectionService.java index 6f8233e..4e706f5 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractConnectionService.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractConnectionService.java @@ -255,12 +255,10 @@ public abstract class AbstractConnectionService } catch (Throwable e) { session.exceptionCaught(e); + log.warn("sendHeartBeat({}) failed ({}) to send heartbeat #{} request={}: {}", + session, e.getClass().getSimpleName(), heartbeatCount, heartbeatType, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("sendHeartBeat({}) failed ({}) to send heartbeat #{} request={}: {}", - session, e.getClass().getSimpleName(), heartbeatCount, heartbeatType, e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("sendHeartBeat(" + session + ") exception details", e); + log.warn("sendHeartBeat(" + session + ") exception details", e); } return false; @@ -818,9 +816,10 @@ public abstract class AbstractConnectionService sendChannelOpenFailure(buf, sender, reasonCode, message, ""); } } catch (IOException e) { + log.warn("operationComplete({}) {}: {}", + AbstractConnectionService.this, e.getClass().getSimpleName(), e.getMessage()); if (debugEnabled) { - log.debug("operationComplete({}) {}: {}", - AbstractConnectionService.this, e.getClass().getSimpleName(), e.getMessage()); + log.warn("operationComplete(" + AbstractConnectionService.this + ") exception details", e); } session.exceptionCaught(e); } @@ -875,7 +874,7 @@ public abstract class AbstractConnectionService log.warn("globalRequest({})[{}, want-reply={}] failed ({}) to process: {}", this, req, wantReply, e.getClass().getSimpleName(), e.getMessage()); if (debugEnabled) { - log.debug("globalRequest(" + this + ")[" + req + ", want-reply=" + wantReply + "] failure details", e); + log.warn("globalRequest(" + this + ")[" + req + ", want-reply=" + wantReply + "] failure details", e); } result = RequestHandler.Result.ReplyFailure; } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSession.java b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSession.java index 6718034..d951e16 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSession.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSession.java @@ -625,13 +625,11 @@ public abstract class AbstractSession extends SessionHelper { try { startService(serviceName, buffer); } catch (Throwable e) { - if (debugEnabled) { - log.debug("handleServiceRequest({}) Service {} rejected: {} = {}", - this, serviceName, e.getClass().getSimpleName(), e.getMessage()); - } + log.warn("handleServiceRequest({}) Service {} rejected: {} = {}", + this, serviceName, e.getClass().getSimpleName(), e.getMessage()); - if (log.isTraceEnabled()) { - log.trace("handleServiceRequest(" + this + ") service=" + serviceName + " rejection details", e); + if (debugEnabled) { + log.warn("handleServiceRequest(" + this + ") service=" + serviceName + " rejection details", e); } disconnect(SshConstants.SSH2_DISCONNECT_SERVICE_NOT_AVAILABLE, "Bad service request: " + serviceName); return false; @@ -865,8 +863,10 @@ public abstract class AbstractSession extends SessionHelper { try { checkRekey(); } catch (GeneralSecurityException e) { + log.warn("writePacket({}) failed ({}) to check re-key: {}", + this, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("writePacket(" + this + ") rekey security exception details", e); + log.warn("writePacket(" + this + ") rekey security exception details", e); } throw ValidateUtils.initializeExceptionCause( new ProtocolException("Failed (" + e.getClass().getSimpleName() + ")" @@ -1804,7 +1804,7 @@ public abstract class AbstractSession extends SessionHelper { log.warn("negotiate({}) failed ({}) to invoke disconnect handler due to mismatched KEX option={}: {}", this, e.getClass().getSimpleName(), paramType, e.getMessage()); if (debugEnabled) { - log.debug("negotiate(" + this + ") handler invocation exception details", e); + log.warn("negotiate(" + this + ") handler invocation exception details", e); } } @@ -2041,8 +2041,10 @@ public abstract class AbstractSession extends SessionHelper { try { requestNewKeysExchange(); } catch (GeneralSecurityException e) { + log.warn("reExchangeKeys({}) failed ({}) to request new keys: {}", + this, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("reExchangeKeys(" + this + ") security exception details", e); + log.warn("reExchangeKeys(" + this + ") security exception details", e); } throw ValidateUtils.initializeExceptionCause( new ProtocolException("Failed (" + e.getClass().getSimpleName() + ")" diff --git a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSessionIoHandler.java b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSessionIoHandler.java index 6b4f56c..04f2e73 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSessionIoHandler.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/AbstractSessionIoHandler.java @@ -62,13 +62,10 @@ public abstract class AbstractSessionIoHandler extends AbstractLoggingBean imple try { session.messageReceived(message); } catch (Error e) { + log.error("messageReceived({}) failed {} to handle message: {}", + ioSession, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("messageReceived({}) failed {} to handle message: {}", - ioSession, e.getClass().getSimpleName(), e.getMessage()); - } - - if (log.isTraceEnabled()) { - log.trace("messageReceived(" + ioSession + ") message handling error details", e); + log.error("messageReceived(" + ioSession + ") message handling error details", e); } throw new RuntimeSshException(e); } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionHelper.java b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionHelper.java index 7e021ba..1cb4c22 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionHelper.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionHelper.java @@ -226,8 +226,9 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements * @see #checkIdleTimeout(long, long, long) */ protected TimeoutIndicator checkForTimeouts() throws IOException { + boolean debugEnabled = log.isDebugEnabled(); if ((!isOpen()) || isClosing() || isClosed()) { - if (log.isDebugEnabled()) { + if (debugEnabled) { log.debug("checkForTimeouts({}) session closing", this); } return TimeoutIndicator.NONE; @@ -238,7 +239,7 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements TimeoutStatus status = (result == null) ? TimeoutStatus.NoTimeout : result.getStatus(); if ((status != null) && (status != TimeoutStatus.NoTimeout)) { - if (log.isDebugEnabled()) { + if (debugEnabled) { log.debug("checkForTimeouts({}) already detected {}", this, result); } return result; @@ -264,13 +265,13 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements // If disconnect handler throws an exception continue with the disconnect log.warn("checkForTimeouts({}) failed ({}) to invoke disconnect handler to handle {}: {}", this, e.getClass().getSimpleName(), result, e.getMessage()); - if (log.isDebugEnabled()) { - log.debug("checkForTimeouts(" + this + ") disconnect handler exception details", e); + if (debugEnabled) { + log.warn("checkForTimeouts(" + this + ") disconnect handler exception details", e); } } if (resetTimeout) { - if (log.isDebugEnabled()) { + if (debugEnabled) { log.debug("checkForTimeouts({}) cancel {} due to handler intervention", this, result); } @@ -288,7 +289,7 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements return TimeoutIndicator.NONE; } - if (log.isDebugEnabled()) { + if (debugEnabled) { log.debug("checkForTimeouts({}) disconnect - reason={}", this, result); } @@ -582,12 +583,10 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements }); } catch (Throwable err) { Throwable e = GenericUtils.peelException(err); + log.error("Failed ({}) to announce session={} established: {}", + e.getClass().getSimpleName(), ioSession, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("Failed ({}) to announce session={} established: {}", - e.getClass().getSimpleName(), ioSession, e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("Session=" + ioSession + " establish failure details", e); + log.error("Session=" + ioSession + " establish failure details", e); } if (e instanceof Exception) { throw (Exception) e; @@ -612,12 +611,10 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements }); } catch (Throwable err) { Throwable e = GenericUtils.peelException(err); + log.error("Failed ({}) to announce session={} created: {}", + e.getClass().getSimpleName(), ioSession, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("Failed ({}) to announce session={} created: {}", - e.getClass().getSimpleName(), ioSession, e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("Session=" + ioSession + " creation failure details", e); + log.error("Session=" + ioSession + " creation failure details", e); } if (e instanceof Exception) { throw (Exception) e; @@ -642,12 +639,10 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements }); } catch (Throwable err) { Throwable e = GenericUtils.peelException(err); + log.error("signalPeerIdentificationReceived({}) Failed ({}) to announce peer={}: {}", + this, e.getClass().getSimpleName(), version, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("signalPeerIdentificationReceived({}) Failed ({}) to announce peer={}: {}", - this, e.getClass().getSimpleName(), version, e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("signalPeerIdentificationReceived(" + this + ")[" + version + "] failure details", e); + log.error("signalPeerIdentificationReceived(" + this + ")[" + version + "] failure details", e); } if (e instanceof Exception) { throw (Exception) e; @@ -680,12 +675,10 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements }); } catch (Throwable err) { Throwable t = GenericUtils.peelException(err); + log.error("sendSessionEvent({})[{}] failed ({}) to inform listeners: {}", + this, event, t.getClass().getSimpleName(), t.getMessage()); if (log.isDebugEnabled()) { - log.debug("sendSessionEvent({})[{}] failed ({}) to inform listeners: {}", - this, event, t.getClass().getSimpleName(), t.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("sendSessionEvent(" + this + ")[" + event + "] listener inform details", t); + log.error("sendSessionEvent(" + this + ")[" + event + "] listener inform details", t); } if (t instanceof IOException) { throw (IOException) t; @@ -1084,20 +1077,19 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements IoWriteFuture packetFuture = writePacket(buffer, disconnectTimeoutMs, TimeUnit.MILLISECONDS); packetFuture.addListener(future -> { Throwable t = future.getException(); - if (log.isDebugEnabled()) { - if (t == null) { + boolean debugEnabled = log.isDebugEnabled(); + if (t == null) { + if (debugEnabled) { log.debug("disconnect({}) operation successfully completed for reason={} [{}]", SessionHelper.this, SshConstants.getDisconnectReasonName(reason), msg); - } else { - log.debug("disconnect({}) operation failed ({}) for reason={} [{}]: {}", - SessionHelper.this, t.getClass().getSimpleName(), - SshConstants.getDisconnectReasonName(reason), msg, t.getMessage()); } - } + } else { + log.warn("disconnect({}) operation failed ({}) for reason={} [{}]: {}", + SessionHelper.this, t.getClass().getSimpleName(), + SshConstants.getDisconnectReasonName(reason), msg, t.getMessage()); - if (t != null) { - if (log.isTraceEnabled()) { - log.trace("disconnect(" + SessionHelper.this + ")" + if (debugEnabled) { + log.warn("disconnect(" + SessionHelper.this + ")" + " reason=" + SshConstants.getDisconnectReasonName(reason) + " failure details", t); } @@ -1139,15 +1131,13 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements }); } catch (Throwable err) { Throwable e = GenericUtils.peelException(err); - if (log.isDebugEnabled()) { - log.debug("signalDisconnect(" + this + ") signal session disconnect details", e); - } + log.warn("signalDisconnect(" + this + ") signal session disconnect details", e); - if (log.isTraceEnabled()) { + if (log.isDebugEnabled()) { Throwable[] suppressed = e.getSuppressed(); if (GenericUtils.length(suppressed) > 0) { for (Throwable s : suppressed) { - log.trace("signalDisconnect(" + this + ") suppressed session disconnect signalling", s); + log.warn("signalDisconnect(" + this + ") suppressed session disconnect signalling", s); } } } @@ -1174,13 +1164,12 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements public void exceptionCaught(Throwable t) { State curState = state.get(); // Ignore exceptions that happen while closing immediately + boolean debugEnabled = log.isDebugEnabled(); if ((!State.Opened.equals(curState)) && (!State.Graceful.equals(curState))) { - if (log.isDebugEnabled()) { - log.debug("exceptionCaught({}) ignore {} due to state={}, message='{}'", - this, t.getClass().getSimpleName(), curState, t.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("exceptionCaught(" + this + ")[state=" + curState + "] ignored exception details", t); + log.warn("exceptionCaught({}) ignore {} due to state={}, message='{}'", + this, t.getClass().getSimpleName(), curState, t.getMessage()); + if (debugEnabled) { + log.warn("exceptionCaught(" + this + ")[state=" + curState + "] ignored exception details", t); } return; } @@ -1196,10 +1185,10 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements this, curState, cause.getClass().getSimpleName(), cause.getMessage()); } - if (log.isDebugEnabled()) { - log.debug("exceptionCaught(" + this + ")[state=" + curState + "] details", t); + if (debugEnabled) { + log.warn("exceptionCaught(" + this + ")[state=" + curState + "] details", t); if (cause != null) { - log.debug("exceptionCaught(" + this + ")[state=" + curState + "] cause", cause); + log.warn("exceptionCaught(" + this + ")[state=" + curState + "] cause", cause); } } @@ -1211,12 +1200,10 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements try { disconnect(code, t.getMessage()); } catch (Throwable t2) { - if (log.isDebugEnabled()) { - log.debug("exceptionCaught({}) {} while disconnect with code={}: {}", - this, t2.getClass().getSimpleName(), SshConstants.getDisconnectReasonName(code), t2.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("exceptionCaught(" + this + ")[code=" + SshConstants.getDisconnectReasonName(code) + "] disconnect exception details", t2); + log.warn("exceptionCaught({}) {} while disconnect with code={}: {}", + this, t2.getClass().getSimpleName(), SshConstants.getDisconnectReasonName(code), t2.getMessage()); + if (debugEnabled) { + log.warn("exceptionCaught(" + this + ")[code=" + SshConstants.getDisconnectReasonName(code) + "] disconnect exception details", t2); } } return; @@ -1234,15 +1221,15 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements }); } catch (Throwable err) { Throwable e = GenericUtils.peelException(err); + log.warn("signalExceptionCaught({}) {}: {}", + this, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("signalExceptionCaught(" + this + ") signal session exception details", e); - } + log.warn("signalExceptionCaught(" + this + ") signal session exception details", e); - if (log.isTraceEnabled()) { Throwable[] suppressed = e.getSuppressed(); if (GenericUtils.length(suppressed) > 0) { for (Throwable s : suppressed) { - log.trace("signalExceptionCaught(" + this + ") suppressed session exception signalling", s); + log.warn("signalExceptionCaught(" + this + ") suppressed session exception signalling", s); } } } @@ -1268,14 +1255,12 @@ public abstract class SessionHelper extends AbstractKexFactoryManager implements log.warn("signalSessionClosed({}) {} while signal session closed: {}", this, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("signalSessionClosed(" + this + ") signal session closed exception details", e); - } + log.warn("signalSessionClosed(" + this + ") signal session closed exception details", e); - if (log.isTraceEnabled()) { Throwable[] suppressed = e.getSuppressed(); if (GenericUtils.length(suppressed) > 0) { for (Throwable s : suppressed) { - log.trace("signalSessionClosed(" + this + ") suppressed session closed signalling", s); + log.warn("signalSessionClosed(" + this + ") suppressed session closed signalling", s); } } } diff --git a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionTimeoutListener.java b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionTimeoutListener.java index de3d107..a5bc4ea 100644 --- a/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionTimeoutListener.java +++ b/sshd-core/src/main/java/org/apache/sshd/common/session/helpers/SessionTimeoutListener.java @@ -84,12 +84,16 @@ public class SessionTimeoutListener @Override public void run() { + boolean debugEnabled = log.isDebugEnabled(); for (SessionHelper session : sessions) { try { session.checkForTimeouts(); } catch (Exception e) { log.warn(e.getClass().getSimpleName() + " while checking" + " session=" + session + " timeouts: " + e.getMessage(), e); + if (debugEnabled) { + log.warn("Session " + session + " timeouts check exception details", e); + } } } } diff --git a/sshd-core/src/main/java/org/apache/sshd/server/session/AbstractServerSession.java b/sshd-core/src/main/java/org/apache/sshd/server/session/AbstractServerSession.java index 7da497a..7232935 100644 --- a/sshd-core/src/main/java/org/apache/sshd/server/session/AbstractServerSession.java +++ b/sshd-core/src/main/java/org/apache/sshd/server/session/AbstractServerSession.java @@ -265,7 +265,7 @@ public abstract class AbstractServerSession extends AbstractSession implements S log.warn("startService({})[{}] failed ({}) to invoke disconnect handler: {}", this, name, e.getClass().getSimpleName(), e.getMessage()); if (log.isDebugEnabled()) { - log.debug("startService(" + this + ")[" + name + "] disconnect handler invocation exception details", e); + log.warn("startService(" + this + ")[" + name + "] disconnect handler invocation exception details", e); } } @@ -336,7 +336,7 @@ public abstract class AbstractServerSession extends AbstractSession implements S log.warn("handleServiceAccept({}) failed ({}) to invoke disconnect handler of unknown service={}: {}", this, e.getClass().getSimpleName(), serviceName, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("handleServiceAccept(" + this + ")[" + serviceName + "] handler invocation exception details", e); + log.warn("handleServiceAccept(" + this + ")[" + serviceName + "] handler invocation exception details", e); } } @@ -374,7 +374,7 @@ public abstract class AbstractServerSession extends AbstractSession implements S log.warn("resolveAvailableSignaturesProposal({}) failed ({}) to get key types: {}", this, e.getClass().getSimpleName(), e.getMessage()); if (debugEnabled) { - log.debug("resolveAvailableSignaturesProposal(" + this + ") fetch key types failure details", e); + log.warn("resolveAvailableSignaturesProposal(" + this + ") fetch key types failure details", e); } throw new RuntimeSshException(e); @@ -430,7 +430,7 @@ public abstract class AbstractServerSession extends AbstractSession implements S log.warn("readIdentification({}) failed ({}) to accept proxy metadata: {}", this, t.getClass().getSimpleName(), t.getMessage()); if (debugEnabled) { - log.debug("readIdentification(" + this + ") proxy metadata acceptance failure details", t); + log.warn("readIdentification(" + this + ") proxy metadata acceptance failure details", t); } if (t instanceof IOException) { @@ -503,7 +503,7 @@ public abstract class AbstractServerSession extends AbstractSession implements S log.warn("getHostKey({}) failed ({}) to load key of type={}[{}]: {}", this, e.getClass().getSimpleName(), proposedKey, keyType, e.getMessage()); if (log.isDebugEnabled()) { - log.debug("getHostKey(" + this + ") " + proposedKey + "[" + keyType + "] key load failure details", e); + log.warn("getHostKey(" + this + ") " + proposedKey + "[" + keyType + "] key load failure details", e); } throw new RuntimeSshException(e); diff --git a/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java b/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java index 242267e..9847c4c 100644 --- a/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java +++ b/sshd-core/src/main/java/org/apache/sshd/server/session/ServerUserAuthService.java @@ -193,12 +193,10 @@ public class ServerUserAuthService extends AbstractCloseable implements Service, return; } catch (Exception e) { // Continue + log.warn("process({}) Failed ({}) to authenticate using current method={}: {}", + session, e.getClass().getSimpleName(), currentAuth.getName(), e.getMessage()); if (debugEnabled) { - log.debug("process({}) Failed ({}) to authenticate using current method={}: {}", - session, e.getClass().getSimpleName(), currentAuth.getName(), e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("process(" + session + ") current authentication=" + currentAuth.getName() + " failure details", e); + log.warn("process(" + session + ") current authentication=" + currentAuth.getName() + " failure details", e); } } } @@ -276,7 +274,7 @@ public class ServerUserAuthService extends AbstractCloseable implements Service, this.authUserName, username, this.authService, service, nbAuthRequests, maxAuthRequests, e.getMessage()); if (debugEnabled) { - log.debug("process(" + session + ") disconnect handler auth requests count invocation exception", e); + log.warn("process(" + session + ") disconnect handler auth requests count invocation exception", e); } } @@ -304,7 +302,7 @@ public class ServerUserAuthService extends AbstractCloseable implements Service, session, e.getClass().getSimpleName(), this.authUserName, username, this.authService, service, e.getMessage()); if (debugEnabled) { - log.debug("handleUserAuthRequestMessage(" + session + ") disconnect handler auth mismatched parameters invocation exception", e); + log.warn("handleUserAuthRequestMessage(" + session + ") disconnect handler auth mismatched parameters invocation exception", e); } } @@ -347,12 +345,10 @@ public class ServerUserAuthService extends AbstractCloseable implements Service, async.addListener(authenticated -> asyncAuth(SshConstants.SSH_MSG_USERAUTH_REQUEST, buffer, authenticated)); return false; } catch (Exception e) { + log.warn("handleUserAuthRequestMessage({}) Failed ({}) to authenticate using factory method={}: {}", + session, e.getClass().getSimpleName(), method, e.getMessage()); if (debugEnabled) { - log.debug("handleUserAuthRequestMessage({}) Failed ({}) to authenticate using factory method={}: {}", - session, e.getClass().getSimpleName(), method, e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("handleUserAuthRequestMessage(" + session + ") factory authentication=" + method + " failure details", e); + log.warn("handleUserAuthRequestMessage(" + session + ") factory authentication=" + method + " failure details", e); } } @@ -367,7 +363,12 @@ public class ServerUserAuthService extends AbstractCloseable implements Service, handleAuthenticationFailure(cmd, buffer); } } catch (Exception e) { - log.warn("Error performing async authentication: {}", e.getMessage(), e); + ServerSession session = getServerSession(); + log.warn("asyncAuth({}) Error ({}) performing async authentication via cmd={}: {}", + session, e.getClass().getSimpleName(), cmd, e.getMessage()); + if (log.isDebugEnabled()) { + log.warn("asyncAuth(" + session + ")[cmd=" + cmd + "] exception details", e); + } } } @@ -411,7 +412,7 @@ public class ServerUserAuthService extends AbstractCloseable implements Service, log.warn("handleAuthenticationSuccess({}@{}) failed ({}) to invoke disconnect handler due to {}/{} sessions count: {}", username, session, e.getClass().getSimpleName(), currentSessionCount, maxSessionCount, e.getMessage()); if (debugEnabled) { - log.debug("handleAuthenticationSuccess(" + username + "@" + session + ") invocation handler exception details", e); + log.warn("handleAuthenticationSuccess(" + username + "@" + session + ") invocation handler exception details", e); } } diff --git a/sshd-core/src/main/java/org/apache/sshd/server/x11/DefaultX11ForwardSupport.java b/sshd-core/src/main/java/org/apache/sshd/server/x11/DefaultX11ForwardSupport.java index e5cd422..94506f7 100644 --- a/sshd-core/src/main/java/org/apache/sshd/server/x11/DefaultX11ForwardSupport.java +++ b/sshd-core/src/main/java/org/apache/sshd/server/x11/DefaultX11ForwardSupport.java @@ -45,7 +45,6 @@ import org.apache.sshd.common.util.closeable.AbstractInnerCloseable; * @author <a href="mailto:d...@mina.apache.org">Apache MINA SSHD Project</a> */ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements X11ForwardSupport { - private final ConnectionService service; private IoAcceptor acceptor; @@ -80,7 +79,7 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements if (OsUtils.isWin32()) { if (debugEnabled) { log.debug("createDisplay(auth={}, cookie={}, screen={}) Windows O/S N/A", - authenticationProtocol, authenticationCookie, screen); + authenticationProtocol, authenticationCookie, screen); } return null; } @@ -108,8 +107,8 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements } catch (BindException bindErr) { if (debugEnabled) { log.debug("createDisplay(auth={}, cookie={}, screen={}) failed ({}) to bind to address={}: {}", - authenticationProtocol, authenticationCookie, screen, - bindErr.getClass().getSimpleName(), addr, bindErr.getMessage()); + authenticationProtocol, authenticationCookie, screen, + bindErr.getClass().getSimpleName(), addr, bindErr.getMessage()); } addr = null; @@ -125,13 +124,13 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements if (GenericUtils.isEmpty(boundAddresses)) { if (debugEnabled) { log.debug("createDisplay(auth={}, cookie={}, screen={}) closing - no more bound addresses", - authenticationProtocol, authenticationCookie, screen); + authenticationProtocol, authenticationCookie, screen); } close(); } else { if (debugEnabled) { log.debug("createDisplay(auth={}, cookie={}, screen={}) closing - remaining bound addresses: {}", - authenticationProtocol, authenticationCookie, screen, boundAddresses); + authenticationProtocol, authenticationCookie, screen, boundAddresses); } } @@ -142,14 +141,18 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements int displayNumber = port - basePort; String authDisplay = "unix:" + displayNumber + "." + screen; try { - Process p = new ProcessBuilder(XAUTH_COMMAND, "remove", authDisplay).start(); + ProcessBuilder processBuilder = new ProcessBuilder(XAUTH_COMMAND, "remove", authDisplay); + Process p = processBuilder.start(); int result = p.waitFor(); if (debugEnabled) { log.debug("createDisplay({}) {} remove result={}", authDisplay, XAUTH_COMMAND, result); } if (result == 0) { - p = new ProcessBuilder(XAUTH_COMMAND, "add", authDisplay, authenticationProtocol, authenticationCookie).start(); + processBuilder = + new ProcessBuilder( + XAUTH_COMMAND, "add", authDisplay, authenticationProtocol, authenticationCookie); + p = processBuilder.start(); result = p.waitFor(); if (debugEnabled) { @@ -164,9 +167,9 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements return bindHost + ":" + displayNumber + "." + screen; } catch (Throwable e) { log.warn("createDisplay({}) failed ({}) run xauth: {}", - authDisplay, e.getClass().getSimpleName(), e.getMessage()); + authDisplay, e.getClass().getSimpleName(), e.getMessage()); if (debugEnabled) { - log.debug("createDisplay(" + authDisplay + ") xauth failure details", e); + log.warn("createDisplay(" + authDisplay + ") xauth failure details", e); } return null; } @@ -180,7 +183,8 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements log.debug("sessionCreated({}) channel{}", session, channel); } this.service.registerChannel(channel); - channel.open().verify(channel.getLongProperty(CHANNEL_OPEN_TIMEOUT_PROP, DEFAULT_CHANNEL_OPEN_TIMEOUT)); + long openTimeout = channel.getLongProperty(CHANNEL_OPEN_TIMEOUT_PROP, DEFAULT_CHANNEL_OPEN_TIMEOUT); + channel.open().verify(openTimeout); } @Override @@ -190,7 +194,7 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements if (channel != null) { if (log.isDebugEnabled()) { log.debug("sessionClosed({}) close channel={} - cause={}", - session, channel, (cause == null) ? null : cause.getClass().getSimpleName()); + session, channel, (cause == null) ? null : cause.getClass().getSimpleName()); } // If exception signaled then close channel immediately channel.close(cause != null); @@ -214,11 +218,11 @@ public class DefaultX11ForwardSupport extends AbstractInnerCloseable implements @Override public void exceptionCaught(IoSession session, Throwable cause) throws Exception { session.setAttribute(X11ForwardingExceptionMarker.class, cause); + log.error("exceptionCaught({}) {}: {}", + session, cause.getClass().getSimpleName(), cause.getMessage()); + if (log.isDebugEnabled()) { - log.debug("exceptionCaught({}) {}: {}", session, cause.getClass().getSimpleName(), cause.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("exceptionCaught(" + session + ") caught exception details", cause); + log.error("exceptionCaught(" + session + ") caught exception details", cause); } session.close(true); } diff --git a/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaAcceptor.java b/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaAcceptor.java index 7987fda..efaf8c0 100644 --- a/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaAcceptor.java +++ b/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaAcceptor.java @@ -101,8 +101,10 @@ public class MinaAcceptor extends MinaService implements org.apache.sshd.common. try { listener.abortAcceptedConnection(this, local, remote, service, e); } catch (Exception exc) { + log.warn("sessionCreated({})[{}] ignoring abort event failure={}: {}", + session, listener, exc.getClass().getSimpleName(), exc.getMessage()); if (log.isDebugEnabled()) { - log.debug("sessionCreated(" + session + ") listener=" + listener + " ignoring abort event exception", exc); + log.warn("sessionCreated(" + session + ") listener=" + listener + " ignoring abort event exception", exc); } } } diff --git a/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaConnector.java b/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaConnector.java index 620de98..d8e506a 100644 --- a/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaConnector.java +++ b/sshd-mina/src/main/java/org/apache/sshd/common/io/mina/MinaConnector.java @@ -98,8 +98,10 @@ public class MinaConnector extends MinaService implements org.apache.sshd.common try { listener.abortEstablishedConnection(this, local, context, remote, e); } catch (Exception exc) { + log.warn("sessionCreated({}) ignoring abort connection failure={}: {}", + session, exc.getClass().getSimpleName(), exc.getMessage()); if (log.isDebugEnabled()) { - log.debug("sessionCreated(" + session + ") listener=" + listener + " ignoring abort event exception", exc); + log.warn("sessionCreated(" + session + ") listener=" + listener + " ignoring abort event exception", exc); } } } diff --git a/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/SftpDirEntryIterator.java b/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/SftpDirEntryIterator.java index abf3a1d..dd04766 100644 --- a/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/SftpDirEntryIterator.java +++ b/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/SftpDirEntryIterator.java @@ -177,8 +177,8 @@ public class SftpDirEntryIterator extends AbstractLoggingBean implements Iterato try { close(); } catch (IOException t) { - if (log.isTraceEnabled()) { - log.trace(t.getClass().getSimpleName() + " while close handle=" + handle + if (log.isDebugEnabled()) { + log.warn(t.getClass().getSimpleName() + " while close handle=" + handle + " due to " + e.getClass().getSimpleName() + " [" + e.getMessage() + "]" + ": " + t.getMessage()); } diff --git a/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/fs/SftpFileSystemProvider.java b/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/fs/SftpFileSystemProvider.java index 5acf6da..0e58138 100644 --- a/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/fs/SftpFileSystemProvider.java +++ b/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/fs/SftpFileSystemProvider.java @@ -267,7 +267,7 @@ public class SftpFileSystemProvider extends FileSystemProvider { session.close(); } catch (IOException t) { if (log.isDebugEnabled()) { - log.debug("Failed (" + t.getClass().getSimpleName() + ")" + log.warn("Failed (" + t.getClass().getSimpleName() + ")" + " to close session for new file system on " + host + ":" + port + " due to " + e.getClass().getSimpleName() + "[" + e.getMessage() + "]" + ": " + t.getMessage()); @@ -293,7 +293,8 @@ public class SftpFileSystemProvider extends FileSystemProvider { return fileSystem; } - protected SftpVersionSelector resolveSftpVersionSelector(URI uri, SftpVersionSelector defaultSelector, PropertyResolver resolver) { + protected SftpVersionSelector resolveSftpVersionSelector( + URI uri, SftpVersionSelector defaultSelector, PropertyResolver resolver) { String preference = resolver.getString(VERSION_PARAM); if (GenericUtils.isEmpty(preference)) { return defaultSelector; diff --git a/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/impl/SimpleSftpClientImpl.java b/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/impl/SimpleSftpClientImpl.java index 468610a..2a00052 100644 --- a/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/impl/SimpleSftpClientImpl.java +++ b/sshd-sftp/src/main/java/org/apache/sshd/client/subsystem/sftp/impl/SimpleSftpClientImpl.java @@ -102,13 +102,11 @@ public class SimpleSftpClientImpl extends AbstractLoggingBean implements SimpleS try { client.close(); } catch (Exception t) { - if (log.isDebugEnabled()) { - log.debug("createSftpClient({}) failed ({}) to close client: {}", - session, t.getClass().getSimpleName(), t.getMessage()); - } + log.warn("createSftpClient({}) failed ({}) to close client: {}", + session, t.getClass().getSimpleName(), t.getMessage()); - if (log.isTraceEnabled()) { - log.trace("createSftpClient(" + session + ") client close failure details", t); + if (log.isDebugEnabled()) { + log.warn("createSftpClient(" + session + ") client close failure details", t); } err = GenericUtils.accumulateException(err, t); } @@ -119,18 +117,16 @@ public class SimpleSftpClientImpl extends AbstractLoggingBean implements SimpleS // This point is reached if error occurred log.warn("createSftpClient({}) failed ({}) to create session: {}", - session, err.getClass().getSimpleName(), err.getMessage()); + session, err.getClass().getSimpleName(), err.getMessage()); try { session.close(); } catch (Exception e) { - if (log.isDebugEnabled()) { - log.debug("createSftpClient({}) failed ({}) to close session: {}", - session, e.getClass().getSimpleName(), e.getMessage()); - } + log.warn("createSftpClient({}) failed ({}) to close session: {}", + session, e.getClass().getSimpleName(), e.getMessage()); - if (log.isTraceEnabled()) { - log.trace("createSftpClient(" + session + ") session close failure details", e); + if (log.isDebugEnabled()) { + log.warn("createSftpClient(" + session + ") session close failure details", e); } err = GenericUtils.accumulateException(err, e); } @@ -152,9 +148,9 @@ public class SimpleSftpClientImpl extends AbstractLoggingBean implements SimpleS try { result = method.invoke(client, args); } catch (Throwable t) { - if (log.isTraceEnabled()) { - log.trace("invoke(SftpClient#{}) failed ({}) to execute: {}", - name, t.getClass().getSimpleName(), t.getMessage()); + if (log.isDebugEnabled()) { + log.warn("invoke(SftpClient#{}) failed ({}) to execute: {}", + name, t.getClass().getSimpleName(), t.getMessage()); } err = GenericUtils.accumulateException(err, t); } @@ -165,8 +161,8 @@ public class SimpleSftpClientImpl extends AbstractLoggingBean implements SimpleS session.close(); } catch (Throwable t) { if (log.isDebugEnabled()) { - log.debug("invoke(ClientSession#{}) failed ({}) to execute: {}", - name, t.getClass().getSimpleName(), t.getMessage()); + log.warn("invoke(ClientSession#{}) failed ({}) to execute: {}", + name, t.getClass().getSimpleName(), t.getMessage()); } err = GenericUtils.accumulateException(err, t); } diff --git a/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/AbstractSftpSubsystemHelper.java b/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/AbstractSftpSubsystemHelper.java index 1380251..e53cb44 100644 --- a/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/AbstractSftpSubsystemHelper.java +++ b/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/AbstractSftpSubsystemHelper.java @@ -1466,12 +1466,10 @@ public abstract class AbstractSftpSubsystemHelper try { attrs = getAttributes(p, options); } catch (IOException e) { - if (debugEnabled) { - log.debug("doRealPath({}) - failed ({}) to retrieve attributes of {}: {}", - session, e.getClass().getSimpleName(), p, e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("doRealPath(" + session + ")[" + p + "] attributes retrieval failure details", e); + log.warn("doRealPath({}) - failed ({}) to retrieve attributes of {}: {}", + session, e.getClass().getSimpleName(), p, e.getMessage()); + if (log.isDebugEnabled()) { + log.warn("doRealPath(" + session + ")[" + p + "] attributes retrieval failure details", e); } } } else { @@ -2414,6 +2412,7 @@ public abstract class AbstractSftpSubsystemHelper Path file, int flags, Map<String, Object> current, LinkOption... options) throws IOException { boolean debugEnabled = log.isDebugEnabled(); + ServerSession session = getServerSession(); NavigableMap<String, Object> attrs = null; // Cannot use forEach because the attrs variable is not effectively final for (Map.Entry<String, FileInfoExtractor<?>> re : SftpFileSystemAccessor.FILEATTRS_RESOLVERS.entrySet()) { @@ -2434,15 +2433,13 @@ public abstract class AbstractSftpSubsystemHelper if (debugEnabled) { log.debug("resolveMissingFileAttributes({})[{}[{}]] replace {} with {}", - getServerSession(), file, name, value, resolved); + session, file, name, value, resolved); } } catch (IOException e) { - if (debugEnabled) { - log.debug("resolveMissingFileAttributes({})[{}[{}]] failed ({}) to resolve missing value: {}", - getServerSession(), file, name, e.getClass().getSimpleName(), e.getMessage()); - } - if (log.isTraceEnabled()) { - log.trace("resolveMissingFileAttributes(" + getServerSession() + ")" + log.warn("resolveMissingFileAttributes({})[{}[{}]] failed ({}) to resolve missing value: {}", + session, file, name, e.getClass().getSimpleName(), e.getMessage()); + if (log.isDebugEnabled()) { + log.warn("resolveMissingFileAttributes(" + session + ")" + "[" + file + "[" + name + "]] missing value resolution failure details", e); } } diff --git a/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/SftpSubsystem.java b/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/SftpSubsystem.java index c9bfd97..2cbfc52 100644 --- a/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/SftpSubsystem.java +++ b/sshd-sftp/src/main/java/org/apache/sshd/server/subsystem/sftp/SftpSubsystem.java @@ -279,7 +279,7 @@ public class SftpSubsystem CloseableExecutorService executor = getExecutorService(); pendingFuture = executor.submit(this); } catch (RuntimeException e) { // e.g., RejectedExecutionException - log.error("Failed (" + e.getClass().getSimpleName() + ") to start command: " + e.toString(), e); + log.error("Failed (" + e.getClass().getSimpleName() + ") to start command: " + e.getMessage(), e); throw new IOException(e); } } @@ -324,7 +324,7 @@ public class SftpSubsystem log.error("run({}) {} caught in SFTP subsystem: {}", session, t.getClass().getSimpleName(), t.getMessage()); if (log.isDebugEnabled()) { - log.debug("run(" + session + ") caught exception details", t); + log.error("run(" + session + ") caught exception details", t); } } } finally { @@ -1011,7 +1011,7 @@ public class SftpSubsystem log.warn("destroy({}) Failed ({}) to announce destruction event: {}", session, e.getClass().getSimpleName(), e.getMessage()); if (debugEnabled) { - log.debug("destroy(" + session + ") destruction announcement failure details", e); + log.warn("destroy(" + session + ") destruction announcement failure details", e); } } @@ -1043,7 +1043,7 @@ public class SftpSubsystem } } catch (IOException e) { if (debugEnabled) { - log.debug("destroy(" + session + ")" + log.warn("destroy(" + session + ")" + " failed (" + e.getClass().getSimpleName() + ")" + " to close file system: " + e.getMessage(), e); }