How to SFTP after session timeout using JSch and Spring Integration

Question

I have application that SFTPs a file via a SftpInboundFileSynchronizer:

@Bean
public SftpInboundFileSynchronizer sftpInboundFileSynchronizer() {
    SftpInboundFileSynchronizer fileSynchronizer = new SftpInboundFileSynchronizer(sftpSessionFactory());
    fileSynchronizer.setDeleteRemoteFiles(false);
    fileSynchronizer.setRemoteDirectory(applicationProperties.getSftpDirectory());
    CompositeFileListFilter<ChannelSftp.LsEntry> compositeFileListFilter = new CompositeFileListFilter<ChannelSftp.LsEntry>();
    compositeFileListFilter.addFilter(new SftpPersistentAcceptOnceFileListFilter(store, "sftp"));
    compositeFileListFilter.addFilter(new SftpSimplePatternFileListFilter(applicationProperties.getLoadFileNamePattern()));
    fileSynchronizer.setFilter(compositeFileListFilter);
    fileSynchronizer.setPreserveTimestamp(true);
    return fileSynchronizer;
}

Session factory is:

@Bean
public SessionFactory<LsEntry> sftpSessionFactory() {
    DefaultSftpSessionFactory sftpSessionFactory = new DefaultSftpSessionFactory();
    sftpSessionFactory.setHost(applicationProperties.getSftpHost());
    sftpSessionFactory.setPort(applicationProperties.getSftpPort());
    sftpSessionFactory.setUser(applicationProperties.getSftpUser());
    sftpSessionFactory.setPassword(applicationProperties.getSftpPassword());
    sftpSessionFactory.setAllowUnknownKeys(true);
    return new CachingSessionFactory<LsEntry>(sftpSessionFactory);
}

The SftpInboundFileSynchronizingMessageSource is set to poll using a compound trigger.

@Bean
@InboundChannelAdapter(autoStartup="true", channel = "sftpChannel", poller = @Poller("pollerMetadata"))
public SftpInboundFileSynchronizingMessageSource sftpMessageSource() {
    SftpInboundFileSynchronizingMessageSource source =
            new SftpInboundFileSynchronizingMessageSource(sftpInboundFileSynchronizer());
    source.setLocalDirectory(applicationProperties.getScheduledLoadDirectory());
    source.setAutoCreateLocalDirectory(true);
    CompositeFileListFilter<File> compositeFileFilter = new CompositeFileListFilter<File>();
    compositeFileFilter.addFilter(new LastModifiedFileListFilter());
    compositeFileFilter.addFilter(new FileSystemPersistentAcceptOnceFileListFilter(store, "dailyfilesystem"));
    source.setLocalFilter(compositeFileFilter);
    source.setCountsEnabled(true);
    return source;
}

The poller is set up with a compound trigger. It has a cron trigger to try to SFTP the expected file once a day. If the expected file is not found, I have a periodic trigger that overrides the cron trigger. It tries every 15 minutes to SFTP the file (up to 5 times). After it either gets the file or has tried 5 times to get the file, the cron trigger overrides the periodic trigger. The RetryCompoundTriggerAdvice contains this logic.

@Bean
public PollerMetadata pollerMetadata(RetryCompoundTriggerAdvice retryCompoundTriggerAdvice) {
    PollerMetadata pollerMetadata = new PollerMetadata();
    List<Advice> adviceChain = new ArrayList<Advice>();
    adviceChain.add(retryCompoundTriggerAdvice);
    pollerMetadata.setAdviceChain(adviceChain);
    pollerMetadata.setTrigger(compoundTrigger());
    pollerMetadata.setMaxMessagesPerPoll(1);
    return pollerMetadata;
}

@Bean
public CompoundTrigger compoundTrigger() {
    CompoundTrigger compoundTrigger = new CompoundTrigger(primaryTrigger());
    return compoundTrigger;
}

@Bean
public CronTrigger primaryTrigger() {
    return new CronTrigger(applicationProperties.getSchedule());
}

@Bean
public PeriodicTrigger secondaryTrigger() {
    return new PeriodicTrigger(applicationProperties.getRetryInterval());
}

RetryCompoundTriggerAdvice

@Component
public class RetryCompoundTriggerAdvice extends AbstractMessageSourceAdvice {

    private final static Logger logger = LoggerFactory.getLogger(RetryCompoundTriggerAdvice.class);

    private final CompoundTrigger compoundTrigger;

    private final Trigger override;

    private final ApplicationProperties applicationProperties;

    private final Mail mail;

    private int attempts = 0;

    public RetryCompoundTriggerAdvice(CompoundTrigger compoundTrigger, 
            @Qualifier("secondaryTrigger") Trigger override, 
            ApplicationProperties applicationProperties,
            Mail mail) {
        this.compoundTrigger = compoundTrigger;
        this.override = override;
        this.applicationProperties = applicationProperties;
        this.mail = mail;
    }

    @Override
    public boolean beforeReceive(MessageSource<?> source) {
        return true;
    }

    @Override
    public Message<?> afterReceive(Message<?> result, MessageSource<?> source) {
        final int  maxOverrideAttempts = applicationProperties.getMaxFileRetry();
        attempts++;
        if (result == null && attempts < maxOverrideAttempts) {
            logger.info("Unable to find load file after " + attempts + " attempt(s). Will reattempt");
            this.compoundTrigger.setOverride(this.override);
        } else if (result == null && attempts >= maxOverrideAttempts) {
            mail.sendAdminsEmail("Missing File");
            attempts = 0;
            this.compoundTrigger.setOverride(null);
        }
        else {
            attempts = 0;
            this.compoundTrigger.setOverride(null);
            logger.info("Found load file");
        }
        return result;
    }

    public void setOverrideTrigger() {
        this.compoundTrigger.setOverride(this.override);
    }

    public CompoundTrigger getCompoundTrigger() {
        return compoundTrigger;
    }
}

The problem is that when the application reattempts the SFTP after 15 minutes, the server session has timed out. So, JSch reports:

2017-01-27 18:30:01.447  INFO 14248 --- [Connect thread my.sftp.com session] com.jcraft.jsch                          : Caught an exception, leaving main loop due to End of IO Stream Read
2017-01-27 18:30:01.448  INFO 14248 --- [Connect thread my.sftp.com session] com.jcraft.jsch                          : Disconnecting from my.sftp.com port 22

As a result, no further messages are received and the application will not attempt to SFTP the file until the next cron time (i.e. the next day). How can I reattempt to SFTP file after waiting for 15 minutes?

I tried calling setServerAliveInterval on the DefaultSftpSessionFactory with out any luck. Note: After the file is retrieved or 5 attempts I want to cease communications with the SFTP server until the next cron run.

Update I was finally able to get a test executed. Adding the debug log as requested. Note: Debug logging set as follows in prop file:

logging.level.org.springframework: DEBUG
logging.level.com.jcraft.jsch: DEBUG

Here's the log:

2017-02-15 18:15:56.206 DEBUG 26748 --- [task-scheduler-9] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:16:56.211 DEBUG 26748 --- [task-scheduler-9] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:17:56.213 DEBUG 26748 --- [task-scheduler-8] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:18:56.214 DEBUG 26748 --- [task-scheduler-8] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:19:56.215 DEBUG 26748 --- [task-scheduler-8] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:20:56.215 DEBUG 26748 --- [task-scheduler-8] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:21:56.217 DEBUG 26748 --- [task-scheduler-8] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:22:56.218 DEBUG 26748 --- [task-scheduler-8] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:23:56.219 DEBUG 26748 --- [task-scheduler-3] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:24:56.221 DEBUG 26748 --- [task-scheduler-2] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:25:56.222 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:26:56.223 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:27:56.224 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:28:56.225 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:29:56.226 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:30:03.884  INFO 26748 --- [Connect thread my.sftp.com session] com.jcraft.jsch                          : Caught an exception, leaving main
loop due to End of IO Stream Read
2017-02-15 18:30:03.884  INFO 26748 --- [Connect thread my.sftp.com session] com.jcraft.jsch                          : Disconnecting from my.sftp.com port 22
2017-02-15 18:30:56.227 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:31:56.228 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:32:56.228 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'
2017-02-15 18:33:56.230 DEBUG 26748 --- [task-scheduler-6] o.s.i.e.SourcePollingChannelAdapter      : Received no Message during the poll, returning 'false'

JSCH doesn't log a debug statement even though I have debug level set. From the log it looks like the SFTP connection is terminated. Note: The task-scheduler-6 thread is polling ever minute as a result of a another poller for file system synch.

Answer 1

The cache should detect the session is no longer valid and hand out a new one. I'd need to see a DEBUG log (for spring and jsch) to figure out what's going on.

However, if you are only running once a day, there is really no need to cache sessions, just use the session factory directly and you'll get a new session on every poll.