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.connectIfNecessary]:
> 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.connectIfNecessary]:
> 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.connectIfNecessary]:
> 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.java: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.java: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.java: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
