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.