[
https://issues.apache.org/jira/browse/DIRMINA-1021?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15043758#comment-15043758
]
Doug Kelly commented on DIRMINA-1021:
-------------------------------------
Ah, glad you mentioned that! Here's what happens in when enabling debug
logging in Gerrit (working successfully -- as in, this did not trigger the bug):
{code}
[2015-11-19 14:43:22,812] DEBUG com.google.gerrit.sshd.GerritServerSession :
Received SSH_MSG_DISCONNECT (reason=11, msg=disconnected by user)
[2015-11-19 14:43:22,813] DEBUG com.google.gerrit.sshd.GerritServerSession :
Closing GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319] immediately
[2015-11-19 14:43:22,815] DEBUG
org.apache.sshd.server.session.ServerConnectionService : Closing
ServerConnectionService[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319]]
immediately
[2015-11-19 14:43:22,815] DEBUG
org.apache.sshd.common.forward.DefaultTcpipForwarder : Closing
DefaultTcpipForwarder[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319]]
immediately
[2015-11-19 14:43:22,815] DEBUG
org.apache.sshd.common.forward.DefaultTcpipForwarder :
DefaultTcpipForwarder[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319]] closed
[2015-11-19 14:43:22,815] DEBUG
org.apache.sshd.agent.common.AgentForwardSupport : Closing
AgentForwardSupport[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319]]
immediately
[2015-11-19 14:43:22,815] DEBUG
org.apache.sshd.agent.common.AgentForwardSupport :
AgentForwardSupport[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319]] closed
[2015-11-19 14:43:22,815] DEBUG org.apache.sshd.server.x11.X11ForwardSupport :
Closing org.apache.sshd.server.x11.X11ForwardSupport@16efad0a immediately
[2015-11-19 14:43:22,815] DEBUG org.apache.sshd.server.x11.X11ForwardSupport :
org.apache.sshd.server.x11.X11ForwardSupport@16efad0a closed
[2015-11-19 14:43:22,815] DEBUG org.apache.sshd.server.channel.ChannelSession :
Closing ChannelSession[id=0, recipient=0] immediately
[2015-11-19 14:43:22,860] DEBUG org.apache.sshd.server.channel.ChannelSession :
ChannelSession[id=0, recipient=0] closed
[2015-11-19 14:43:22,860] DEBUG
org.apache.sshd.server.session.ServerConnectionService :
ServerConnectionService[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319]]
closed
[2015-11-19 14:43:22,860] DEBUG org.apache.sshd.common.io.mina.MinaSession :
Closing MinaSession[local=/0:0:0:0:0:0:0:1:29418,
remote=/0:0:0:0:0:0:0:1:56319] immediately
[2015-11-19 14:43:22,860] DEBUG org.apache.sshd.common.io.mina.MinaSession :
MinaSession[local=/0:0:0:0:0:0:0:1:29418, remote=/0:0:0:0:0:0:0:1:56319] closed
[2015-11-19 14:43:22,861] DEBUG com.google.gerrit.sshd.GerritServerSession :
GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319] closed
[2015-11-19 14:43:22,862] DEBUG com.google.gerrit.sshd.GerritServerSession :
GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56319] is already closed
[2015-11-19 14:43:22,864] ERROR com.google.gerrit.sshd.BaseCommand : Internal
server error (user dougk account 1000000) during git-upload-pack '/gerrit'
org.apache.sshd.common.channel.WindowClosedException: Already closed
{code}
Here's a case where I successfully reproduced the issue:
{code}
[2015-11-19 14:47:20,202] WARN com.google.gerrit.sshd.GerritServerSession :
Exception caught
java.nio.channels.CancelledKeyException
at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
at
org.apache.mina.transport.socket.nio.NioProcessor.setInterestedInWrite(NioProcessor.java:287)
at
org.apache.mina.transport.socket.nio.NioProcessor.setInterestedInWrite(NioProcessor.java:45)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:880)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:778)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor.access$700(AbstractPollingIoProcessor.java:67)
at
org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1126)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
[2015-11-19 14:47:20,202] DEBUG com.google.gerrit.sshd.GerritServerSession :
Closing GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415] immediately
[2015-11-19 14:47:20,202] DEBUG
org.apache.sshd.server.session.ServerConnectionService : Closing
ServerConnectionService[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415]]
immediately
[2015-11-19 14:47:20,202] DEBUG
org.apache.sshd.common.forward.DefaultTcpipForwarder : Closing
DefaultTcpipForwarder[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415]]
immediately
[2015-11-19 14:47:20,203] DEBUG
org.apache.sshd.common.forward.DefaultTcpipForwarder :
DefaultTcpipForwarder[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415]] closed
[2015-11-19 14:47:20,203] DEBUG
org.apache.sshd.agent.common.AgentForwardSupport : Closing
AgentForwardSupport[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415]]
immediately
[2015-11-19 14:47:20,203] DEBUG
org.apache.sshd.agent.common.AgentForwardSupport :
AgentForwardSupport[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415]] closed
[2015-11-19 14:47:20,203] DEBUG org.apache.sshd.server.x11.X11ForwardSupport :
Closing org.apache.sshd.server.x11.X11ForwardSupport@5774e544 immediately
[2015-11-19 14:47:20,203] DEBUG org.apache.sshd.server.channel.ChannelSession :
Send SSH_MSG_CHANNEL_DATA on channel 0
[2015-11-19 14:47:20,203] DEBUG org.apache.sshd.server.x11.X11ForwardSupport :
org.apache.sshd.server.x11.X11ForwardSupport@5774e544 closed
[2015-11-19 14:47:20,203] DEBUG org.apache.sshd.server.channel.ChannelSession :
Closing ChannelSession[id=0, recipient=0] immediately
[2015-11-19 14:47:20,209] DEBUG org.apache.sshd.server.channel.ChannelSession :
ChannelSession[id=0, recipient=0] closed
[2015-11-19 14:47:20,209] DEBUG
org.apache.sshd.server.session.ServerConnectionService :
ServerConnectionService[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415]]
closed
[2015-11-19 14:47:20,210] DEBUG org.apache.sshd.common.io.mina.MinaSession :
Closing MinaSession[local=0.0.0.0/0.0.0.0:29418, remote=/0:0:0:0:0:0:0:1:56415]
immediately
[2015-11-19 14:47:20,203] DEBUG org.apache.sshd.server.channel.ChannelSession :
Send SSH_MSG_CHANNEL_DATA on channel 0
[2015-11-19 14:47:20,203] DEBUG org.apache.sshd.server.x11.X11ForwardSupport :
org.apache.sshd.server.x11.X11ForwardSupport@5774e544 closed
[2015-11-19 14:47:20,203] DEBUG org.apache.sshd.server.channel.ChannelSession :
Closing ChannelSession[id=0, recipient=0] immediately
[2015-11-19 14:47:20,209] DEBUG org.apache.sshd.server.channel.ChannelSession :
ChannelSession[id=0, recipient=0] closed
[2015-11-19 14:47:20,209] DEBUG
org.apache.sshd.server.session.ServerConnectionService :
ServerConnectionService[GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415]]
closed
[2015-11-19 14:47:20,210] DEBUG org.apache.sshd.common.io.mina.MinaSession :
Closing MinaSession[local=0.0.0.0/0.0.0.0:29418, remote=/0:0:0:0:0:0:0:1:56415]
immediately
[2015-11-19 14:47:20,210] DEBUG org.apache.sshd.common.io.mina.MinaSession :
MinaSession[local=0.0.0.0/0.0.0.0:29418, remote=/0:0:0:0:0:0:0:1:56415] closed
[2015-11-19 14:47:20,210] DEBUG com.google.gerrit.sshd.GerritServerSession :
GerritServerSession[dougk@/0:0:0:0:0:0:0:1:56415] closed
{code}
Also, a stack trace from when I ended up in exceptionCaught() (i.e. this
triggered the bug):
{code}
Thread [NioProcessor-2] (Suspended (breakpoint at line 47 in
AbstractSessionIoHandler))
SshDaemon$1(AbstractSessionIoHandler).exceptionCaught(IoSession,
Throwable) line: 47
MinaAcceptor(MinaService).exceptionCaught(IoSession, Throwable) line:
101
DefaultIoFilterChain$TailFilter.exceptionCaught(IoFilter$NextFilter,
IoSession, Throwable) line: 824
DefaultIoFilterChain.callNextExceptionCaught(IoFilterChain$Entry,
IoSession, Throwable) line: 590
DefaultIoFilterChain.access$1100(DefaultIoFilterChain,
IoFilterChain$Entry, IoSession, Throwable) line: 48
DefaultIoFilterChain$EntryImpl$1.exceptionCaught(IoSession, Throwable)
line: 933
DefaultIoFilterChain$HeadFilter(IoFilterAdapter).exceptionCaught(IoFilter$NextFilter,
IoSession, Throwable) line: 102
DefaultIoFilterChain.callNextExceptionCaught(IoFilterChain$Entry,
IoSession, Throwable) line: 590
DefaultIoFilterChain.fireExceptionCaught(Throwable) line: 580
NioProcessor(AbstractPollingIoProcessor<S>).read(S) line: 741
NioProcessor(AbstractPollingIoProcessor<S>).process(S) line: 668
NioProcessor(AbstractPollingIoProcessor<S>).process() line: 657
AbstractPollingIoProcessor<S>.access$600(AbstractPollingIoProcessor)
line: 67
AbstractPollingIoProcessor$Processor.run() line: 1121
NamePreservingRunnable.run() line: 64
ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: 1142
ThreadPoolExecutor$Worker.run() line: 617
Thread.run() line: 745
{code}
> MINA-CORE does not remove sessions if exceptions occur while closing
> --------------------------------------------------------------------
>
> Key: DIRMINA-1021
> URL: https://issues.apache.org/jira/browse/DIRMINA-1021
> Project: MINA
> Issue Type: Bug
> Affects Versions: 2.0.8
> Environment: mina-ssh 0.14.0
> mina-core 2.0.8
> Multiple OSes / Java configurations:
> * Mac OS X El Capitan on Java 8 (1.8.0_60)
> * CentOS 6.4 on Java 8 (1.8.0_60)
> * CentOS 6.5 on Java 8 (1.8.0_20-b26).
> Reporter: Doug Kelly
> Attachments: attempt-removing-sessions-closing.patch
>
>
> MINA SSHD isn't removing sessions when using the MINA/NIO backend if an
> exception as received as the session is closing (such as a connection reset
> is received with data still in the write buffer). When this case happens, it
> seems that {{NioProcessor.getState}} returns the state as {{CLOSING}} (I'm
> assuming since the underlying channel is now closed), which means that the
> {{AbstractPollingIoProcessor.removeSessions()}} won't ever prune the session,
> since a {{CLOSING}} state is simply ignored. The result is a resource leak
> over time, since these sessions are never pruned (it's a slow leak, since
> entering this condition is racy – on my workstation, I can produce it through
> randomly interrupting connections anywhere from 1/6 to 1/10th of the time).
> (This may either be major or critical; reprioritize as necessary.)
> I specifically see this error with Gerrit 2.10.4 and Gerrit 2.11.5 (using
> mina-sshd 0.14.0 / mina-core 2.0.8), and it looks like the code path is
> unchanged in mina-sshd 1.0.0 / mina-core 2.0.9. I was unsure if this is
> specifically a bug in mina-core or, if it's something unique to mina-sshd. My
> local development system runs Mac OS X El Capitan on Java 8 (1.8.0_60), but
> I've also seen this on Linux (CentOS 6.4, again Java 1.8.0_60 and CentOS 6.5
> on Java 1.8.0_20-b26).
> The fix may be as simple as attempting to remove the session if {{OPENED}} or
> {{CLOSING}}, but I'm unsure what side-effects this may have with other
> backends. I'll be happy to test it locally, but I'm fairly ignorant when it
> comes to MINA's code.
> The attached patch (to mina-core) seems to resolve the issue by following the
> reproduction case I have on the [Gerrit issue
> tracker|https://code.google.com/p/gerrit/issues/detail?id=3685].
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
