Announcement Announcement Module
Collapse
No announcement yet.
File removed before SFTP gets to it; MessageDeliveryException, FileNotFoundException Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • File removed before SFTP gets to it; MessageDeliveryException, FileNotFoundException

    I have a class receiving a report object in the message body then putting it on the appropriate channels based on a database profile for the client. The report might go onto a channel to an email adapter, another channel to a ftp adapter, or to a SFTP adapter, but also always goes to an ftp adapter and is sent to an archive folder hierarchy.

    The channel to the SFTP adapter is the new part, and it seems like some automatic file cleanup is taking place that's removing a temp file before the authentication is complete. I'm guessing it may be happening when the archive is complete. The application is passing byte[] around, not writing files, so the missing file shown in the log snip below is apparently created by the framework and removed by the framework.

    How can I guarantee the byte[] sent to the SFTP channel is going to be available when it's ready to send?


    [2013-07-16 17:50:19,290|INFO|CLTEST|225] Requisition: 11999781 ReportRouter class has been called. Step: ReportRouter handleMessage
    [2013-07-16 17:50:19,290|INFO|CLTEST|225] Requisition: 11999781 Initiating sftpReport for file: scsv_TEST_11999781_071620131750.csv on channel: sftpCBAChannel Step: ReportRouter sftpReport
    [2013-07-16 17:50:19,291|INFO|CLTEST|225] Requisition: 11999781 Report scsv_TEST_11999781_071620131750.csv for customer TEST sent to SFTP channel: sftpCBAChannel Step: ReportRouter sftpReport
    [2013-07-16 17:50:19,291|INFO|CLTEST|225] Requisition: 11999781 Report scsv_TEST_11999781_071620131750.csv for customer TEST sent to \CLTest\dev\ArchivedReports\TEST Step: ReportRouter sendReportLocal
    [2013-07-16 17:50:19,291|INFO|CLTEST|225] Requisition: 11999781 Completed routing for report scsv_TEST_11999781_071620131750.csv. Step: ReportRouter log
    [2013-07-16 17:50:19,364|INFO|jcraft.jsch|52] Connecting to testSFTPServer02 port 22
    [2013-07-16 17:50:19,372|INFO|jcraft.jsch|52] Connection established
    [2013-07-16 17:50:19,375|INFO|jcraft.jsch|52] Remote version string: SSH-2.0-WeOnlyDo 2.2.9
    [2013-07-16 17:50:19,377|INFO|jcraft.jsch|52] Local version string: SSH-2.0-JSCH-0.1.50
    [2013-07-16 17:50:19,378|INFO|jcraft.jsch|52] CheckCiphers: aes256-ctr,aes192-ctr,aes128-ctr,aes256-cbc,aes192-cbc,aes128-cbc,3des-ctr,arcfour,arcfour128,arcfour256
    [2013-07-16 17:50:19,387|INFO|session.FtpSession|85] File has been successfully transfered to: \CLTest\dev\ArchivedReports\TEST\ccsv_TEST_1199978 1_071620131750.csv.writing
    [2013-07-16 17:50:19,391|INFO|session.FtpSession|118] File has been successfully renamed from: \CLTest\dev\ArchivedReports\TEST\ccsv_TEST_1199978 1_071620131750.csv.writing to \CLTest\dev\ArchivedReports\TEST\ccsv_TEST_1199978 1_071620131750.csv
    [2013-07-16 17:50:19,435|INFO|session.FtpSession|85] File has been successfully transfered to: \CLTest\dev\ArchivedReports\TEST\scsv_TEST_1199978 1_071620131750.csv.writing
    [2013-07-16 17:50:19,439|INFO|session.FtpSession|118] File has been successfully renamed from: \CLTest\dev\ArchivedReports\TEST\scsv_TEST_1199978 1_071620131750.csv.writing to \CLTest\dev\ArchivedReports\TEST\scsv_TEST_1199978 1_071620131750.csv
    [2013-07-16 17:50:19,559|INFO|jcraft.jsch|52] CheckKexes: diffie-hellman-group14-sha1
    [2013-07-16 17:50:19,630|INFO|jcraft.jsch|52] SSH_MSG_KEXINIT sent
    [2013-07-16 17:50:19,631|INFO|jcraft.jsch|52] SSH_MSG_KEXINIT received
    [2013-07-16 17:50:19,632|INFO|jcraft.jsch|52] kex: server: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1
    [2013-07-16 17:50:19,633|INFO|jcraft.jsch|52] kex: server: ssh-rsa
    [2013-07-16 17:50:19,633|INFO|jcraft.jsch|52] kex: server: aes128-cbc,aes128-ctr,3des-cbc,blowfish-cbc,aes192-cbc,aes192-ctr,aes256-cbc,aes256-ctr,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,[email protected],cast128-cbc
    [2013-07-16 17:50:19,633|INFO|jcraft.jsch|52] kex: server: aes128-cbc,aes128-ctr,3des-cbc,blowfish-cbc,aes192-cbc,aes192-ctr,aes256-cbc,aes256-ctr,rijndael128-cbc,rijndael192-cbc,rijndael256-cbc,ri[email protected],cast128-cbc
    [2013-07-16 17:50:19,634|INFO|jcraft.jsch|52] kex: server: hmac-sha1,hmac-sha1-96,hmac-md5,none
    [2013-07-16 17:50:19,634|INFO|jcraft.jsch|52] kex: server: hmac-sha1,hmac-sha1-96,hmac-md5,none
    [2013-07-16 17:50:19,635|INFO|jcraft.jsch|52] kex: server: zlib,none
    [2013-07-16 17:50:19,635|INFO|jcraft.jsch|52] kex: server: zlib,none
    [2013-07-16 17:50:19,635|INFO|jcraft.jsch|52] kex: server:
    [2013-07-16 17:50:19,636|INFO|jcraft.jsch|52] kex: server:
    [2013-07-16 17:50:19,636|INFO|jcraft.jsch|52] kex: client: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha1
    [2013-07-16 17:50:19,637|INFO|jcraft.jsch|52] kex: client: ssh-rsa,ssh-dss
    [2013-07-16 17:50:19,637|INFO|jcraft.jsch|52] kex: client: aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-cbc,aes192-cbc,aes256-cbc
    [2013-07-16 17:50:19,637|INFO|jcraft.jsch|52] kex: client: aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-cbc,aes192-cbc,aes256-cbc
    [2013-07-16 17:50:19,638|INFO|jcraft.jsch|52] kex: client: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha1-96,hmac-md5-96
    [2013-07-16 17:50:19,638|INFO|jcraft.jsch|52] kex: client: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha1-96,hmac-md5-96
    [2013-07-16 17:50:19,639|INFO|jcraft.jsch|52] kex: client: none
    [2013-07-16 17:50:19,639|INFO|jcraft.jsch|52] kex: client: none
    [2013-07-16 17:50:19,639|INFO|jcraft.jsch|52] kex: client:
    [2013-07-16 17:50:19,640|INFO|jcraft.jsch|52] kex: client:
    [2013-07-16 17:50:19,640|INFO|jcraft.jsch|52] kex: server->client aes128-ctr hmac-md5 none
    [2013-07-16 17:50:19,641|INFO|jcraft.jsch|52] kex: client->server aes128-ctr hmac-md5 none
    [2013-07-16 17:50:19,683|INFO|jcraft.jsch|52] SSH_MSG_KEXDH_INIT sent
    [2013-07-16 17:50:19,684|INFO|jcraft.jsch|52] expecting SSH_MSG_KEXDH_REPLY
    [2013-07-16 17:50:19,747|INFO|jcraft.jsch|52] ssh_rsa_verify: signature true
    [2013-07-16 17:50:19,762|WARN|jcraft.jsch|55] Permanently added 'ngate-didsvr02' (RSA) to the list of known hosts.
    [2013-07-16 17:50:19,763|INFO|jcraft.jsch|52] SSH_MSG_NEWKEYS sent
    [2013-07-16 17:50:19,766|INFO|jcraft.jsch|52] SSH_MSG_NEWKEYS received
    [2013-07-16 17:50:19,786|INFO|jcraft.jsch|52] SSH_MSG_SERVICE_REQUEST sent
    [2013-07-16 17:50:19,789|INFO|jcraft.jsch|52] SSH_MSG_SERVICE_ACCEPT received
    [2013-07-16 17:50:19,796|INFO|jcraft.jsch|52] Authentications that can continue: password
    [2013-07-16 17:50:19,798|INFO|jcraft.jsch|52] Next authentication method: password
    [2013-07-16 17:50:19,806|INFO|jcraft.jsch|52] Authentication succeeded (password).
    [2013-07-16 17:50:19,877|INFO|CLTEST|225] Requisition: 11999781 Cust_No: TEST Reports (Profile): ResultReport_CSV ConfirmatoryCSV Step: CLTest.logging.DBLogger Status: SUCCESS Path: /CLTest/dev/transfer/history/TEST/R1201201TEST_BOTH_C_FINAL.201307161750 MessageId: b5a17447-d525-41cf-a3b2-47673e5a37fc Timestamp: 2013-07-16 17:50:19.876 Payload Type: class java.lang.String
    [2013-07-16 17:50:19,878|INFO|CLTEST|225] Output Files: [ccsv_TEST_11999781_071620131750.csv, scsv_TEST_11999781_071620131750.csv] [2013-07-16 17:50:19,956|ERROR|handler.LoggingHandler|126] org.springframework.integration.MessageDeliveryExc eption: File [/u1/tomcat/temp/ccsv_TEST_11999781_071620131750.csv.tmp] not found in local working directory; it was moved or deleted unexpectedly.
    at org.springframework.integration.file.remote.handle r.FileTransferringMessageHandler.handleMessageInte rnal(FileTransferringMessageHandler.java:139)
    at org.springframework.integration.handler.AbstractMe ssageHandler.handleMessage(AbstractMessageHandler. java:73)
    at org.springframework.integration.endpoint.PollingCo nsumer.doPoll(PollingConsumer.java:70)
    at org.springframework.integration.endpoint.AbstractP ollingEndpoint$1.call(AbstractPollingEndpoint.java :146)
    at org.springframework.integration.endpoint.AbstractP ollingEndpoint$1.call(AbstractPollingEndpoint.java :144)
    at org.springframework.integration.endpoint.AbstractP ollingEndpoint$Poller$1.run(AbstractPollingEndpoin t.java:207)
    at org.springframework.integration.util.ErrorHandling TaskExecutor$1.run(ErrorHandlingTaskExecutor.java: 52)
    at org.springframework.core.task.SyncTaskExecutor.exe cute(SyncTaskExecutor.java:48)
    at org.springframework.integration.util.ErrorHandling TaskExecutor.execute(ErrorHandlingTaskExecutor.jav a:49)
    at org.springframework.integration.endpoint.AbstractP ollingEndpoint$Poller.run(AbstractPollingEndpoint. java:202)
    at org.springframework.scheduling.support.DelegatingE rrorHandlingRunnable.run(DelegatingErrorHandlingRu nnable.java:53)
    at org.springframework.scheduling.concurrent.Reschedu lingRunnable.run(ReschedulingRunnable.java:81)
    at java.util.concurrent.Executors$RunnableAdapter.cal l(Executors.java:471)
    at java.util.concurrent.FutureTask$Sync.innerRun(Futu reTask.java:334)
    at java.util.concurrent.FutureTask.run(FutureTask.jav a:166)
    at java.util.concurrent.ScheduledThreadPoolExecutor$S cheduledFutureTask.access$101(ScheduledThreadPoolE xecutor.java:165)
    at java.util.concurrent.ScheduledThreadPoolExecutor$S cheduledFutureTask.run(ScheduledThreadPoolExecutor .java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker( ThreadPoolExecutor.java:1146)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:679)
    Caused by: java.io.FileNotFoundException: /u1/tomcat/temp/ccsv_TEST_11999781_071620131750.csv.tmp (No such file or directory)
    at java.io.FileInputStream.open(Native Method)
    at java.io.FileInputStream.<init>(FileInputStream.jav a:137)
    at org.springframework.integration.file.remote.handle r.FileTransferringMessageHandler.sendFileToRemoteD irectory(FileTransferringMessageHandler.java:220)
    at org.springframework.integration.file.remote.handle r.FileTransferringMessageHandler.handleMessageInte rnal(FileTransferringMessageHandler.java:136)
    ... 19 more
    Last edited by Gary Russell; Jul 17th, 2013, 07:37 AM.

  • #2
    It looks like you are using multi-threading (either pollers or ExecutorChannels).

    Hint: It is usually a good idea to include the thread name (%t in log4j) when debugging multi-threaded applications.

    I see FTP and SFTP activity concurrently.

    The adapters are both concurrently using the same temporary file during the transfer (adds .tmp).

    Please open a JIRA Issue for this; the adapters should use a randomized temporary filename to avoid this collision.

    The simplest work around would be to make sure the transfers happen serially (on the same thread) (SFTP after FTP, or vice versa) - don't use an async handoff to an ExecutorChannel.

    Another alternative might be to use a slightly different filename header in each message.

    Comment


    • #3
      You were right, naturally. I chose answer B, using a different file name for my archive channel. I will open a JIRA.

      Thanks for the tip on logging the thread. Here's how it looks now. No exceptions!

      Code:
      [2013-07-17  10:16:58,402|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  ReportRouter class has been called. Step: ReportRouter handleMessage
      [2013-07-17  10:16:58,403|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Initiating sftpReport for file: ccsv_TEST_11999781_071720131016.csv on  channel: sftpCBAChannel Step: ReportRouter sftpReport
      [2013-07-17  10:16:58,404|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Report ccsv_TEST_11999781_071720131016.csv for customer TEST sent to  SFTP channel: sftpCBAChannel Step: ReportRouter sftpReport
      [2013-07-17  10:16:58,404|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Report ccsv_TEST_11999781_071720131016.csv for customer TEST sent to  \CLTest\dev\ArchivedReports\TEST Step: ReportRouter sendReportLocal
      [2013-07-17  10:16:58,405|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Completed routing for report ccsv_TEST_11999781_071720131016.csv. Step:  ReportRouter log
      [2013-07-17  10:16:58,451|INFO|session.FtpSession|85|task-scheduler-10] File has been  successfully transfered to:  \CLTest\dev\ArchivedReports\TEST\_ccsv_TEST_11999781_071720131016.csv.writing
      [2013-07-17  10:16:58,454|INFO|session.FtpSession|118|task-scheduler-10] File has  been successfully renamed from:  \CLTest\dev\ArchivedReports\TEST\_ccsv_TEST_11999781_071720131016.csv.writing  to  \CLTest\dev\ArchivedReports\TEST\_ccsv_TEST_11999781_071720131016.csv
      [2013-07-17  10:16:58,754|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  ReportRouter class has been called. Step: ReportRouter handleMessage
      [2013-07-17  10:16:58,755|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Initiating sftpReport for file: scsv_TEST_11999781_071720131016.csv on  channel: sftpCBAChannel Step: ReportRouter sftpReport
      [2013-07-17  10:16:58,755|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Report scsv_TEST_11999781_071720131016.csv for customer TEST sent to  SFTP channel: sftpCBAChannel Step: ReportRouter sftpReport
      [2013-07-17  10:16:58,756|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Report scsv_TEST_11999781_071720131016.csv for customer TEST sent to  \CLTest\dev\ArchivedReports\TEST Step: ReportRouter sendReportLocal
      [2013-07-17  10:16:58,757|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Completed routing for report scsv_TEST_11999781_071720131016.csv. Step:  ReportRouter log
      [2013-07-17  10:16:58,783|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Exporter parameter - csv filename: ccsv_TEST_11999781_071720131016.csv  Step: ReportGen generate
      [2013-07-17  10:16:58,784|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Sending ccsv_TEST_11999781_071720131016.csv to router. Step: ReportGen  sendToRouter
      [2013-07-17  10:16:58,790|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Exporter parameter - csv filename: scsv_TEST_11999781_071720131016.csv  Step: ReportGen generate
      [2013-07-17  10:16:58,790|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Sending scsv_TEST_11999781_071720131016.csv to router. Step: ReportGen  sendToRouter
      [2013-07-17  10:16:58,791|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  Completed report generation. Step: ReportGen log
      [2013-07-17  10:16:58,791|INFO|CLTEST|225|task-scheduler-5] Requisition: 11999781  File names: [ccsv_TEST_11999781_071720131016.csv,  scsv_TEST_11999781_071720131016.csv] Step: ReportGen log
      [2013-07-17  10:16:58,795|INFO|session.FtpSession|85|task-scheduler-10] File has been  successfully transfered to:  \CLTest\dev\ArchivedReports\TEST\_scsv_TEST_11999781_071720131016.csv.writing
      [2013-07-17  10:16:58,798|INFO|session.FtpSession|118|task-scheduler-10] File has  been successfully renamed from:  \CLTest\dev\ArchivedReports\TEST\_scsv_TEST_11999781_071720131016.csv.writing  to  \CLTest\dev\ArchivedReports\TEST\_scsv_TEST_11999781_071720131016.csv

      Comment

      Working...
      X