[
https://issues.apache.org/jira/browse/SSHD-833?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16551446#comment-16551446
]
jpalacios commented on SSHD-833:
--------------------------------
Hi [~lgoldstein],
Following up on the built in Nio2 service factory, I was hoping you could help
us understand an exception that's being logged occasionally.
We first saw the following being logged at {{WARN}} level.
{code:java}
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2Acceptor$AcceptCompletionHandler.onCompleted(Nio2Acceptor.java:205)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
java.security.AccessController.doPrivileged(Native Method)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.io.nio2.Nio2Acceptor$AcceptCompletionHandler.onCompleted(Nio2Acceptor.java:174)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.session.helpers.AbstractSession.getSession(AbstractSession.java:318)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.sessionClosed(AbstractSessionIoHandler.java:45)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor at
org.apache.sshd.common.session.helpers.AbstractSession.getSession(AbstractSession.java:335)
2018-07-18 02:51:02,707 WARN [sshd-SshServer[37418a2a]-nio2-thread-1]
o.a.sshd.common.io.nio2.Nio2Acceptor Caught MissingAttachedSessionException
while accepting incoming connection from /<ADDRESS>:<PORT>: No session attached
to Nio2Session[local=/<ADDRESS>:<PORT>, remote=/<ADDRESS>:<PORT>]
{code}
When we saw this we switched on {{DEBUG}} level logging which added a bit of
context to the issue. We saw the following lines just before the exception
happened:
{code:java}
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session
writePacket(Nio2Session[local=/<ADDRESS>:<PORT>, remote=/<ADDRESS>:<PORT>])
Writing 22 bytes
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session
handleWriteCycleFailure(Nio2Session[local=/<ADDRESS>:<PORT>,
remote=/<ADDRESS>:<PORT>]) failed (IOException) to write 22 bytes: Connection
reset by peer
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session
exceptionCaught(Nio2Session[local=/<ADDRESS>:<PORT>, remote=/<ADDRESS>:<PORT>])
caught IOException[Connection reset by peer] - calling handler
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session close(Nio2Session[local=/<ADDRESS>:<PORT>,
remote=/<ADDRESS>:<PORT>]) Closing immediately
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session
doCloseImmediately(Nio2Session[local=/<ADDRESS>:<PORT>,
remote=/<ADDRESS>:<PORT>]) closing
socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected
local=/<ADDRESS>:<PORT> remote=/<ADDRESS>:<PORT>]
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session
doCloseImmediately(Nio2Session[local=/<ADDRESS>:<PORT>,
remote=/<ADDRESS>:<PORT>])
socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Acceptor unmapSession(id=361963): null
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session close(Nio2Session[local=/<ADDRESS>:<PORT>,
remote=/<ADDRESS>:<PORT>])[Immediately] closed
2018-07-18 09:20:43,480 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Session close(Nio2Session[local=/<ADDRESS>:<PORT>,
remote=/<ADDRESS>:<PORT>])[Immediately] state already Closed
2018-07-18 09:20:43,481 DEBUG [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Acceptor unmapSession(id=361963):
Nio2Session[local=/<ADDRESS>:<PORT>, remote=/<ADDRESS>:<PORT>]
2018-07-18 09:20:43,481 WARN [sshd-SshServer[6e517559]-nio2-thread-3]
o.a.sshd.common.io.nio2.Nio2Acceptor Caught MissingAttachedSessionException
while accepting incoming connection from /<ADDRESS>:<PORT>: No session attached
to Nio2Session[local=/<ADDRESS>:<PORT>, remote=/<ADDRESS>:<PORT>]
{code}
Is this just some overzealous logging for connections closed before the
handshake completes?
> Netty: ByteBuf LEAK message
> ---------------------------
>
> Key: SSHD-833
> URL: https://issues.apache.org/jira/browse/SSHD-833
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 2.0.0
> Reporter: jpalacios
> Priority: Major
>
> We recently switched from the {{MinaServiceFactoryFactory}} to the
> {{NettyIoServiceFactoryFactory}}. Now whenever the application starts we see
> the following message:
> {code:java}
> ERROR [nioEventLoopGroup-2-2] io.netty.util.ResourceLeakDetector LEAK:
> ByteBuf.release() was not called before it's garbage-collected. See
> http://netty.io/wiki/reference-counted-objects.html for more information.
> Recent access records:
> Created at:
>
> io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:331)
>
> io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:185)
>
> io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:176)
>
> io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:137)
>
> io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:114)
>
> io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:147)
>
> io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:647)
>
> io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:582)
>
> io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:499)
> io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:461)
>
> io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
>
> io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
> java.lang.Thread.run(Thread.java:748)
> {code}
> It will happen a certain number of times (first time it was 5, then it was
> 20) but then it won't happen any more.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
