[
https://issues.apache.org/jira/browse/SSHD-1215?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17422572#comment-17422572
]
Roberto Deandrea commented on SSHD-1215:
----------------------------------------
Hi, after debugging Apache SSHD code we found the root cause of the problem.
The problem because WinSCP open the file in *APPEND* mode. From front-end
server traces I see SSH_FXP_OPEN (path=/upload/rsa.key, *access=0x6*,
pflags=0x1, attrs=\{isRegular=true}) )
I verified that other SFTP clients (sftp by OpenSSH, lftp etc...) work fine
because the file is opened in *WRITE* mode.
Code review :
The following is the stack trace where we found out the problem that manifest
in SftpRemotePathChannel.doWrite() method, because when the file is opened in
APPEND mode the implementation calls SftpRemotePathChannel.size() to set the
offset of file to be written between successive SftpRemotePathChannel.doWrite()
calls, but the size is always 0.
*size:306, SftpRemotePathChannel (org.apache.sshd.sftp.client.impl)*
*append:126, FileHandle (org.apache.sshd.sftp.server)*
*doWrite:784, SftpSubsystem (org.apache.sshd.sftp.server)*
*doWrite:576, AbstractSftpSubsystemHelper (org.apache.sshd.sftp.server)*
*doProcess:342, AbstractSftpSubsystemHelper (org.apache.sshd.sftp.server)*
*doProcess:296, SftpSubsystem (org.apache.sshd.sftp.server)*
*process:324, AbstractSftpSubsystemHelper (org.apache.sshd.sftp.server)*
*run:272, SftpSubsystem (org.apache.sshd.sftp.server)*
*call:511, Executors$RunnableAdapter (java.util.concurrent)*
*run:266, FutureTask (java.util.concurrent)*
*runWorker:1149, ThreadPoolExecutor (java.util.concurrent)*
*run:624, ThreadPoolExecutor$Worker (java.util.concurrent)*
*run:821, Thread (java.lang)*
The FileHandle.append() use the size of file channel as the offset of the file
to be written.
_public void append(byte[] data, int doff, int length) throws IOException {_
_SeekableByteChannel channel = getFileChannel();_
_write(data, doff, length, channel.size());_
_}_
The SftpRemotePathChannel.write() method set this offset as a position of file
channel:
_public void write(byte[] data, int doff, int length, long offset) throws
IOException {_
_SeekableByteChannel channel = getFileChannel();_
_channel = channel.position(offset);_
_channel.write(ByteBuffer.wrap(data, doff, length));_
}
But SftpRemotePathChannel.size() return a size that is always 0.
_@Override_
_public long size() throws IOException {_
_ensureOpen(Collections.emptySet());_
_Attributes stat = sftp.stat(handle);_
_return stat.getSize();_
_}_
Each SftpRemotePathChannel.doWrite() set correctly the position of file in the
finally block, but the method write() reset it before each write().
_protected long doWrite(Collection<? extends ByteBuffer> buffers, long
position) throws IOException {_
_ensureOpen(WRITE_MODES);_
_ClientSession clientSession = sftp.getClientSession();_
_int copySize = SftpModuleProperties.COPY_BUF_SIZE.getRequired(clientSession);_
_boolean debugEnabled = log.isDebugEnabled();_
_if (debugEnabled) {_
_log.debug("doWrite({})[position={}] write {} buffers using copySize={}",_
_this, position, buffers.size(), copySize);_
_}_
_boolean completed = false;_
_long totalWritten = 0L;_
_int numBufsUsed = 0;_
_synchronized (lock) {_
_long curPos = (position >= 0L) ? position : posTracker.get(); //posTracker is
0 because before doWrite the channel position is set to size of file_
_try {_
_beginBlocking("doWrite");_
_for (ByteBuffer buffer : buffers) {_
_numBufsUsed++;_
_while (buffer.remaining() > 0) {_
_ByteBuffer wrap = buffer;_
_if (!buffer.hasArray()) {_
_wrap = ByteBuffer.allocate(Math.min(copySize, buffer.remaining()));_
_buffer.get(wrap.array(), wrap.arrayOffset(), wrap.remaining());_
_}_
_int written = wrap.remaining();_
_sftp.write(handle, curPos, wrap.array(),_
_wrap.arrayOffset() + wrap.position(), written);_
_// reference equality on purpose_
_if (wrap == buffer) {_
_wrap.position(wrap.position() + written);_
_}_
_curPos += written;_
_totalWritten += written;_
_}_
_}_
_completed = true;_
_} finally {_
_if (position < 0L) {_
_posTracker.set(curPos);_
_}_
_endBlocking("doWrite", completed);_
_}_
_}_
Can you check the source code and evaluate if you can fix it in a future
release of Apache SSHD or can you suggest us a workaround ?
Thank in advance
Roberto
> WinsCP transfer failure to Apache SSHD Server
> ---------------------------------------------
>
> Key: SSHD-1215
> URL: https://issues.apache.org/jira/browse/SSHD-1215
> Project: MINA SSHD
> Issue Type: Bug
> Affects Versions: 2.6.0
> Reporter: Roberto Deandrea
> Priority: Major
> Attachments: logs.zip
>
>
> Hi
> I have a failure transferring small files from a WinSCP SFTP client version
> 5.19.2 to a front-end Apache SSHD Server 2.6.0.
> The front-end Apache SSHD server is configured with a Filesystem built upon
> SFTPFileSystemProvider to proxy files to an Apache SSHD back-end server.
> WinSCP SFTP transfer files successfully directly to back-end Apache SSHD
> Server.
> I traced the SFTP file transfer on the front-end server and back-end server
> and it seems that something get wrong in the remote FileSystem set on the
> front-end server.
> From traces it seems that the first chunk of file is received correctly by
> the back-end server, but something is wrong on the second chuck of file
> transmitted.
> -------------------------------------------------------------------------------------------------------------------------
> First SSH_FXP_WRITE chunk received from front-end server :
> [16/09/21 09:18:26:364 CEST] 00000175 id=00000000
> org.apache.sshd.sftp.server.AbstractSftpSubsystemHelper 1 process
> process(ServerSessionImpl[allfuser1@/172.18.202.33:55400])[length=32757,
> type=SSH_FXP_WRITE, id=19718] processing
> [16/09/21 09:18:26:364 CEST] 00000175 id=00000000
> org.apache.sshd.sftp.server.SftpSubsystem 3 doWrite
> doWrite(ServerSessionImpl[allfuser1@/172.18.202.33:55400])[id=19718]
> *SSH_FXP_WRITE
> (handle=de6fcf635cb34b0e6d3d56643b7539a3[[/upload/rsa.key|https://issues.apache.org/upload/rsa.key]],
> offset=0, data=byte[32704])*
> First SSH_FXP_WRITE chunk sent by front-end SFTP client to back.end-server :
> [16/09/21 09:18:26:913 CEST] 00000175 id=00000000
> org.apache.sshd.sftp.client.impl.DefaultSftpClient 3 send
> send(SftpChannelSubsystem[id=0,
> recipient=0]-ClientSessionImpl[DMZ/172.18.202.33/allfuser1@/10.6.6.22:6471][sftp])
> cmd=SSH_FXP_WRITE, len=32752, id=139
> [16/09/21 09:18:27:010 CEST] 00000175 id=00000000
> org.apache.sshd.sftp.client.impl.AbstractSftpClient 3 checkResponseStatus
> checkResponseStatus(SftpChannelSubsystem[id=0,
> recipient=0]-ClientSessionImpl[DMZ/172.18.202.33/allfuser1@/10.6.6.22:6471][sftp])[id=139]
> cmd=SSH_FXP_WRITE status=SSH_FX_OK lang= msg=
>
> First SSH_FXP_WRITE chunk received succesfully from back-end server :
> [16/09/21 09:18:27:007 CEST] 00005c15 id=00000000
> org.apache.sshd.sftp.server.SftpSubsystem 3 doWrite
> doWrite(ServerSessionImpl[DMZ/172.18.202.33/allfuser1@/10.6.6.22:34445])[id=139]
> *SSH_FXP_WRITE
> (handle=c88cfd55dd514ccdd0428571191f5ea1[[/upload/rsa.key|https://issues.apache.org/upload/rsa.key]],
> offset=0, data=byte[32704])*
> [16/09/21 09:18:27:545 CEST] 00005c15 id=00000000
> org.apache.sshd.sftp.server.AbstractSftpSubsystemHelper 1 process
> process(ServerSessionImpl[DMZ/172.18.202.33/allfuser1@/10.6.6.22:34445])[length=32757,
>
> -----------------------------------------------------------------------------------------------------
> Second SSH_FXP_WRITE chunk received from front-end server:
> [16/09/21 09:18:27:012 CEST] 00000175 id=00000000
> org.apache.sshd.sftp.server.AbstractSftpSubsystemHelper 1 process
> process(ServerSessionImpl[allfuser1@/172.18.202.33:55400])[length=32757,
> type=SSH_FXP_WRITE, id=19974] processing
> [16/09/21 09:18:27:013 CEST] 00000175 id=00000000
> org.apache.sshd.sftp.server.SftpSubsystem 3 doWrite
> doWrite(ServerSessionImpl[allfuser1@/172.18.202.33:55400])[id=19974]
> *SSH_FXP_WRITE
> (handle=de6fcf635cb34b0e6d3d56643b7539a3[[/upload/rsa.key|https://issues.apache.org/upload/rsa.key]],
> offset=32704, data=byte[32704])*
>
> Second SSH_FXP_WRITE chunk sent by front-end SFTP client to back-end server:
> [16/09/21 09:18:27:473 CEST] 00000175 id=00000000
> org.apache.sshd.sftp.client.impl.DefaultSftpClient 3 send
> send(SftpChannelSubsystem[id=0,
> recipient=0]-ClientSessionImpl[DMZ/172.18.202.33/allfuser1@/10.6.6.22:6471][sftp])
> cmd=SSH_FXP_WRITE, len=32752, *id=141*
>
> Second SSH_FXP_WRITE chunk received from back-end server:
> type=SSH_FXP_WRITE, *id=141*] processing
> [16/09/21 09:18:27:545 CEST] 00005c15 id=00000000
> org.apache.sshd.sftp.server.SftpSubsystem 3 doWrite
> doWrite(ServerSessionImpl[DMZ/172.18.202.33/allfuser1@/10.6.6.22:34445])[*id=141*]
> SSH_FXP_WRITE
> (handle=c88cfd55dd514ccdd0428571191f5ea1[[/upload/rsa.key|https://issues.apache.org/upload/rsa.key]],
> *offset=0, data=byte[32704*])
> Now the back-end server complains about this data. The back-end server is
> expecting a chunk of data at offset=32704 and not offset = 0.
> java.io.IOException:
> position([/upload/rsa.key|https://issues.apache.org/upload/rsa.key]) *illegal
> file channel position, expected frsPosition: 32704, found: 0*
> This is a blocking error and causes the connection closing of the parts
> involved.
> ----------------------------------------------------------------------------------------------------------------------
> Full traces are attached to this jira.
>
> Questions and considerations.
> # Is this a known problem and is fixed in the latest release of Apache SSHD?
> # If this is a new problem can you suggest me how to fix it, or better
> troubleshoot it
> # Let me know if you need further info for troubleshooting
>
> Thanks in advance for your support
>
> Kind Regards
> Roberto Deandrea
>
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
