JDK-6351539 : LDAP implementation of JNDI when used with connection pooling enabled hangs
  • Type: Bug
  • Component: core-libs
  • Sub-Component: javax.naming
  • Affected Version: 1.1,5.0u4
  • Priority: P2
  • Status: Closed
  • Resolution: Not an Issue
  • OS: generic,solaris_10
  • CPU: generic,sparc
  • Submitted: 2005-11-16
  • Updated: 2010-08-19
  • Resolved: 2005-12-15
Related Reports
Duplicate :  
Description
The LDAP implementation of the JNDI SPI that comes bundled with the jvm(1.5)
seems to have a bug when connection pooling is enabled. This is causing
an issue with the customers of Sun Java System Application Server when they use
this LDAP as the authentication datasore. I have created a standalone test case
that reproduces the problem(see below) - essentially the request hangs while making
a call into the com.sun.jndi.ldap.pool.* classes . 

The code seems to be doing all the cleanup that needs to be done i.e.,
calling close() on the Context and NamingEnumeration classes in the finally blocks.
Apparently a connection does not get released when one of the contexts is closed(ctx.close() on line# 99 of the testcase). 

Stack trace and other details:

java version "1.5.0_04"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_04-b05)
Java HotSpot(TM) Server VM (build 1.5.0_04-b05, mixed mode)

Command use:
java -Dcom.sun.jndi.ldap.connect.pool.maxsize=1 TestCase

Full thread dump Java HotSpot(TM) Server VM (1.5.0_04-b05 mixed mode):

"Thread-1" daemon prio=10 tid=0x001db488 nid=0xe runnable [0xd3a7f000..0xd3a7fb10]
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
	- locked <0xed8477e0> (a java.io.BufferedInputStream)
	at com.sun.jndi.ldap.Connection.run(Connection.java:780)
	at java.lang.Thread.run(Thread.java:595)

"Thread-0" daemon prio=10 tid=0x001a4868 nid=0xd runnable [0xd3b7f000..0xd3b7fa90]
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
	at java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
	- locked <0xed83cdb8> (a java.io.BufferedInputStream)
	at com.sun.jndi.ldap.Connection.run(Connection.java:780)
	at java.lang.Thread.run(Thread.java:595)

"Low Memory Detector" daemon prio=10 tid=0x00149530 nid=0xb runnable [0x00000000..0x00000000]

"CompilerThread1" daemon prio=10 tid=0x00148488 nid=0xa waiting on condition [0x00000000..0x00000000]

"CompilerThread0" daemon prio=10 tid=0x00147620 nid=0x9 waiting on condition [0x00000000..0xf857eb70]

"AdapterThread" daemon prio=10 tid=0x001467b8 nid=0x8 waiting on condition [0x00000000..0x00000000]

"Signal Dispatcher" daemon prio=10 tid=0x001459a0 nid=0x7 waiting on condition [0x00000000..0x00000000]

"Finalizer" daemon prio=10 tid=0x00139f00 nid=0x6 in Object.wait() [0xfa97f000..0xfa97fb10]
	at java.lang.Object.wait(Native Method)
	- waiting on <0xed800848> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
	- locked <0xed800848> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00137fb8 nid=0x5 in Object.wait() [0xfaa7f000..0xfaa7fa90]
	at java.lang.Object.wait(Native Method)
	- waiting on <0xed800758> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:474)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
	- locked <0xed800758> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x00037138 nid=0x1 in Object.wait() [0xffbfd000..0xffbfea58]
	at java.lang.Object.wait(Native Method)
	- waiting on <0xed8470b0> (a com.sun.jndi.ldap.pool.Connections)
	at java.lang.Object.wait(Object.java:474)
	at com.sun.jndi.ldap.pool.Connections.get(Connections.java:137)
	- locked <0xed8470b0> (a com.sun.jndi.ldap.pool.Connections)
	at com.sun.jndi.ldap.pool.Pool.getPooledConnection(Pool.java:129)
	at com.sun.jndi.ldap.LdapPoolManager.getLdapClient(LdapPoolManager.java:291)
	at com.sun.jndi.ldap.LdapClient.getInstance(LdapClient.java:1572)
	at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2596)
	at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:283)
	at com.sun.jndi.ldap.LdapCtxFactory.getUsingURL(LdapCtxFactory.java:175)
	at com.sun.jndi.ldap.LdapCtxFactory.getUsingURLs(LdapCtxFactory.java:193)
	at com.sun.jndi.ldap.LdapCtxFactory.getLdapCtxInstance(LdapCtxFactory.java:136)
	at com.sun.jndi.ldap.LdapCtxFactory.getInitialContext(LdapCtxFactory.java:66)
	at javax.naming.spi.NamingManager.getInitialContext(NamingManager.java:667)
	at javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:247)
	at javax.naming.InitialContext.init(InitialContext.java:223)
	at javax.naming.InitialContext.<init>(InitialContext.java:197)
	at javax.naming.directory.InitialDirContext.<init>(InitialDirContext.java:82)
	at TestCase.bindAsUser(TestCase.java:177)
	at TestCase.findAndBind(TestCase.java:79)
	at TestCase.authenticate(TestCase.java:62)
	at TestCase.main(TestCase.java:55)

"VM Thread" prio=10 tid=0x00135b08 nid=0x4 runnable 

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0011cd88 nid=0x2 runnable 

"GC task thread#1 (ParallelGC)" prio=10 tid=0x0011cfc8 nid=0x3 runnable 

"VM Periodic Task Thread" prio=10 tid=0x0014a7b0 nid=0xc waiting on condition 

TestCase source code
---------------------
import java.util.*;

import javax.security.auth.*;
import javax.security.auth.callback.*;
import javax.security.auth.login.*;
import javax.security.auth.spi.*;

import javax.naming.*;
import javax.naming.directory.*;

import java.security.acl.Group;
import java.security.Principal;
import javax.security.auth.x500.X500Principal;
// imported from the ldap booster pack
//import com.sun.jndi.ldap.obj.GroupOfURLs;
import javax.security.auth.login.LoginException;

public class TestCase {

    public static final String SUBST_SUBJECT_NAME="%s";
    public static final String SUBST_SUBJECT_DN="%d";
    public static final String DYNAMIC_GROUP_FILTER = 
                "(&(objectclass=groupofuniquenames)(objectclass=*groupofurls*))";

    String username = "munta";
    String password = "munta";
    String userDNbase =  "dc=sfbay,dc=sun,dc=com";
    String searchFilter   = "uid=%s";
    String grpDNbase =  "dc=sfbay,dc=sun,dc=com";
    String grpSearchFilter = "uniquemember=%d";
    String grpTarget = "cn";
    static Properties ldapBindProps = new Properties();

    static {
        ldapBindProps.setProperty("java.naming.factory.initial", "com.sun.jndi.ldap.LdapCtxFactory");
        ldapBindProps.setProperty("java.naming.provider.url", "ldap://jws-cust-280-6.sfbay.sun.com:389/");
        ldapBindProps.setProperty("com.sun.jndi.ldap.connect.pool", "true");
        ldapBindProps.setProperty("java.naming.factory.state", "com.sun.jndi.ldap.obj.LdapGroupFactory");
        ldapBindProps.setProperty("java.naming.factory.object", "com.sun.jndi.ldap.obj.LdapGroupFactory");
        
        //java.naming.security.principal=uid=munta,ou=People,dc=s1peqe,dc=sfbay,dc=sun,dc=com,
        //java.naming.security.credentials=munta
    }

    public static void main(String[] args) throws Exception {
        TestCase tc = new TestCase();

        System.out.println("Sending first request ..");
        tc.authenticate();
        System.out.println("Completed first request.");

        System.out.println();

        System.out.println("Sending second request ..");
        tc.authenticate();
        System.out.println("Completed second request.");
    }

    private String[] dnOnly = {"dn"};

    protected void authenticate () throws Exception {
            findAndBind();
    }

    private void findAndBind() throws Exception {

        StringBuffer sb = new StringBuffer(searchFilter);
        substitute(sb, SUBST_SUBJECT_NAME, username);
        String userid = sb.toString();
        String realUserDN = userSearch(userDNbase, userid);
        if (realUserDN == null) {
            throw new Exception("real user DN is NULL");
        }

        DirContext ctx = null;
        String srcFilter = null;
        String[] grpList = null;
        try {
            ctx = bindAsUser(realUserDN, password);
            System.out.println("  Got context: " + ctx);
            if (ctx == null) {
                throw new Exception("bind failed. ctx is NULL");
            }

            sb = new StringBuffer(grpSearchFilter);
            substitute(sb, SUBST_SUBJECT_NAME, username);
            substitute(sb, SUBST_SUBJECT_DN, realUserDN);

            srcFilter = sb.toString();
            ArrayList groupsList = new ArrayList();
            //groupsList.addAll(groupSearch(ctx, grpDNbase, srcFilter, grpTarget));
            groupsList.addAll(dynamicGroupSearch(ctx, grpDNbase, grpTarget, realUserDN));          
            grpList = new String[groupsList.size()];
            groupsList.toArray(grpList);
        } finally {
            if (ctx != null) {
                try {
                    System.out.println("  Closing context: " + ctx);
                    ctx.close();
                } catch (NamingException e) {};
            }
        }

    }


    private String userSearch(String baseDN, String filter)
    {
            
        String foundDN = null;
        DirContext ctx = null;
        NamingEnumeration namingEnum = null;

        SearchControls ctls = new SearchControls();
        ctls.setReturningAttributes(dnOnly);
        ctls.setSearchScope(SearchControls.SUBTREE_SCOPE);
        ctls.setCountLimit(1);

        try {
            ctx = new InitialDirContext(ldapBindProps);
            System.out.println("  Got context: " + ctx);

            namingEnum = ctx.search(baseDN, filter, ctls);
            System.out.println("    Got naming enumeration: " + namingEnum);

            if (namingEnum.hasMore()) {
                SearchResult res = (SearchResult)namingEnum.next();

                StringBuffer sb = new StringBuffer();
                CompositeName compDN = new CompositeName(res.getName());
                String ldapDN = compDN.get(0);
                sb.append(ldapDN);
                
                if (res.isRelative()) {
                    sb.append(",");
                    sb.append(baseDN);
                }
                foundDN = sb.toString();
            }
        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            if (namingEnum != null) {
                try {
                    System.out.println("    Closing naming enumeration: " + namingEnum);
                    namingEnum.close();
                } catch(Exception ex) {
                }
            }
            if (ctx != null) {
                try {
                    System.out.println("  Closing context: " + ctx);
                    ctx.close();
                } catch(Exception ex) {
                }
            }
        }

        return foundDN;
    }


    private DirContext bindAsUser(String bindDN, String password)
    {

        Properties p = (Properties)ldapBindProps.clone();
        
        //p.put(Context.SECURITY_PRINCIPAL, bindDN);
        //p.put(Context.SECURITY_CREDENTIALS, password);
        //java.naming.security.principal=uid=munta,ou=People,dc=s1peqe,dc=sfbay,dc=sun,dc=com,
        //java.naming.security.credentials=munta
        p.put(Context.SECURITY_PRINCIPAL, "uid=munta,ou=People,dc=s1peqe,dc=sfbay,dc=sun,dc=com");
        p.put(Context.SECURITY_CREDENTIALS, "munta");

        DirContext ctx = null;
        try {
            ctx = new InitialDirContext(p);
        } catch (Exception e) {
            e.printStackTrace();
        }
        
        return ctx;
    }

    private List dynamicGroupSearch(DirContext ctx, String baseDN, 
            String target, String userDN) {        
        List groupList = new ArrayList();
        String filter = DYNAMIC_GROUP_FILTER;
        
        String[] targets = new String[] { target, "memberUrl" };

        NamingEnumeration ne = null;

        try {
            SearchControls ctls = new SearchControls();
            ctls.setReturningAttributes(targets);
            ctls.setSearchScope(SearchControls.SUBTREE_SCOPE);
            ctls.setReturningObjFlag(true);
            
            ne = ctx.search(baseDN, filter, ctls);
            System.out.println("    Got naming enumeration: " + ne);
            
            while(ne.hasMore()) {
                   SearchResult res = (SearchResult)ne.next();
//                 Object searchedObject = res.getObject();
//                 if(searchedObject instanceof com.sun.jndi.ldap.obj.GroupOfURLs){ // dynamic group
//                     com.sun.jndi.ldap.obj.GroupOfURLs gurls = (com.sun.jndi.ldap.obj.GroupOfURLs) searchedObject;
//                     Principal x500principal = new X500Principal(userDN);
//                     if (gurls.isMember(x500principal)) {
                        
//                         Attribute grpAttr = res.getAttributes().get(target);
//                         int sz = grpAttr.size();
//                         for (int i=0; i<sz; i++) {
//                             String s = (String)grpAttr.get(i);
//                             groupList.add(s);
//                         }
//                     }
//                }
            }
        } catch (Exception ex) {
            ex.printStackTrace();
        } finally {
            if( ne != null ) {
                try {
                    System.out.println("    Closing naming enumeration: " + ne);
                    ne.close();
                } catch(Exception ex) {
                    ex.printStackTrace();
                }
            }
        }
        return groupList;
    }
    
    private List groupSearch(DirContext ctx, String baseDN,
                                 String filter, String target)
    {        
        List groupList = new ArrayList();
        
        NamingEnumeration ne = null;

        try {
            String[] targets = new String[1];
            targets[0] = target;
            
            SearchControls ctls = new SearchControls();
            ctls.setReturningAttributes(targets);
            ctls.setSearchScope(SearchControls.SUBTREE_SCOPE);
            
            ne = ctx.search(baseDN, filter, ctls);
            System.out.println("    Got naming enumeration: " + ne);
            
            while(ne.hasMore()) {
                SearchResult res = (SearchResult)ne.next();
                Attribute grpAttr = res.getAttributes().get(target);
                int sz = grpAttr.size();
                for (int i=0; i<sz; i++) {
                    String s = (String)grpAttr.get(i);
                    groupList.add(s);
                }
            }
                
        } catch (Exception ex) {
            ex.printStackTrace();
        } finally {
            if( ne != null ) {
                try {
                    System.out.println("    Closing naming enumeration: " + ne);
                    ne.close();
                } catch(Exception ex) {}
            }
        }

        return groupList;
    }

    private static void substitute(StringBuffer sb,
                                   String target, String value)
    {
        int i = sb.indexOf(target);
        while (i >= 0) {
            sb.replace(i, i+target.length(), value);
            i = sb.indexOf(target);
        }
    }

}
// End of Source Code
//--------------------


When the finalizer ran, it seems to free up the connection that was hung as demonstrated
by this stack trace
java.lang.Throwable: release
	at com.sun.jndi.ldap.pool.ConnectionDesc.release(ConnectionDesc.java:82)
	at com.sun.jndi.ldap.pool.Connections.releasePooledConnection(Connections.java:231)
	at com.sun.jndi.ldap.LdapClient.close(LdapClient.java:426)
	at com.sun.jndi.ldap.LdapCtx.closeConnection(LdapCtx.java:2701)
	at com.sun.jndi.ldap.LdapCtx.close(LdapCtx.java:2489)
	at com.sun.jndi.ldap.LdapCtx.finalize(LdapCtx.java:2464)
	at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
	at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
	at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160)

Comments
EVALUATION What's happening is that in the method below: private List dynamicGroupSearch(DirContext ctx, String baseDN, String target, String userDN); The search control is set to return the objects. ctls.setReturningObjFlag(true); What if this returns another Context that shares the same connection as the parent (search) context? This is exactly what's happening in this case. Even if the the code to retrieve the object from the search result is commented out, the object is already available. If the code below is added while enumerating through the search result, the connections are released as one expects: Object searchedObject = res.getObject(); : : if (searchedObject instanceof Context) { ((Context) searchedObject).close(); } This would solve the current problem. However, there is another problem that I can see if the code that is using the ldap booster pack to obtain GroupOfURLs is uncommented. Calling a close on GroupOfURLs is not releasing the connections. This is a bug against LDAP Booster Pack. A new bug is created for this with bug ID: 6356966 The JNDI/LDAP service provider does not require a fix. The fix has been made in the LDAP Booster Pack and it's been delivered (version 1.1_01) to the AppServer Team. There is no bugtraq category to track the fixes to LDAP Booster Pack. With this note I am closing this bug.
30-11-2005

EVALUATION This doesn't appear as a bug to me from the available information. It looks like the idle connection timeout for the pooled connections is not set, hence the connections remain in the pool until they are GC'ed. Here is a relevant info from the JNDI tutorial: When the application is finished with a pooled connection (by invoking Context.close() on all contexts that share the connection), the underlying pooled connection is marked as idle, waiting to be reused. By default, idle connections remain in the pool indefinitely until they are garbage-collected. If the "com.sun.jndi.ldap.connect.pool.timeout" system property has been set, the LDAP provider will automatically close and remove pooled connections that have been idle for more than the specified period. http://java.sun.com/products/jndi/tutorial/ldap/connect/config.html Also, the system property below can be used to generate debug information for the pooled connections: com.sun.jndi.ldap.connect.pool.debug=all or com.sun.jndi.ldap.connect.pool.debug=fine
17-11-2005