The custom sftp server was blocked while processing ls

[xinghhhhhhh]

description

I wrote an sftp server proxy using mina-sshd, and I found that the listener logging for open requests took a long time to process, sometimes blocking.

Log Description

One of my test logs showed a difference of about 20s.See attached sftp-2160-test-ls.log for the full log

2025-11-25 18:38:37.859 [sshd-SshClient[6c827e56]-nio2-thread-1] TRACE org.apache.sshd.common.io.nio2.Nio2Session - handleCompletedWriteCycle(Nio2Session[local=/0:0:0:0:0:0:0:0:53369, remote=/10.10.16.195:1234]) finished writing len=80 at cycle=18 after 536100 nanos
2025-11-25 18:38:52.862 [sshd-MySftpSubsystem-58008-thread-1] DEBUG org.example.sftpServerTest.SftpAuditRecorder - TEST LOG: Open file: /

Some information

Appears when the target device is a network device.
In 2.16.0, it doesn't block when I comment out the log output in the open method of SftpAuditRecorder.
In 2.13.2, log printing blocks even if you comment it out, and will always block.

public class SftpAuditRecorder implements SftpEventListener {

    private static final Log log = LogFactory.getLog(SftpAuditRecorder.class);

    @Override
    public void open(ServerSession session, String remoteHandle, Handle localHandle) throws IOException {
        Path path = localHandle.getFile();
        if (log.isDebugEnabled()) {
            log.debug( "TEST LOG: Open " + (Files.isDirectory(path) ? "dir: " : "file: ") + path);
        }
    }
}

attachment

sshd-sftp-2160-Test.zip

sftp-2160-test-ls.log

[xinghhhhhhh]

Some information

Below is a snapshot of the thread I took.Every time I block is in DefaultSftpClientFactory.createSftpClient(), It seems that each method in the sftpSubsystem that handles an sftp request recreates the client, and when the server does not respond, it becomes completely stuck.

"sshd-MySftpSubsystem-26624-thread-1@2579" daemon prio=5 tid=0x21 nid=NA waiting
  java.lang.Thread.State: WAITING
      at java.lang.Object.wait(Object.java:-1)
      at org.apache.sshd.common.future.DefaultSshFuture.await0(DefaultSshFuture.java:80)
      at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:111)
      at org.apache.sshd.client.future.DefaultOpenFuture.verify(DefaultOpenFuture.java:39)
      at org.apache.sshd.client.future.DefaultOpenFuture.verify(DefaultOpenFuture.java:32)
      at org.apache.sshd.common.future.VerifiableFuture.verify(VerifiableFuture.java:110)
      at org.apache.sshd.common.future.VerifiableFuture.verify(VerifiableFuture.java:96)
      at org.apache.sshd.sftp.client.impl.DefaultSftpClient.<init>(DefaultSftpClient.java:105)
      at org.apache.sshd.sftp.client.impl.DefaultSftpClientFactory.createDefaultSftpClient(DefaultSftpClientFactory.java:66)
      at org.apache.sshd.sftp.client.impl.DefaultSftpClientFactory.createSftpClient(DefaultSftpClientFactory.java:50)
      at org.apache.sshd.sftp.client.fs.SftpFileSystem.getClient(SftpFileSystem.java:251)
      at org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.resolveRemoteFileAttributes(SftpFileSystemProvider.java:1128)
      at org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.lambda$readRemoteAttributes$0(SftpFileSystemProvider.java:1119)
      at org.apache.sshd.sftp.client.fs.SftpFileSystemProvider$$Lambda$183.1925216384.apply(Unknown Source:-1)
      at org.apache.sshd.sftp.client.impl.SftpPathImpl.withAttributeCache(SftpPathImpl.java:95)
      at org.apache.sshd.sftp.client.fs.WithFileAttributeCache.withAttributeCache(WithFileAttributeCache.java:66)
      at org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.readRemoteAttributes(SftpFileSystemProvider.java:1119)
      at org.apache.sshd.sftp.client.impl.AbstractSftpFileAttributeView.readRemoteAttributes(AbstractSftpFileAttributeView.java:71)
      at org.apache.sshd.sftp.client.fs.SftpPosixFileAttributeView.readAttributes(SftpPosixFileAttributeView.java:52)
      at org.apache.sshd.sftp.client.fs.SftpFileSystemProvider.readAttributes(SftpFileSystemProvider.java:1026)
      at java.nio.file.Files.readAttributes(Files.java:1737)
      at java.nio.file.Files.isDirectory(Files.java:2192)
      at org.example.sftpServerTest.SftpAuditRecorder.open(SftpAuditRecorder.java:20)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:498)
      at org.apache.sshd.common.util.EventListenerUtils.lambda$proxyWrapper$1(EventListenerUtils.java:199)
      at org.apache.sshd.common.util.EventListenerUtils$$Lambda$4.1793329556.invoke(Unknown Source:-1)
      at com.sun.proxy.$Proxy3.open(Unknown Source:-1)
      at org.apache.sshd.sftp.server.Handle.signalHandleOpen(Handle.java:70)
      at org.apache.sshd.sftp.server.DirectoryHandle.<init>(DirectoryHandle.java:67)
      at org.apache.sshd.sftp.server.SftpSubsystem.doOpenDir(SftpSubsystem.java:808)
      - locked <0xa46> (a java.util.concurrent.ConcurrentHashMap)
      at org.apache.sshd.sftp.server.AbstractSftpSubsystemHelper.doOpenDir(AbstractSftpSubsystemHelper.java:735)
      at org.apache.sshd.sftp.server.AbstractSftpSubsystemHelper.doProcess(AbstractSftpSubsystemHelper.java:378)
      at org.apache.sshd.sftp.server.SftpSubsystem.doProcess(SftpSubsystem.java:354)
      at org.apache.sshd.sftp.server.AbstractSftpSubsystemHelper.process(AbstractSftpSubsystemHelper.java:345)
      at org.apache.sshd.sftp.server.SftpSubsystem.run(SftpSubsystem.java:330)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      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:750)

attachment

threads_report.txt

[xinghhhhhhh]

@tomaswolf Hi, may I ask if you are concerned about this issue 😄

Then I found that 2.9.2 version does not have this problem

[tomaswolf]

I've seen this issue you reported. Don't know when I will have time to try to reproduce and then analyze this.

In any case: Files.isDirectory(path) is a remote operation, which you probably want to avoid for logging. Why don't you you simply do localHandle instanceof DirectoryHandle ? "dir" : "file" instead?

I'm also confused as to why your event listener logs TEST LOG: Open file: /. Surely / is a directory?

[xinghhhhhhh]

I've seen this issue you reported. Don't know when I will have time to try to reproduce and then analyze this.

In any case: Files.isDirectory(path) is a remote operation, which you probably want to avoid for logging. Why don't you you simply do localHandle instanceof DirectoryHandle ? "dir" : "file" instead?

I'm also confused as to why your event listener logs TEST LOG: Open file: /. Surely / is a directory?

Yes, I can replace this part in another way. Then the log is a meaningless output, due to my negligence written "file", sorry. For this problem can be ignored. I then tested locally that downloading files when the client tool was winscp also blocked the thread stack like before. 🙏

[xinghhhhhhh]

I'm also confused as to why your event listener logs TEST LOG: Open file: /. Surely / is a directory?

That's a directory

[xinghhhhhhh]

In any case: Files.isDirectory(path) is a remote operation, which you probably want to avoid for logging. Why don't you you simply do localHandle instanceof DirectoryHandle ? "dir" : "file" instead?

At present, the main problem is that after I delete the corresponding log operation, in 2.13.2, when I execute ls after the sftp connection is successfully established, it will block for a long time, and then in 2.16.0, it will be alleviated for about 20 seconds. In 2.9.2, this problem is not found, ls will return soon. The test code used did not change, only the version of sshd was switched

[xinghhhhhhh]

Hi, I recently tried to refer to the 2.9.2 version of the code and changed it in 2.13.2, and my problem does not reappear locally. I'm not sure if my changes had any other effect, though.

attachment

fix__Refer_to_version_2_9_2_to_change_the_client_fetching_method.patch

[tomaswolf]

These ThreadLocals lead easily to memory leaks, which was the reason why we removed them.

[xinghhhhhhh]

These ThreadLocals lead easily to memory leaks, which was the reason why we removed them.

At the moment, it seems that the new approach will try to open multiple new channels, but some devices will not respond to these requests from mina-sshd and will block the normal transfer of data until the timeout configured by SFTP_CHANNEL_OPEN_TIMEOUT is triggered.

[tomaswolf]

At the moment, it seems that the new approach will try to open multiple new channels, but some devices will not respond to these requests ...

That's what I suspect, too. My current thinking is that to resolve this SftpClient needs to be made thread safe, and then an SftpFileSystem can use a single SftpClient (and thus channel). I may have some time in January to look into this.

[tomaswolf]

My current thinking is that to resolve this SftpClient needs to be made thread safe, and then an SftpFileSystem can use a single SftpClient (and thus channel).

PR #864 implements this.

@xinghhhhhhh : could you please give PR #864 a try?

[xinghhhhhhh]

My current thinking is that to resolve this SftpClient needs to be made thread safe, and then an SftpFileSystem can use a single SftpClient (and thus channel).

PR #864 implements this.

@xinghhhhhhh : could you please give PR #864 a try?

Yes, it's my pleasure. I just tried using this commit locally and the issue has been resolved. Thank you