WriteTimeoutHandler throw an IllegalStateException

[arcadmlafon]

For a reason I can not explain, the com.unboundid.ldap.sdk.WriteTimeoutHandler try to schedule a task on a cancelled Timer:

Caused by: java.lang.IllegalStateException: Timer already cancelled.
at java.util.Timer.sched(Timer.java:397)
at java.util.Timer.schedule(Timer.java:248)
at com.unboundid.ldap.sdk.WriteTimeoutHandler.(WriteTimeoutHandler.java:138)
at com.unboundid.ldap.sdk.LDAPConnectionInternals.(LDAPConnectionInternals.java:178)

This error appears from time to time while getting a new connection from a pool through the following call stack:

at com.unboundid.ldap.sdk.LDAPConnection.connect(LDAPConnection.java:915)
at com.unboundid.ldap.sdk.LDAPConnection.connect(LDAPConnection.java:802)
at com.unboundid.ldap.sdk.LDAPConnection.connect(LDAPConnection.java:740)
at com.unboundid.ldap.sdk.LDAPConnection.(LDAPConnection.java:560)
at com.unboundid.ldap.sdk.SingleServerSet.getConnection(SingleServerSet.java:329)
at com.unboundid.ldap.sdk.FailoverServerSet.getConnection(FailoverServerSet.java:688)
at com.unboundid.ldap.sdk.LDAPConnectionPool.createConnection(LDAPConnectionPool.java:1297)
at com.unboundid.ldap.sdk.LDAPConnectionPool.createConnection(LDAPConnectionPool.java:1269)
at com.unboundid.ldap.sdk.LDAPConnectionPool.getConnection(LDAPConnectionPool.java:1866)
...

When the problem occurs, it seams to deadlock the LDAP connections and we need to shutdown our program to be able to reconnect with the LDAP server... anyway this is really hard to reproduce, and quite impossible to reproduce in debug.

The UnboundId library used in version 6.0.5, with Java 1.8.

I can't see how the timer could be cancelled before it is used to schedule a new task, the synchronization block look correct... may except the cancel() method call in the destroy() one which should be synchronized too (because the Timer's purge() method may cancel the timer if the task is the last one...)

I am going to try to get more information on what could have been append before this error occurs. And make more test with higher versions (of UndoundID and Java).

[dirmgr]

I spent some time looking into this, and I’m having a hard time seeing how this could happen. The synchronization all looks correct to me, and I don’t think that it’s necessary to have the cancel call be synchronized because neither TimerTask.cancel nor Timer.purge should affect the validity of the Timer itself.

The exception stack trace that you’ve provided shows that it’s happening when a new WriteTimeoutHandler is being created. In that case, the TIMER_REFERENCE has a non-null value, and the associated Timer instance should be valid because we only ever invalidate it in a synchronized block, and when that happens, it’s only after we have set the TIMER_REFERENCE value to null.

The only thing I can think of is a possible bug in the Timer implementation itself. The “Timer already cancelled” message looks like it should only be called if TimerThread.newTasksMayBeScheduled is false, and that’s only set to false if Timer.mainLoop exits, which would be if the queue is empty after a call to queue.wait. Perhaps there is some bug in the Java SE code that could cause the queue to be empty after a wait?

I don’t believe that there have been any substantial changes around this code in the LDAP SDK for a while, but since you’re going to be testing on new LDAP SDK versions and new Java versions, then please let me know if you still see it with the latest versions.

[arcadmlafon]

yes, I agree. I don't know how the program gets to this state my hypothesis is that something serious is happening rather that breaks the system... but I don't have any information yet (possibly it's not even related to the LDAP connection...)

I'll keep you informed, thanks for the time spent.

[frankk3]

Hello everyone,

since this kind of java.lang.IllegalStateException is also thrown if the timer thread died for any reason (e.g. due to serious java.lang.Error, or an uncaught runtime exception), it might be useful to have a look at standard out and especially standard error of the JVM process, in addition to the application log.

Could be an issue on getting the system time, or on concurrently iterating over the writeTimeouts. That would be from my point of view a JRE issue, since the javadoc states that the view's iterators and spliterators are weakly consistent, i.e. may proceed concurrently with other operations and will never throw ConcurrentModificationException.

Just to get an impression what’s going on here.

[arcadmlafon]

Hi, I was not able to reproduce this problem in my dev environment and I did not get any more information about the context, logs or anything... As the JVM used initially is a java 1.8 version (and not the latest one I assume) and as the process is server highly busy, a side effect due to a failure elsewhere in the code is the most likely.

I think that you (or I ?) can close this ticket, I will come back if I have any new clue on this !

Thanks again for your help.