Out of Memory Error with edtFTPjPro 1.3.3

Question

Hi.

We are experiencing OOM error since a while on our server. We use your software (since 2006) as an embeeded component to SFTP files from a server.
Once in a while we see occurence of this problem. Unfortunatly I haven't been able to corrolate this problem to any cause.

As you can see in the javacore below, the OOM occurs when 1gig is requested by one of your class. My assumptions now are either :

1. Encryption/Decryption cause the data to be "inflated" in gigantic proportion ; or
2. Our FTP server sends corrupted message to FTP client

Here are some informations

* edtFTPjPro version: 1.3.3
* JVM vendor : IBM
* JVM version : 1.5
* Processor arch : 64 bits

JAVACORE :

NULL           ------------------------------------------------------------------------
0SECTION       TITLE subcomponent dump routine
NULL           ===============================
1TISIGINFO     Dump Event "throw" (00000010) Detail "java/lang/OutOfMemoryError" received 
1TIDATETIME    Date:                 2009/05/04 at 19:34:10
1TIFILENAME    Javacore filename:    /core_files/javacore.20090504.193202.401524.0004.txt
NULL           ------------------------------------------------------------------------
0SECTION       GPINFO subcomponent dump routine
NULL           ================================
2XHOSLEVEL     OS Level         : AIX 5.3
2XHCPUS        Processors -
3XHCPUARCH       Architecture   : ppc64
3XHNUMCPUS       How Many       : 4
NULL           
1XHERROR2      Register dump section only produced for SIGSEGV, SIGILL or SIGFPE.
NULL           
NULL           ------------------------------------------------------------------------
0SECTION       ENVINFO subcomponent dump routine
NULL           =================================
1CIJAVAVERSION J2RE 5.0 IBM J9 2.3 AIX ppc64-64 build j9vmap6423ifx-20080811
1CIVMVERSION   VM build 20080809_21892_BHdSMr
1CIJITVERSION  JIT enabled - 20080620_1845_r8
1CIRUNNINGAS   Running as a standalone JVM
1CIJAVAHOMEDIR Java Home Dir:   /usr/java5_64/jre
1CIJAVADLLDIR  Java DLL Dir:    /usr/java5_64/jre/bin
1CISYSCP       Sys Classpath:   /usr/java5_64/jre/lib/vm.jar;
         /usr/java5_64/jre/lib/core.jar;
         /usr/java5_64/jre/lib/charsets.jar;
         /usr/java5_64/jre/lib/graphics.jar;
         /usr/java5_64/jre/lib/security.jar;
         /usr/java5_64/jre/lib/ibmpkcs.jar;
         /usr/java5_64/jre/lib/ibmorb.jar;
         /usr/java5_64/jre/lib/ibmcfw.jar;
         /usr/java5_64/jre/lib/ibmorbapi.jar;
         /usr/java5_64/jre/lib/ibmjcefw.jar;
         /usr/java5_64/jre/lib/ibmjgssprovider.jar;
         /usr/java5_64/jre/lib/ibmjsseprovider2.jar;
         /usr/java5_64/jre/lib/ibmjaaslm.jar;
         /usr/java5_64/jre/lib/ibmcertpathprovider.jar;
         /usr/java5_64/jre/lib/server.jar;
         /usr/java5_64/jre/lib/xml.jar;
         /opt/wily/WbmAgent/wily/Agent.jar;
1CIUSERARGS    UserArgs:
2CIUSERARG               -Xjcl:jclscar_23
2CIUSERARG               -Dcom.ibm.oti.vm.bootstrap.library.path=/usr/java5_64/jre/bin
2CIUSERARG               -Dsun.boot.library.path=/usr/java5_64/jre/bin
2CIUSERARG               -Djava.library.path=/usr/java5_64/jre/bin:
                                                                /usr/java5_64/jre/bin:/usr/java5_64/jre/bin/classic:
                                                                /usr/java5_64/jre/bin:
                                                                /webmethods/wbmEDI/IntegrationServer/../common/lib:
                                                                /webmethods/wbmEDI/IntegrationServer/lib:
                                                                /appl/cyb_agent/r7:.:/appl/cyb_agent/r7:
                                                                /appl/cyb_agent/r7/jre/bin:
                                                                /appl/cyb_agent/r7/jre/bin/classic:
                                                                /usr/java5_64/jre/bin/j9vm:
                                                                /webmethods/wbmEDI/IntegrationServer/../common/lib:
                                                                /webmethods/wbmEDI/IntegrationServer/lib:
                                                                /usr/lib
2CIUSERARG               -Djava.home=/usr/java5_64/jre
2CIUSERARG               -Djava.ext.dirs=/usr/java5_64/jre/lib/ext
2CIUSERARG               -Duser.dir=/webmethods/wbmEDI/IntegrationServer
2CIUSERARG               _j2se_j9=70912 0x09001000A0190420
2CIUSERARG               vfprintf 0x0000000110001930
2CIUSERARG      &nbsp

Answer 1

Do you know what operation is being performed at the time? Could you post a source code snippet?

Also, there's been a huge number of fixes since 1.3.3 - you should consider upgrading to see if that fixes the problem.

http://www.enterprisedt.com/products/ed ... story.html

Answer 2

Bruce,

Thanks for your post. We are indeed considering to upgrade to a newer version. However I want to determine the cause of this OOM, so any help would be appreciated. As for the operation it performed at the time of the error, it is mostly a GET as beside the GET only CD and PWD are performed.

This is the code for connect.

            try {
                ftp = new com.enterprisedt.net.ftp.ssh.SSHFTPClient();
                if (debugThis) {
                    String msgText = "\nSSHFTPClient created";
                    message.append(msgText);
                    log.debug(msgText);
                }
                ftp.setRemoteHost(remoteHost);
                ftp.setRemotePort(Integer.parseInt(remoteHostPort));
                ftp.getValidator().loadKnownHosts(knownHostsFile);
                ftp.setAuthentication(user, password);
                ftp.connect();

                if (debugThis) {
                    String msgText = "\nSSHFTPClient connected";
                    message.append(msgText);
                    log.debug(msgText);
                }

                ftp.setType(FTPTransferType.ASCII);
                if (debugThis) {
                    String msgText = "\nSSH CONNECTION established";
                    message.append(msgText);
                    log.debug(msgText);
                }

                localStartPath = localdir;
                if (remotedirs.length > 1
                        || (remotedirs.length == 1 && (!(""
                                .equals(remotedirs[0])) && !(remotedirs[0] == null)))) {
                    if (debugThis) {
                        String msgText = "\nremotedirs loop in";
                        message.append(msgText);
                        log.debug(msgText);
                    }
                    for (int i = 0; i < remotedirs.length; i++) {
                        setLocalPath(localdir);
                        setRemotePath(remotedirs[i]);
                        int tempStatus = downloadAll(remotedirs[i], dodelete,
                                message);
                        if (tempStatus > status)
                            status = tempStatus;
                    }
                }
            } catch (Exception ex) {
                if (debugThis) {
                    if (log != null) {
                        log.error(ex.toString());
                    }
                    throw new ServiceException(ex.toString() + "\n"
                            + message.toString());
                } else {
                    throw new ServiceException(ex.toString());
                }
            } finally {
                if (ftp != null) {
                    try {
                        ftp.quit();
                        if (debugThis) {
                            message.append("sFtp connection closed");
                            log.debug("sFtp connection closed");
                        }

                    } catch (IOException ex) {
                        message.append(ex.toString());
                        log.debug(ex.toString());

                    } catch (FTPException ex) {
                        message.append(ex.toString());
                        log.debug(ex.toString());
                    }
                }
                if (log != null) {
                    Logger.shutdown();
                }
            }

This is the code for the GET (it is recursive)

 private int downloadDir(String dir, boolean doDelete, StringBuffer message) throws ParseException, 
&nb

Answer 3

I've looked at the code from this version and compared it to the current version.

There are some differences that could possibly account for the problem you are experiencing but I can't be sure.

We don't want to spend time diagnosing problems in old code (v 1.17 compared v 1.39) when the chances are that this has been fixed over the last three years.

If you are able to upgrade and can replicate the problem then we know we have a problem that needs resolving asap.

Answer 4

We have upgraded to the latest version, so far we haven't experienced any out of memory error but now we have problem with connect() :

We see the following as well as time-out on the connect().

Have you any hints for me ?

Local identification: SSH-2.0-edtFTPjPRO-3.0.2
DEBUG [TransportProtocolCommon] 4 Jun 2009 15:48:13.399 : EOL is guessed at LF
DEBUG [TransportProtocolCommon] 4 Jun 2009 15:48:13.399 : Remote identification: '???????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????'
ERROR [TransportProtocolCommon] 4 Jun 2009 15:48:13.400 : The Transport Protocol thread failed : String index out of range: -1
java.lang.StringIndexOutOfBoundsException: String index out of range: -1
   at java.lang.String.substring(String.java:1938)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.A(Unknown Source)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.run(Unknown Source)
   at java.lang.Thread.run(Thread.java:619)

com.enterprisedt.net.j2ssh.transport.TransportProtocolException: The connection did not complete
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolClient.onStartTransportProtocol(Unknown Source)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.startTransportProtocol(Unknown Source)
   at com.enterprisedt.net.j2ssh.SshClient.connect(Unknown Source)
   at com.enterprisedt.net.ftp.ssh.SCPClient.connectSSH(Unknown Source)
   at com.enterprisedt.net.ftp.ssh.SSHFTPClient.connect(Unknown Source)
   at com.cn.wm.sftp.testSFTP.main(testSFTP.java:38)
com.enterprisedt.net.ftp.ssh.SSHFTPException: The SSH client has not yet connected to the server.  The requested action cannot be performed until after a connection has been established.
java.lang.StringIndexOutOfBoundsException: String index out of range: -1
   at java.lang.String.substring(String.java:1938)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.A(Unknown Source)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.run(Unknown Source)
   at java.lang.Thread.run(Thread.java:619)
DEBUG [TransportProtocolCommon] 4 Jun 2009 15:48:13.401 : stop() called
DEBUG [TransportProtocolCommon] 4 Jun 2009 15:48:13.402 : The Transport Protocol has been stopped

   at com.enterprisedt.net.ftp.ssh.SCPClient.checkConnection(Unknown Source)
   at com.enterprisedt.net.ftp.ssh.SSHFTPClient.quit(Unknown Source)
   at com.cn.wm.sftp.testSFTP.main(testSFTP.java:62)

[/code]

Answer 5

The fact that the server is returning an identification string of "??????" hints that it isn't actually an SFTP server. SFTP servers usually return something like "SSH-2.0-CompleteFTP-2.2.0'".

Can you connect to it using other SFTP clients, such as FileZilla or WinSCP?

- Hans (EnterpriseDT)

Answer 6

Sorry for the confusion, I must have said that most of time we have, eg . everything works fine :

DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:10.077 : Registering transport protocol messages with inputstream
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:10.079 : Negotiating protocol version
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:10.079 : Local identification: SSH-2.0-edtFTPjPRO-3.0.2
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:10.091 : EOL is guessed at LF
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:10.091 : Remote identification: 'SSH-2.0-OpenSSH_3.8p1'
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:10.091 : Protocol negotiation complete

but once in a while we get an error :

DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:11.537 : Negotiating protocol version
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:11.537 : Local identification: SSH-2.0-edtFTPjPRO-3.0.2
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:11.542 : EOL is guessed at LF
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:11.543 : Remote identification: '???????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????????'
ERROR [TransportProtocolCommon] 5 Jun 2009 09:22:11.544 : The Transport Protocol thread failed : String index out of range: -1
java.lang.StringIndexOutOfBoundsException: String index out of range: -1
   at java.lang.String.substring(String.java:1938)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.A(Unknown Source)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.run(Unknown Source)
   at java.lang.Thread.run(Thread.java:619)


java.lang.StringIndexOutOfBoundsException: String index out of range: -1
   at java.lang.String.substring(String.java:1938)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.A(Unknown Source)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.run(Unknown Source)
   at java.lang.Thread.run(Thread.java:619)
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:11.549 : stop() called
DEBUG [TransportProtocolCommon] 5 Jun 2009 09:22:11.550 : The Transport Protocol has been stopped
com.enterprisedt.net.j2ssh.transport.TransportProtocolException: The connection did not complete
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolClient.onStartTransportProtocol(Unknown Source)
   at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.startTransportProtocol(Unknown Source)
   at com.enterprisedt.net.j2ssh.SshClient.connect(Unknown Source)
   at com.enterprisedt.net.ftp.ssh.SCPClient.connectSSH(Unknown Source)
   at com.enterprisedt.net.ftp.ssh.SSHFTPClient.connect(Unknown Source)
   at com.cn.wm.sftp.testSFTP.main(testSFTP.java:38)

Regards[/code]

Answer 7

It surely looks like a server problem - the first thing it needs to do upon client connection is return a version string as described above, but for some weird reason it is returning '??????????????????.....'

The client has to parse this string to figure out what SSH version is supported so there's no way it can succeed.

The best we can do with this problem is to throw a more sensible exception - we can do a patch for that if you like. You should consult your server administrator to ask why it is returning such a weird string (e.g. is there anything in the logs that might explain it?).

Some details on the type of server might help in diagnosing the problem.

Answer 8

Bruce,

the server is : ProFTPD 1.2.10rc3.

Regards,

Answer 9

We've made a patch to resolve this - email us at support at enterprisedt dot com if you'd like to try it out.

Answer 10

Hi we upgraded last October to the latest version availlable at the time and we haven't experience any OOM since. Yesterday we had our first OOM...

The current version of EDT is :
Class: com.enterprisedt.net.ftp.ssh.SSHFTPClient
Location: file:/webmethods/wbmEDI/IntegrationServer/lib/jars/edtftpj-pro.jar
Version: 3.0.2
Build timestamp: 11-May-2009 10:05:47 EST
Java version: 1.5.0
CLASSPATH: ::/usr/java5_64/jre/lib/i18n.jar:/webmethods/wbmEDI/IntegrationServer/lib/wm-isproxy.jar:/webmethods/wbmEDI/IntegrationServer/../common/lib/wm-converters.jar:/webmethods/wbmEDI/IntegrationServer/config/Caching:
OS name: AIX
OS arch: ppc64
OS version: 5.3

Here is a fragment of the javacore file :

1STGCHTYPE     GC History  
3STHSTTYPE     16:20:09:865626000 GMT j9mm.126 -   at 00000001166D78D0 java/lang/Thread.run()V, jit 0000000116176DDC, pc 000000011FD7ACAC 
3STHSTTYPE     16:20:09:865619000 GMT j9mm.126 -   at 000000011F1FF128 com/enterprisedt/net/j2ssh/transport/TransportProtocolCommon.run()V, jit 0000000115FE8500, pc 0000000115B9570C 
3STHSTTYPE     16:20:09:865613000 GMT j9mm.126 -   at 000000011F1FF5A8 com/enterprisedt/net/j2ssh/transport/TransportProtocolCommon.startBinaryPacketProtocol()V, jit 0000000115FE9228, pc 0000000115B96F14 
3STHSTTYPE     16:20:09:865608000 GMT j9mm.126 -   at 000000011F1FF708 com/enterprisedt/net/j2ssh/transport/TransportProtocolCommon.processMessages()Lcom/enterprisedt/net/j2ssh/transport/SshMessage;, jit 0000000115FE9C88, pc 0000000115B98488 
3STHSTTYPE     16:20:09:865602000 GMT j9mm.126 -   at 000000011F1DF910 com/enterprisedt/net/j2ssh/transport/A.B()[B, jit 0000000115FEA458, pc 0000000115B99884 
3STHSTTYPE     16:20:09:865594000 GMT j9mm.126 -   at 0000000116A690B8 java/io/ByteArrayOutputStream.write([BII)V, jit 0000000115D3E380, pc 0000000115581160 
3STHSTTYPE     16:20:09:865580000 GMT j9mm.101 -   J9AllocateIndexableObject() returning NULL! 1073741848 bytes requested for object of class 00000001166A2200 from memory space '' id=0000000000000000 
3STHSTTYPE     16:20:09:858792000 GMT j9mm.53 -   GlobalGC end: workstackoverflow=0 overflowcount=0 weakrefs=2164338 soft=846 phantom=0 finalizers=2414 newspace=59632056/60397568 oldspace=503759176/4227858432 loa=0/0 

Many Thanks