While performing an sftp get on a jar file of size 2765226 from a Linux server, the get would hang on this particular file every time.
One would see that a file of the same name being created on the local system of 0 bytes in length.
The thread performing the get would hang everytime - no exception shown or propagated.
If Log4j initialized such that all trace is turned prior to performing the get, one would then see the exception.
The trace (including stack trace) follows:
10421 [ssh-connection 1] DEBUG com.sshtools.j2ssh.connection.ConnectionProtocol
- Received 32780 bytes of data for channel id 2
10421 [ssh-connection 1] FATAL com.sshtools.j2ssh.transport.Service - Service message loop failed!
java.lang.ArrayIndexOutOfBoundsException
at java.lang.System.arraycopy(Native Method)
at com.sshtools.j2ssh.io.DynamicBuffer.write(DynamicBuffer.java:186)
at com.sshtools.j2ssh.io.DynamicBuffer$DynamicBufferOutputStream.write(D
ynamicBuffer.java:285)
at java.io.OutputStream.write(OutputStream.java:58)
at com.sshtools.j2ssh.subsystem.SubsystemChannel.onChannelData(Subsystem
Channel.java:121)
at com.sshtools.j2ssh.connection.Channel.processChannelData(Channel.java
:169)
at com.sshtools.j2ssh.connection.ConnectionProtocol.onMsgChannelData(Con
nectionProtocol.java:802)
at com.sshtools.j2ssh.connection.ConnectionProtocol.onMessageReceived(Co
nnectionProtocol.java:604)
at com.sshtools.j2ssh.transport.AsyncService.run(AsyncService.java:116)
at java.lang.Thread.run(Thread.java:595)
10468 [ssh-connection 1] INFO com.sshtools.j2ssh.connection.ConnectionProtocol
- Closing all active channels
10468 [ssh-connection 1] DEBUG com.sshtools.j2ssh.connection.ConnectionProtocol
- Closing sftp id=2
10468 [ssh-connection 1] DEBUG com.sshtools.j2ssh.connection.Channel - Connection is not connected
10468 [ssh-connection 1] INFO com.sshtools.j2ssh.connection.Channel - Finializing channel close
10468 [ssh-connection 1] INFO com.sshtools.j2ssh.connection.ConnectionProtocol
- Freeing channel 2 [sftp]
10468 [ssh-connection 1] INFO com.sshtools.j2ssh.transport.Service - ssh-connection thread is exiting
15390 [main] DEBUG com.sshtools.j2ssh.sftp.SftpMessageStore - Waiting for new messages
20390 [main] DEBUG com.sshtools.j2ssh.sftp.SftpMessageStore - Waiting for new messages
25390 [main] DEBUG com.sshtools.j2ssh.sftp.SftpMessageStore - Waiting for new messages
30390 [main] DEBUG com.sshtools.j2ssh.sftp.SftpMessageStore - Waiting for new messages
Terminate batch job (Y/N)? y
Logged In: YES
user_id=1711425
Originator: YES
Following code fix will prevent the problem. There is a logic error in j2ssh.io.DynamicBuffer.java.
Replace verifyBufferSize(..) with this one that contains the fix:
private synchronized void verifyBufferSize(int count) {
// If there is not enough data in the buffer, then first attempt to
// move the unread data back to the beginning
if (count > (buf.length - writepos)) {
System.arraycopy(buf, readpos, buf, 0, writepos - readpos);
writepos -= readpos;
readpos = 0;
}
// Now double check and increase the buffer size if necersary
if (count > (buf.length - writepos)) {
/*
They are assuming the space needed is handled by DEFAULT_BUFFER_SIZE
so they made the new buffer length by (buf.length + DEFAULT_BUFFER_SIZE).
The space needed is actually count + writepos-readpos, so if
(buf.length + DEFAULT_BUFFER_SIZE) < (count+writepos-readpos) then
ArrayIndexException is thrown in the write() method that calls this
method!
Pattern of data count received observed that lead to this problem:
several small blocks of data received followed by
16128 bytes received several times, then 33292 bytes received which
triggered the buffer lengthening but which was not increased enough!.
*/
int lenNeeded = count + writepos - readpos + 1; // total bytes of data we have
int newLen = lenNeeded < buf.length + DEFAULT_BUFFER_SIZE ?
buf.length + DEFAULT_BUFFER_SIZE : lenNeeded + DEFAULT_BUFFER_SIZE;
byte[] tmp = new byte[newLen]; // FIX buf.length + DEFAULT_BUFFER_SIZE];
System.arraycopy(buf, 0, tmp, 0, writepos - readpos);
buf = tmp;
}
}