Unable to rename file in SFTP remote directory - Please help

[priyavenkat]

We have been using spring integration/batch in one of our applications. As a part of the batch process, there is an sftp handler that transfers files to a remote sftp server. When the code was newly implemented things were working wonderfully as expected with spring integration 2.1.1 a couple of months back.

Recently a couple of days back, we have started seeing the following exception while making the sftp transfer (which is very much reproducible every time). The underlying API is unable to rename the .writing file to its original file name. This causes an exception and I dug into the Spring Integration API and found the following - Since an exception was thrown while renaming, the API assumes that there is an already existing file with that file name and tries to remove the file from that directory. In reality, we do not have an already existing file with that name in that directory and hence "path is invalid" message is received from SFTP server.

I understand that we can make the use-temporary-filename to false. But, Could any of you please help me in understanding whether there is any problem in the underlying API in this regard? I am not able to say that this is a permission issue since we are able to manually enter into the sftp server and rename the file with .writing extn to the actual file name without errors. - Please help since this is urgent.

Eagerly waiting for some help in this regard..I have spent around 1 full day trying to get out of this issue...but ended up in vain..

 at java.lang.Thread.run(Thread.java:662)
Caused by: org.springframework.integration.MessageDeliveryException: 
Error handling message for file 
[<file path with file name>]
     at 
org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.handleMessageInternal(FileTransferringMessageHandler.java:166)
     at 
org.springframework.integration.handler.AbstractMessageHandler.handleMessage(AbstractMessageHandler.java:73)
     at 
org.springframework.integration.dispatcher.UnicastingDispatcher.doDispatch(UnicastingDispatcher.java:115)
     at 
org.springframework.integration.dispatcher.UnicastingDispatcher.dispatch(UnicastingDispatcher.java:102)
     at 
org.springframework.integration.channel.AbstractSubscribableChannel.doSend(AbstractSubscribableChannel.java:77)
     at 
org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:157)
     at 
org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:128)
     at 
<package name where error occurs>(SftpHandler.java:195)
     at 
<package with method name where error occurs>(SftpHandler.java:144)
     at 
<package with method name internal - where error occurs>(SftpHandler.java:97)
     at 
     ... 52 more
Caused by: org.springframework.integration.MessagingException: Failed to 
write to 
'<filename with its extension.writing>' 
while uploading the file
     at 
org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.sendFileToRemoteDirectory(FileTransferringMessageHandler.java:249)
     at 
org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.handleMessageInternal(FileTransferringMessageHandler.java:155)
     ... 62 more
Caused by: org.springframework.core.NestedIOException: Failed to delete 
file <filename with its extension>; nested 
exception is org.springframework.core.NestedIOException: Failed to 
remove file: 2: Specified file path is invalid.
     at 
org.springframework.integration.sftp.session.SftpSession.rename(SftpSession.java:159)
     at 
org.springframework.integration.file.remote.session.CachingSessionFactory$CachedSession.rename(CachingSessionFactory.java:157)
     at 
org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.sendFileToRemoteDirectory(FileTransferringMessageHandler.java:245)
     ... 63 more
Caused by: org.springframework.core.NestedIOException: Failed to remove 
file: 2: Specified file path is invalid.
     at 
org.springframework.integration.sftp.session.SftpSession.remove(SftpSession.java:73)
     at 
org.springframework.integration.sftp.session.SftpSession.rename(SftpSession.java:153)
     ... 65 more
------

[oleg.zhurakousky]

Ok, help me understand it better. The way 'rename' works now is like this:

Try a simple rename. If fails assume existing file; Try to remove it; If remove fails throw exception (what happens to you) else try rename again; If still fails then propagate exception.

So if that's correct then my question is this.
It would never attempt to remove IF the initial rename didn't fail, so why did it fail initially? If DEBUG is enabled you should see the following message before the exception:

Initial File rename failed, possibly because file already exists. Will attempt to delete file. . .

Can you post it?

[priyavenkat]

Thanks a lot for the instant reply. Please just give me a couple of hours. Let me get to my workplace, check out the DEBUG LOG and let you know within 1-2 hours surely. Appreciate your quick response. Thanks. Will get back...

[priyavenkat]

Hi oleg.zhurakousky,

I have been into this since I came in. I did enable the debug in log4j.properties and tried to run the application jar. SFTP handler has no errors now. Am not sure what to tell you now. Tried it several times and that indeed was the reason for the delay in replying to this post. Am sure we were able to replicate this issue several times consistently for the past 2 days when we did not run with DEBUG enabled though!!!

by the way, do you think we should try again without the DEBUG - will that be utile in ur opinion?

I shall surely get back to this thread when we are able to reproduce this again. Will keep you posted.

Thanks for the help.

[oleg.zhurakousky]

Some times i exercise my supernatural powers of projecting fixes over the internet, so I am glad it worked this time

But in all seriousness, yes please run with DEBUG for some time and when it happens let me know what the message says.
We probably should change that message to WARN

[priyavenkat]

I have also disabled the DEBUG logs now and tried running the app again. There are absolutely no errors in SFTP handling showing up now. But will keep monitoring and would keep you updated

[priyavenkat]

After posting this message above, I saw ur message related to having the DEBUG on. I will surely turn the DEBUG on again and will continue to monitor this issue definitely since the app will be running on the production server for the forthcoming several months...and we expect it to work seamlessly(:-))

[priyavenkat]

After a long time, We are getting the following exception (This is usually after the job completes and waits for the next trigger that occurs after 8 hours)

java.lang.Exception: org.springframework.integration.MessageDeliveryException: Failed to transfer file [] from local working directory to remote FTP directory.
	at org.caltesting.di.batch.jobs.CandidateRecordProcessor.process(Processor.java:92)
	at org.caltesting.di.batch.jobs.Processor.process(Processor.java:25)
	at sun.reflect.GeneratedMethodAccessor27.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
	at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
	at $Proxy9.process(Unknown Source)
	at org.springframework.batch.core.step.item.SimpleChunkProcessor.doProcess(SimpleChunkProcessor.java:125)
	at org.springframework.batch.core.step.item.SimpleChunkProcessor.transform(SimpleChunkProcessor.java:276)
	at org.springframework.batch.core.step.item.SimpleChunkProcessor.process(SimpleChunkProcessor.java:187)
	at org.springframework.batch.core.step.item.ChunkOrientedTasklet.execute(ChunkOrientedTasklet.java:74)
	at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:386)
	at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:130)
	at org.springframework.batch.core.step.tasklet.TaskletStep$2.doInChunkContext(TaskletStep.java:264)
	at org.springframework.batch.core.scope.context.StepContextRepeatCallback.doInIteration(StepContextRepeatCallback.java:76)
	at org.springframework.batch.repeat.support.RepeatTemplate.getNextResult(RepeatTemplate.java:367)
	at org.springframework.batch.repeat.support.RepeatTemplate.executeInternal(RepeatTemplate.java:214)
	at org.springframework.batch.repeat.support.RepeatTemplate.iterate(RepeatTemplate.java:143)
	at org.springframework.batch.core.step.tasklet.TaskletStep.doExecute(TaskletStep.java:250)
	at org.springframework.batch.core.step.AbstractStep.execute(AbstractStep.java:195)
	at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:135)
	at org.springframework.batch.core.job.flow.JobFlowExecutor.executeStep(JobFlowExecutor.java:61)
	at org.springframework.batch.core.job.flow.support.state.StepState.handle(StepState.java:60)
	at org.springframework.batch.core.job.flow.support.SimpleFlow.resume(SimpleFlow.java:144)
	at org.springframework.batch.core.job.flow.support.SimpleFlow.start(SimpleFlow.java:124)
	at org.springframework.batch.core.job.flow.FlowJob.doExecute(FlowJob.java:135)
	at org.springframework.batch.core.job.AbstractJob.execute(AbstractJob.java:281)
	at org.caltesting.di.BatchProcessInvoker.invokeBatchJob(BatchProcessInvoker.java:64)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:64)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:53)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
Caused by: org.springframework.integration.MessageDeliveryException: Failed to transfer file [] from local working directory to remote FTP directory.
	at org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.handleMessageInternal(FileTransferringMessageHandler.java:162)
	at org.springframework.integration.handler.AbstractMessageHandler.handleMessage(AbstractMessageHandler.java:73)
	at org.springframework.integration.dispatcher.UnicastingDispatcher.doDispatch(UnicastingDispatcher.java:115)
	at org.springframework.integration.dispatcher.UnicastingDispatcher.dispatch(UnicastingDispatcher.java:102)
	at org.springframework.integration.channel.AbstractSubscribableChannel.doSend(AbstractSubscribableChannel.java:77)
	at org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:157)
	at org.springframework.integration.channel.AbstractMessageChannel.send(AbstractMessageChannel.java:128)
	at org.caltesting.di.batch.jobs.SftpHandler.sftpFile(SftpHandler.java:196)
	at org.caltesting.di.batch.jobs.SftpHandler.LoopThroughFiles(SftpHandler.java:144)
	at org.caltesting.di.batch.jobs.SftpHandler.execute(SftpHandler.java:97)
	at org.caltesting.di.batch.jobs.Processor.process(Processor.java:84)
	... 48 more
Caused by: org.springframework.core.NestedIOException: failed to create remote directory '<name>'.; nested exception is 4: 
	at org.springframework.integration.sftp.session.SftpSession.mkdir(SftpSession.java:179)
	at org.springframework.integration.file.remote.session.CachingSessionFactory$CachedSession.mkdir(CachingSessionFactory.java:161)
	at org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.makeDirectories(FileTransferringMessageHandler.java:289)
	at org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.sendFileToRemoteDirectory(FileTransferringMessageHandler.java:232)
	at org.springframework.integration.file.remote.handler.FileTransferringMessageHandler.handleMessageInternal(FileTransferringMessageHandler.java:155)
	... 58 more
Caused by: 4: 
	at com.jcraft.jsch.ChannelSftp.mkdir(ChannelSftp.java:1980)
	at org.springframework.integration.sftp.session.SftpSession.mkdir(SftpSession.java:176)
	... 62 more
Caused by: java.io.IOException: Pipe closed
	at java.io.PipedInputStream.read(PipedInputStream.java:291)
	at java.io.PipedInputStream.read(PipedInputStream.java:361)
	at com.jcraft.jsch.ChannelSftp.fill(ChannelSftp.java:2605)
	at com.jcraft.jsch.ChannelSftp.header(ChannelSftp.java:2631)
	at com.jcraft.jsch.ChannelSftp.mkdir(ChannelSftp.java:1963)
	... 63 more

Here, should the jshSession not be validated by the DefaultSFTPSessionFactory before giving it to the adapter?