12 Replies Latest reply: May 12, 2011 8:05 AM by 860165 RSS

    How to debug com.sun.jndi.ldap

    860165
      What is the best way to debug com.sun.jndi.ldap classes?

      I'm using the sun jndi ldap implementation to authenticate users. It works, but frequently (and seemingly randomly) there is a 15 seconds delay in connecting to the LDAP server. Here are a few things I've tried:

      I've added the -Djavax.net.debug system property to get additional output (ssl is being used). I'm not sure what to look for but one interesting thing is that it appears closing the connection causes a "java.net.SocketException: Connection reset by peer: socket write error"

      I've connected to the process using JConsole and obtained a stack trace. I'm not sure I'm catching the thread at the right moment, but it looks like it is hanging on com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1096)

      I've downloaded source from openjdk.java.net, and attached a debugger, but the source doesn't line up with the binary. Know where I can get source for com.sun.jndi.ldap.* as used in Java 1.6 build 20?

      Here is the line that occasionally hangs for 15 seconds:
      ctx = new InitialLdapContext(env, null);
        • 1. Re: How to debug com.sun.jndi.ldap
          EJP
          it looks like it is hanging on com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1096)
          Which is deep inside SSL. Nothing to do with LDAP whatsoever.
          • 2. Re: How to debug com.sun.jndi.ldap
            860165
            Thanks for the reply. As mentioned already, I'm not sure I grabbed the stack trace at the right moment, and even if I did, the fact that the top of the stack was hung on an SSL communication call may not mean much; lower on the stack the LDAP library is invoking the call and could be doing so in a way which causes it to hang.

            I found a post on Stack Overflow (http://stackoverflow.com/questions/1138082/ldap-requests-hanging-for-15-seconds) that suggested my issue could be due to a DNS configuration problem or a Sun bug. I switched from using a hostname to an IP address and the problem persists so I think I can rule DNS out.

            The Sun bug is listed here: http://bugs.sun.com/view_bug.do?bug%5Fid=6870947 . I'm not sure how to confirm this is the issue I have though since I can't get the JDK 6 source code. Interestingly, it looks like JDK 5 is available under a research license (http://java.sun.com/j2se/jrl_download.html). If I'm understanding the bug report correctly it appears the fix will be available in Java 7.

            Oh yeah, it is probably worth mentioning that I've got a PHP application running on the same host that also connects to same LDAP server for authentication and it works without any delay and has been for years. This is making Java look really bad.
            • 3. Re: How to debug com.sun.jndi.ldap
              EJP
              lower on the stack the LDAP library is invoking the call and could be doing so in a way which causes it to hang.
              No, lower on the stack the LDAP library is doing its first piece of I/O on the SSLSocket, i.e. sending the first request, which is causing the SSL handshake, which is hanging for some reason, presumably waiting for a server handshake response, which concerns SSL, not LDAP. LDAP does always send requests: it won't be that.
              I found a post on Stack Overflow
              Not relevant. It is stuck in wait() while doing com.sun.jndi.ldap.Connection.readReply(). You are stuck in the SSL handshake, which would occur before sending the request, which precedes reading the reply. And the DNS lookups have already happened by the time the socket is connected, which it must be to be in the SSL handshake.
              The Sun bug is listed here
              If it's this bug, the question becomes why the LDAP server reset the connection. Which in turn indicates an SSL setup problem such as certificate.
              • 4. Re: How to debug com.sun.jndi.ldap
                860165
                You seem to be suggesting that the problem is with the SSL certificate. Any suggestions on how to troubleshoot that? I simply obtained the root certificate from my company and installed it in the cacerts.jks keystore of GlassFish:

                keytool -keystore cacerts.jks -import -alias MyCompanyCA -file MyCompanyCA.crt
                • 5. Re: How to debug com.sun.jndi.ldap
                  EJP
                  Looks OK assuming that is Glassfish's truststore, so I don't think it is the server certificate actually, unless it's of a type that the Java client can't handle - allthough I would expect an SSLException for that. Is the LDAP server using client authentication?
                  • 6. Re: How to debug com.sun.jndi.ldap
                    860165
                    I'm not exactly sure what you mean by client authentication, but I'm creating a new connection for each authentication request and the credentials of the user are being used to make the connection. In other words I'm not creating a connection first and then checking the user's credentials with bind as is often done with pooled LDAP connections. Here is a snippet of the client code:

                    protected void authenticate(String username, String password) throws LoginException {
                    String base = LDAP_BASE_DN_PARAM;
                    String dn = "CN=" + username + "," + base;
                    String url = LDAP_URL_PARAM;
                    DirContext ctx = null;

                    // Note: This is extremely important since an empty password instructs LDAP to login anonymously.
                    if (password == null || password.equals("")) {
                    throw new LoginException("Password cannot be empty");
                    }

                    Properties env = new Properties();
                    env.setProperty(Context.INITIAL_CONTEXT_FACTORY, "com.sun.jndi.ldap.LdapCtxFactory");
                    env.setProperty(Context.PROVIDER_URL, url);
                    env.setProperty(Context.SECURITY_PROTOCOL, "ssl");
                    env.setProperty(Context.SECURITY_AUTHENTICATION, "simple");
                    env.setProperty(Context.SECURITY_PRINCIPAL, dn);
                    env.setProperty(Context.SECURITY_CREDENTIALS, password);

                    try {
                    long start = System.currentTimeMillis();
                    ctx = new InitialLdapContext(env, null);
                    long end = System.currentTimeMillis();
                    logger.log(Level.FINE, "Elapsed Seconds: {0}", (end - start) / 1000.0f);
                    //If here then authentication successful!
                    logger.log(Level.FINE, "Authentication successful");

                    } catch(NamingException e) {
                    LoginException le = new LoginException("Unable to perform login request");
                    le.initCause(e);
                    throw le;
                    } finally {
                    if (ctx != null) {
                    try {
                    ctx.close();
                    } catch(NamingException e) {
                    LoginException le = new LoginException("Unable to close context");
                    le.initCause(e);
                    throw le;
                    }
                    }
                    }
                    }
                    • 7. Re: How to debug com.sun.jndi.ldap
                      EJP
                      I mean SSL client authentication where the client also has a certificate. But if you were doing that you'd know.

                      Your code looks OK, although I too get the connection first then do the LDAP bind via the reconnect() method after changing the principal & credentials. But as I said I don't think the LDAP client code has anything to do with this. What's the LDAP server? And are you sure it's talking SSL? Over the port you're using?

                      I would also have a look tom see what other useful SSL & LDAP env properties could be set, e.g. a read timeout.
                      • 8. Re: How to debug com.sun.jndi.ldap
                        860165
                        I took the connection string that was being used in a PHP application running on Apache on the same host so I think the port and host are good. The PHP application is also using the one connection per authentication strategy with simple authentication over SSL.

                        I've tried the com.sun.jndi.ldap.read.timeout and the com.sun.jndi.ldap.connect.timeout parameters, but they don't seem to do anything for me (setting them both to 5 seconds does not prevent 15 second wait).

                        I've also tried the debug system property java.security.debug=certpath and can see that the certification path is being resolved successfully, and then afterwards the hang occurs.
                        • 9. Re: How to debug com.sun.jndi.ldap
                          EJP
                          Can you try -Djava.net.debug=ssl,handshake.
                          • 10. Re: How to debug com.sun.jndi.ldap
                            860165
                            I think you mean javax.net.debug. That is how I noticed the close connection error I mentioned in a previous post (which I'm not sure what to do about). Here is some of the logging:

                            INFO: %% No cached client session
                            INFO: *** ClientHello, TLSv1
                            INFO: RandomCookie:
                            INFO: GMT: 1288252248
                            INFO: bytes = {
                            ...
                            INFO: %% Cached client session: [Session-1, TLS_RSA_WITH_AES_128_CBC_SHA]
                            INFO: http-thread-pool-8080(4), WRITE: TLSv1 Application Data, length = 80
                            INFO: Thread-57, READ: TLSv1 Application Data, length = 48
                            ...
                            INFO: http-thread-pool-8080(4), WRITE: TLSv1 Application Data, length = 64
                            INFO: http-thread-pool-8080(4), called close()
                            INFO: http-thread-pool-8080(4), called closeInternal(true)
                            INFO: Thread-57, handling exception: java.net.SocketException: Connection reset
                            INFO: %% Invalidated: [Session-1, TLS_RSA_WITH_AES_128_CBC_SHA]
                            INFO: Thread-57
                            INFO: , SEND TLSv1 ALERT:
                            INFO: fatal,
                            INFO: description = unexpected_message
                            INFO: Thread-57, WRITE: TLSv1 Alert, length = 32
                            INFO: Thread-57, Exception sending alert: java.net.SocketException: Connection reset by peer: socket write error
                            INFO: Thread-57, called closeSocket()
                            ...
                            INFO: Finalizer, called close()
                            INFO: Finalizer, called closeInternal(true)

                            The close connection error happens even when the delay does not happen so it might not have anything to do with the delay.
                            • 11. Re: How to debug com.sun.jndi.ldap
                              EJP
                              I'd like to see what's in the elided dotted sections. The main issue here is the premature close. Can you enable any logging at the LDAP server side?
                              • 12. Re: How to debug com.sun.jndi.ldap
                                860165
                                The part of the logging that is in elipses includes info about all certificates being loaded such as:

                                Subject: CN=thawte Primary Root CA, OU="(c) 2006 thawte, Inc. - For authorized use only", OU=Certifi...
                                Issuer: CN=thawte Primary Root CA, OU="(c) 2006 thawte, Inc. - For authorized use only", OU=Certifi...
                                Algorithm: RSA; Serial number: 0x344...
                                Valid from Thu Nov 16 19:00:00 EST 2006 until Wed Jul 16 19:59:59 EDT 2036
                                adding as trusted cert...

                                Also the bytes that are being exchanged are dumped to the log such as:
                                142
                                126
                                236
                                224
                                222
                                253
                                ...

                                The LDAP server is maintained by a department in our company that I'm not a member of so getting them to participate in the debugging effort is a little tricky, especially since they have it working with numerous other (non-Java) applications. Their first reaction is that the problem is with Java (and at this point I'm starting to agree since even I have it working on the exact same server with PHP). In the meantime I've created a Java LoginModule that uses IMAP instead of LDAP and it appears to be working great so I guess I'm abandoning Java LDAP authentication.

                                Note: If I use an LDAP LoginModule that uses connection pooling (the one that comes with GlassFish for example) then I don't have any delays. I assume this is because the connections are created before the user tries to authenticate and then are pooled so as to not incur the creation costs again. I'm not in a position to use connection pooling however because our LDAP server is not configured for anonymous binds and I don't have an account just for making connections (I used my personal account when experimenting, but what I need to do in production is essentially auth-only mode as found in the JAAS LDAPLoginModule).