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
