Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6968459

JNDI timeout fails before timeout is reached

    Details

      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.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                igerasim Ivan Gerasimov (Inactive)
                Reporter:
                webbuggrp Webbug Group
              • Votes:
                0 Vote for this issue
                Watchers:
                7 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Imported:
                  Indexed: