Hi Claus,
Thank you for your reply. Yes, there's only the one application with the route
running, though there are separate test and production servers. Their
configuration points to separate external FTP servers, matching the
environment.
I've changed the route to only start polling the FTP server in the morning (as
the error seems to occur in the night when the supplier uploads the files) and
we haven't experienced any issues since. Though this really only circumvents
the problem.
As far as I can see in any logs we haven't experienced it on the test server,
save once. I've upgraded to Camel 3.11.0 and Spring Boot 2.5.2 and deployed it
on test, though from what I can see of changelogs I don't really expect the FTP
component to be changed between these releases.
Kind regards
Carsten Bülow
-----Oprindelig meddelelse-----
Fra: Claus Ibsen <claus.ib...@gmail.com>
Sendt: 2. juli 2021 16:10
Til: users@camel.apache.org
Emne: Re: Camel FTP bug? Filename used for another file
Hi
This would be the first time I hear about this.
Do you have only one active Camel application (node) that runs this route with
the FTP consumer?
If you can reproduce this on a test environment, then you are also welcome to
try with Camel 3.11.0 release.
On Thu, Jul 1, 2021 at 5:12 PM Carsten Bulow <carsten.bu...@process-factory.dk>
wrote:
>
> Hi Camel team,
>
> I'm currently looking into a production issue we're having that has led to
> data loss. I've tried searching for solutions but to no avail. In short, what
> we're experiencing is that a Camel route downloads several files from a FTPS
> server and saves them to a local file path. Some files are fine, some files
> have had their content replaced by the content of another file.
>
> As an example, 3 files: Test1.xml, Test2.xml, Test3.xml. The content of file
> Test3.xml has been replaced by the content of file Test1.xml. Test1.xml and
> Test2.xml are unaffected. In my world this is a "should never be able to
> happen"-error.
>
> The issue doesn't happen every day and I can see in our logs that the
> retrieve file operations have failed on days with error in files. We're
> getting read time out and cannot retrieve file exceptions, possible because
> the supplier is currently writing to the file or having a file lock, I don't
> know. My assumption is that the route will re-try to fetch the file and
> somehow the active context filename of one filename is transferred into
> another context (not sure of the inner workings) of another file leading to
> using an incorrect filename. I don't have any idea how this can happen.
>
> We didn't use the fileExist option when writing the files because we know the
> file supplier uses unique filenames but I made an immediate hotfix adding
> fileExist=Move to the route so we'll at least have a backup.
>
> Any help with this issue will be appreciated.
>
>
> Further details:
> New application that has been running for two weeks before first issue. We've
> had the issue on 4 separate occasions. We've been using older Camel versions
> for almost a decade that has a similar route with no issues.
> Camel 3.8.0
> Spring Boot 2.4.2
> Windows Server 2016, Java 8 (AdoptOpenJDK jdk-8.0.282.8)
>
>
> The route, using Java DSL:
> Sort the files on the FTPS server, download each file, save file in an
> archive folder by date and then in a different folder for further handling.
>
> from(uri)
> .routeId("consume-ftp")
> .setHeader("direction", simple("inbound"))
> .log(LoggingLevel.DEBUG, "route.ftp-download", "Retrieving file from
> FTP: ${file:name}")
> .toD(file:// + configuration.getArchiveInbound() +
> "/${date:now:yyyy-MM-dd}?flatten=true")
> .to(file:// + configuration.getInbound() + "?flatten=true")
> .log(LoggingLevel.INFO, "route.ftp-download", "Inbound file
> archived and sent to handling: ${file:name}");
>
> where,
> String uri = "ftps://example.com:1234/download?username=user&password=pw" +
> "&ftpClient.keyStore.file=filepath" +
> "&ftpClient.keyStore.password=pw" +
> "&ftpClient.keyStore.keyPassword=pw" +
> "&delete=true" +
> "&include=.*\\.xml\\Z" +
> "&passiveMode=true" +
> "&binary=true" +
> "&stepwise=false" +
> "&autoCreate=false" +
> "&disconnect=true" +
> "&maxMessagesPerPoll=100" +
> "&maximumReconnectAttempts=3" +
> "&reconnectDelay=600000" +
> "&scheduler=quartz" +
> "&scheduler.cron=0 0/30 * * * ?" +
> "&localWorkDirectory=localpath" +
> "&preSort=true" +
> "&sorter=#fileSorter";
>
> I don't know why maximumReconnectAttempts and reconnectDelay were added and
> they might be related to the issue since they could keep a filename in
> memory. I have now removed those two and added fileExist and moveExisting to
> the two producers to avoid losing data.
>
>
> Logs:
> The handling of the below logs has led to:
> The content of Test11.xml has been replaced by Test6.xml The content
> of Test13.xml has been replaced by Test11.xml The content of
> Test14.xml has been replaced by Test12.xml
>
> I did a bit of cleanup to avoid too much repetition:
>
> 2021-06-17 01:30:00,015 [DEBUG]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.RemoteFileConsumer.connectIfNe
> cessary]: Exception checking connection status: File operation failed:
> null Connection is not open. Code: 221
> 2021-06-17 01:30:00,015 [DEBUG]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.RemoteFileConsumer.connectIfNe
> cessary]: Not connected/logged in, connecting to:
> ftps://u...@example.com:1234
> 2021-06-17 01:30:09,312 [DEBUG]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.RemoteFileConsumer.connectIfNe
> cessary]: Connected and logged in to: ftps://u...@example.com:1234
> 2021-06-17 01:30:09,577 [WARN ] (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error processing
> file RemoteFile[Test1.xml] due to File operation failed: 150 File status
> okay; about to open data connection.
> Couldn't kickstart handshaking. Code: 150. Caused by:
> [org.apache.camel.component.file.GenericFileOperationFailedException - File
> operation failed: 150 File status okay; about to open data connection.
> Couldn't kickstart handshaking. Code: 150]
> org.apache.camel.component.file.GenericFileOperationFailedException: File
> operation failed: 150 File status okay; about to open data connection.
> Couldn't kickstart handshaking. Code: 150
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFileToFileInLocalWorkDirectory(FtpOperations.java:629)
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFile(FtpOperations.java:416)
> at
> org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:435)
> at
> org.apache.camel.component.file.remote.RemoteFileConsumer.processExchange(RemoteFileConsumer.java:147)
> at
> org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:240)
> at
> org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:201)
> at
> org.apache.camel.support.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:190)
> at
> org.apache.camel.support.ScheduledPollConsumer.run(ScheduledPollConsumer.java:107)
> at
> org.apache.camel.pollconsumer.quartz.QuartzScheduledPollConsumerJob.execute(QuartzScheduledPollConsumerJob.java:61)
> at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
> at
> org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.ja
> va:573) Caused by: javax.net.ssl.SSLException: Couldn't kickstart
> handshaking
> at sun.security.ssl.Alert.createSSLException(Alert.java:127)
> at sun.security.ssl.TransportContext.fatal(TransportContext.java:324)
> at sun.security.ssl.TransportContext.fatal(TransportContext.java:267)
> at
> sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:397)
> at
> org.apache.commons.net.ftp.FTPSClient._openDataConnection_(FTPSClient.java:641)
> at
> org.apache.commons.net.ftp.FTPClient._retrieveFile(FTPClient.java:1896)
> at
> org.apache.commons.net.ftp.FTPClient.retrieveFile(FTPClient.java:1882)
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFileToFileInLocalWorkDirectory(FtpOperations.java:602)
> ... 10 common frames omitted
> Suppressed: java.net.SocketException: Connection reset by peer:
> socket write error
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> at
> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
> at
> java.net.SocketOutputStream.write(SocketOutputStream.java:155)
> at
> sun.security.ssl.SSLSocketOutputRecord.encodeAlert(SSLSocketOutputRecord.java:81)
> at
> sun.security.ssl.TransportContext.fatal(TransportContext.java:355)
> ... 16 common frames omitted Caused by:
> java.net.SocketException: Connection reset by peer: socket write error
> at java.net.SocketOutputStream.socketWrite0(Native Method)
> at
> java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
> at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
> at
> sun.security.ssl.SSLSocketOutputRecord.flush(SSLSocketOutputRecord.java:251)
> at
> sun.security.ssl.HandshakeOutStream.flush(HandshakeOutStream.java:89)
> at
> sun.security.ssl.ClientHello$ClientHelloKickstartProducer.produce(ClientHello.java:580)
> at sun.security.ssl.SSLHandshake.kickstart(SSLHandshake.java:500)
> at
> sun.security.ssl.ClientHandshakeContext.kickstart(ClientHandshakeContext.java:107)
> at
> sun.security.ssl.TransportContext.kickstart(TransportContext.java:231)
> at
> sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:387)
> ... 14 common frames omitted
> 2021-06-17 01:35:09,577 [WARN ] (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error processing
> file RemoteFile[Test2.xml] due to File operation failed: Read timed out.
> Code: 150.
> org.apache.camel.component.file.GenericFileOperationFailedException: File
> operation failed: Read timed out. Code: 150
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFileToFileInLocalWorkDirectory(FtpOperations.java:629)
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFile(FtpOperations.java:416)
> at
> org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:435)
> at
> org.apache.camel.component.file.remote.RemoteFileConsumer.processExchange(RemoteFileConsumer.java:147)
> at
> org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:240)
> at
> org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:201)
> at
> org.apache.camel.support.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:190)
> at
> org.apache.camel.support.ScheduledPollConsumer.run(ScheduledPollConsumer.java:107)
> at
> org.apache.camel.pollconsumer.quartz.QuartzScheduledPollConsumerJob.execute(QuartzScheduledPollConsumerJob.java:61)
> at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
> at
> org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.ja
> va:573) Caused by: java.net.SocketTimeoutException: Read timed out
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> at java.net.SocketInputStream.read(SocketInputStream.java:171)
> at java.net.SocketInputStream.read(SocketInputStream.java:141)
> at
> sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:457)
> at
> sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:68)
> at
> sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1095)
> at sun.security.ssl.SSLSocketImpl.access$200(SSLSocketImpl.java:72)
> at
> sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:815)
> at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
> at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
> at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
> at java.io.InputStreamReader.read(InputStreamReader.java:184)
> at java.io.BufferedReader.fill(BufferedReader.java:161)
> at java.io.BufferedReader.readLine(BufferedReader.java:324)
> at java.io.BufferedReader.readLine(BufferedReader.java:389)
> at org.apache.commons.net.ftp.FTP.__getReply(ftp://FTP.java:320)
> at org.apache.commons.net.ftp.FTP.__getReply(ftp://FTP.java:299)
> at org.apache.commons.net.ftp.FTP.sendCommand(ftp://FTP.java:522)
> at
> org.apache.commons.net.ftp.FTPSClient.sendCommand(FTPSClient.java:563)
> at org.apache.commons.net.ftp.FTP.sendCommand(ftp://FTP.java:644)
> at org.apache.commons.net.ftp.FTP.sendCommand(ftp://FTP.java:618)
> at org.apache.commons.net.ftp.FTP.pasv(ftp://FTP.java:1041)
> at
> org.apache.commons.net.ftp.FTPClient._openDataConnection_(FTPClient.java:896)
> at
> org.apache.commons.net.ftp.FTPSClient._openDataConnection_(FTPSClient.java:622)
> at
> org.apache.commons.net.ftp.FTPClient._retrieveFile(FTPClient.java:1896)
> at
> org.apache.commons.net.ftp.FTPClient.retrieveFile(FTPClient.java:1882)
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFileToFileInLocalWorkDirectory(FtpOperations.java:602)
> ... 10 common frames omitted
> 2021-06-17 01:40:09,577 [WARN ] (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error processing
> file RemoteFile[Test3.xml] due to File operation failed: Read timed out.
> Code: 150.
> org.apache.camel.component.file.GenericFileOperationFailedException: File
> operation failed: Read timed out. Code: 150
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFileToFileInLocalWorkDirectory(FtpOperations.java:629)
> ...
> 2021-06-17 01:40:09,671 [WARN ]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error
> processing file RemoteFile[Test4.xml] due to Cannot retrieve file
> org.apache.camel.component.file.GenericFileOperationFailedException: Cannot
> retrieve file: RemoteFile[Test4.xml] from: ftps://example.com:1234...
> at
> org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:457)
> at
> org.apache.camel.component.file.remote.RemoteFileConsumer.processExchange(RemoteFileConsumer.java:147)
> at
> org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:240)
> at
> org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:201)
> at
> org.apache.camel.support.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:190)
> at
> org.apache.camel.support.ScheduledPollConsumer.run(ScheduledPollConsumer.java:107)
> at
> org.apache.camel.pollconsumer.quartz.QuartzScheduledPollConsumerJob.execute(QuartzScheduledPollConsumerJob.java:61)
> at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
> at
> org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.ja
> va:573)
> 2021-06-17 01:40:12,718 [WARN ]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error
> processing file RemoteFile[Test5.xml] due to Cannot retrieve file
> org.apache.camel.component.file.GenericFileOperationFailedException: Cannot
> retrieve file: RemoteFile[Test5.xml] from: ftps://example.com:1234...
> ...
> 2021-06-17 01:40:12,718 [WARN ]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error
> processing file RemoteFile[Test6.xml] due to Cannot retrieve file
> org.apache.camel.component.file.GenericFileOperationFailedException: Cannot
> retrieve file: RemoteFile[Test6.xml] from: ftps://example.com:1234...
> ...
> 2021-06-17 01:40:12,734 [WARN ]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error
> processing file RemoteFile[Test7.xml] due to Cannot retrieve file
> org.apache.camel.component.file.GenericFileOperationFailedException: Cannot
> retrieve file: RemoteFile[Test7.xml] from: ftps://example.com:1234...
> ...
> 2021-06-17 01:45:12,749 [WARN ] (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error processing
> file RemoteFile[Test8.xml] due to File operation failed: Read timed out.
> Code: 150.
> org.apache.camel.component.file.GenericFileOperationFailedException: File
> operation failed: Read timed out. Code: 150
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFileToFileInLocalWorkDirectory(FtpOperations.java:629)
> ...
> 2021-06-17 01:50:12,749 [WARN ] (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error processing
> file RemoteFile[Test9.xml] due to File operation failed: Read timed out.
> Code: 150.
> org.apache.camel.component.file.GenericFileOperationFailedException: File
> operation failed: Read timed out. Code: 150
> at
> org.apache.camel.component.file.remote.FtpOperations.retrieveFileToFileInLocalWorkDirectory(FtpOperations.java:629)
> ...
> 2021-06-17 01:50:12,827 [WARN ]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error
> processing file RemoteFile[Test10.xml] due to Cannot retrieve file
> org.apache.camel.component.file.GenericFileOperationFailedException: Cannot
> retrieve file: RemoteFile[Test10.xml] from: ftps://example.com:1234...
> at
> org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:457)
> ...
> 2021-06-17 01:50:22,030 [DEBUG]
> (DefaultQuartzScheduler-camel-1_Worker-1) [route.ftp-download]:
> Retrieving file from FTP: Test11.xml
> 2021-06-17 01:50:22,046 [INFO ]
> (DefaultQuartzScheduler-camel-1_Worker-1) [route.ftp-download]:
> Inbound file archived and sent to handling: Test11.xml
> 2021-06-17 01:50:22,187 [WARN ]
> (DefaultQuartzScheduler-camel-1_Worker-1)
> [org.apache.camel.component.file.remote.FtpConsumer.log]: Error
> processing file RemoteFile[Test12.xml] due to Cannot retrieve file
> org.apache.camel.component.file.GenericFileOperationFailedException: Cannot
> retrieve file: RemoteFile[Test12.xml] from: ftps://example.com:1234...
> at
> org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:457)
> ...
> 2021-06-17 01:50:22,359 [DEBUG]
> (DefaultQuartzScheduler-camel-1_Worker-1) [route.ftp-download]:
> Retrieving file from FTP: Test13.xml.xml
> 2021-06-17 01:50:22,359 [INFO ]
> (DefaultQuartzScheduler-camel-1_Worker-1) [route.ftp-download]:
> Inbound file archived and sent to handling: Test13.xml.xml
> 2021-06-17 01:50:22,531 [DEBUG]
> (DefaultQuartzScheduler-camel-1_Worker-1) [route.ftp-download]:
> Retrieving file from FTP: Test14.xml
> 2021-06-17 01:50:22,531 [INFO ]
> (DefaultQuartzScheduler-camel-1_Worker-1) [route.ftp-download]:
> Inbound file archived and sent to handling: Test14.xml
>
>
>
> Kind regards
>
> Carsten Bülow
--
Claus Ibsen
-----------------
http://davsclaus.com @davsclaus
Camel in Action 2: https://www.manning.com/ibsen2
