Loop in client results in NPE + CommunicationException Request: 1 cancelled

• Key: DIRSERVER-391
• Type: Bug
• Status: Closed
• Resolution: Fixed
• Priority: Major
• Assignee: Alex Karasulu
• Reporter: David Geleyn

Description

The source code that fails is too complicated to add here, so I've made a test program that results in the same behaviour.

This program doesn't do anything useful. It checks twice whether Alex Karasulu is an administrator and repeats this for a thousand times. It results in an CommunicationException at client side and a NPE at server side. I added both stacktraces at the end. I also added the code that starts up the LDAP server.

I googled to find some explanation for the "Request 1: Cancelled", but I didn't find an useful explanation. There was some topic on a forum that mentionned that the number of connections was reached. Can this be the problem?

After the NPE (which is never a good thing), new server requests will be processed. It's only the thread that handles the request that fails (i guess).

============= SAMPLE CLIENT CODE
public static void main(String[] args) throws Exception
{
        final Properties env = new Properties();
        env.put(Context.INITIAL_CONTEXT_FACTORY,
"com.sun.jndi.ldap.LdapCtxFactory");
        env.put(Context.PROVIDER_URL, "ldap://david:389");
        env.put(Context.SECURITY_AUTHENTICATION, "simple");
        env.put("java.naming.ldap.version", "3");
        env.put(Context.SECURITY_PRINCIPAL, "uid=admin,ou=system");
        env.put(Context.SECURITY_CREDENTIALS, "secret");
        int positive = 0;
 
        for (int i = 0; i < 1000; i++)
        {
                // Try to authenticate user.
                DirContext userContext = new InitialDirContext(env);
 
                final SearchControls constraints = new SearchControls();
                constraints.setDerefLinkFlag(true);
                constraints.setSearchScope(SearchControls.SUBTREE_SCOPE);
                String filter =
"(&(cn=administrators)(uniqueMember=uid=akarasulu,ou=users,ou=system))";
                NamingEnumeration enum =
userContext.search("ou=groups,ou=system", filter, constraints);
                enum = userContext.search("ou=groups,ou=system", filter,
constraints);
 
                if (enum.hasMoreElements()) positive++;
                userContext.close();
        }
        System.out.println(positive);
 
}

============= SERVER STARTUP CODE
// Start the LDAP server
Properties env = new Properties();
env.setProperty(Context.PROVIDER_URL, "ou=system");
env.setProperty(Context.INITIAL_CONTEXT_FACTORY,
"org.apache.ldap.server.jndi.ServerContextFactory");
try
{
        new InitialDirContext(env);
}
catch (NamingException e)
{
        e.printStackTrace();
}

============= CLIENT STACK TRACE
javax.naming.CommunicationException: Request: 1 cancelled
        at com.sun.jndi.ldap.LdapRequest.getReplyBer(LdapRequest.java:60)
        at com.sun.jndi.ldap.Connection.readReply(Connection.java:405)
        at com.sun.jndi.ldap.LdapClient.ldapBind(LdapClient.java:340)
        at com.sun.jndi.ldap.LdapClient.authenticate(LdapClient.java:193)
        at com.sun.jndi.ldap.LdapCtx.connect(LdapCtx.java:2640)
        at com.sun.jndi.ldap.LdapCtx.<init>(LdapCtx.java:290)
        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:662)
        at
javax.naming.InitialContext.getDefaultInitCtx(InitialContext.java:243)
        at javax.naming.InitialContext.init(InitialContext.java:219)
        at javax.naming.InitialContext.<init>(InitialContext.java:195)
        at
javax.naming.directory.InitialDirContext.<init>(InitialDirContext.java:80)
        at id.security.authentication.service.ldap.Test.main(Test.java:34)

============= SERVER STACK TRACE
java.lang.NullPointerException
        at
sun.nio.ch.WindowsSelectorImpl$SubSelector.processFDSet(WindowsSelectorImpl.java:321)
        at
sun.nio.ch.WindowsSelectorImpl$SubSelector.processSelectedKeys(WindowsSelectorImpl.java:290)
        at
sun.nio.ch.WindowsSelectorImpl$SubSelector.access$2800(WindowsSelectorImpl.java:253)
        at
sun.nio.ch.WindowsSelectorImpl.updateSelectedKeys(WindowsSelectorImpl.java:439)
        at
sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:145)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:59)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:70)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:74)
        at
org.apache.apseda.input.TCPInputManager.run(TCPInputManager.java:158)
        at java.lang.Thread.run(Thread.java:534)

Comments

[David Geleyn]

Client source code

[David Geleyn]

When testing this issue, sometimes following stacktrace occurs in server:

java.nio.channels.ClosedChannelException
at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:112)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:139)
at org.apache.apseda.input.TCPInputManager.processInput(TCPInputManager.java:393)
at org.apache.apseda.input.TCPInputManager.run(TCPInputManager.java:186)
at java.lang.Thread.run(Thread.java:534)

I'm not capable of reproducing this at a regular basis...

[David Geleyn]

I retested this issue with my snapshot of the 0.9 release, which I'm using now. There are no errors at client side. At server side I get the following stacktraces multiple times, but I'm not sure this is a Apache DS issue:

java.io.IOException: An existing connection was forcibly closed by the remote host
at sun.nio.ch.SocketDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:25)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
at sun.nio.ch.IOUtil.read(IOUtil.java:200)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:207)
at org.apache.mina.io.socket.SocketIoProcessor.read(SocketIoProcessor.java:242)
at org.apache.mina.io.socket.SocketIoProcessor.processSessions(SocketIoProcessor.java:216)
at org.apache.mina.io.socket.SocketIoProcessor.access$300(SocketIoProcessor.java:41)
at org.apache.mina.io.socket.SocketIoProcessor$Worker.run(SocketIoProcessor.java:496)

[Alex Karasulu]

This may be due to a previous limitation on the number of socket connections. Let's make sure this goes away in 0.9.

[Alex Karasulu]

Yep just ran your tests and it does look like some of the socket changes made to MINA has resolved this issue. I'll take it off as fixed but please confirm.

[Nikolay Ugarov]

Alex,

I have the stacktrace in my project (not related to ApacheDS in any way) exactly similar to the one you have on server - actually found this bug searching the net for the stacktrace.

It looks like this is sun's bug. http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4729342

Could you please comment, did you upgrade your JDK when when you where testing the resolution?

[Emmanuel Lecharny]

Closing all issues created in 2005 and before which are marked resolved