Hi guys,
i think i found a bug in the "GenericFileRenameProcessStrategy" when
using the ftp component with the options "streamDownload=true" and
"move=testfolder".
After successfully retrieving the stream, the rename command (and the
directory checks) is executed before the
"FTPClient.completePendingCommand()". The "PWD" command therefor
returns the line "226 Successfully transferred /demo/demofile.txt" but
expects the replycode "257" (complete response "257 "/" is current
directory") and now the following commands and their responses are all
mixed up and the renaming fails. I think it is a bug and the method
"FTPOperations.releaseRetrievedFileResources()" (which calls
"FTPClient.completePendingCommand()") should be called at the
beginning of "GenericFileRenameProcessStrategy.commit()" (like in the
"GenericFileDeleteProcessStrategy" line 64) instead of the end.
WIthout the "streamDownload=true" option everything works fine, as the
"FTPClient._retrieveFile()" method calls the
"completePendingCommand()" directly after it finished downloading the
file.
Tested version: 2.23.1 (and 2.24.2)
FTP Server: Filezilla 0.96.0
Demoroute:
************************************
from("ftp://demo@localhost/demo?password=demo&delay=120000";
+ "&move=archive"
+ "&antExclude=archive/**"
+ "&disconnect=true"
+ "&streamDownload=true")
.log("Consuming file")
.process(exchange -> {
System.out.println(exchange.getIn().getBody(String.class));
})
.end();
*****************************
Log output:
****************************
...
2019-09-29 15:36:10.739 INFO 13852 --- [ main]
o.a.camel.spring.SpringCamelContext : Route: route1 started and
consuming from:
ftp://demo@localhost/demo?antExclude=archive%2F**&delay=120000&disconnect=true&move=archive&password=xxxxxx&streamDownload=true
2019-09-29 15:36:10.741 INFO 13852 --- [ main]
o.a.camel.spring.SpringCamelContext : Total 1 routes, of which 1
are started
2019-09-29 15:36:10.744 INFO 13852 --- [ main]
o.a.camel.spring.SpringCamelContext : Apache Camel 2.24.2
(CamelContext: camel-1) started in 0.427 seconds
2019-09-29 15:36:10.749 INFO 13852 --- [ main]
c.e.c.CamelFtpDemoApplication : Started
CamelFtpDemoApplication in 4.023 seconds (JVM running for 4.651)
2019-09-29 15:36:11.774 INFO 13852 --- [@localhost/demo] route1
: Consuming file
Hi, i am a demo file!!!!
2019-09-29 15:36:11.789 WARN 13852 --- [@localhost/demo]
o.a.c.c.file.GenericFileOnCompletion : Error during commit.
Exchange[ID-peter-1569764169435-0-1]. Caused by:
[org.apache.camel.component.file.GenericFileOperationFailedException -
Cannot rename file: RemoteFile[demofile.txt] to:
RemoteFile[archive/demofile.txt]]
org.apache.camel.component.file.GenericFileOperationFailedException:
Cannot rename file: RemoteFile[demofile.txt] to:
RemoteFile[archive/demofile.txt]
at
org.apache.camel.component.file.strategy.GenericFileProcessStrategySupport.renameFile(GenericFileProcessStrategySupport.java:130)
~[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.strategy.GenericFileRenameProcessStrategy.commit(GenericFileRenameProcessStrategy.java:111)
~[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.GenericFileOnCompletion.processStrategyCommit(GenericFileOnCompletion.java:127)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.GenericFileOnCompletion.onCompletion(GenericFileOnCompletion.java:83)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.GenericFileOnCompletion.onComplete(GenericFileOnCompletion.java:59)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.util.UnitOfWorkHelper.doneSynchronizations(UnitOfWorkHelper.java:104)
[camel-core-2.24.2.jar:2.24.2]
at org.apache.camel.impl.DefaultUnitOfWork.done(DefaultUnitOfWork.java:243)
[camel-core-2.24.2.jar:2.24.2]
at org.apache.camel.util.UnitOfWorkHelper.doneUow(UnitOfWorkHelper.java:65)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:685)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.processor.CamelInternalProcessor$UnitOfWorkProcessorAdvice.after(CamelInternalProcessor.java:634)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.processor.CamelInternalProcessor$InternalCallback.done(CamelInternalProcessor.java:251)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:183)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:454)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.remote.RemoteFileConsumer.processExchange(RemoteFileConsumer.java:133)
[camel-ftp-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:223)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:187)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.impl.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:174)
[camel-core-2.24.2.jar:2.24.2]
at
org.apache.camel.impl.ScheduledPollConsumer.run(ScheduledPollConsumer.java:101)
[camel-core-2.24.2.jar:2.24.2]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[na:1.8.0_202]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[na:1.8.0_202]
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
[na:1.8.0_202]
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
[na:1.8.0_202]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[na:1.8.0_202]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[na:1.8.0_202]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_202]
...
***********************
Filezilla Server output:
**********************************
(000010)29.09.2019 15:36:10 - (not logged in) (127.0.0.1)> Connected
on port 21, sending welcome message...
(000010)29.09.2019 15:36:10 - (not logged in) (127.0.0.1)>
220-FileZilla Server 0.9.60 beta
(000010)29.09.2019 15:36:10 - (not logged in) (127.0.0.1)> 220-written
by Tim Kosse ([email protected])
(000010)29.09.2019 15:36:10 - (not logged in) (127.0.0.1)> 220 Please
visit https://filezilla-project.org/
(000010)29.09.2019 15:36:10 - (not logged in) (127.0.0.1)> USER demo
(000010)29.09.2019 15:36:10 - (not logged in) (127.0.0.1)> 331
Password required for demo
(000010)29.09.2019 15:36:10 - (not logged in) (127.0.0.1)> PASS ****
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> 230 Logged on
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> TYPE A
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> 200 Type set to A
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> PWD
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> 257 "/" is current directory.
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> CWD demo
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> 250 CWD successful.
"/demo" is current directory.
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> CWD /
(000010)29.09.2019 15:36:10 - demo (127.0.0.1)> 250 CWD successful.
"/" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> NOOP
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 200 OK
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> PWD
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 257 "/" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> CWD demo
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 250 CWD successful.
"/demo" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> SYST
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 215 UNIX emulated by FileZilla
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> PORT 127,0,0,1,201,185
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 200 Port command successful
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> LIST
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 150 Opening data
channel for directory listing of "/demo"
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 226 Successfully
transferred "/demo"
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> CWD /
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 250 CWD successful.
"/" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> PWD
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 257 "/" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> CWD demo
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 250 CWD successful.
"/demo" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> PORT 127,0,0,1,201,186
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 200 Port command successful
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> RETR demofile.txt
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 150 Opening data
channel for file download from server of "/demo/demofile.txt"
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 226 Successfully
transferred "/demo/demofile.txt"
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> CWD /
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 250 CWD successful.
"/" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> PWD
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 257 "/" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> CWD demo
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 250 CWD successful.
"/demo" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> CWD archive
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 250 CWD successful.
"/demo/archive" is current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> DELE demofile.txt
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 550 File not found
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> PWD
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 257 "/demo/archive" is
current directory.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> CWD demo/archive
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 550 CWD failed.
"/demo/archive/demo/archive": directory not found.
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> RNFR demo/demofile.txt
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 550 file/directory not found
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> QUIT
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> 221 Goodbye
(000010)29.09.2019 15:36:11 - demo (127.0.0.1)> disconnected.
**********************************
Best regards,
Peter
--
Peter Nowak
Developer
ecosio GmbH
Lange Gasse 30, 1080 Vienna, Austria/Europe
Mail: [email protected]
T: +43 1 996 2106-0, F: +43 1 996 2106-99
UID: ATU68241501, FBNR: FN 405017 p, Handelsgericht Wien
Geschäftsführer: Christoph Ebm, Philipp Liegl, Marco Zapletal
Web: https://ecosio.com, Blog: https://ecosio.com/blog, Newsletter
