Directory Client API
  1. Directory Client API
  2. DIRAPI-140

Test ClientSearchRequestTest.testSubDn() fails

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.0.0-M18
    • Labels:
      None
    • Environment:

      Description

      In trunk the test ClientSearchRequestTest.testSubDn (module ldap-client-test) fails quite often. When adding a for loop around the test code it fails after 1-10 executions. The first search works always, but the second search which uses the SearchRequest object sometimes doesn't contain a result and searchCursor.next() is false. Please note that I'm not sure if that is a pb in client or in the server.

        Activity

        Hide
        Stefan Seelmann added a comment -

        Added a test that demonstrates the issue: http://svn.apache.org/r1484614

        Show
        Stefan Seelmann added a comment - Added a test that demonstrates the issue: http://svn.apache.org/r1484614
        Hide
        Emmanuel Lecharny added a comment -

        Thanks Stefan. I confirm that there is an issue. I had to increase the loop, because sometime it faisl after more than 200 iterations.

        Let's the bug tracking begin...

        Show
        Emmanuel Lecharny added a comment - Thanks Stefan. I confirm that there is an issue. I had to increase the loop, because sometime it faisl after more than 200 iterations. Let's the bug tracking begin...
        Hide
        Emmanuel Lecharny added a comment -

        Note that it could explain the random failures I sometime encountered on CollectiveAttribute tests...

        Show
        Emmanuel Lecharny added a comment - Note that it could explain the random failures I sometime encountered on CollectiveAttribute tests...
        Hide
        Emmanuel Lecharny added a comment -

        Weird...

        I receive an ExtendedResponse in the middle of the loop :

        ...
        Waiting for 30
        Message ID :30 for SearchResultEntryDecorator
        Message ID :30 for SearchResultDoneDecorator
        Loop 21
        Waiting for 31
        Message ID :31 for SearchResultEntryDecorator
        Message ID :31 for SearchResultDoneDecorator
        Loop 22
        Waiting for 32
        Message ID :0 for ExtendedResponseDecorator

        (Here, the number is the message ID, and we always wait for a SearchRequest)

        Show
        Emmanuel Lecharny added a comment - Weird... I receive an ExtendedResponse in the middle of the loop : ... Waiting for 30 Message ID :30 for SearchResultEntryDecorator Message ID :30 for SearchResultDoneDecorator Loop 21 Waiting for 31 Message ID :31 for SearchResultEntryDecorator Message ID :31 for SearchResultDoneDecorator Loop 22 Waiting for 32 Message ID :0 for ExtendedResponseDecorator (Here, the number is the message ID, and we always wait for a SearchRequest)
        Hide
        Emmanuel Lecharny added a comment -

        More specifically, I get a NotoceOfDisconnection :

        Received an extended response :MessageType : EXTENDED_RESPONSE
        Message ID : 0
        Extended Response
        ResponseName :'1.3.6.1.4.1.1466.20036'
        Ldap Result
        Result code : (SUCCESS) success
        Matched Dn : 'null'
        Diagnostic message : 'null'

        which explains why the test fails.

        Now, I see only one reason for the server to generate such an extendedResponse : an exception has occured on the server.

        Show
        Emmanuel Lecharny added a comment - More specifically, I get a NotoceOfDisconnection : Received an extended response :MessageType : EXTENDED_RESPONSE Message ID : 0 Extended Response ResponseName :'1.3.6.1.4.1.1466.20036' Ldap Result Result code : (SUCCESS) success Matched Dn : 'null' Diagnostic message : 'null' which explains why the test fails. Now, I see only one reason for the server to generate such an extendedResponse : an exception has occured on the server.
        Hide
        Emmanuel Lecharny added a comment -

        Here is the exception :

        org.apache.directory.api.ldap.model.cursor.CursorClosedException
        at org.apache.directory.api.ldap.model.cursor.DefaultClosureMonitor.checkNotClosed(DefaultClosureMonitor.java:123)
        at org.apache.directory.api.ldap.model.cursor.AbstractCursor.checkNotClosed(AbstractCursor.java:61)
        at org.apache.directory.api.ldap.model.cursor.SetCursor.get(SetCursor.java:379)
        at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:165)
        at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45)
        at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:841)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1148)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleWithReferrals(SearchRequestHandler.java:1239)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:217)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:1)
        at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:207)
        at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56)
        at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
        at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
        at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
        at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
        at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
        at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
        at java.lang.Thread.run(Thread.java:680)

        The cursor is closed when we try to get some data from it.

        I don't understand how possibly we can close the cursor while we are reading information from it, unless the closure was caused by another exception...

        In any case, I do think there is another thread that change something somewhere and cause the cursor to be closed too early.

        Show
        Emmanuel Lecharny added a comment - Here is the exception : org.apache.directory.api.ldap.model.cursor.CursorClosedException at org.apache.directory.api.ldap.model.cursor.DefaultClosureMonitor.checkNotClosed(DefaultClosureMonitor.java:123) at org.apache.directory.api.ldap.model.cursor.AbstractCursor.checkNotClosed(AbstractCursor.java:61) at org.apache.directory.api.ldap.model.cursor.SetCursor.get(SetCursor.java:379) at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:165) at org.apache.directory.server.core.partition.impl.btree.EntryCursorAdaptor.get(EntryCursorAdaptor.java:45) at org.apache.directory.server.core.api.filtering.BaseEntryFilteringCursor.next(BaseEntryFilteringCursor.java:379) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.writeResults(SearchRequestHandler.java:391) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.doSimpleSearch(SearchRequestHandler.java:841) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1148) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleWithReferrals(SearchRequestHandler.java:1239) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:217) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:1) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:207) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765) at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428) at java.lang.Thread.run(Thread.java:680) The cursor is closed when we try to get some data from it. I don't understand how possibly we can close the cursor while we are reading information from it, unless the closure was caused by another exception... In any case, I do think there is another thread that change something somewhere and cause the cursor to be closed too early.
        Hide
        Emmanuel Lecharny added a comment -

        Weirder and weirder... We do receive an AbandonRequest from the client, which cause the cursor to be closed :

        in DefaultClosureMonitor :
        public final void close( final Exception cause )
        {
        // state check needed to "try" not to overwrite exception (lack of
        // synchronization may still allow overwriting but who cares that much
        if ( !closed )
        {
        cause.printStackTrace();

        And the trace is :

        org.apache.directory.api.ldap.model.exception.OperationAbandonedException
        at org.apache.directory.server.ldap.handlers.SearchAbandonListener.requestAbandoned(SearchAbandonListener.java:91)
        at org.apache.directory.api.ldap.model.message.AbstractAbandonableRequest$1.update(AbstractAbandonableRequest.java:95)
        at java.util.Observable.notifyObservers(Observable.java:142)
        at java.util.Observable.notifyObservers(Observable.java:98)
        at org.apache.directory.api.ldap.model.message.AbstractAbandonableRequest.abandon(AbstractAbandonableRequest.java:70)
        at org.apache.directory.api.ldap.codec.decorators.SearchRequestDecorator.abandon(SearchRequestDecorator.java:1079)
        at org.apache.directory.server.ldap.LdapSession.abandonOutstandingRequest(LdapSession.java:266)
        at org.apache.directory.server.ldap.handlers.request.AbandonRequestHandler.handle(AbandonRequestHandler.java:47)
        at org.apache.directory.server.ldap.handlers.request.AbandonRequestHandler.handle(AbandonRequestHandler.java:33)
        at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:207)
        at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56)
        at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
        at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
        at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
        at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
        at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
        at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
        at java.lang.Thread.run(Thread.java:680)

        Show
        Emmanuel Lecharny added a comment - Weirder and weirder... We do receive an AbandonRequest from the client, which cause the cursor to be closed : in DefaultClosureMonitor : public final void close( final Exception cause ) { // state check needed to "try" not to overwrite exception (lack of // synchronization may still allow overwriting but who cares that much if ( !closed ) { cause.printStackTrace(); And the trace is : org.apache.directory.api.ldap.model.exception.OperationAbandonedException at org.apache.directory.server.ldap.handlers.SearchAbandonListener.requestAbandoned(SearchAbandonListener.java:91) at org.apache.directory.api.ldap.model.message.AbstractAbandonableRequest$1.update(AbstractAbandonableRequest.java:95) at java.util.Observable.notifyObservers(Observable.java:142) at java.util.Observable.notifyObservers(Observable.java:98) at org.apache.directory.api.ldap.model.message.AbstractAbandonableRequest.abandon(AbstractAbandonableRequest.java:70) at org.apache.directory.api.ldap.codec.decorators.SearchRequestDecorator.abandon(SearchRequestDecorator.java:1079) at org.apache.directory.server.ldap.LdapSession.abandonOutstandingRequest(LdapSession.java:266) at org.apache.directory.server.ldap.handlers.request.AbandonRequestHandler.handle(AbandonRequestHandler.java:47) at org.apache.directory.server.ldap.handlers.request.AbandonRequestHandler.handle(AbandonRequestHandler.java:33) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:207) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:56) at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765) at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428) at java.lang.Thread.run(Thread.java:680)
        Hide
        Emmanuel Lecharny added a comment -

        Ok, get it...

        This is a vicious problem, but not really a bug.

        What happens is that in the test, we do one single cursor.next(), then we close the cursor. At this point, we may not have yet received the SearchResultDone, and in this case, closing the cursor results in the sending of a Disconnect extended request.

        Changing the test to be

        for ( int i = 0; i < 1000; i++ )
        {
        System.out.println( "Loop " + i );

        SearchRequest req = new SearchRequestImpl();
        ...

        SearchCursor searchCursor = connection.search( req );

        while ( searchCursor.next() )
        {
        }

        searchCursor.close();
        }

        make it passes, even with 100000 loops ( I did the test

        Now, the question is : how should we deal with that ? Should we send an abandon request to the server in this premature close ? All in all, I'm not sure how we can detect that we don't have anymore result when we do the close, we may potentially have hundreds...

        I do think that it's not a bug, in fact...

        Show
        Emmanuel Lecharny added a comment - Ok, get it... This is a vicious problem, but not really a bug. What happens is that in the test, we do one single cursor.next(), then we close the cursor. At this point, we may not have yet received the SearchResultDone, and in this case, closing the cursor results in the sending of a Disconnect extended request. Changing the test to be for ( int i = 0; i < 1000; i++ ) { System.out.println( "Loop " + i ); SearchRequest req = new SearchRequestImpl(); ... SearchCursor searchCursor = connection.search( req ); while ( searchCursor.next() ) { } searchCursor.close(); } make it passes, even with 100000 loops ( I did the test Now, the question is : how should we deal with that ? Should we send an abandon request to the server in this premature close ? All in all, I'm not sure how we can detect that we don't have anymore result when we do the close, we may potentially have hundreds... I do think that it's not a bug, in fact...
        Hide
        Stefan Seelmann added a comment -

        Interesting. But I think we can't expect that a user of the API consumes the cursor completely. IMHO it must be possible to close the cursor without iterating to the end of the cursor.

        Show
        Stefan Seelmann added a comment - Interesting. But I think we can't expect that a user of the API consumes the cursor completely. IMHO it must be possible to close the cursor without iterating to the end of the cursor.
        Hide
        Emmanuel Lecharny added a comment -

        Totally agree, and this is why I didn't close the issue.

        The pb is to distinguish such a situation with one where a user sends a request which bring backs many entries, but want to stop searching - by closing the cursor - . In this case, the close() should send an AbandonRequest. How can we wo ?

        Show
        Emmanuel Lecharny added a comment - Totally agree, and this is why I didn't close the issue. The pb is to distinguish such a situation with one where a user sends a request which bring backs many entries, but want to stop searching - by closing the cursor - . In this case, the close() should send an AbandonRequest. How can we wo ?
        Hide
        Stefan Seelmann added a comment -

        Added an cause.printStackTrace() to LdapProtocolHandler.exceptionCaught():

        java.lang.NullPointerException
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleException(SearchRequestHandler.java:1646)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1179)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleWithReferrals(SearchRequestHandler.java:1237)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:217)
        at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:1)
        at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:207)
        at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:1)
        at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221)
        at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765)
        at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74)
        at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
        at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474)
        at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428)
        at java.lang.Thread.run(Thread.java:662)

        In SearchRequestHandler.handleException line 1646, where an error message is composed, the "e" is null! I'll continue debugging this tonight.

        Show
        Stefan Seelmann added a comment - Added an cause.printStackTrace() to LdapProtocolHandler.exceptionCaught(): java.lang.NullPointerException at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleException(SearchRequestHandler.java:1646) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleIgnoringReferrals(SearchRequestHandler.java:1179) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handleWithReferrals(SearchRequestHandler.java:1237) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:217) at org.apache.directory.server.ldap.handlers.request.SearchRequestHandler.handle(SearchRequestHandler.java:1) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:207) at org.apache.directory.server.ldap.handlers.LdapRequestHandler.handleMessage(LdapRequestHandler.java:1) at org.apache.mina.handler.demux.DemuxingIoHandler.messageReceived(DemuxingIoHandler.java:221) at org.apache.directory.server.ldap.LdapProtocolHandler.messageReceived(LdapProtocolHandler.java:217) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:690) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:417) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:47) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:765) at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:74) at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.runTask(UnorderedThreadPoolExecutor.java:474) at org.apache.mina.filter.executor.UnorderedThreadPoolExecutor$Worker.run(UnorderedThreadPoolExecutor.java:428) at java.lang.Thread.run(Thread.java:662) In SearchRequestHandler.handleException line 1646, where an error message is composed, the "e" is null! I'll continue debugging this tonight.
        Hide
        Emmanuel Lecharny added a comment -

        OTOH, the AbandonRequest response has a MessageID of 0, which is really wrong...

        Show
        Emmanuel Lecharny added a comment - OTOH, the AbandonRequest response has a MessageID of 0, which is really wrong...
        Hide
        Emmanuel Lecharny added a comment -

        Ok, I have a better understanding on what's going on.

        On the server, when we process a searchRequest, we loop on the created cursor until we have no more elements to return. This is done by the SearchRequestHandler.writeResults() method :

        while ( ( count < sizeLimit ) && cursor.next() )
        {
        ...

        If, for any reason, the abandonRequest is received and processed at the very same time, what will happen is that the cursor will be closed. We do check this condition :

        public boolean next() throws LdapException, CursorException, IOException
        {
        checkNotClosed( "next()" );
        ...

        public final void checkNotClosed( String operation ) throws CursorClosedException

        { monitor.checkNotClosed(); }

        and

        public void checkNotClosed() throws CursorClosedException
        {
        // lack of synchronization may cause pass but eventually it will work
        if ( closed )

        { throw new CursorClosedException( cause.getMessage() ); }

        }

        So basically, we get an exception instead of something easier to handle.

        It's not happening very often, but still, with 1000 loop, it's almost guaranteed to happen.

        As a side effect, we generate an exception which has no cause, which leads to a NPE later in the SearchRequestHandler.handleException() method :

        public void handleException( LdapSession session, ResultResponseRequest req, Exception e )
        {
        LdapResult result = req.getResultResponse().getLdapResult();

        /*

        • Set the result code or guess the best option.
          */
          ResultCodeEnum code;

        if ( e instanceof CursorClosedException )

        { e = ( Exception ) ( ( CursorClosedException ) e ).getCause(); <<<-------------- Bad ! We should not overwrite the exception parameter here... }

        Here, e becomes null and it shows in the trace because of :

        String msg = code.toString() + ": failed for " + req + ": " + e.getLocalizedMessage(); <<<--- NPE

        In any case, we should not throw an exception when the cursor is simply closed because of an abandon request, we should instead return false to a call to cursor.next().

        There is a bit of work to fix that, but it's not really complicated.

        Show
        Emmanuel Lecharny added a comment - Ok, I have a better understanding on what's going on. On the server, when we process a searchRequest, we loop on the created cursor until we have no more elements to return. This is done by the SearchRequestHandler.writeResults() method : while ( ( count < sizeLimit ) && cursor.next() ) { ... If, for any reason, the abandonRequest is received and processed at the very same time, what will happen is that the cursor will be closed. We do check this condition : public boolean next() throws LdapException, CursorException, IOException { checkNotClosed( "next()" ); ... public final void checkNotClosed( String operation ) throws CursorClosedException { monitor.checkNotClosed(); } and public void checkNotClosed() throws CursorClosedException { // lack of synchronization may cause pass but eventually it will work if ( closed ) { throw new CursorClosedException( cause.getMessage() ); } } So basically, we get an exception instead of something easier to handle. It's not happening very often, but still, with 1000 loop, it's almost guaranteed to happen. As a side effect, we generate an exception which has no cause, which leads to a NPE later in the SearchRequestHandler.handleException() method : public void handleException( LdapSession session, ResultResponseRequest req, Exception e ) { LdapResult result = req.getResultResponse().getLdapResult(); /* Set the result code or guess the best option. */ ResultCodeEnum code; if ( e instanceof CursorClosedException ) { e = ( Exception ) ( ( CursorClosedException ) e ).getCause(); <<<-------------- Bad ! We should not overwrite the exception parameter here... } Here, e becomes null and it shows in the trace because of : String msg = code.toString() + ": failed for " + req + ": " + e.getLocalizedMessage(); <<<--- NPE In any case, we should not throw an exception when the cursor is simply closed because of an abandon request, we should instead return false to a call to cursor.next(). There is a bit of work to fix that, but it's not really complicated.
        Hide
        Emmanuel Lecharny added a comment -

        One solution that works :

        • we don't anymore close the cursor in the AbandonRequest handler : it's enough to signal that the request is abandonned
        • in the searchRequestHandler loop (writeRequests) we now can close the cursor if the request is abandonned.

        This works.

        Show
        Emmanuel Lecharny added a comment - One solution that works : we don't anymore close the cursor in the AbandonRequest handler : it's enough to signal that the request is abandonned in the searchRequestHandler loop (writeRequests) we now can close the cursor if the request is abandonned. This works.
        Hide
        Emmanuel Lecharny added a comment -

        I think I have fixed the issue with http://svn.apache.org/r1484804

        Show
        Emmanuel Lecharny added a comment - I think I have fixed the issue with http://svn.apache.org/r1484804
        Hide
        Stefan Seelmann added a comment -

        Thanks Emmanule for fixing this. I can confirm that the test succeeds now on my machine. I only wonder if the "test_DIRAPI140" test with the 10000 loop should be kept, as the test takes 180 seconds?

        Show
        Stefan Seelmann added a comment - Thanks Emmanule for fixing this. I can confirm that the test succeeds now on my machine. I only wonder if the "test_DIRAPI140" test with the 10000 loop should be kept, as the test takes 180 seconds?
        Hide
        Emmanuel Lecharny added a comment -

        I have ignored the test, to save the 180 seconds.

        Show
        Emmanuel Lecharny added a comment - I have ignored the test, to save the 180 seconds.

          People

          • Assignee:
            Unassigned
            Reporter:
            Stefan Seelmann
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development