I encounter a strange error when camel ftp consumer is deleting file in
remote server.
Is there any problem in my route setting and how to prevent it?
----------
Story
I am testing ftp consumer behavior with delete option and attempt to use
thread to speed up the process, but encounter a strange error. To better
simulate the problem, I remove the delete right of the user account.
The target folder is 2 level deep from ftp access root
folder(/timtest/delete_test) and contains 2 files.
When the ftp consumer is attempt to delete the remote files, some strange
errors occur. These errors does not always happen.
In 50 tests,
> - 46/50 => [Normal]
> org.apache.camel.component.file.GenericFileOperationFailedException:
> Cannot delete file: RemoteFile[test.txt]
> - 4/50 => [Abnormal]
> org.apache.camel.component.file.GenericFileOperationFailedException:
> File operation failed: 550 CWD failed. "/timtest/timtest": directory
> not found. Cannot change directory to: delete_test. Code: 550
Camel version: 2.17.0
----------
Error
20161110 15:36:32.391 [Camel (routeLoader_route) thread #8 -
inboundRecieveThread] INFO inboundGenericErrHandler - ERR-2000-IG000-ST :
inbound Stack Trace:
org.apache.camel.component.file.GenericFileOperationFailedException: File
operation failed: 550 CWD failed. "/timtest/timtest": directory not found.
Cannot change directory to: delete_test. Code: 550
at
org.apache.camel.component.file.remote.FtpOperations.doChangeDirectory(FtpOperations.java:778)
at
org.apache.camel.component.file.remote.FtpOperations.changeCurrentDirectory(FtpOperations.java:756)
at
org.apache.camel.component.file.remote.FtpOperations.deleteFile(FtpOperations.java:245)
at
org.apache.camel.component.file.strategy.GenericFileDeleteProcessStrategy.commit(GenericFileDeleteProcessStrategy.java:71)
at
org.apache.camel.component.file.GenericFileOnCompletion.processStrategyCommit(GenericFileOnCompletion.java:127)
at
org.apache.camel.component.file.GenericFileOnCompletion.onCompletion(GenericFileOnCompletion.java:83)
at
org.apache.camel.component.file.GenericFileOnCompletion.onComplete(GenericFileOnCompletion.java:57)
at
org.apache.camel.util.UnitOfWorkHelper.doneSynchronizations(UnitOfWorkHelper.java:104)
at
org.apache.camel.impl.DefaultUnitOfWork.done(DefaultUnitOfWork.java:229)
at
org.apache.camel.util.UnitOfWorkHelper.doneUow(UnitOfWorkHelper.java:65)
at
org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:654)
at
org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:609)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:239)
at org.apache.camel.processor.Pipeline$1.done(Pipeline.java:148)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.processor.RedeliveryErrorHandler$1.done(RedeliveryErrorHandler.java:480)
at
org.apache.camel.management.InstrumentationProcessor$1.done(InstrumentationProcessor.java:86)
at
org.apache.camel.processor.SendProcessor$1.done(SendProcessor.java:155)
at
org.apache.camel.component.directvm.DirectVmProcessor$1.done(DirectVmProcessor.java:63)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.management.InstrumentationProcessor$1.done(InstrumentationProcessor.java:86)
at
org.apache.camel.processor.TryProcessor$1.done(TryProcessor.java:141)
at org.apache.camel.processor.Pipeline$1.done(Pipeline.java:148)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.management.InstrumentationProcessor$1.done(InstrumentationProcessor.java:86)
at org.apache.camel.processor.Pipeline$1.done(Pipeline.java:148)
at
org.apache.camel.processor.ThreadsProcessor$ProcessCall.run(ThreadsProcessor.java:85)
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:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
20161110 15:36:32.391 [Camel (routeLoader_route) thread #9 -
inboundRecieveThread] INFO inboundGenericErrHandler - ERR-2000-IG000-ST :
inbound Stack Trace:
org.apache.camel.component.file.GenericFileOperationFailedException: File
operation failed: 550 CWD failed. "/delete_test": directory not found.
Cannot change directory to: delete_test. Code: 550
at
org.apache.camel.component.file.remote.FtpOperations.doChangeDirectory(FtpOperations.java:778)
at
org.apache.camel.component.file.remote.FtpOperations.changeCurrentDirectory(FtpOperations.java:756)
at
org.apache.camel.component.file.remote.FtpOperations.deleteFile(FtpOperations.java:245)
at
org.apache.camel.component.file.strategy.GenericFileDeleteProcessStrategy.commit(GenericFileDeleteProcessStrategy.java:71)
at
org.apache.camel.component.file.GenericFileOnCompletion.processStrategyCommit(GenericFileOnCompletion.java:127)
at
org.apache.camel.component.file.GenericFileOnCompletion.onCompletion(GenericFileOnCompletion.java:83)
at
org.apache.camel.component.file.GenericFileOnCompletion.onComplete(GenericFileOnCompletion.java:57)
at
org.apache.camel.util.UnitOfWorkHelper.doneSynchronizations(UnitOfWorkHelper.java:104)
at
org.apache.camel.impl.DefaultUnitOfWork.done(DefaultUnitOfWork.java:229)
at
org.apache.camel.util.UnitOfWorkHelper.doneUow(UnitOfWorkHelper.java:65)
at
org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:654)
at
org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:609)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:239)
at org.apache.camel.processor.Pipeline$1.done(Pipeline.java:148)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.processor.RedeliveryErrorHandler$1.done(RedeliveryErrorHandler.java:480)
at
org.apache.camel.management.InstrumentationProcessor$1.done(InstrumentationProcessor.java:86)
at
org.apache.camel.processor.SendProcessor$1.done(SendProcessor.java:155)
at
org.apache.camel.component.directvm.DirectVmProcessor$1.done(DirectVmProcessor.java:63)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.management.InstrumentationProcessor$1.done(InstrumentationProcessor.java:86)
at
org.apache.camel.processor.TryProcessor$1.done(TryProcessor.java:141)
at org.apache.camel.processor.Pipeline$1.done(Pipeline.java:148)
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:250)
at
org.apache.camel.management.InstrumentationProcessor$1.done(InstrumentationProcessor.java:86)
at org.apache.camel.processor.Pipeline$1.done(Pipeline.java:148)
at
org.apache.camel.processor.ThreadsProcessor$ProcessCall.run(ThreadsProcessor.java:85)
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:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
----------
Related server log
(000053)11/10/2016 15:36:30 PM - (not logged in) (x.x.x.x)> Connected,
sending welcome message...
(000053)11/10/2016 15:36:30 PM - (not logged in) (x.x.x.x)>
220-FileZilla Server version 0.9.45 beta
(000053)11/10/2016 15:36:30 PM - (not logged in) (x.x.x.x)> 220-written
by Tim Kosse (tim.ko...@filezilla-project.org)
(000053)11/10/2016 15:36:30 PM - (not logged in) (x.x.x.x)> 220 Please
visit http://sourceforge.net/projects/filezilla/
(000053)11/10/2016 15:36:30 PM - (not logged in) (x.x.x.x)> USER abc+def
(000053)11/10/2016 15:36:30 PM - (not logged in) (x.x.x.x)> 331 Password
required for abc+def
(000053)11/10/2016 15:36:30 PM - (not logged in) (x.x.x.x)> PASS ***
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> 230 Logged on
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> TYPE I
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> 200 Type set to I
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> PWD
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> 257 "/" is current
directory.
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> CWD
timtest/delete_test
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest/delete_test" is current directory.
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> CWD /
(000053)11/10/2016 15:36:30 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> NOOP
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 200 OK
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PWD
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 257 "/" is current
directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD timtest
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD delete_test
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest/delete_test" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> SYST
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 215 UNIX emulated by
FileZilla
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PASV
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 227 Entering Passive
Mode (x,x,x,x,250,43)
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> LIST
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 150 Opening data
channel for directory listing of "/timtest/delete_test"
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 226 Successfully
transferred "/timtest/delete_test"
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD /
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PWD
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 257 "/" is current
directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD timtest
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD delete_test
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest/delete_test" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PASV
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 227 Entering Passive
Mode (x,x,x,x,250,45)
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> RETR test - Copy.txt
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 150 Opening data
channel for file download from server of "/timtest/delete_test/test -
Copy.txt"
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 226 Successfully
transferred "/timtest/delete_test/test - Copy.txt"
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD /
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PWD
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 257 "/" is current
directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD timtest
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD delete_test
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest/delete_test" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PASV
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 227 Entering Passive
Mode (x,x,x,x,250,47)
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> RETR test.txt
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 150 Opening data
channel for file download from server of "/timtest/delete_test/test.txt"
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 226 Successfully
transferred "/timtest/delete_test/test.txt"
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD /
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PWD
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 257 "/" is current
directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> PWD
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 257 "/" is current
directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD timtest
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD timtest
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 550 CWD failed.
"/timtest/timtest": directory not found.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD delete_test
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/timtest/delete_test" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD /
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/" is current directory.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD delete_test
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 550 CWD failed.
"/delete_test": directory not found.
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> CWD /
(000053)11/10/2016 15:36:31 PM - abc+def (x.x.x.x)> 250 CWD successful.
"/" is current directory.
(000053)11/10/2016 15:36:40 PM - abc+def (x.x.x.x)> disconnected.
----------
Route Setting
protected static RouteBuilder createInRouteBuilder(final String routeId,
final String[] uri) throws Exception{
return new RouteBuilder() {
@Override
public void configure() throws Exception {
from (uri[0])
.log(routeId)
.routeId(routeId)
.to("direct-vm:ingen.process");
}
};
}
<route id="inboundRoute">
<from uri="direct-vm:ingen.process"/>
<doTry>
<log message="inbound_route - START"
loggingLevel="INFO" />
<threads executorServiceRef="inboundRecieveThreadPool">
<recipientList>
<method ref="inProcBean"
method="dynamicRouteToEMSQueue" />
</recipientList>
</threads>
<doCatch>
<exception>java.lang.Exception</exception>
</doCatch>
<doFinally>
<log message="inbound_route - END" loggingLevel="INFO"
/>
<stop/>
</doFinally>
</doTry>
</route>
uri[0] =
ftp://127.0.0.1:21/timtest/delete_test?username=RAW(abc+def)&password=123&binary=true&delete=true&disconnect=false&passiveMode=true&consumer.delay=30000&maxMessagesPerPoll=2
--
View this message in context:
http://camel.465427.n5.nabble.com/FTP-Consumer-strange-error-when-delete-file-tp5790126.html
Sent from the Camel - Users mailing list archive at Nabble.com.
