Spring Integration - SFTP - JSCH - Session disconnects

Question

I'm trying to poll remote directories for file presence and sending a MQ message notifying some other component to move the file. We have this situation, threads/pollers login via password and connect to the server and immediately after a few seconds or so disconnect from the server and through the exception "Problem synchronizing remote directories..." and the threads recover from it and repeatedly go through the same issue.

Here's the life cycle of of a particular thread 00000027, it connects and disconnects within a few secs. The credentials are being passed in as via Jsch API. It seems like its trying to authenticate using other options and only succeeding via password, but immediately getting disconnected.

Spring Integration xml (SFTP Adapter - config)

<int:publish-subscribe-channel id="fileChannel">
    <int:interceptors>
        <int:wire-tap channel="logger"/>
    </int:interceptors>
</int:publish-subscribe-channel>

<int:logging-channel-adapter id="logger" level="INFO"/>

<!-- File polling and retrieval from source -->
<int-sftp:inbound-channel-adapter id="fileSource"
    channel="fileChannel" session-factory="sftpSessionFactory"
    charset="UTF-8" auto-create-local-directory="true"
    delete-remote-files="false" 
    remote-directory="${sourceRootDir}/${dir}" remote-file-separator="/"
    local-directory="${tempPath}" auto-startup="false" filter="fileFilter">
            <int:poller fixed-rate="5000" max-messages-per-poll="-1"/>  <!-- negative value means "get every file", DO NOT CHANGE without revisiting fileFilter logic -->
</int-sftp:inbound-channel-adapter>
<!-- Need an instance of the file filter per each context so it can carry 
    the property of the unique dir (which otherwise it has no way of discovering) -->
<bean id="fileFilter" class="com.pnc.tsc.hca.DownloadAvoidingFileFilter">
    <property name="filter" value=".tmp" />
    <property name="directory" value="${dir}" />
    <property name="channel" ref="queueChannel" />
    <property name="sourceRootDir" value="${sourceRootDir}" />
    <property name="destinationRootDir" value="${destinationRootDir}" />
</bean>

<bean id="sftpSessionFactory" 
    class="org.springframework.integration.sftp.session.DefaultSftpSessionFactory">
        <property name="host" value="${SOURCE_FTP_HOST}"/>
        <property name="port" value="${SOURCE_FTP_PORT}"/>
        <property name="user" value="${SOURCE_FTP_USER}"/>
        <property name="password" value="${SOURCE_FTP_PASS}"/>
    </bean>

<bean id="cachingSessionFactory" 
    class="org.springframework.integration.file.remote.session.CachingSessionFactory">
    <constructor-arg ref="sftpSessionFactory"/>
        <property name="poolSize" value="${poolSize}"/>
        <property name="sessionWaitTimeout" value="${sessionWaitTimeout}"/>
</bean>

Logs with Error Messages

[6/30/15 13:54:37:073 EDT] 00000027 jsch          I    org.springframework.integration.sftp.session.JschLogger log Connecting to <<servername>> port 22
[6/30/15 13:54:37:112 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Connection established
[6/30/15 13:54:37:146 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Remote version string: SSH-2.0-OpenSSH_6.0
[6/30/15 13:54:37:274 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Local version string: SSH-2.0-JSCH-0.1.53
[6/30/15 13:54:37:415 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log CheckCiphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-ctr,arcfour,arcfour128,arcfour256
[6/30/15 13:54:37:435 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log CheckKexes: diffie-hellman-group14-sha1,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521
[6/30/15 13:54:38:251 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log CheckSignatures: ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
[6/30/15 13:54:38:889 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log SSH_MSG_KEXINIT sent
[6/30/15 13:54:38:932 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log SSH_MSG_KEXINIT received
[6/30/15 13:54:38:944 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[6/30/15 13:54:39:023 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256
[6/30/15 13:54:39:036 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
[6/30/15 13:54:39:099 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
[6/30/15 13:54:39:195 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
[6/30/15 13:54:39:270 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-sha2-256,hmac-sha2-256-96,hmac-sha2-512,hmac-sha2-512-96,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
[6/30/15 13:54:39:283 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: none,zlib@openssh.com
[6/30/15 13:54:39:297 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server: none,zlib@openssh.com
[6/30/15 13:54:39:616 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server:
[6/30/15 13:54:39:736 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server:
[6/30/15 13:54:39:764 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
[6/30/15 13:54:39:789 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521
[6/30/15 13:54:39:798 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc
[6/30/15 13:54:39:808 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc
[6/30/15 13:54:39:817 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha1-96,hmac-md5-96
[6/30/15 13:54:39:833 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha1-96,hmac-md5-96
[6/30/15 13:54:39:842 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: none
[6/30/15 13:54:39:853 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client: none
[6/30/15 13:54:39:868 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client:
[6/30/15 13:54:39:888 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client:
[6/30/15 13:54:39:912 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: server->client aes128-ctr hmac-md5 none
[6/30/15 13:54:39:922 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client->server aes128-ctr hmac-md5 none
[6/30/15 13:54:40:190 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log SSH_MSG_KEX_ECDH_INIT sent
[6/30/15 13:54:40:215 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log expecting SSH_MSG_KEX_ECDH_REPLY
[6/30/15 13:54:40:279 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log ssh_rsa_verify: signature true
[6/30/15 13:54:40:376 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Host '<<servername>>' is known and matches the RSA host key
[6/30/15 13:54:40:398 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log SSH_MSG_NEWKEYS sent
[6/30/15 13:54:40:561 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log SSH_MSG_NEWKEYS received
[6/30/15 13:54:40:582 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log SSH_MSG_SERVICE_REQUEST sent
[6/30/15 13:54:40:595 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log SSH_MSG_SERVICE_ACCEPT received
[6/30/15 13:54:40:644 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Authentications that can continue: publickey,keyboard-interactive,password
[6/30/15 13:54:40:660 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Next authentication method: publickey
[6/30/15 13:54:40:776 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Authentications that can continue: keyboard-interactive,password
[6/30/15 13:54:40:901 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Next authentication method: keyboard-interactive
[6/30/15 13:54:41:339 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Authentications that can continue: password
[6/30/15 13:54:41:349 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Next authentication method: password
[6/30/15 13:54:41:381 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Authentication succeeded (password).
[6/30/15 13:54:41:564 EDT] 00000027 SystemOut     O 13:54:41.564 INFO  [task-scheduler-2][com.pnc.tsc.hca.DownloadAvoidingFileFilter] File in directory inbound/cmnzip/ appear to be : [Lcom.jcraft.jsch.ChannelSftp$LsEntry;@5fda5fda
[6/30/15 13:54:41:565 EDT] 00000027 jsch          I org.springframework.integration.sftp.session.JschLogger log Disconnecting from <<servername>> port 22
[6/30/15 13:54:41:605 EDT] 00000027 LoggingHandle E org.springframework.integration.handler.LoggingHandler handleMessageInternal org.springframework.messaging.MessagingException: Problem occurred while synchronizing remote to local directory; nested exception is org.springframework.messaging.MessagingException: Failed to execute on session; nested exception is org.springframework.core.NestedIOException: Failed to list files; nested exception is 2: No such file
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizer.synchronizeToLocalDirectory(AbstractInboundFileSynchronizer.java:217)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizingMessageSource.doReceive(AbstractInboundFileSynchronizingMessageSource.java:196)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizingMessageSource.doReceive(AbstractInboundFileSynchronizingMessageSource.java:60)
at org.springframework.integration.endpoint.AbstractMessageSource.receive(AbstractMessageSource.java:64)
at org.springframework.integration.endpoint.SourcePollingChannelAdapter.receiveMessage(SourcePollingChannelAdapter.java:144)
at org.springframework.integration.endpoint.AbstractPollingEndpoint.doPoll(AbstractPollingEndpoint.java:192)
at org.springframework.integration.endpoint.AbstractPollingEndpoint.access$000(AbstractPollingEndpoint.java:55)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$1.call(AbstractPollingEndpoint.java:149)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$1.call(AbstractPollingEndpoint.java:146)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$Poller$1.run(AbstractPollingEndpoint.java:298)
at org.springframework.integration.util.ErrorHandlingTaskExecutor$1.run(ErrorHandlingTaskExecutor.java:52)
at org.springframework.core.task.SyncTaskExecutor.execute(SyncTaskExecutor.java:50)
at org.springframework.integration.util.ErrorHandlingTaskExecutor.execute(ErrorHandlingTaskExecutor.java:49)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$Poller.run(AbstractPollingEndpoint.java:292)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:738)
Caused by: org.springframework.messaging.MessagingException: Failed to execute on session; nested exception is org.springframework.core.NestedIOException: Failed to list files; nested exception is 2: No such file
at org.springframework.integration.file.remote.RemoteFileTemplate.execute(RemoteFileTemplate.java:345)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizer.synchronizeToLocalDirectory(AbstractInboundFileSynchronizer.java:175)
... 23 more
Caused by: org.springframework.core.NestedIOException: Failed to list files; nested exception is 2: No such file
at org.springframework.integration.sftp.session.SftpSession.list(SftpSession.java:103)
at org.springframework.integration.sftp.session.SftpSession.list(SftpSession.java:50)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizer$1.doInSession(AbstractInboundFileSynchronizer.java:179)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizer$1.doInSession(AbstractInboundFileSynchronizer.java:175)
at org.springframework.integration.file.remote.RemoteFileTemplate.execute(RemoteFileTemplate.java:336)
... 24 more
Caused by: 2: No such file
at com.jcraft.jsch.ChannelSftp.throwStatusError(ChannelSftp.java:2846)
at com.jcraft.jsch.ChannelSftp._stat(ChannelSftp.java:2198)
at com.jcraft.jsch.ChannelSftp._stat(ChannelSftp.java:2215)
at com.jcraft.jsch.ChannelSftp.ls(ChannelSftp.java:1565)
at com.jcraft.jsch.ChannelSftp.ls(ChannelSftp.java:1526)
at org.springframework.integration.sftp.session.SftpSession.list(SftpSession.java:91)
... 28 more 

07072015:1:38PM EST

After switching to cachingSessionFactory..i get this exception message...

[7/7/15 13:17:52:751 EDT] 000000a0 jsch          I org.springframework.integration.sftp.session.JschLogger log kex: client->server aes128-ctr hmac-md5 none
[7/7/15 13:17:52:255 EDT] 000000a5 LoggingHandle E org.springframework.integration.handler.LoggingHandler handleMessageInternal org.springframework.messaging.MessagingException: Problem occurred while synchronizing remote to local directory; nested exception is org.springframework.messaging.MessagingException: Failed to obtain pooled item; nested exception is java.lang.IllegalStateException: failed to create SFTP Session
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizer.synchronizeToLocalDirectory(AbstractInboundFileSynchronizer.java:217)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizingMessageSource.doReceive(AbstractInboundFileSynchronizingMessageSource.java:196)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizingMessageSource.doReceive(AbstractInboundFileSynchronizingMessageSource.java:60)
at org.springframework.integration.endpoint.AbstractMessageSource.receive(AbstractMessageSource.java:64)
at org.springframework.integration.endpoint.SourcePollingChannelAdapter.receiveMessage(SourcePollingChannelAdapter.java:144)
at org.springframework.integration.endpoint.AbstractPollingEndpoint.doPoll(AbstractPollingEndpoint.java:192)
at org.springframework.integration.endpoint.AbstractPollingEndpoint.access$000(AbstractPollingEndpoint.java:55)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$1.call(AbstractPollingEndpoint.java:149)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$1.call(AbstractPollingEndpoint.java:146)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$Poller$1.run(AbstractPollingEndpoint.java:298)
at org.springframework.integration.util.ErrorHandlingTaskExecutor$1.run(ErrorHandlingTaskExecutor.java:52)
at org.springframework.core.task.SyncTaskExecutor.execute(SyncTaskExecutor.java:50)
at org.springframework.integration.util.ErrorHandlingTaskExecutor.execute(ErrorHandlingTaskExecutor.java:49)
at org.springframework.integration.endpoint.AbstractPollingEndpoint$Poller.run(AbstractPollingEndpoint.java:292)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:439)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:98)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:206)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:738)
Caused by: org.springframework.messaging.MessagingException: Failed to obtain pooled item; nested exception is java.lang.IllegalStateException: failed to create SFTP Session
at org.springframework.integration.util.SimplePool.getItem(SimplePool.java:178)
at org.springframework.integration.file.remote.session.CachingSessionFactory.getSession(CachingSessionFactory.java:118)
at org.springframework.integration.file.remote.RemoteFileTemplate.execute(RemoteFileTemplate.java:334)
at org.springframework.integration.file.remote.synchronizer.AbstractInboundFileSynchronizer.synchronizeToLocalDirectory(AbstractInboundFileSynchronizer.java:175)
... 23 more
Caused by: java.lang.IllegalStateException: failed to create SFTP Session
at org.springframework.integration.sftp.session.DefaultSftpSessionFactory.getSession(DefaultSftpSessionFactory.java:355)
at org.springframework.integration.sftp.session.DefaultSftpSessionFactory.getSession(DefaultSftpSessionFactory.java:49)
at org.springframework.integration.file.remote.session.CachingSessionFactory$1.createForPool(CachingSessionFactory.java:76)
at org.springframework.integration.file.remote.session.CachingSessionFactory$1.createForPool(CachingSessionFactory.java:73)
at org.springframework.integration.util.SimplePool.doGetItem(SimplePool.java:188)
at org.springframework.integration.util.SimplePool.getItem(SimplePool.java:169)
... 26 more
Caused by: java.lang.IllegalStateException: failed to connect
at org.springframework.integration.sftp.session.SftpSession.connect(SftpSession.java:272)
at org.springframework.integration.sftp.session.DefaultSftpSessionFactory.getSession(DefaultSftpSessionFactory.java:350)
... 31 more
Caused by: com.jcraft.jsch.JSchException: connection is closed by foreign host
at com.jcraft.jsch.Session.connect(Session.java:269)
at com.jcraft.jsch.Session.connect(Session.java:183)
at org.springframework.integration.sftp.session.SftpSession.connect(SftpSession.java:263)
... 32 more

Answer 1

I had 20 odd directories to poll, so therefore at the startup, SI SFTP adapter will try to instantiate minimum 20 connections/sessions with the remote server. But my cacheSessionFactory settings of poolsize=10 and sessionWaitTimeout=1000. Clearly that was the problem, the poolsize was limiting to 10, whereas i had 20 directories to pool. SI/Spring sftp was trying its best to share these 10 connections among 20 pollers. ====Setting the poolsize=50 and sessionTimeOut=10000 .. works like a charm.

Answer 2

Best guess is the remote directory doesn't exist. The failure is during the list operation.