[
https://issues.apache.org/jira/browse/SSHD-939?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16927710#comment-16927710
]
Anudeep commented on SSHD-939:
------------------------------
Hi [~lgoldstein] ,
Its ok ,we suppose to get back to you for help if we face some hurdles in
uplifting.
One last question which we do not understand from logs is invalid length.
Is there a way to decode it .The log in Abstract session prints the encrypted
packet length /actual packet length ?
Below one
// Read packet length decoderLength = decoderBuffer.getInt();
{code:java}
for (;;) {
// Wait for beginning of packet
if (decoderState == 0) {
// The read position should always be 0 at this point because
we have compacted this buffer
assert decoderBuffer.rpos() == 0;
// If we have received enough bytes, start processing those
if (decoderBuffer.available() > inCipherSize) {
// Decrypt the first bytes
if (inCipher != null) {
inCipher.update(decoderBuffer.array(), 0, inCipherSize);
}
// Read packet length
decoderLength = decoderBuffer.getInt();
// Check packet length validity
if (decoderLength < 5 || decoderLength > (256 * 1024)) {
log.info("Error decoding packet (invalid length) {}",
decoderBuffer.printHex());
throw new
SshException(SshConstants.SSH2_DISCONNECT_PROTOCOL_ERROR,
"Invalid packet length: " +
decoderLength);
}
// Ok, that's good, we can go to the next step
decoderState = 1;
} else {
// need more data
break;
} {code}
Why we ask is the previous log before invalid length says it has read 184 bytes
and in the exception we see it as some long negative integer and even some
times a long positive integer.
{code:java}
2019-08-22 09:53:29,106 DEBUG [org.apache.sshd.common.io.nio2.Nio2Session]
(sshd-SshServer[6162dce4]-nio2-th
read-2) Read 184 bytes
2019-08-22 09:53:29,106 INFO [org.apache.sshd.server.session.ServerSession]
(sshd-SshServer[6162dce4]-nio2-
thread-2) Error decoding packet (invalid length) a5 5f 74 5f a6 6f ea 41 02 c0
0a 54 83 22 e4 77 53 7d 0d b9
25 de 36 1d 07 cb cd 43 66 95 51 b2 72 54 d5 4e 2d 0a d5 17 f4 5e 81 4d 6a b8
ab f7 00 bf 4d 40 f5 56 b7 61
9b 8a be fe 54 d4 89 a2 c5 07 3c de 25 95 44 18 4f 90 dc aa 5b de 40 85 71 12
cc f6 c0 34 8d 0e 75 95 a5 5b
8d f6 b9 f6 94 04 d8 b5 25 5c d5 58 06 d1 82 68 13 2f 4c a0 ee 78 6b 20 97 52
2d 93 4c 88 bc 17 53 ca eb 34
23 c1 c6 1e 5a f9 31 e7 52 f9 ef 88 03 de e8 af ba 11 5e 97 50 1e c2 26 ba 80
34 55 3f 38 49 0c a9 80 8c a3
fe 6f b6 b6 5d 45 41 e9 e0 e6 d5 15 d6 44 f8 c4
2019-08-22 09:53:29,106 DEBUG [org.apache.sshd.common.io.nio2.Nio2Session]
(sshd-SshServer[6162dce4]-nio2-th
read-2) Caught exception, now calling handler
2019-08-22 09:53:29,106 WARN [org.apache.sshd.server.session.ServerSession]
(sshd-SshServer[6162dce4]-nio2-
thread-2) Exception caught: org.apache.sshd.common.SshException: Invalid packet
length: -16976455
at
org.apache.sshd.common.session.AbstractSession.decode(AbstractSession.java:677)
[sshd-core-0.13.0
.jar:0.13.0]
{code}
Please let us know if there is way to know what has caused this invalid length.
Regards,
Anudeep
> SSH threads get blocked in Object.wait() method forever resulting in
> CLOSE_WAIT connections
> -------------------------------------------------------------------------------------------
>
> Key: SSHD-939
> URL: https://issues.apache.org/jira/browse/SSHD-939
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 0.13.0
> Reporter: Anudeep
> Assignee: Goldstein Lyor
> Priority: Major
> Attachments: svc-1-bnsiserv_06_09_2019-server.7z,
> svc-1-bnsiserv_thread.log
>
>
> Ssh threads get blocked in object.wait() for ever and if the count of such
> threads crosses 3 no more ssh requests are served.
> We had an analysis of the logs and from the thread model of apache we see the
> maximum number of I/O threads is number of cores +1 in our server the number
> of cores is 2.
> SO after three such blocked threads we are not able to open any new ssh
> connection.
> Can you please confirm if the above logic is correct .
>
> We too found a ticket raised in 0.14.0
> (https://issues.apache.org/jira/browse/SSHD-348)which says threads in blocked
> state are fixed with 0.14.0 so we need a confirmation from you if 0.14.0 will
> fix the threads to be released and do not hung the process even if there are
> more than 3 of such a kind.
>
> Logs from thread dumps
> {code:java}
> From the thread dump it looks like we have a deadlock, e.g.
> In one thread we're trying to send out data on an SSH connection, but we're
> waiting for "space"
> "pool-7-thread-2213" #2677 prio=5 os_prio=0 tid=0x00007f85554cc800 nid=0x61e3
> in Object.wait() [0x00007f84ea29f000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at java.lang.Object.wait(Object.java:502)
> at org.apache.sshd.common.channel.Window.waitForSpace(Window.java:148)
> - locked <0x0000000764942ad8> (a
> org.apache.sshd.common.channel.Window)
> at
> org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:116)
> - eliminated <0x0000000764942c20> (a
> org.apache.sshd.common.channel.ChannelOutputStream)
> at
> org.apache.sshd.common.channel.ChannelOutputStream.write(ChannelOutputStream.java:84)
> - locked <0x0000000764942c20> (a
> org.apache.sshd.common.channel.ChannelOutputStream)
> at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
> at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
> at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
> - locked <0x0000000764943500> (a java.io.OutputStreamWriter)
> at java.io.OutputStreamWriter.write(OutputStreamWriter.java:207)
> at java.io.BufferedWriter.write(BufferedWriter.java:188)
> - locked <0x0000000764943500> (a java.io.OutputStreamWriter)
> at java.io.PrintWriter.write(PrintWriter.java:426)
> - locked <0x00000007649434d8> (a java.io.BufferedWriter)
> at java.io.PrintWriter.write(PrintWriter.java:443)
> In another thread, we trying to close the same connection
> "sshd-SshServer[1ae27e4e]-nio2-thread-3" #356 prio=5 os_prio=0
> tid=0x00000000015f6000 nid=0x30b8 waiting for monitor entry
> [0x00007f851ab9c000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at
> org.apache.sshd.common.channel.ChannelOutputStream.close(ChannelOutputStream.java:146)
> - waiting to lock <0x0000000764942c20> (a
> org.apache.sshd.common.channel.ChannelOutputStream)
> at
> com.ericsson.oss.nbi.connection.ssh.SshCommandContext.shutdown(SshCommandContext.java:146)
> at
> com.ericsson.oss.nbi.connection.ssh.SshCommand$ContextStarter.shutdown(SshCommand.java:104)
> at
> com.ericsson.oss.nbi.connection.ssh.SshCommand.destroy(SshCommand.java:78)
> at
> org.apache.sshd.server.channel.ChannelSession.doCloseImmediately(ChannelSession.java:242)
> at
> org.apache.sshd.common.util.CloseableUtils$AbstractCloseable.close(CloseableUtils.java:276)
> at
> org.apache.sshd.common.util.CloseableUtils$ParallelCloseable.doClose(CloseableUtils.java:182)
> at
> org.apache.sshd.common.util.CloseableUtils$SimpleCloseable.close(CloseableUtils.java:151)
> .... at
> org.apache.sshd.common.io.nio2.Nio2Session$1.onFailed(Nio2Session.java:199)
> at
> org.apache.sshd.common.io.nio2.Nio2CompletionHandler$2.run(Nio2CompletionHandler.java:41)
> at java.security.AccessController.doPrivileged(Native Method)
> at
> org.apache.sshd.common.io.nio2.Nio2CompletionHandler.failed(Nio2CompletionHandler.java:39)
> at
> org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:195)
> at
> org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:170)
> at
> org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:32)
> at java.security.AccessController.doPrivileged(Native Method)
> at
> org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:30)
> at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
> at sun.nio.ch.Invoker$2.run(Invoker.java:218)
> at
> sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> {code}
>
> Theory for the number of I/O process threads
> {code:java}
> https://cwiki.apache.org/confluence/display/MINA/Configuring+Thread+Model
> I/O processor thread performs the actual read and write operation until the
> connection is closed.Each SocketAcceptor or SocketConnector creates its own
> I/O processor thread(s). You can configure the number of the I/O processor
> threads. The default maximum number of the I/O processor threads is the
> number of CPU cores + 1. {code}
>
>
>
>
>
--
This message was sent by Atlassian Jira
(v8.3.2#803003)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org
For additional commands, e-mail: dev-h...@mina.apache.org
