InterruptedByTimeoutException from UnixAsynchronousSocketChannelImpl on big files after around 10 minutes

[baiglin]

Version

2.14.0

Bug description

Hi,

While sending files around 1.4 Gb to an sftp server:

Client string: 'SSH-2.0-APACHE-SSHD-2.14.0' vs. Server string: 'SSH-2.0-6.4.13.36 SSH Tectia Server'

We get all the time after around 10 minutes java.nio.channels.InterruptedByTimeoutException

Got a functional exception com.amadeus.dis.distribution.exception.DistributionFunctionalException: Problem in the SFTP upload of file '...' in directory '/xxxxxx': Unable to transmit file: xxxxxxx

	at com.amadeus.dis.distribution.process.sftp.SftpProfileClient.sendSource(SftpProfileClient.java:200) ~[common-process-3.30.38.jar!/:?]

	...
	at java.base/java.lang.Thread.run(Thread.java:829) [?:?]

Caused by: com.amadeus.dis.distribution.transfer.exception.TransferException: Unable to transmit file: AvlReport.D250613.T043149.output.jsonl.gz

	at com.amadeus.dis.distribution.transfer.sftp.sshd.SshdSftpClient.doWrite(SshdSftpClient.java:219) ~[common-transfer-3.30.38.jar!/:?]

	at com.amadeus.dis.distribution.transfer.sftp.AbstractSftpClient.transferStream(AbstractSftpClient.java:80) ~[common-transfer-3.30.38.jar!/:?]

	at com.amadeus.dis.distribution.transfer.sftp.SftpFallbackClient.transferStream(SftpFallbackClient.java:22) ~[common-transfer-3.30.38.jar!/:?]

	at com.amadeus.dis.distribution.process.sftp.SftpProfileClient.sendSource(SftpProfileClient.java:194) ~[common-process-3.30.38.jar!/:?]

	... 17 more

Caused by: org.apache.sshd.common.SshException: IoWriteFutureImpl[SftpChannelSubsystem[id=1, recipient=1]-ClientSessionImpl[usertoto@/xx.xxx.xx:22][sftp][SSH_MSG_CHANNEL_DATA]]: Failed (InterruptedByTimeoutException) to execute: null

	at org.apache.sshd.common.future.AbstractSshFuture.lambda$verifyResult$2(AbstractSshFuture.java:146) ~[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:145) ~[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]

	at java.base/java.io.InputStream.transferTo(InputStream.java:705) ~[?:?]

	at com.amadeus.dis.distribution.transfer.sftp.sshd.SshdSftpClient.doWrite(SshdSftpClient.java:215) ~[common-transfer-3.30.38.jar!/:?]

	at com.amadeus.dis.distribution.transfer.sftp.AbstractSftpClient.transferStream(AbstractSftpClient.java:80) ~[common-transfer-3.30.38.jar!/:?]

	at com.amadeus.dis.distribution.transfer.sftp.SftpFallbackClient.transferStream(SftpFallbackClient.java:22) ~[common-transfer-3.30.38.jar!/:?]

	at com.amadeus.dis.distribution.process.sftp.SftpProfileClient.sendSource(SftpProfileClient.java:194) ~[common-process-3.30.38.jar!/:?]

	... 17 more

	Suppressed: org.apache.sshd.common.SshException: Write attempt on closing session: SSH_MSG_CHANNEL_DATA

		at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:141) ~[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.DefaultSftpClient.send(DefaultSftpClient.java:273) ~[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]

		at com.amadeus.dis.distribution.transfer.sftp.sshd.SshdSftpClient.doWrite(SshdSftpClient.java:213) ~[common-transfer-3.30.38.jar!/:?]

	...

		at java.base/java.lang.Thread.run(Thread.java:829) [?:?]

	Caused by: org.apache.sshd.common.SshException: Write attempt on closing session: SSH_MSG_CHANNEL_DATA

		at org.apache.sshd.common.session.helpers.KeyExchangeMessageHandler.writeOrEnqueue(KeyExchangeMessageHandler.java:300) ~[sshd-core-2.14.0.jar!/:2.14.0]

		at org.apache.sshd.common.session.helpers.KeyExchangeMessageHandler.writePacket(KeyExchangeMessageHandler.java:246) ~[sshd-core-2.14.0.jar!/:2.14.0]

		at org.apache.sshd.common.session.helpers.AbstractSession.writePacket(AbstractSession.java:1078) ~[sshd-core-2.14.0.jar!/:2.14.0]

		at org.apache.sshd.common.channel.AbstractChannel.writePacket(AbstractChannel.java:818) ~[sshd-core-2.14.0.jar!/:2.14.0]

		at org.apache.sshd.common.channel.throttle.DefaultChannelStreamWriter.writeData(DefaultChannelStreamWriter.java:46) ~[sshd-core-2.14.0.jar!/:2.14.0]

		at org.apache.sshd.common.channel.ChannelAsyncOutputStream.writePacket(ChannelAsyncOutputStream.java:348) ~[sshd-core-2.14.0.jar!/:2.14.0]

		at org.apache.sshd.common.channel.ChannelAsyncOutputStream.doWriteIfPossible(ChannelAsyncOutputStream.java:225) ~[sshd-core-2.14.0.jar!/:2.14.0]

		at org.apache.sshd.common.channel.ChannelAsyncOutputStream.writeBuffer(ChannelAsyncOutputStream.java:119) ~[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]

		... 26 more


Caused by: java.nio.channels.InterruptedByTimeoutException

	at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl$2.run(UnixAsynchronousSocketChannelImpl.java:661) ~[?:?]

	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]

	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]

	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]

	... 3 more

I found from long ago https://issues.apache.org/jira/browse/SSHD-1020 that seems to be fixed for a long time now ...

And I am having hard time to undertand what is this timeout coming from and leading to the channel closing,

Actual behavior

Timeout after 10 minutes

Expected behavior

I do not see why any timeout should happen

Relevant log output

Areound the time of the issue I gathered the following logs from Mina

2025/06/13 08:51:03.236000 lgsap253-MUC disapp03 DDS_UDD#0-0 APP WARN <o.a.s.c.s.ClientSessionImpl#0 TID#00000> Multi1 [sshd-SshClient[5134a7d6]-nio2-thread-15] {} exceptionCaught(ClientSessionImpl[toto@/xx.xx.xxx.xxx:22])[state=Opened] InterruptedByTimeoutException: null
  
2025/06/13 08:51:03.237000 lgsap234-MUC disapp03 DDS_UDD#0-0 APP WARN <o.a.s.s.c.i.DefaultSftpClient$SftpChannelSubsystem$1#0 TID#00000> Multi1 [sshd-SshClient[5134a7d6]-nio2-thread-15] {} doCloseImmediately([SftpChannelSubsystem[id=1, recipient=1]-ClientSessionImpl[toto@/xxx.xxx.xxxx:22][sftp]] cmd=SSH_MSG_CHANNEL_DATA): still have 21 bytes of 21 on closing channel

Other information

No response

[tomaswolf]

10 minutes might be CoreModuleProperties.IDLE_TIMEOUT. If that triggers while sending data that would be a bug.

Let's first establish that this is the cause. Try setting this to a lower value, for instance one minute: CoreModuleProperties.IDLE_TIMEOOUT.set(sshClient, Duration.ofMinutes(1));. If you then get that exception after roughly one minute, this is the culprit.

If that's it, can you try with the latest 2.15.1-SNAPSHOT version available from the Apache Snapshot maven repository? If it still occurs, we'll have to track down why it triggers. It should be reset on every read or write, but if if it isn't, we'll have to find where the reset is missing.

[baiglin]

Hi @tomaswolf,

Actually that was a wrong assumption as I could reproduce it, after 4 minutes ... so this is not really accurate about this 10 minutes, sorry about that...
I tried before writing to increase the idle timeout to a much higher value, and still the issue happened ... I should have made that clear...

If you have other hint on how to investigate that one.. I will be really happy, unfortunately since this happens on PRD only, this is impossible for me to debug...

[tomaswolf]

Get a network trace using something like WireShark. When you get the exception, examine the trace. Try to determine how frequently the client sends messages. For uploading, I'd expect to see large messages sent by the client (the data), and short messages being received from the server (the SFTP ACKs). You won't be able to inspect the message contents since it'll be encrypted, but you can analyze the timings. Is there anything suspicious with the timings of these messages? No ACKs being received or coming in slower and slower, or the client sending messages slower and slower?

Does this occur only with that Tectia server, or also with other servers, for instance OpenSSH?

On a closer look another relevant timeout is CoreModuleProperties.NIO2_MIN_WRITE_TIMEOUT. This is the timeout for a single NIO2 write operation; by default 30 seconds. If the single buffer cannot be written by NIO2 within that time, you might get the exception you've shown above:

...
Caused by: java.nio.channels.InterruptedByTimeoutException
	at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl$2.run(UnixAsynchronousSocketChannelImpl.java:661) ~[?:?]
...

A single write should never take that long.