A write operation is already pending

[baiglin]

Version

2.13.2

Bug description

Hi @tomaswolf,

I have a strange situation where I get this exception:
org.apache.sshd.common.io.WritePendingException: A write operation is already pending; cannot write ... bytes.

To explain the context, I use a shared session:

ClientSession clientSession =
        this.sshClient
            .connect(sshdConfiguration.getUserName(), sshdConfiguration.getHost(),
                sshdConfiguration.getPort())
            .verify(verifyTimeout)
            .getSession();

And then in order to not create too many sessions I create different channels on this same session:

SftpClient client = SftpClientFactory.instance().createSftpClient(clientSession);

The different clients are used in one thread only, there is no concurrency involved when using them… So for me I should not have parallels write operations on the same client so not on the same ChannelAsyncOutputStream …

Still I get this exception… However, I can see that I first get a:

Caused by: org.apache.sshd.common.SshException: IoWriteFutureImpl[SftpChannelSubsystem[id=8, recipient=8]-ClientSessionImpl[xxxxxxxxxxx@/xx.x.xxx.xx:22][sftp][SSH_MSG_CHANNEL_DATA]]: Failed to get operation result within specified timeout: 30000 msec
	at org.apache.sshd.common.future.AbstractSshFuture.lambda$verifyResult$1(AbstractSshFuture.java:114) ~[sshd-common-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.common.future.AbstractSshFuture.formatExceptionMessage(AbstractSshFuture.java:206) ~[sshd-common-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:114) ~[sshd-common-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.common.io.AbstractIoWriteFuture.verify(AbstractIoWriteFuture.java:41) ~[sshd-common-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.common.io.AbstractIoWriteFuture.verify(AbstractIoWriteFuture.java:32) ~[sshd-common-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.common.future.VerifiableFuture.verify(VerifiableFuture.java:110) ~[sshd-common-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.common.future.VerifiableFuture.verify(VerifiableFuture.java:96) ~[sshd-common-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.sftp.client.SftpMessage.waitUntilSent(SftpMessage.java:85) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.sftp.client.impl.SftpOutputStreamAsync.internalFlush(SftpOutputStreamAsync.java:358) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.sftp.client.impl.SftpOutputStreamAsync.internalTransfer(SftpOutputStreamAsync.java:285) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
	at org.apache.sshd.sftp.client.impl.SftpOutputStreamAsync.write(SftpOutputStreamAsync.java:180) ~[sshd-sftp-2.14.0.jar!/:2.14.0]

Then I get when closing the channel or trying to send another message later:

org.apache.sshd.common.io.WritePendingException: A write operation is already pending; cannot write 31 bytes
		at org.apache.sshd.common.channel.ChannelAsyncOutputStream.writeBuffer(ChannelAsyncOutputStream.java:110) ~[sshd-core-2.14.0.jar!/:2.14.0]
		at org.apache.sshd.sftp.client.impl.DefaultSftpClient.write(DefaultSftpClient.java:308) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
		at org.apache.sshd.sftp.client.impl.DefaultSftpClient.send(DefaultSftpClient.java:272) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
		at org.apache.sshd.sftp.client.impl.AbstractSftpClient.rpc(AbstractSftpClient.java:167) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
		at org.apache.sshd.sftp.client.impl.AbstractSftpClient.checkCommandStatus(AbstractSftpClient.java:232) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
		at org.apache.sshd.sftp.client.impl.AbstractSftpClient.close(AbstractSftpClient.java:609) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
		at org.apache.sshd.sftp.client.impl.DefaultCloseableHandle.close(DefaultCloseableHandle.java:53) ~[sshd-sftp-2.14.0.jar!/:2.14.0]
		at org.apache.sshd.sftp.client.impl.SftpOutputStreamAsync.close(SftpOutputStreamAsync.java:440) ~[sshd-sftp-2.14.0.jar!/:2.14.0]

I wonder if the internal state ChannelAsyncOutputStream#writeState.writeInProgress = true; is not reset leading to that problem ?
I can add that I check before trying a new transfer if the channel is closed, so if my first guess is correct I guess we should have the channel closed in such case or the state reset ?

Also if you could confirm that the first timeout is caused by the fact that server is not replying at all or at least we did not receive a reply ?

Actual behavior

We get a time out then exception on next write

Expected behavior

I expected to be able to write again on the same channel or get the channel closed

Relevant log output

No response

Other information

No response

[tomaswolf]

Hm. There seem to be two things missing (this is just from code inspection):

1. In SftpMessage.waitUntilSent(), we should cancel the write attempt.
2. In ChannelAsyncOutputStream, we should propagate cancellation down to the actual future for the write.

The timeout appears to be hit because no SFTP ACK was received from the server. (Edit: actually, no. It's unclear why the previous write was not sent.)

I'll see if I can reproduce that with a unit test.

[baiglin]

Hi @tomaswolf, I tried to reproduce the problem locally, but could not and after more investigation, I understand that it is the timeout to send data, and not the receive timeout, so not sure how I can mock this ...

Also I am not sure how the write future complete, but does it mean on client side we did not manage to even write the data from our side and maybe the server did not even receive something ? ...