Timeout too long, but not sure which timeout?

Question

We are using version 3.5 of edtj-PRO. We have just discovered that at any given time, there are several threads that are simply hanging due to (what seems to be) waiting for disconnection.

Here is the classes that are currently waiting to timeout, and therefore disconnect and release their resources. Please note that this is not an exception trace, but a current stack trace from a running thread. At the time of this writing, there are 7 threads with exactly the same trace, for a job that runs twice an hour, and where the last one completed over 20 minutes ago.

java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
com.enterprisedt.net.ftp.async.AsyncResult.waitTillComplete(Unknown Source)
com.enterprisedt.net.ftp.async.AsyncResult.endAsyncInternal(Unknown Source)
com.enterprisedt.net.ftp.async.DisconnectResult.endAsync(Unknown Source)
com.enterprisedt.net.ftp.SecureFileTransferClient.disconnect(Unknown Source)
com.planetenergy.transaction.batch.tasklet.FTPTasklet.disconnectFTP(FTPTasklet.java:50)
com.planetenergy.transaction.batch.tasklet.FTPTasklet.execute(FTPTasklet.java:176)
org.springframework.batch.core.step.tasklet.TaskletStep.doExecute(TaskletStep.java:98)
org.springframework.batch.core.step.AbstractStep.execute(AbstractStep.java:172)

Its the call to disconnect() that prompts the hang. We have setup our logging to see the basic FTP commands being sent, and there is nothing after disconnect() is called. I should note that this is the common case, as about 20% of the time the QUIT command is indeed sent (closing the thread successfully).

We are assuming that these threads DO time out, but that it's taking too long. Unfortunately, we don't have any idea which timeout it might be. Could anyone shed any light on this? There are many other options in the API we could try, such as disconnect(immediately = true), but we're trying to figure out the correct solution first.

Any help is appreciated.

Answer 1

The best thing to do here is to enable logging at the debug level, and send us the zipped log at support at enterprisedt dot com. The log should tell us why this call isn't completing.

Answer 2

Fair enough. Here is the log of a single FTP run, that has hung and presents the thread state as listed above. This one happens to be an upload, but we see exactly the same thing happen (or not happen) with a download.

2011-03-08 15:15:00,795 DEBUG [com.planetenergy.transaction.batch.tasklet.FTPTasklet] FTP2.ecinfosystems.com -------> Creating FTP client..
2011-03-08 15:15:00,796 DEBUG [com.planetenergy.transaction.batch.tasklet.FTPTasklet] FTP2.ecinfosystems.com -------> Protocol set to SFTP
2011-03-08 15:15:00,796 DEBUG [com.planetenergy.transaction.batch.tasklet.FTPTasklet] FTP2.ecinfosystems.com -------> Connect mode set to ACTIVE
2011-03-08 15:15:00,796 INFO  [com.planetenergy.transaction.batch.tasklet.FTPTasklet] FTP2.ecinfosystems.com -------> Connecting ...
2011-03-08 15:15:01,099 DEBUG [com.enterprisedt.net.j2ssh.transport.cipher.SshCipherFactory] Creating new 3des-cbc cipher instance
2011-03-08 15:15:01,100 DEBUG [com.enterprisedt.net.j2ssh.transport.cipher.SshCipherFactory] Creating new 3des-cbc cipher instance
2011-03-08 15:15:01,360 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Starting sftp subsystem
2011-03-08 15:15:01,393 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_INIT subsystem message
2011-03-08 15:15:01,458 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_REALPATH subsystem message
2011-03-08 15:15:01,497 INFO  [com.planetenergy.transaction.batch.tasklet.FTPTasklet] FTP2.ecinfosystems.com -------> Connected
2011-03-08 15:15:01,747 DEBUG [com.enterprisedt.net.j2ssh.transport.cipher.SshCipherFactory] Creating new 3des-cbc cipher instance
2011-03-08 15:15:01,748 DEBUG [com.enterprisedt.net.j2ssh.transport.cipher.SshCipherFactory] Creating new 3des-cbc cipher instance
2011-03-08 15:15:01,947 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Starting sftp subsystem
2011-03-08 15:15:01,987 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_INIT subsystem message
2011-03-08 15:15:02,028 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_REALPATH subsystem message
2011-03-08 15:15:02,069 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_REALPATH subsystem message
2011-03-08 15:15:02,163 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_OPENDIR subsystem message
2011-03-08 15:15:02,200 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_STAT subsystem message
2011-03-08 15:15:02,793 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_CLOSE subsystem message
2011-03-08 15:15:02,835 DEBUG [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] calling startTransfer() in FtpUploadTasklet........
2011-03-08 15:15:02,835 DEBUG [com.planetenergy.transaction.batch.tasklet.UploadTasklet] Filtering file for *.xml
2011-03-08 15:15:02,836 INFO  [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] found file on server: 2
2011-03-08 15:15:02,836 INFO  [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] Uploading file: 20110308WCRJ66J.xml
2011-03-08 15:15:02,836 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_REALPATH subsystem message
2011-03-08 15:15:02,882 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_OPENDIR subsystem message
2011-03-08 15:15:02,924 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_STAT subsystem message
2011-03-08 15:15:02,966 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_CLOSE subsystem message
2011-03-08 15:15:03,003 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_STAT subsystem message
2011-03-08 15:15:03,044 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_OPEN subsystem message
2011-03-08 15:15:03,094 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_WRITE subsystem message
2011-03-08 15:15:03,222 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_CLOSE subsystem message
2011-03-08 15:15:03,262 INFO  [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] File uploading complete: 20110308WCRJ66J.xml
2011-03-08 15:15:03,262 INFO  [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] Trying to verify file, Try : 1
2011-03-08 15:15:03,263 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_STAT subsystem message
2011-03-08 15:15:03,307 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_OPEN subsystem message
2011-03-08 15:15:03,351 INFO  [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] remote stream collected
2011-03-08 15:15:03,351 INFO  [com.planetenergy.transaction.util.FileVerificationUtil] in verify()
2011-03-08 15:15:03,351 INFO  [com.planetenergy.transaction.util.FileVerificationUtil] in verifySHA1()
2011-03-08 15:15:03,352 INFO  [com.planetenergy.transaction.util.FileVerificationUtil] sha1HashLocal : 5d2c7a774e2059b57bf8bdf51694e5b0a33aa32d
2011-03-08 15:15:03,352 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,406 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,452 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,495 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,545 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,592 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,641 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,693 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,741 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,791 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,836 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_READ subsystem message
2011-03-08 15:15:03,872 INFO  [com.planetenergy.transaction.util.FileVerificationUtil] sha1Hashremote: 5d2c7a774e2059b57bf8bdf51694e5b0a33aa32d
2011-03-08 15:15:03,872 INFO  [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] PASSED!
2011-03-08 15:15:03,872 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_CLOSE subsystem message
2011-03-08 15:15:03,914 DEBUG [com.enterprisedt.net.j2ssh.subsystem.SubsystemChannel] Sending SSH_FXP_RENAME subsystem message
2011-03-08 15:15:03,970 INFO  [com.planetenergy.transaction.batch.tasklet.UploadTasklet] Archived local file: /opt/job-queues/createNyXMLTransactionJob/input/20110308WCRJ66J.xml after upload to FTP2.ecinfosystems.com
2011-03-08 15:15:03,970 INFO  [com.planetenergy.transaction.batch.tasklet.FtpUploadTasklet] Uploading file: 201103080X3EUBD.xml
2011-03-08 15:15:03,971 DEBUG &#91

Answer 3

Hmm, there's not much info in that log.

I think the best thing to do if possible is to add some extra logging in the disconnect() method and send you the jar file. Are you able to run a new jar file?

Answer 4

In theory, I have no problem with that.

I will of course assume that any 'custom' jar will have been tested to within an inch of it's life, just like any other version release?

Let's move to direct email communication. Please email to jpress at planetenergy dot ca.

Thanks.

Answer 5

Email sent.