Details

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

      Description

      Calling LdapNetworkConnection.unbind() while iterating over an EntryCursor lets the iterator hang, either infinite (if timelimit is 0) or till the timeout occurs.

      Here is the part of a thread dump:

      "main" prio=10 tid=0x00007f3e5400b800 nid=0x117f waiting on condition [0x00007f3e5c5ab000]
         java.lang.Thread.State: TIMED_WAITING (parking)
      	at sun.misc.Unsafe.park(Native Method)
      	- parking to wait for  <0x00000000e310c000> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
      	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
      	at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
      	at org.apache.directory.ldap.client.api.future.ResponseFuture.get(ResponseFuture.java:133)
      	at org.apache.directory.ldap.client.api.future.SearchFuture.get(SearchFuture.java:69)
      	at org.apache.directory.ldap.client.api.SearchCursorImpl.next(SearchCursorImpl.java:121)
      	at org.apache.directory.ldap.client.api.EntryCursorImpl.next(EntryCursorImpl.java:90)
      	at org.apache.directory.shared.client.api.operations.bind.SimpleBindRequestTest.testUnbindDuringSearch(SimpleBindRequestTest.java:635)
      

        Activity

        Hide
        seelmann Stefan Seelmann added a comment -

        Added testcase to demostrate the problem: http://svn.apache.org/r1676106

        Show
        seelmann Stefan Seelmann added a comment - Added testcase to demostrate the problem: http://svn.apache.org/r1676106
        Hide
        elecharny Emmanuel Lecharny added a comment -

        Here is the stack trace when the client hangs :

        2015-04-26 17:44:30
        Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.5-b02 mixed mode):
        
        "YJPAgent-OOMESnapshotDetector" #29 daemon prio=10 os_prio=31 tid=0x00007fdd2b0b4800 nid=0x6a0b runnable [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "YJPAgent-CPUSampler" #28 daemon prio=10 os_prio=31 tid=0x00007fdd2ba18800 nid=0x7207 runnable [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "YJPAgent-RequestListener" #27 daemon prio=1 os_prio=31 tid=0x00007fdd2b0b4000 nid=0x7007 runnable [0x00000001295e0000]
           java.lang.Thread.State: RUNNABLE
        	at java.net.PlainSocketImpl.socketAccept(Native Method)
        	at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404)
        	at java.net.ServerSocket.implAccept(ServerSocket.java:545)
        	at java.net.ServerSocket.accept(ServerSocket.java:513)
        	at com.yourkit.runtime.Core$4.run(Core.java:717)
        	at java.lang.Thread.null (Redefined)
        
        "YJPAgent-Telemetry" #26 daemon prio=5 os_prio=31 tid=0x00007fdd2ca71800 nid=0x6e07 waiting on condition [0x00000001294dd000]
           java.lang.Thread.State: TIMED_WAITING (sleeping)
        	at java.lang.Thread.sleep(Native Method)
        	at com.yourkit.util.Util.sleep(Util.java:60)
        	at com.yourkit.runtime.TelemetryThread.run(TelemetryThread.java:573)
        
        "Attach Listener" #25 daemon prio=9 os_prio=31 tid=0x00007fdd2b0b3000 nid=0x5b07 runnable [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "NioSocketAcceptor-2" #19 prio=5 os_prio=31 tid=0x00007fdd2c8ef800 nid=0x440b runnable [0x0000000127889000]
           java.lang.Thread.State: RUNNABLE
        	at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
        	at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:202)
        	at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
        	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        	- locked <0x00000006c14d2518> (a sun.nio.ch.Util$2)
        	- locked <0x00000006c14d2508> (a java.util.Collections$UnmodifiableSet)
        	- locked <0x00000006c14d23d8> (a sun.nio.ch.KQueueSelectorImpl)
        	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
        	at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:281)
        	at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:452)
        	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        	at java.lang.Thread.null (Redefined)
        
        "NioSocketAcceptor-1" #18 prio=5 os_prio=31 tid=0x00007fdd2b8da000 nid=0x3b07 runnable [0x0000000127319000]
           java.lang.Thread.State: RUNNABLE
        	at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
        	at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:202)
        	at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103)
        	at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        	- locked <0x00000006c14e9e50> (a sun.nio.ch.Util$2)
        	- locked <0x00000006c14e9e40> (a java.util.Collections$UnmodifiableSet)
        	- locked <0x00000006c14e9d20> (a sun.nio.ch.KQueueSelectorImpl)
        	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        	at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
        	at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:281)
        	at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:452)
        	at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        	at java.lang.Thread.null (Redefined)
        
        "kdc%0052eplay%0043ache.data" #16 prio=5 os_prio=31 tid=0x00007fdd2ba9f800 nid=0x6703 waiting on condition [0x0000000126e2c000]
           java.lang.Thread.State: TIMED_WAITING (parking)
        	at sun.misc.Unsafe.park(Native Method)
        	- parking to wait for  <0x00000006c026bd58> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        	at java.lang.Thread.null (Redefined)
        
        "group%0043ache.data" #15 prio=5 os_prio=31 tid=0x00007fdd2ba9f000 nid=0x6503 waiting on condition [0x0000000126d29000]
           java.lang.Thread.State: TIMED_WAITING (parking)
        	at sun.misc.Unsafe.park(Native Method)
        	- parking to wait for  <0x00000006c026bfb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        	at java.lang.Thread.null (Redefined)
        
        "ou=system.data" #14 prio=5 os_prio=31 tid=0x00007fdd2aa52800 nid=0x6303 waiting on condition [0x0000000126c26000]
           java.lang.Thread.State: TIMED_WAITING (parking)
        	at sun.misc.Unsafe.park(Native Method)
        	- parking to wait for  <0x00000006c026c1f8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        	at java.lang.Thread.null (Redefined)
        
        "Statistics Thread-2810fae9-ea58-4421-ba79-a6d5f38dfe3e-1" #13 daemon prio=5 os_prio=31 tid=0x00007fdd2aa0b000 nid=0x6103 waiting on condition [0x0000000126b23000]
           java.lang.Thread.State: TIMED_WAITING (parking)
        	at sun.misc.Unsafe.park(Native Method)
        	- parking to wait for  <0x00000006c01edbb0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        	at java.lang.Thread.null (Redefined)
        
        "change%0050wd%0052eplay%0043ache.data" #12 prio=5 os_prio=31 tid=0x00007fdd2bac0000 nid=0x5f03 waiting on condition [0x0000000126a20000]
           java.lang.Thread.State: TIMED_WAITING (parking)
        	at sun.misc.Unsafe.park(Native Method)
        	- parking to wait for  <0x00000006c01fd6c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        	at java.lang.Thread.null (Redefined)
        
        "2810fae9-ea58-4421-ba79-a6d5f38dfe3e" #11 daemon prio=5 os_prio=31 tid=0x00007fdd2aa10000 nid=0x5d03 in Object.wait() [0x0000000126133000]
           java.lang.Thread.State: WAITING (on object monitor)
        	at java.lang.Object.wait(Native Method)
        	- waiting on <0x00000006c0201690> (a java.util.TaskQueue)
        	at java.lang.Object.wait(Object.java:502)
        	at java.util.TimerThread.mainLoop(Timer.java:526)
        	- locked <0x00000006c0201690> (a java.util.TaskQueue)
        	at java.util.TimerThread.run(Timer.java:505)
        
        "Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007fdd2b002000 nid=0x5703 runnable [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007fdd2a869000 nid=0x5503 waiting on condition [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fdd2a848000 nid=0x5303 waiting on condition [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fdd2b823000 nid=0x5103 waiting on condition [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fdd2a018000 nid=0x4f03 waiting on condition [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fdd2a017800 nid=0x4d03 waiting on condition [0x0000000000000000]
           java.lang.Thread.State: RUNNABLE
        
        "Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fdd2a846800 nid=0x3903 in Object.wait() [0x0000000125240000]
           java.lang.Thread.State: WAITING (on object monitor)
        	at java.lang.Object.wait(Native Method)
        	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142)
        	- locked <0x00000006c002fcf0> (a java.lang.ref.ReferenceQueue$Lock)
        	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158)
        	at java.lang.ref.Finalizer$FinalizerThread.null (Redefined)
        
        "Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fdd2a845800 nid=0x3703 in Object.wait() [0x000000012513d000]
           java.lang.Thread.State: WAITING (on object monitor)
        	at java.lang.Object.wait(Native Method)
        	at java.lang.Object.wait(Object.java:502)
        	at java.lang.ref.Reference$ReferenceHandler.null (Redefined)
        	- locked <0x00000006c0030a70> (a java.lang.ref.Reference$Lock)
        
        "main" #1 prio=5 os_prio=31 tid=0x00007fdd2c800800 nid=0x1903 waiting on condition [0x000000010773e000]
           java.lang.Thread.State: TIMED_WAITING (parking)
        	at sun.misc.Unsafe.park(Native Method)
        	- parking to wait for  <0x00000006c1644d70> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        	at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        	at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
        	at org.apache.directory.ldap.client.api.future.ResponseFuture.get(ResponseFuture.java:130)
        	at org.apache.directory.ldap.client.api.future.SearchFuture.get(SearchFuture.java:69)
        	at org.apache.directory.ldap.client.api.SearchCursorImpl.next(SearchCursorImpl.java:119)
        	at org.apache.directory.ldap.client.api.EntryCursorImpl.next(EntryCursorImpl.java:90)
        	at org.apache.directory.shared.client.api.operations.bind.SimpleBindRequestTest.null (Redefined)
        	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        	at java.lang.reflect.Method.invoke(Method.java:483)
        	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
        	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
        	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
        	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
        	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
        	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
        	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        	at org.apache.directory.server.core.integ.FrameworkRunner.runChild(FrameworkRunner.java:379)
        	at org.apache.directory.server.core.integ.FrameworkRunner.runChild(FrameworkRunner.java:56)
        	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        	at org.apache.directory.server.core.integ.FrameworkRunner.run(FrameworkRunner.java:154)
        	at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.null (Redefined)
        	at org.eclipse.jdt.internal.junit.runner.TestExecution.null (Redefined)
        	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.null (Redefined)
        	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.null (Redefined)
        	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.null (Redefined)
        	at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.null (Redefined)
        
        "VM Thread" os_prio=31 tid=0x00007fdd2a009800 nid=0x3503 runnable 
        
        "GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fdd2a81a800 nid=0x2503 runnable 
        
        "GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fdd2a81b000 nid=0x2703 runnable 
        
        "GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fdd2b807000 nid=0x2903 runnable 
        
        "GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fdd2b807800 nid=0x2b03 runnable 
        
        "GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fdd2b808000 nid=0x2d03 runnable 
        
        "GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fdd2b809000 nid=0x2f03 runnable 
        
        "GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fdd2b809800 nid=0x3103 runnable 
        
        "GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fdd2b80a000 nid=0x3303 runnable 
        
        "VM Periodic Task Thread" os_prio=31 tid=0x00007fdd2a063800 nid=0x5903 waiting on condition 
        
        JNI global references: 573850
        
        Heap
         PSYoungGen      total 72704K, used 17885K [0x000000076ab00000, 0x0000000770600000, 0x00000007c0000000)
          eden space 67072K, 26% used [0x000000076ab00000,0x000000076bc77510,0x000000076ec80000)
          from space 5632K, 0% used [0x000000076ec80000,0x000000076ec80000,0x000000076f200000)
          to   space 5632K, 0% used [0x0000000770080000,0x0000000770080000,0x0000000770600000)
         ParOldGen       total 30720K, used 25061K [0x00000006c0000000, 0x00000006c1e00000, 0x000000076ab00000)
          object space 30720K, 81% used [0x00000006c0000000,0x00000006c18795e0,0x00000006c1e00000)
         Metaspace       used 22696K, capacity 22888K, committed 23344K, reserved 1069056K
          class space    used 2784K, capacity 2817K, committed 2944K, reserved 1048576K
        

        It seems we are waiting on the SearchFuture forever. There is something wrong in the Search/Unbind/Cursor.next() sequence handling...

        Show
        elecharny Emmanuel Lecharny added a comment - Here is the stack trace when the client hangs : 2015-04-26 17:44:30 Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.5-b02 mixed mode): "YJPAgent-OOMESnapshotDetector" #29 daemon prio=10 os_prio=31 tid=0x00007fdd2b0b4800 nid=0x6a0b runnable [0x0000000000000000] java.lang. Thread .State: RUNNABLE "YJPAgent-CPUSampler" #28 daemon prio=10 os_prio=31 tid=0x00007fdd2ba18800 nid=0x7207 runnable [0x0000000000000000] java.lang. Thread .State: RUNNABLE "YJPAgent-RequestListener" #27 daemon prio=1 os_prio=31 tid=0x00007fdd2b0b4000 nid=0x7007 runnable [0x00000001295e0000] java.lang. Thread .State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:404) at java.net.ServerSocket.implAccept(ServerSocket.java:545) at java.net.ServerSocket.accept(ServerSocket.java:513) at com.yourkit.runtime.Core$4.run(Core.java:717) at java.lang. Thread . null (Redefined) "YJPAgent-Telemetry" #26 daemon prio=5 os_prio=31 tid=0x00007fdd2ca71800 nid=0x6e07 waiting on condition [0x00000001294dd000] java.lang. Thread .State: TIMED_WAITING (sleeping) at java.lang. Thread .sleep(Native Method) at com.yourkit.util.Util.sleep(Util.java:60) at com.yourkit.runtime.TelemetryThread.run(TelemetryThread.java:573) "Attach Listener" #25 daemon prio=9 os_prio=31 tid=0x00007fdd2b0b3000 nid=0x5b07 runnable [0x0000000000000000] java.lang. Thread .State: RUNNABLE "NioSocketAcceptor-2" #19 prio=5 os_prio=31 tid=0x00007fdd2c8ef800 nid=0x440b runnable [0x0000000127889000] java.lang. Thread .State: RUNNABLE at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:202) at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) - locked <0x00000006c14d2518> (a sun.nio.ch.Util$2) - locked <0x00000006c14d2508> (a java.util.Collections$UnmodifiableSet) - locked <0x00000006c14d23d8> (a sun.nio.ch.KQueueSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101) at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:281) at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:452) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang. Thread . null (Redefined) "NioSocketAcceptor-1" #18 prio=5 os_prio=31 tid=0x00007fdd2b8da000 nid=0x3b07 runnable [0x0000000127319000] java.lang. Thread .State: RUNNABLE at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:202) at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:103) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) - locked <0x00000006c14e9e50> (a sun.nio.ch.Util$2) - locked <0x00000006c14e9e40> (a java.util.Collections$UnmodifiableSet) - locked <0x00000006c14e9d20> (a sun.nio.ch.KQueueSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101) at org.apache.mina.transport.socket.nio.NioSocketAcceptor.select(NioSocketAcceptor.java:281) at org.apache.mina.core.polling.AbstractPollingIoAcceptor$Acceptor.run(AbstractPollingIoAcceptor.java:452) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang. Thread . null (Redefined) "kdc%0052eplay%0043ache.data" #16 prio=5 os_prio=31 tid=0x00007fdd2ba9f800 nid=0x6703 waiting on condition [0x0000000126e2c000] java.lang. Thread .State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c026bd58> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang. Thread . null (Redefined) "group%0043ache.data" #15 prio=5 os_prio=31 tid=0x00007fdd2ba9f000 nid=0x6503 waiting on condition [0x0000000126d29000] java.lang. Thread .State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c026bfb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang. Thread . null (Redefined) "ou=system.data" #14 prio=5 os_prio=31 tid=0x00007fdd2aa52800 nid=0x6303 waiting on condition [0x0000000126c26000] java.lang. Thread .State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c026c1f8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang. Thread . null (Redefined) "Statistics Thread -2810fae9-ea58-4421-ba79-a6d5f38dfe3e-1" #13 daemon prio=5 os_prio=31 tid=0x00007fdd2aa0b000 nid=0x6103 waiting on condition [0x0000000126b23000] java.lang. Thread .State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c01edbb0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang. Thread . null (Redefined) "change%0050wd%0052eplay%0043ache.data" #12 prio=5 os_prio=31 tid=0x00007fdd2bac0000 nid=0x5f03 waiting on condition [0x0000000126a20000] java.lang. Thread .State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c01fd6c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093) at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang. Thread . null (Redefined) "2810fae9-ea58-4421-ba79-a6d5f38dfe3e" #11 daemon prio=5 os_prio=31 tid=0x00007fdd2aa10000 nid=0x5d03 in Object .wait() [0x0000000126133000] java.lang. Thread .State: WAITING (on object monitor) at java.lang. Object .wait(Native Method) - waiting on <0x00000006c0201690> (a java.util.TaskQueue) at java.lang. Object .wait( Object .java:502) at java.util.TimerThread.mainLoop(Timer.java:526) - locked <0x00000006c0201690> (a java.util.TaskQueue) at java.util.TimerThread.run(Timer.java:505) "Service Thread " #9 daemon prio=9 os_prio=31 tid=0x00007fdd2b002000 nid=0x5703 runnable [0x0000000000000000] java.lang. Thread .State: RUNNABLE "C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007fdd2a869000 nid=0x5503 waiting on condition [0x0000000000000000] java.lang. Thread .State: RUNNABLE "C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fdd2a848000 nid=0x5303 waiting on condition [0x0000000000000000] java.lang. Thread .State: RUNNABLE "C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fdd2b823000 nid=0x5103 waiting on condition [0x0000000000000000] java.lang. Thread .State: RUNNABLE "C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fdd2a018000 nid=0x4f03 waiting on condition [0x0000000000000000] java.lang. Thread .State: RUNNABLE "Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fdd2a017800 nid=0x4d03 waiting on condition [0x0000000000000000] java.lang. Thread .State: RUNNABLE "Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fdd2a846800 nid=0x3903 in Object .wait() [0x0000000125240000] java.lang. Thread .State: WAITING (on object monitor) at java.lang. Object .wait(Native Method) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:142) - locked <0x00000006c002fcf0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:158) at java.lang.ref.Finalizer$FinalizerThread. null (Redefined) "Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fdd2a845800 nid=0x3703 in Object .wait() [0x000000012513d000] java.lang. Thread .State: WAITING (on object monitor) at java.lang. Object .wait(Native Method) at java.lang. Object .wait( Object .java:502) at java.lang.ref.Reference$ReferenceHandler. null (Redefined) - locked <0x00000006c0030a70> (a java.lang.ref.Reference$Lock) "main" #1 prio=5 os_prio=31 tid=0x00007fdd2c800800 nid=0x1903 waiting on condition [0x000000010773e000] java.lang. Thread .State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c1644d70> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467) at org.apache.directory.ldap.client.api. future .ResponseFuture.get(ResponseFuture.java:130) at org.apache.directory.ldap.client.api. future .SearchFuture.get(SearchFuture.java:69) at org.apache.directory.ldap.client.api.SearchCursorImpl.next(SearchCursorImpl.java:119) at org.apache.directory.ldap.client.api.EntryCursorImpl.next(EntryCursorImpl.java:90) at org.apache.directory.shared.client.api.operations.bind.SimpleBindRequestTest. null (Redefined) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:483) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) at org.apache.directory.server.core.integ.FrameworkRunner.runChild(FrameworkRunner.java:379) at org.apache.directory.server.core.integ.FrameworkRunner.runChild(FrameworkRunner.java:56) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) at org.junit.runners.ParentRunner.run(ParentRunner.java:363) at org.apache.directory.server.core.integ.FrameworkRunner.run(FrameworkRunner.java:154) at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference. null (Redefined) at org.eclipse.jdt.internal.junit.runner.TestExecution. null (Redefined) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner. null (Redefined) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner. null (Redefined) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner. null (Redefined) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner. null (Redefined) "VM Thread " os_prio=31 tid=0x00007fdd2a009800 nid=0x3503 runnable "GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fdd2a81a800 nid=0x2503 runnable "GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fdd2a81b000 nid=0x2703 runnable "GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fdd2b807000 nid=0x2903 runnable "GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fdd2b807800 nid=0x2b03 runnable "GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fdd2b808000 nid=0x2d03 runnable "GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fdd2b809000 nid=0x2f03 runnable "GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fdd2b809800 nid=0x3103 runnable "GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fdd2b80a000 nid=0x3303 runnable "VM Periodic Task Thread " os_prio=31 tid=0x00007fdd2a063800 nid=0x5903 waiting on condition JNI global references: 573850 Heap PSYoungGen total 72704K, used 17885K [0x000000076ab00000, 0x0000000770600000, 0x00000007c0000000) eden space 67072K, 26% used [0x000000076ab00000,0x000000076bc77510,0x000000076ec80000) from space 5632K, 0% used [0x000000076ec80000,0x000000076ec80000,0x000000076f200000) to space 5632K, 0% used [0x0000000770080000,0x0000000770080000,0x0000000770600000) ParOldGen total 30720K, used 25061K [0x00000006c0000000, 0x00000006c1e00000, 0x000000076ab00000) object space 30720K, 81% used [0x00000006c0000000,0x00000006c18795e0,0x00000006c1e00000) Metaspace used 22696K, capacity 22888K, committed 23344K, reserved 1069056K class space used 2784K, capacity 2817K, committed 2944K, reserved 1048576K It seems we are waiting on the SearchFuture forever. There is something wrong in the Search/Unbind/Cursor.next() sequence handling...
        Hide
        elecharny Emmanuel Lecharny added a comment -

        That was an easy one to fix ! The map containing all the futures (ie, pending operations) was cleared when an unbind was done, while we would expect some of those future to be used later.

        I cancelled the future before clearing the map, so the search operation (and all the others) are not anymore hanging, waiting for the associated future to complete.

        The test has been activated, with 3 searches instead of one.

        Show
        elecharny Emmanuel Lecharny added a comment - That was an easy one to fix ! The map containing all the futures (ie, pending operations) was cleared when an unbind was done, while we would expect some of those future to be used later. I cancelled the future before clearing the map, so the search operation (and all the others) are not anymore hanging, waiting for the associated future to complete. The test has been activated, with 3 searches instead of one.
        Hide
        seelmann Stefan Seelmann added a comment -

        I still have problems.

        A general question: Is (or should be) the API thread safe? Is it ok that multiple threads use the same LdapNetworkConnection object, e.g. one does a search() and another unbinds/closes the connection?

        Show
        seelmann Stefan Seelmann added a comment - I still have problems. A general question: Is (or should be) the API thread safe? Is it ok that multiple threads use the same LdapNetworkConnection object, e.g. one does a search() and another unbinds/closes the connection?
        Hide
        elecharny Emmanuel Lecharny added a comment -

        Good question. I would say that, yes, the API should be thread safe, but atm, it's not guaranteed. We can protect the critical sections of the API if needed.

        Show
        elecharny Emmanuel Lecharny added a comment - Good question. I would say that, yes, the API should be thread safe, but atm, it's not guaranteed. We can protect the critical sections of the API if needed.
        Hide
        seelmann Stefan Seelmann added a comment - - edited

        Here is another test: http://svn.apache.org/r1676138

        More complex. One connection, two threads. One thread always unbinds and sleeps a bit. The second binds and then permanently searches, till the first thread unbinds.

        After some rounds there is only output to sysout from the "unbind thread: unbind", the serach thread hangs. In the thread dump I see the same as above.

        If I use close() instead of unBind() the test is green. Spoke too fast: It also happens with close() if I reduce the sleep to 50.

        Show
        seelmann Stefan Seelmann added a comment - - edited Here is another test: http://svn.apache.org/r1676138 More complex. One connection, two threads. One thread always unbinds and sleeps a bit. The second binds and then permanently searches, till the first thread unbinds. After some rounds there is only output to sysout from the "unbind thread: unbind", the serach thread hangs. In the thread dump I see the same as above. If I use close() instead of unBind() the test is green. Spoke too fast: It also happens with close() if I reduce the sleep to 50.
        Hide
        seelmann Stefan Seelmann added a comment -

        To clarify the "if needed": In Studio each (by UI triggered) action that communicates with the LDAP server is executed in a background job. So there we have the situation that multiple threads access the same connection object. Just think of a long running export of the whole DIT, during that time the user can continue to browse around or even close the connection.

        If a single connection is not thread safe we can also change Studio, e.g. queue up operations or use multiple connections via the connection pool.

        Show
        seelmann Stefan Seelmann added a comment - To clarify the "if needed": In Studio each (by UI triggered) action that communicates with the LDAP server is executed in a background job. So there we have the situation that multiple threads access the same connection object. Just think of a long running export of the whole DIT, during that time the user can continue to browse around or even close the connection. If a single connection is not thread safe we can also change Studio, e.g. queue up operations or use multiple connections via the connection pool.
        Hide
        elecharny Emmanuel Lecharny added a comment -

        I get it. I think the API should be thread safe, and various threads should be able to use the same connection. All in all, the messages are atomic (requests or responses) when they are sent.

        I guess we have a lot of things to check in the API in order to guarantee we don't mess with concurrent requests.

        Show
        elecharny Emmanuel Lecharny added a comment - I get it. I think the API should be thread safe, and various threads should be able to use the same connection. All in all, the messages are atomic (requests or responses) when they are sent. I guess we have a lot of things to check in the API in order to guarantee we don't mess with concurrent requests.
        Hide
        elecharny Emmanuel Lecharny added a comment -

        Do you mind if I create another issues : 'Make the API thread safe' ?

        Show
        elecharny Emmanuel Lecharny added a comment - Do you mind if I create another issues : 'Make the API thread safe' ?
        Hide
        seelmann Stefan Seelmann added a comment -

        Of course, and no need to fix it for M30

        Show
        seelmann Stefan Seelmann added a comment - Of course, and no need to fix it for M30

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development