sometimes login issue using ldap users

[saleht]

Hi All,

Regrading the issue which i raise in meeting user 2017. it is blocking issue for us and i will paste here some log maybe this will help us to find the problem.

issue: sometime in Random ldap users trying to log in either from web or Omero.insight it waiting endless

in web after a timeout (nginx 405 Not Allowed)

nginx error log is

Code: Select all

2017/06/08 10:52:30 [error] 13952#0: *3148 upstream prematurely closed connection while reading response header from upstream, client: 134.99.190.4, server: , request: "POST /webclient/login/?url=%2Fwebclient%2F HTTP/1.1", upstream: "http://127.0.0.1:4080/webclient/login/?url=%2Fwebclient%2F", host: "omero-cai.hhu.de", referrer: "https://omero-cai.hhu.de/webclient/login/?url=%2Fwebclient%2F"
2017/06/08 10:57:23 [error] 13952#0: OCSP_basic_verify() failed (SSL: error:27069065:OCSP routines:OCSP_basic_verify:certificate verify error:Verify error:unable to get issuer certificate) while requesting certificate status, responder: ocsp.pca.dfn.de
2017/06/08 10:58:27 [error] 13952#0: *3150 upstream prematurely closed connection while reading response header from upstream, client: 134.99.190.4, server: , request: "POST /webclient/login/?url=%2Fwebclient%2F HTTP/1.1", upstream: "http://127.0.0.1:4080/webclient/login/?url=%2Fwebclient%2F", host: "omero-cai.hhu.de", referrer: "https://omero-cai.hhu.de/webclient/login/?url=%2Fwebclient%2F"


jstack log is

2017-06-08 10:50:20
Full thread dump OpenJDK 64-Bit Server VM (25.131-b12 mixed mode):

"Attach Listener" #25 daemon prio=9 os_prio=0 tid=0x00007fd540001000 nid=0x3868 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"pool-2-thread-5" #24 prio=5 os_prio=0 tid=0x00007fd51400b800 nid=0x24ec waiting on condition [0x00007fd5443cc000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000cf78f0c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
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.run(Thread.java:748)

"pool-2-thread-4" #23 prio=5 os_prio=0 tid=0x00007fd514009800 nid=0x24e1 waiting on condition [0x00007fd5444cd000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000cf78f0c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
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.run(Thread.java:748)

"pool-2-thread-3" #22 prio=5 os_prio=0 tid=0x00007fd514007800 nid=0x24db waiting on condition [0x00007fd5445ce000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000cf78f0c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
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.run(Thread.java:748)

"Indexer-0-Ice.Timer" #21 prio=5 os_prio=0 tid=0x00007fd57dadf800 nid=0x24d9 waiting on condition [0x00007fd5448cf000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000d0324620> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
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.run(Thread.java:748)

"Indexer-0-Ice.ThreadPool.Server-0" #20 prio=5 os_prio=0 tid=0x00007fd57dacf800 nid=0x24d8 runnable [0x00007fd5449d0000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x00000000d0393248> (a sun.nio.ch.Util$3)
- locked <0x00000000d0393238> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000000d0392940> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
at IceInternal.Selector.select(Selector.java:201)
at IceInternal.ThreadPool.run(ThreadPool.java:414)
at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
at java.lang.Thread.run(Thread.java:748)

"pool-2-thread-2" #19 prio=5 os_prio=0 tid=0x00007fd514006800 nid=0x24d7 waiting on condition [0x00007fd544ad1000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000cf78f0c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
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.run(Thread.java:748)

"pool-2-thread-1" #18 prio=5 os_prio=0 tid=0x00007fd514001800 nid=0x24d6 waiting on condition [0x00007fd544bd2000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000cf78f0c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
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.run(Thread.java:748)

"Indexer-0-Ice.ThreadPool.Client-0" #17 prio=5 os_prio=0 tid=0x00007fd57daa0800 nid=0x24d5 runnable [0x00007fd544cd3000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x00000000d03954f8> (a sun.nio.ch.Util$3)
- locked <0x00000000d03954e8> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000000d03952b0> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
at IceInternal.Selector.select(Selector.java:201)
at IceInternal.ThreadPool.run(ThreadPool.java:414)
at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
at java.lang.Thread.run(Thread.java:748)

"OMERO.scheduler_QuartzSchedulerThread" #16 prio=5 os_prio=0 tid=0x00007fd57d435800 nid=0x24d3 waiting on condition [0x00007fd5451d4000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:272)

"metrics-logger-reporter-thread-1" #15 daemon prio=5 os_prio=0 tid=0x00007fd57cf01800 nid=0x24d2 waiting on condition [0x00007fd5452d5000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000cf823d48> (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.run(Thread.java:748)

"Ice.ThreadPool.Client-0" #14 prio=5 os_prio=0 tid=0x00007fd57ccd4000 nid=0x24c6 runnable [0x00007fd568fc8000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x00000000cbbf7e50> (a sun.nio.ch.Util$3)
- locked <0x00000000cbbf7e60> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000000cbbf7e08> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
at IceInternal.Selector.select(Selector.java:201)
at IceInternal.ThreadPool.run(ThreadPool.java:414)
at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
at java.lang.Thread.run(Thread.java:748)

"net.sf.ehcache.CacheManager@33308786" #13 daemon prio=5 os_prio=0 tid=0x00007fd57cc5c800 nid=0x24c4 in Object.wait() [0x00007fd5690c9000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000cbb66088> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000000cbb66088> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)

"PostgreSQL-JDBC-SharedTimer-1" #12 daemon prio=5 os_prio=0 tid=0x00007fd57cc0c800 nid=0x24c0 in Object.wait() [0x00007fd5693ca000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000cbba92f8> (a java.util.TaskQueue)
at java.lang.Object.wait(Object.java:502)
at java.util.TimerThread.mainLoop(Timer.java:526)
- locked <0x00000000cbba92f8> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)

"bitronix-task-scheduler" #11 daemon prio=5 os_prio=0 tid=0x00007fd57cbbb000 nid=0x24be waiting on condition [0x00007fd5694cb000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:245)

"perf4j-async-stats-appender-sink-CoalescingStatistics" #10 daemon prio=5 os_prio=0 tid=0x00007fd57c8d2000 nid=0x2478 waiting on condition [0x00007fd569de3000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000cbb28cc8> (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.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender$StopWatchesFromQueueIterator.getNext(GenericAsyncCoalescingStatisticsAppender.java:388)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender$StopWatchesFromQueueIterator.hasNext(GenericAsyncCoalescingStatisticsAppender.java:349)
at org.perf4j.helpers.GroupingStatisticsIterator.getNext(GroupingStatisticsIterator.java:149)
at org.perf4j.helpers.GroupingStatisticsIterator.hasNext(GroupingStatisticsIterator.java:102)
at org.perf4j.helpers.GenericAsyncCoalescingStatisticsAppender$Dispatcher.run(GenericAsyncCoalescingStatisticsAppender.java:314)
at java.lang.Thread.run(Thread.java:748)

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007fd57c19a800 nid=0x2406 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007fd57c195800 nid=0x2405 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007fd57c194000 nid=0x2404 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007fd57c186800 nid=0x23fd waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007fd57c184800 nid=0x23fb runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007fd57c15a800 nid=0x23f3 in Object.wait() [0x00007fd56afc8000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000cbbf9ab0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked <0x00000000cbbf9ab0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fd57c155800 nid=0x23f1 in Object.wait() [0x00007fd56b0c9000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000cbbf9d38> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000000cbbf9d38> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00007fd57c009000 nid=0x23e6 in Object.wait() [0x00007fd585129000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d0391fd8> (a IceInternal.ObjectAdapterFactory)
at java.lang.Object.wait(Object.java:502)
at IceInternal.ObjectAdapterFactory.waitForShutdown(ObjectAdapterFactory.java:63)
- locked <0x00000000d0391fd8> (a IceInternal.ObjectAdapterFactory)
at Ice.CommunicatorI.waitForShutdown(CommunicatorI.java:32)
at ome.services.blitz.Entry.start(Entry.java:202)
at ome.services.blitz.Entry.main(Entry.java:146)

"VM Thread" os_prio=0 tid=0x00007fd57c14c000 nid=0x23f0 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fd57c01e000 nid=0x23e8 runnable

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fd57c020000 nid=0x23e9 runnable

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fd57c022000 nid=0x23ea runnable

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fd57c023800 nid=0x23eb runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007fd57c19d000 nid=0x2407 waiting on condition

JNI global references: 234

hope this will help, last thing i think the issue realted with java-ldap timeout stuff or seem connection is cashed

cheers
Saleh

[saleht]

Blitz.log file has many Exception ,Error and Warn

Code: Select all


2017-06-08 11:02:33,512 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1496912500053] time[53458] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2017-06-08 11:02:33,512 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:   (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2017-06-08 11:02:33,512 ERROR [        ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork invocation took 53458
2017-06-08 11:02:33,512 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload[5780b200-f502-42a8-bfcd-4683ac9fab7f]
2017-06-08 11:02:33,512 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Args:   [null, InternalSF@391308380]
2017-06-08 11:02:33,520 INFO  [         ome.security.basic.EventHandler] (3-thread-9)  Auth:   user=0,group=0,event=null(Sessions),sess=c4137540-f5f2-4dc4-8a82-d1cb33dde5c4
2017-06-08 11:02:33,524 INFO  [                 org.perf4j.TimingLogger] (3-thread-9) start[1496912477581] time[75943] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2017-06-08 11:02:33,524 INFO  [        ome.services.util.ServiceHandler] (3-thread-9)  Rslt:   (ome.model.meta.Experimenter:Id_103, ome.model.meta.ExperimenterGroup:Id_103, (103, 1, 165, ... 60 more), ... 4 more)
2017-06-08 11:02:33,524 ERROR [        ome.services.util.ServiceHandler] (3-thread-9) Method interface ome.services.util.Executor$Work.doWork invocation took 75943
2017-06-08 11:02:33,525 INFO  [                 org.perf4j.TimingLogger] (.Server-49) start[1496912477579] time[75945] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2017-06-08 11:02:33,525 INFO  [        ome.services.util.ServiceHandler] (.Server-49)  Rslt:   ome.system.SimpleEventContext@88c9299
2017-06-08 11:02:33,525 INFO  [         ome.security.basic.EventHandler] (2-thread-1)  Auth:   user=0,group=0,event=null(Sessions),sess=c4137540-f5f2-4dc4-8a82-d1cb33dde5c4
2017-06-08 11:02:33,525 ERROR [        ome.services.util.ServiceHandler] (.Server-49) Method interface ome.api.IAdmin.getEventContext invocation took 75945
2017-06-08 11:02:33,529 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1496912553512] time[16] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2017-06-08 11:02:33,529 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:   (ome.model.meta.Experimenter:Id_103, ome.model.meta.ExperimenterGroup:Id_103, (103, 1, 165, ... 60 more), ... 4 more)
2017-06-08 11:02:33,529 INFO  [ome.services.sessions.state.SessionCache] (2-thread-1) Destroying session f9abf432-e9c6-465f-b59e-5d002cd7612c due to : Timeout
2017-06-08 11:02:33,529 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1496911644929] time[908600] tag[omero.session]
2017-06-08 11:02:33,535 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload[c4137540-f5f2-4dc4-8a82-d1cb33dde5c4]
2017-06-08 11:02:33,535 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Args:   [null, InternalSF@391308380]
2017-06-08 11:02:33,536 INFO  [         ome.security.basic.EventHandler] (2-thread-1)  Auth:   user=0,group=0,event=null(Sessions),sess=c4137540-f5f2-4dc4-8a82-d1cb33dde5c4
2017-06-08 11:02:33,540 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1496912553535] time[5] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2017-06-08 11:02:33,540 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:   (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2017-06-08 11:02:33,540 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload[d1254bdd-8911-4146-ae7d-11f3de8c52a3]
2017-06-08 11:02:33,540 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Args:   [null, InternalSF@391308380]
2017-06-08 11:02:33,541 INFO  [         ome.security.basic.EventHandler] (2-thread-1)  Auth:   user=0,group=0,event=null(Sessions),sess=c4137540-f5f2-4dc4-8a82-d1cb33dde5c4
2017-06-08 11:02:33,545 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1496912553540] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2017-06-08 11:02:33,545 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:   (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2017-06-08 11:02:33,545 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1496912500053] time[53492] tag[omero.sessions.synchronization]
2017-06-08 11:02:33,545 INFO  [ome.services.sessions.state.SessionCache] (2-thread-1) Synchronization took 53492 ms.
2017-06-08 11:02:53,355 INFO  [                 org.perf4j.TimingLogger] (.Server-44) start[1496911644981] time[928374] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$8.doWork]
2017-06-08 11:02:53,355 INFO  [        ome.services.util.ServiceHandler] (.Server-44)  Rslt:   null
2017-06-08 11:02:53,355 ERROR [        ome.services.util.ServiceHandler] (.Server-44) Method interface ome.services.util.Executor$Work.doWork invocation took 928374
2017-06-08 11:02:53,355 INFO  [        ome.services.util.ServiceHandler] (.Server-44)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW[saleht]
2017-06-08 11:02:53,355 INFO  [        ome.services.util.ServiceHandler] (.Server-44)  Args:   [null, InternalSF@391308380]
2017-06-08 11:02:53,370 INFO  [         ome.security.basic.EventHandler] (.Server-44)  Auth:   user=0,group=0,event=96810(Sessions),sess=c4137540-f5f2-4dc4-8a82-d1cb33dde5c4
2017-06-08 11:02:53,412 INFO  [                 org.perf4j.TimingLogger] (.Server-44) start[1496912573355] time[56] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$9.doWork]
2017-06-08 11:02:53,412 INFO  [        ome.services.util.ServiceHandler] (.Server-44)  Rslt:   true
2017-06-08 11:02:53,413 INFO  [        ome.services.util.ServiceHandler] (.Server-38)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession[]
2017-06-08 11:02:53,413 INFO  [        ome.services.util.ServiceHandler] (.Server-38)  Args:   [null, InternalSF@391308380]
2017-06-08 11:02:53,414 INFO  [    ome.security.basic.BasicEventContext] (.Server-38)  cctx:   group=0
2017-06-08 11:02:53,420 INFO  [         ome.security.basic.EventHandler] (.Server-38)  Auth:   user=0,group=0,event=96811(Sessions),sess=c4137540-f5f2-4dc4-8a82-d1cb33dde5c4
2017-06-08 11:02:53,426 INFO  [       ome.security.basic.CurrentDetails] (.Server-38) Adding log:INSERT,class ome.model.meta.Session,34926
2017-06-08 11:02:53,437 INFO  [                 org.perf4j.TimingLogger] (.Server-38) start[1496912573413] time[23] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2017-06-08 11:02:53,437 INFO  [        ome.services.util.ServiceHandler] (.Server-38)  Rslt:   (ome.model.meta.Experimenter:Id_52, ome.model.meta.ExperimenterGroup:Id_103, (103, 1, 0), ... 4 more)
2017-06-08 11:02:53,439 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-38) Created session ServiceFactoryI(session-ea07ebea-68dc-4916-8c03-0f543619afaa/02f40b55-a225-4197-b983-81776ef09f6c) for user saleht (agent=OMERO.web)
2017-06-08 11:02:53,439 INFO  [o.services.sessions.SessionContext$Count] (.Server-20) -Reference count: 02f40b55-a225-4197-b983-81776ef09f6c=0
2017-06-08 11:02:53,440 INFO  [                      omero.cmd.SessionI] (.Server-20) doDestroy(ServiceFactoryI(session-ea07ebea-68dc-4916-8c03-0f543619afaa/02f40b55-a225-4197-b983-81776ef09f6c))
2017-06-08 11:02:53,440 INFO  [ome.services.sessions.SessionManagerImpl] (.Server-20) closeSession called and no more references: 02f40b55-a225-4197-b983-81776ef09f6c
2017-06-08 11:02:53,440 INFO  [ome.services.sessions.state.SessionCache] (.Server-20) Destroying session 02f40b55-a225-4197-b983-81776ef09f6c due to : Remove session called
2017-06-08 11:02:53,440 INFO  [                 org.perf4j.TimingLogger] (.Server-20) start[1496912573437] time[3] tag[omero.session]
2017-06-08 11:03:00,015 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-2) Performing requestHeartbeats
2017-06-08 11:03:01,547 INFO  [                 org.perf4j.TimingLogger] (.Server-39) start[1496911653291] time[928255] tag[omero.call.exception]
2017-06-08 11:03:01,548 WARN  [        ome.services.util.ServiceHandler] (.Server-39) Unknown exception thrown.

org.springframework.ldap.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
   at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:210) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:319) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:259) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:606) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:524) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at ome.logic.LdapImpl.mapUserName(LdapImpl.java:197) ~[server.jar:na]
   at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174) ~[server.jar:na]
   at ome.logic.LdapImpl.findDN(LdapImpl.java:162) ~[server.jar:na]
   at ome.logic.LdapImpl.lookupLdapAuthExperimenter(LdapImpl.java:689) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.getOmeroDN(LdapPasswordProvider.java:166) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:130) ~[server.jar:na]
   at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:52) ~[server.jar:na]
   at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1197) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:1102) ~[server.jar:na]
   at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) ~[na:na]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) [spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:562) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[spring-orm.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[spring-tx.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) [spring-aop.jar:3.0.1.RELEASE]
   at com.sun.proxy.$Proxy72.doWork(Unknown Source) [na:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:443) [server.jar:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:387) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:1097) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:1069) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:1045) [server.jar:na]
   at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:132) [blitz.jar:na]
   at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:114) [glacier2.jar:na]
   at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:149) [glacier2.jar:na]
   at IceInternal.Incoming.invoke(Incoming.java:221) [ice.jar:na]
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2536) [ice.jar:na]
   at Ice.ConnectionI.dispatch(ConnectionI.java:1145) [ice.jar:na]
   at Ice.ConnectionI.message(ConnectionI.java:1056) [ice.jar:na]
   at IceInternal.ThreadPool.run(ThreadPool.java:395) [ice.jar:na]
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12) [ice.jar:na]
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832) [ice.jar:na]
   at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed
   at com.sun.jndi.ldap.Connection.readReply(Connection.java:454) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:638) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:561) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1985) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1844) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1769) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:392) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:358) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:341) ~[na:1.8.0_131]
   at javax.naming.directory.InitialDirContext.search(InitialDirContext.java:267) ~[na:1.8.0_131]
   at org.springframework.ldap.core.LdapTemplate$4.executeSearch(LdapTemplate.java:253) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:293) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   ... 48 common frames omitted
2017-06-08 11:03:01,548 INFO  [        ome.services.util.ServiceHandler] (.Server-39)  Excp:   org.springframework.ldap.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
2017-06-08 11:03:01,548 ERROR [        ome.services.util.ServiceHandler] (.Server-39) Method interface ome.services.util.Executor$Work.doWork invocation took 928255
2017-06-08 11:03:01,549 ERROR [     o.s.blitz.fire.PermissionsVerifierI] (.Server-39) Exception thrown while checking password for:zobelt
ome.conditions.InternalException:  Wrapped Exception: (org.springframework.ldap.ServiceUnavailableException):
ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
   at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:210) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:319) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:259) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:606) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:524) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at ome.logic.LdapImpl.mapUserName(LdapImpl.java:197) ~[server.jar:na]
   at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174) ~[server.jar:na]
   at ome.logic.LdapImpl.findDN(LdapImpl.java:162) ~[server.jar:na]
   at ome.logic.LdapImpl.lookupLdapAuthExperimenter(LdapImpl.java:689) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.getOmeroDN(LdapPasswordProvider.java:166) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:130) ~[server.jar:na]
   at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:52) ~[server.jar:na]
   at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1197) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:1102) ~[server.jar:na]
   at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) ~[na:na]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:562) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[spring-orm.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[spring-tx.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) ~[spring-aop.jar:3.0.1.RELEASE]
   at com.sun.proxy.$Proxy72.doWork(Unknown Source) ~[na:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:443) ~[server.jar:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:387) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:1097) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:1069) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:1045) ~[server.jar:na]
   at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:132) ~[blitz.jar:na]
   at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:114) [glacier2.jar:na]
   at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:149) [glacier2.jar:na]
   at IceInternal.Incoming.invoke(Incoming.java:221) [ice.jar:na]
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2536) [ice.jar:na]
   at Ice.ConnectionI.dispatch(ConnectionI.java:1145) [ice.jar:na]
   at Ice.ConnectionI.message(ConnectionI.java:1056) [ice.jar:na]
   at IceInternal.ThreadPool.run(ThreadPool.java:395) [ice.jar:na]
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12) [ice.jar:na]
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832) [ice.jar:na]
   at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
2017-06-08 11:03:09,227 INFO  [                 org.perf4j.TimingLogger] (.Server-40) start[1496911660971] time[928255] tag[omero.call.exception]
2017-06-08 11:03:09,228 WARN  [        ome.services.util.ServiceHandler] (.Server-40) Unknown exception thrown.

org.springframework.ldap.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
   at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:210) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:319) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:259) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:606) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:524) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at ome.logic.LdapImpl.mapUserName(LdapImpl.java:197) ~[server.jar:na]
   at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174) ~[server.jar:na]
   at ome.logic.LdapImpl.findDN(LdapImpl.java:162) ~[server.jar:na]
   at ome.logic.LdapImpl.lookupLdapAuthExperimenter(LdapImpl.java:689) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.getOmeroDN(LdapPasswordProvider.java:166) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:130) ~[server.jar:na]
   at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:52) ~[server.jar:na]
   at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1197) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:1102) ~[server.jar:na]
   at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) ~[na:na]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) [spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:562) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[spring-orm.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[spring-tx.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) [spring-aop.jar:3.0.1.RELEASE]
   at com.sun.proxy.$Proxy72.doWork(Unknown Source) [na:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:443) [server.jar:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:387) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:1097) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:1069) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:1045) [server.jar:na]
   at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:132) [blitz.jar:na]
   at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:114) [glacier2.jar:na]
   at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:149) [glacier2.jar:na]
   at IceInternal.Incoming.invoke(Incoming.java:221) [ice.jar:na]
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2536) [ice.jar:na]
   at Ice.ConnectionI.dispatch(ConnectionI.java:1145) [ice.jar:na]
   at Ice.ConnectionI.message(ConnectionI.java:1056) [ice.jar:na]
   at IceInternal.ThreadPool.run(ThreadPool.java:395) [ice.jar:na]
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12) [ice.jar:na]
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832) [ice.jar:na]
   at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed
   at com.sun.jndi.ldap.Connection.readReply(Connection.java:454) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:638) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:561) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1985) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1844) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1769) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:392) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:358) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:341) ~[na:1.8.0_131]
   at javax.naming.directory.InitialDirContext.search(InitialDirContext.java:267) ~[na:1.8.0_131]
   at org.springframework.ldap.core.LdapTemplate$4.executeSearch(LdapTemplate.java:253) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:293) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   ... 48 common frames omitted
2017-06-08 11:03:09,228 INFO  [        ome.services.util.ServiceHandler] (.Server-40)  Excp:   org.springframework.ldap.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
2017-06-08 11:03:09,228 ERROR [        ome.services.util.ServiceHandler] (.Server-40) Method interface ome.services.util.Executor$Work.doWork invocation took 928255
2017-06-08 11:03:09,229 ERROR [     o.s.blitz.fire.PermissionsVerifierI] (.Server-40) Exception thrown while checking password for:zobelt
ome.conditions.InternalException:  Wrapped Exception: (org.springframework.ldap.ServiceUnavailableException):
ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
   at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:210) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:319) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:259) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:606) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:524) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at ome.logic.LdapImpl.mapUserName(LdapImpl.java:197) ~[server.jar:na]
   at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174) ~[server.jar:na]
   at ome.logic.LdapImpl.findDN(LdapImpl.java:162) ~[server.jar:na]
   at ome.logic.LdapImpl.lookupLdapAuthExperimenter(LdapImpl.java:689) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.getOmeroDN(LdapPasswordProvider.java:166) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:130) ~[server.jar:na]
   at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:52) ~[server.jar:na]
   at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1197) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:1102) ~[server.jar:na]
   at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) ~[na:na]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:562) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[spring-orm.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[spring-tx.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) ~[spring-aop.jar:3.0.1.RELEASE]
   at com.sun.proxy.$Proxy72.doWork(Unknown Source) ~[na:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:443) ~[server.jar:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:387) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:1097) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:1069) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:1045) ~[server.jar:na]
   at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:132) ~[blitz.jar:na]
   at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:114) [glacier2.jar:na]
   at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:149) [glacier2.jar:na]
   at IceInternal.Incoming.invoke(Incoming.java:221) [ice.jar:na]
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2536) [ice.jar:na]
   at Ice.ConnectionI.dispatch(ConnectionI.java:1145) [ice.jar:na]
   at Ice.ConnectionI.message(ConnectionI.java:1056) [ice.jar:na]
   at IceInternal.ThreadPool.run(ThreadPool.java:395) [ice.jar:na]
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12) [ice.jar:na]
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832) [ice.jar:na]
   at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
2017-06-08 11:03:11,787 INFO  [                 org.perf4j.TimingLogger] (.Server-41) start[1496911663531] time[928256] tag[omero.call.exception]
2017-06-08 11:03:11,789 WARN  [        ome.services.util.ServiceHandler] (.Server-41) Unknown exception thrown.

org.springframework.ldap.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
   at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:210) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:319) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:259) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:606) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:524) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at ome.logic.LdapImpl.mapUserName(LdapImpl.java:197) ~[server.jar:na]
   at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174) ~[server.jar:na]
   at ome.logic.LdapImpl.findDN(LdapImpl.java:162) ~[server.jar:na]
   at ome.logic.LdapImpl.lookupLdapAuthExperimenter(LdapImpl.java:689) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.getOmeroDN(LdapPasswordProvider.java:166) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:130) ~[server.jar:na]
   at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:52) ~[server.jar:na]
   at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1197) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:1102) ~[server.jar:na]
   at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) ~[na:na]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) [spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:562) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[spring-orm.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[spring-tx.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) [spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) [spring-aop.jar:3.0.1.RELEASE]
   at com.sun.proxy.$Proxy72.doWork(Unknown Source) [na:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:443) [server.jar:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:387) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:1097) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:1069) [server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:1045) [server.jar:na]
   at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:132) [blitz.jar:na]
   at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:114) [glacier2.jar:na]
   at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:149) [glacier2.jar:na]
   at IceInternal.Incoming.invoke(Incoming.java:221) [ice.jar:na]
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2536) [ice.jar:na]
   at Ice.ConnectionI.dispatch(ConnectionI.java:1145) [ice.jar:na]
   at Ice.ConnectionI.message(ConnectionI.java:1056) [ice.jar:na]
   at IceInternal.ThreadPool.run(ThreadPool.java:395) [ice.jar:na]
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12) [ice.jar:na]
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832) [ice.jar:na]
   at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed
   at com.sun.jndi.ldap.Connection.readReply(Connection.java:454) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:638) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:561) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1985) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1844) ~[na:1.8.0_131]
   at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1769) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:392) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:358) ~[na:1.8.0_131]
   at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:341) ~[na:1.8.0_131]
   at javax.naming.directory.InitialDirContext.search(InitialDirContext.java:267) ~[na:1.8.0_131]
   at org.springframework.ldap.core.LdapTemplate$4.executeSearch(LdapTemplate.java:253) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:293) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   ... 48 common frames omitted
2017-06-08 11:03:11,789 INFO  [        ome.services.util.ServiceHandler] (.Server-41)  Excp:   org.springframework.ldap.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
2017-06-08 11:03:11,789 ERROR [        ome.services.util.ServiceHandler] (.Server-41) Method interface ome.services.util.Executor$Work.doWork invocation took 928256
2017-06-08 11:03:11,789 ERROR [     o.s.blitz.fire.PermissionsVerifierI] (.Server-41) Exception thrown while checking password for:zobelt
ome.conditions.InternalException:  Wrapped Exception: (org.springframework.ldap.ServiceUnavailableException):
ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
   at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:210) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:319) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:259) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:606) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:524) ~[spring-ldap-core.jar:1.3.0.RELEASE]
   at ome.logic.LdapImpl.mapUserName(LdapImpl.java:197) ~[server.jar:na]
   at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174) ~[server.jar:na]
   at ome.logic.LdapImpl.findDN(LdapImpl.java:162) ~[server.jar:na]
   at ome.logic.LdapImpl.lookupLdapAuthExperimenter(LdapImpl.java:689) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.getOmeroDN(LdapPasswordProvider.java:166) ~[server.jar:na]
   at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:130) ~[server.jar:na]
   at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:52) ~[server.jar:na]
   at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1197) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:1102) ~[server.jar:na]
   at sun.reflect.GeneratedMethodAccessor306.invoke(Unknown Source) ~[na:na]
   at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
   at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
   at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:562) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[spring-orm.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[spring-tx.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[server.jar:na]
   at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
   at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) ~[spring-aop.jar:3.0.1.RELEASE]
   at com.sun.proxy.$Proxy72.doWork(Unknown Source) ~[na:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:443) ~[server.jar:na]
   at ome.services.util.Executor$Impl.execute(Executor.java:387) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:1097) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:1069) ~[server.jar:na]
   at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:1045) ~[server.jar:na]
   at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:132) ~[blitz.jar:na]
   at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:114) [glacier2.jar:na]
   at Glacier2._PermissionsVerifierDisp.__dispatch(_PermissionsVerifierDisp.java:149) [glacier2.jar:na]
   at IceInternal.Incoming.invoke(Incoming.java:221) [ice.jar:na]
   at Ice.ConnectionI.invokeAll(ConnectionI.java:2536) [ice.jar:na]
   at Ice.ConnectionI.dispatch(ConnectionI.java:1145) [ice.jar:na]
   at Ice.ConnectionI.message(ConnectionI.java:1056) [ice.jar:na]
   at IceInternal.ThreadPool.run(ThreadPool.java:395) [ice.jar:na]
   at IceInternal.ThreadPool.access$300(ThreadPool.java:12) [ice.jar:na]
   at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832) [ice.jar:na]
   at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]

[mtbc]

Dear Saleh,

Would it be possible to use some network packet sniffing tool like tcpdump / wireshark to see what happens with the LDAP request from OMERO.server and the reply from your institutional LDAP for both the failed/hung and the successful logins?

Of course, such network traffic capture may contain all manner of confidential data so we would be fine if you could just summarize what you see. It would be good to be able to pin down if the problem is that OMERO somehow fails to properly make the request or fails to act on the response or what. Ideal would be if you could capture the Blitz log for those periods of packet capture.

(Readers from the OME team can see previous logs in QA 17749, 17751.)

Cheers,
Mark

[saleht]

Hi Mark & all,

i traced it with wire shark it seem that socekt timeout issue, because after Ack- Ack connection after a while a request from omero to my ldap not replied by my ldap because the ldap has the connection drop it.
all what i said is a Believe

and now when this situation happen, i am trying to do
bin/omero login
but the terminal is hanged
actually i gave up because i tried many thing and i tested everything , if it is possible someone to check my server remote will be thanks.
i believe that the problem in some where in OMERO server
cheers
Saleh

[mtbc]

Dear Saleh,

Have you been able to inspect the captured wireshark traffic data well enough to tell if there is some suspicious difference between the LDAP requests from OMERO that your institutional server does reply to and those that it doesn't? If there is some clear indication that OMERO is doing something wrong then that might help us to pinpoint the issue. I am not aware of any of our other LDAP users (including ourselves at Dundee!) running into this issue but maybe there is something in those failed LDAP requests that could be a smoking gun? (If anyone else is monitoring this forum thread because they see a similar issue elsewhere then please speak up.)

It might also be checking with your institutional IT if they have any way to set up a test that their LDAP server even receives the failed requests from OMERO and, if so, if it logs any problem with them that explains the lack of response back to OMERO. Given the exact times and IP they may be able to easily dig up some clues for us.

Cheers,
Mark

[saleht]

Hi All,

i found this in Blitz-0.log file

2017-06-20 16:33:34,146 INFO [ ome.services.util.ServiceHandler] (.Server-15) Excp: org.springframework.ldap.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
2017-06-20 16:33:34,146 ERROR [ ome.services.util.ServiceHandler] (.Server-15) Method interface ome.services.util.Executor$Work.doWork invocation took 928254
2017-06-20 16:33:34,147 ERROR [ o.s.blitz.fire.PermissionsVerifierI] (.Server-15) Exception thrown while checking password for:saleht
ome.conditions.InternalException: Wrapped Exception: (org.springframework.ldap.ServiceUnavailableException):
ldaps.ad.hhu.de:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.ad.hhu.de:3268; socket closed; remaining name ''
at org.springframework.ldap.support.LdapUtils.convertLdapException(LdapUtils.java:210) ~[spring-ldap-core.jar:1.3.0.RELEASE]
at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:319) ~[spring-ldap-core.jar:1.3.0.RELEASE]
at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:259) ~[spring-ldap-core.jar:1.3.0.RELEASE]
at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:606) ~[spring-ldap-core.jar:1.3.0.RELEASE]
at org.springframework.ldap.core.LdapTemplate.search(LdapTemplate.java:524) ~[spring-ldap-core.jar:1.3.0.RELEASE]
at ome.logic.LdapImpl.mapUserName(LdapImpl.java:197) ~[server.jar:na]
at ome.logic.LdapImpl.findExperimenter(LdapImpl.java:174) ~[server.jar:na]
at ome.logic.LdapImpl.findDN(LdapImpl.java:162) ~[server.jar:na]
at ome.logic.LdapImpl.lookupLdapAuthExperimenter(LdapImpl.java:689) ~[server.jar:na]
at ome.security.auth.LdapPasswordProvider.getOmeroDN(LdapPasswordProvider.java:166) ~[server.jar:na]
at ome.security.auth.LdapPasswordProvider.checkPassword(LdapPasswordProvider.java:130) ~[server.jar:na]
at ome.security.auth.PasswordProviders.checkPassword(PasswordProviders.java:52) ~[server.jar:na]
at ome.logic.AdminImpl.checkPassword(AdminImpl.java:1197) ~[server.jar:na]
at ome.services.sessions.SessionManagerImpl$9.doWork(SessionManagerImpl.java:1102) ~[server.jar:na]
at sun.reflect.GeneratedMethodAccessor302.invoke(Unknown Source) ~[na:na]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[spring-aop.jar:3.0.1.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) ~[spring-aop.jar:3.0.1.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) ~[spring-aop.jar:3.0.1.RELEASE]
at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:562) ~[server.jar:na]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[spring-orm.jar:3.0.1.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[spring-tx.jar:3.0.1.RELEASE]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249) ~[server.jar:na]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121) ~[server.jar:na]
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[spring-aop.jar:3.0.1.RELEASE]
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) ~[spring-aop.jar:3.0.1.RELEASE]
at com.sun.proxy.$Proxy72.doWork(Unknown Source) ~[na:na]
at ome.services.util.Executor$Impl.execute(Executor.java:443) ~[server.jar:na]
at ome.services.util.Executor$Impl.execute(Executor.java:387) ~[server.jar:na]
at ome.services.sessions.SessionManagerImpl.executeCheckPasswordRW(SessionManagerImpl.java:1097) ~[server.jar:na]
at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:1069) ~[server.jar:na]
at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:1045) ~[server.jar:na]
at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:132) ~[blitz.jar:na]
at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:114) [glacier2.jar:na]

can someone tell me why i have socket closed
ome.conditions.InternalException: Wrapped Exception: (org.springframework.ldap.ServiceUnavailableException):
ldaps.XXXXXX:3268; socket closed; nested exception is javax.naming.ServiceUnavailableException: ldaps.XXXXXXX:3268; socket closed;

[jmoore]

Hi Saleh,

See:

• https://confluence.atlassian.com/crowdk ... 78175.html and the related
• https://jira.atlassian.com/browse/CWD-1942

You can try adjusting the timeout.

This is the Global Catalogue that you are connecting to, right? Was the error the same before? How many return values are you expecting? How long does the query take with ldapsearch?

Cheers,
~Josh.

[saleht]

Hi Josh,
thx for your support
first of all, this new logs are from new test fresh server, it has the same issue similar to our main server
actually i did
what in past you wrote in this link viewtopic.php?f=4&t=7376
i added

Code: Select all

-Dcom.sun.jndi.ldap.connect.pool.timeout=3

after i overwrite ldap.pool.timeout i not getting any Socekt close Error message any more but the issue still reproducible
do suggest to change timeout to another value or what ?
and when this issue occur i can log in for local users(omero native users )

is there any additional timeout key for ldpa, which can also configured
cheers
Saleh

[saleht]

Hi all,

i have one more question, how can i play around java session cashe
because it seems that Omero trying to use session with Active Directory and Active Directory think the session is expired


Saleh

[mtbc]

Dear Saleh,

Have you tried scripting a bunch of ldapsearch queries to see if you can use that to reproduce the same issue from the machine hosting the OMERO server? How do those queries go?

Cheers,
Mark