JDK-6968459 : JNDI timeout fails before timeout is reached
  • Type: Bug
  • Component: core-libs
  • Sub-Component: javax.naming
  • Affected Version: 6u10
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: linux
  • CPU: x86
  • Submitted: 2010-07-12
  • Updated: 2015-05-22
  • Resolved: 2015-05-22
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
tbd_minorResolved
Related Reports
Duplicate :  
Description
FULL PRODUCT VERSION :
JDK 1.6u17

ADDITIONAL OS VERSION INFORMATION :
RHEL4 64-bit

A DESCRIPTION OF THE PROBLEM :
- create an entry
- in an infinite loop, do:
     1. get a LdapContext (non-pooled) using "new InitialLdapContext", set "com.sun.jndi.ldap.read.timeout" to "30000".
     2. read the entry using the LdapContext
     3. close the LdapContext

It fails randomly at step 1 with a javax.naming.NamingException:
javax.naming.NamingException: LDAP response read timed out, timeout used:30000ms.

But the actual elapsed time is no where near the specified 30000ms.

We've seen this across multiple platforms.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Use the code given below to reproduce.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
It never times out
ACTUAL -
It periodically times out in < 2 ms, even though the timeout is 30,000 ms

ERROR MESSAGES/STACK TRACES THAT OCCUR :
>/System/Library/Frameworks/JavaVM.framework/Versions/1.6/Home/bin/java  LdapReadTimeout
System property java.home=/System/Library/Frameworks/JavaVM.framework/Versions/1.6.0/Home
System property java.runtime.version=1.6.0_20-b02-279-10M3065
System property java.version=1.6.0_20
System property java.vm.info=mixed mode
System property java.vm.name=Java HotSpot(TM) 64-Bit Server VM
System property java.vm.version=16.3-b01-279
System property os.arch=x86_64
System property os.name=Mac OS X
System property os.version=10.6.4
System property sun.arch.data.model=64
System property sun.cpu.endian=little

Created entry: cn=20100712-115925
Tested 100 iterations
Tested 200 iterations
Tested 300 iterations
Tested 400 iterations
Tested 500 iterations
Tested 600 iterations
Tested 700 iterations
Tested 800 iterations
Tested 900 iterations
Tested 1000 iterations
Tested 1100 iterations
Tested 1200 iterations
Tested 1300 iterations
Tested 1400 iterations
Tested 1500 iterations
Tested 1600 iterations
Tested 1700 iterations
Tested 1800 iterations
Tested 1900 iterations
Tested 2000 iterations
Tested 2100 iterations
Tested 2200 iterations
Tested 2300 iterations
Tested 2400 iterations
Tested 2500 iterations
Tested 2600 iterations
Tested 2700 iterations
Tested 2800 iterations
Tested 2900 iterations
Tested 3000 iterations
Tested 3100 iterations
Tested 3200 iterations
Tested 3300 iterations
Tested 3400 iterations
Tested 3500 iterations
Tested 3600 iterations
Tested 3700 iterations
Tested 3800 iterations
Tested 3900 iterations
Tested 4000 iterations
Tested 4100 iterations
Tested 4200 iterations
Tested 4300 iterations
Tested 4400 iterations

Actual elapsed time for "new InitialLdapContext"= 1ms
Failed at iteration: 4488
javax.naming.NamingException: LDAP response read timed out, timeout used:30000ms.
        at com.sun.jndi.ldap.Connection.readReply(Connection.java:448)
        at com.sun.jndi.ldap.LdapClient.ldapBind(LdapClient.java:340)
        at com.sun.jndi.ldap.LdapClient.authenticate(LdapClient.java:192)
        at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2694)
        at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:293)
        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:288)
        at javax.naming.InitialContext.init(InitialContext.java:223)
        at javax.naming.ldap.InitialLdapContext.<init>(InitialLdapContext.java:134)
        at LdapReadTimeout.connect(LdapReadTimeout.java:35)
        at LdapReadTimeout.doTest(LdapReadTimeout.java:83)
        at LdapReadTimeout.main(LdapReadTimeout.java:141)


REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.Hashtable;

import javax.naming.CompositeName;
import javax.naming.Context;
import javax.naming.Name;
import javax.naming.directory.Attributes;
import javax.naming.directory.BasicAttribute;
import javax.naming.directory.BasicAttributes;
import javax.naming.directory.DirContext;
import javax.naming.directory.ModificationItem;

import javax.naming.ldap.InitialLdapContext;
import javax.naming.ldap.LdapContext;

public class LdapReadTimeout {

    private static LdapContext connect() throws Exception {
        Hashtable<String, String> env = new Hashtable<String, String>();
        env.put(Context.INITIAL_CONTEXT_FACTORY, "com.sun.jndi.ldap.LdapCtxFactory");
        env.put(Context.PROVIDER_URL, "ldap://localhost:389");
        env.put(Context.REFERRAL, "follow");
        env.put("com.sun.jndi.ldap.connect.timeout", "30000");
        env.put("com.sun.jndi.ldap.read.timeout", "30000");
        env.put("com.sun.jndi.ldap.connect.pool", "false");
        env.put(Context.SECURITY_AUTHENTICATION, "simple");
        env.put(Context.SECURITY_PRINCIPAL, "uid=zimbra,cn=admins,cn=zimbra");
        env.put(Context.SECURITY_CREDENTIALS, "zimbra");

        LdapContext dirCtxt = null;
        long startTime = 0;
        try {
            startTime = System.currentTimeMillis();
            dirCtxt = new InitialLdapContext(env, null);
        } catch (Exception e) {
            long elapsed = System.currentTimeMillis() - startTime;
            System.out.println("\nActual elapsed time for \"new InitialLdapContext\"= " + elapsed + "ms");
            throw e;
        }

        return dirCtxt;
    }

    private static void createEntry(LdapContext dirCtxt, String dn) throws Exception {

        Attributes attrs = new BasicAttributes(true);
        attrs.put("objectClass", "person");
        attrs.put("sn", "my sn");

        Context newCtxt = null;
        try {
            Name cpName = new CompositeName().add(dn);
            newCtxt = dirCtxt.createSubcontext(cpName, attrs);
        } finally {
            if (newCtxt != null)
                newCtxt.close();
        }
    }

    private static void modifyEntry(LdapContext dirCtxt, String dn) throws Exception {
        Name cpName = new CompositeName().add(dn);

        BasicAttribute ba = new BasicAttribute("sn");
        ba.add("hello");

        ModificationItem[] mods = new ModificationItem[1];
        mods[0] = new ModificationItem(DirContext.REPLACE_ATTRIBUTE, ba);
        dirCtxt.modifyAttributes(cpName, mods);
    }

    private static void getEntry(LdapContext dirCtxt, String dn) throws Exception {
        Name cpName = new CompositeName().add(dn);
        dirCtxt.getAttributes(cpName);
    }

    private static void doTest(String dn, boolean createEntry) throws Exception {

        LdapContext dirCtxt = null;

        try {
            // connect
            dirCtxt = connect();

            // do stuff
            if (createEntry) {
                createEntry(dirCtxt, dn);
                System.out.println("Created entry: " + dn);
            } else {
                // modifyEntry(dirCtxt, dn);
                getEntry(dirCtxt, dn);
            }

        } finally {
            // close
            if (dirCtxt != null) {
                dirCtxt.close();
            }
        }
    }

    private static void printSysInfo() throws Exception {
        System.out.println("System property java.home="            + System.getProperty("java.home"));
        System.out.println("System property java.runtime.version=" + System.getProperty("java.runtime.version"));
        System.out.println("System property java.version="         + System.getProperty("java.version"));
        System.out.println("System property java.vm.info="         + System.getProperty("java.vm.info"));
        System.out.println("System property java.vm.name="         + System.getProperty("java.vm.name"));
        System.out.println("System property java.vm.version="      + System.getProperty("java.vm.version"));
        System.out.println("System property os.arch="              + System.getProperty("os.arch"));
        System.out.println("System property os.name="              + System.getProperty("os.name"));
        System.out.println("System property os.version="           + System.getProperty("os.version"));
        System.out.println("System property sun.arch.data.model="  + System.getProperty("sun.arch.data.model"));
        System.out.println("System property sun.cpu.endian="       + System.getProperty("sun.cpu.endian"));
        // System.out.println("System property sun.cpu.isalist="      + System.getProperty("sun.cpu.isalist"));
        // System.out.println("System property sun.os.patch.level="   + System.getProperty("sun.os.patch.level"));
        System.out.println();
    }

    /**
     * /Users/pshao/dev/workspace/sandbox/sandbox/bin>/System/Library/Frameworks/JavaVM.framework/Versions/1.6/Home/bin/java  LdapReadTimeout
     * /System/Library/Frameworks/JavaVM.framework/Versions/1.6/Home/bin/java LdapReadTimeout
     *
     * @param args
     */
    public static void main(String[] args) {

        Date date = new Date();
        SimpleDateFormat fmt =  new SimpleDateFormat("yyyyMMdd-HHmmss");
        String testId =  fmt.format(date);
        String dn = "cn=" + testId;

        int i = 1;
        try {
            printSysInfo();

            // create the entry
            doTest(dn, true);

            while (true) {
                // do the test
                doTest(dn, false);

                // report some progress
                if (i % 100 == 0)
                    System.out.println("Tested " + i + " iterations");
                ++i;
            }
        } catch (Exception e) {
            System.out.println("Failed at iteration: " + i);
            e.printStackTrace();
        }
    }

}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
No known workaround
Comments copied from http://bugs.openjdk.java.net/show_bug.cgi?id=100216

Description From Joseph Walton 2011-11-07 23:07:44 PDT

The LDAP Connection implementation times out early on a spurious wakeup:

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6968459

This patch checks the elapsed time after wait returns and will wait again if it
returned early.

Comment #1 From Joseph Walton 2011-11-07 23:08:29 PDT

Created an attachment (id=247) [details]
Allow for spurious wakeups when LDAP connections have a timeout.

Comment #2 From Tim Bell 2012-07-11 14:21:25 PDT

Closing.  This is SUNBUG 6968459.  The attachments will be transferred over.

Comments
the last version of the webrev with the test (which is not good enough, though): http://cr.openjdk.java.net/~igerasim/6968459/3/webrev/
06-12-2013

Release team: Approved for deferral.
06-12-2013

8-defer-request. Requesting for deferral as we don't yet have a good test to verify the fix. The failure isn't a regression, it was reported for jdk6.
06-12-2013

I've asked the customer for an instruction about how to setup the environment for the testing. And I'm trying to figure out it myself. Once I have the testing instruction and the results, I'll post the update.
27-11-2013

Release team: Please provide justification, risks assessments, testing done, etc and then put this back on critical request.
21-11-2013

Mail thread: http://mail.openjdk.java.net/pipermail/core-libs-dev/2013-November/023357.html
21-11-2013

SUGGESTED FIX See attached patch from OpenJDK bugzilla.
23-07-2012