Channel not being returned pool if underlying stream is already closed
roligheten opened this issue · 6 comments
Hello, I am experiencing an issue where our SSHChannelPool will slowly "leak" channels until the pool gets exhausted. I have been debugging this issue and it seems like a channel taken from the pool will not be returned to the pool if an SFTP input/output stream gets unexpectedly closed before we close it ourselves. (See [2]) This eventually leads to pool exhaustion.
I have been trying to understand why this happens and my hypothesis is that when we call SFTPOutputStream::close this will attempt to close the underlying output stream. This will cause flush to be called which in our case throws because the stream is already closed. (Why it is getting closed unexpectedly I have not managed to determine)
When this happens SFTPOutputStream::finalizeStream is never called which in turn causes the channel to never be returned to the pool. (See [1])
My immediate idea for a fix would be to make sure SFTPOutputStream::finalizeStream (and SFTPInputStream) always gets called even if an exception is thrown inside the method.
I can make the relevant changes for this in a PR, but I would like to know if my hypothesis sounds correct before doing the actual work. Any feedback would be appreciated. 🙂
[1] Relevant code where a channel might not be returned to the pool if close throws:
[2] Stack-trace I believe causes a connection to be lost in the pool
java.io.IOException: Pipe closed at java.base/java.io.PipedInputStream.read(PipedInputStream.java:307) at java.base/java.io.PipedInputStream.read(PipedInputStream.java:377) at com.jcraft.jsch.ChannelSftp.fill(ChannelSftp.java:2909) at com.jcraft.jsch.ChannelSftp.header(ChannelSftp.java:2935) at com.jcraft.jsch.ChannelSftp.checkStatus(ChannelSftp.java:2473) at com.jcraft.jsch.ChannelSftp.access$300(ChannelSftp.java:36) at com.jcraft.jsch.ChannelSftp$1.flush(ChannelSftp.java:851) at com.jcraft.jsch.ChannelSftp$1.close(ChannelSftp.java:867) at com.github.robtimus.filesystems.sftp.SSHChannelPool$Channel$SFTPOutputStream.close(SSHChannelPool.java:460) at java.base/java.io.FilterOutputStream.close(FilterOutputStream.java:191) at no.finntech.adimport.ImportFtpService.closeOutFiles(ImportFtpService.java:82) at no.finntech.adimport.ImportFtpService.readXML(ImportFtpService.java:129) at no.finntech.adimport.ImportClient.processZipFile(ImportClient.java:177) at no.finntech.adimport.ImportClient.lambda$run$2(ImportClient.java:119) at java.base/java.util.ArrayList.forEach(ArrayList.java:1511) at no.finntech.adimport.ImportClient.run(ImportClient.java:115) at no.finntech.adimport.ImportClient$$FastClassBySpringCGLIB$$75ceb0e.invoke(<generated>) at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:771) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749) at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) at java.base/java.lang.Thread.run(Thread.java:832) Suppressed: java.io.IOException: Pipe closed at java.base/java.io.PipedInputStream.read(PipedInputStream.java:307) at java.base/java.io.PipedInputStream.read(PipedInputStream.java:377) at com.jcraft.jsch.ChannelSftp.fill(ChannelSftp.java:2909) at com.jcraft.jsch.ChannelSftp.header(ChannelSftp.java:2935) at com.jcraft.jsch.ChannelSftp.checkStatus(ChannelSftp.java:2473) at com.jcraft.jsch.ChannelSftp.access$300(ChannelSftp.java:36) at com.jcraft.jsch.ChannelSftp$1.flush(ChannelSftp.java:851) at com.github.robtimus.filesystems.sftp.SSHChannelPool$Channel$SFTPOutputStream.flush(SSHChannelPool.java:454) at java.base/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:143) at java.base/java.io.FilterOutputStream.close(FilterOutputStream.java:182) ... 16 more
Putting the open = false and finalizeStream() in a finally block isn't hard to do. I think it's safe to do that, considering that if the connection is actually broken, the validation performed upon retrieving it from the pool should replace the connection with another. The two statements do need to go together, otherwise there's a risk that calling close() on the stream again will call finalizeStream() again, and will cause other issues; I think the channel would get added to the pool twice.
I've just pushed a change that should work. However, I'd like you to test it first before I officially release it. Can you do the following?
- Clone the repository
- Build it:
mvn install -Dgpg.skip - Use the snapshot version in your project
If this solves your issue, you can expect an official release within a few days.
Thank you for the quick response! I will look into testing this tomorrow or Monday next week and come back to you.
We have been running the new version for 2 days straight without any loss of channels so the fix seems to work. A release would be appreciated as soon as you have the time. Thanks!
@robtimus We use Maven repository to retrieve our dependencies and it looks like you might not have released this version to the Maven repo? Should be at https://mvnrepository.com/artifact/com.github.robtimus/sftp-fs as 2.0.3?
mvnrepository.com isn't official, and is not maintained by the team behind Maven Central. They use some way to sync their database which can have some delay.
The official site is search.maven.org, and there it's available: https://search.maven.org/artifact/com.github.robtimus/sftp-fs/2.0.3/jar