OpTimer error while executing post-function scripts

Question

Hi,

we have post function scripts which transition sub-tasks and parent tasks, assign sub-tasks depending on the parent status etc. At times I get the following error:

Finalizer ERROR      [jdbc.interceptors.connection.SafeDelegatingSqlConnectionInterceptor] Unexpected exception from SQL connection interceptor callback: onConnectionReplaced([DelegatingConnectionImpl[connectionPoolInfo=ConnectionPoolInfo{maxSize=20, minSize=20, initialSize=null, maxIdle=20, maxWait=30000, sleepTime=300000, lifeTime=600000, deadLockMaxWait=600000, deadLockRetryWait=10000, validationQuery='select 1', minEvictableTimeMillis=60000, timeBetweenEvictionRunsMillis=300000, poolPreparedStatements=null, testOnBorrow=null, testOnReturn=null, testWhileIdle=true, maxOpenPreparedStatements=null, numTestsPerEvictionRun=null, removeAbandonedTimeout=300, validationQueryTimeout=3, defaultCatalog=null},sqlConnectionInterceptor=org.ofbiz.core.entity.jdbc.interceptors.connection.SafeDelegatingSqlConnectionInterceptor@1910c771], ConnectionPoolStateImpl[timeToBorrowNanos=0,borrowCount=-561,connectionPoolInfo=ConnectionPoolInfo{maxSize=20, minSize=20, initialSize=null, maxIdle=20, maxWait=30000, sleepTime=300000, lifeTime=600000, deadLockMaxWait=600000, deadLockRetryWait=10000, validationQuery='select 1', minEvictableTimeMillis=60000, timeBetweenEvictionRunsMillis=300000, poolPreparedStatements=null, testOnBorrow=null, testOnReturn=null, testWhileIdle=true, maxOpenPreparedStatements=null, numTestsPerEvictionRun=null, removeAbandonedTimeout=300, validationQueryTimeout=3, defaultCatalog=null}]])
java.lang.IllegalStateException: The OpTimer has been re-used.  end() can only be called once!
    at com.atlassian.instrumentation.operations.SimpleOpTimer.end(SimpleOpTimer.java:142)
    at com.atlassian.instrumentation.operations.SimpleOpTimer.end(SimpleOpTimer.java:99)
    at com.atlassian.instrumentation.operations.SimpleOpTimer.end(SimpleOpTimer.java:117)
    at com.atlassian.jira.ofbiz.InstrumentedSQLInterceptor.onConnectionReplaced(InstrumentedSQLInterceptor.java:39)

Especially if my script has to assign a sub task depending on the parent status, I get the above error.

Can someone help me with this please?

thanks

crf · Answer

If your iteration fails, it is not due to this stack trace.  The stack trace clearly reports from the Finalizer thread, and that this not going to be the thread where you are iterating, so it cannot be the cause.

There could very well be some other error reported in the logs that is more relevant.  You could try catching the exception within your script to verify exactly what is interfering.

Vidula Kulkarni · Answer

Thanks for the explanation Chris.

My post function script iterates through the sub tasks of the parent issue and and assigns a particular type of sub task to 'QA Team'.

The exception is in the logs but my script does not execute as this is thrown during the iteration and before auto assigning the sub task. The end result is the sub-task did not get assigned to 'QA Team'.

I inferred from your answer that the script should execute irrespective of the error logged. Is that correct?

We are using JIRA 6.4.12.

crf · Answer

Closing a JDBC connection is meant to be an idempotent operation, however JIRA is wrapping the connection with calls to this OpTimer to help identify queries that take "too long" to execute.  The connection is getting closed multiple times, so the timer is getting "end()" called on it multiple times.  It doesn't know what to report for the same timing operation reaching its end twice, hence the exception.  This is caused by a race between the Finalizer thread and the thread that is running the query.  The Finalizer thinks that it needs to close a connection that has already been closed.

This code changed considerably in 6.4.8 and 7.0.0 to improve the logic around the failsafe cleanup that the Finalizer is doing here.  It then changed again in 7.0.9 to address a race condition introduced by the earlier changes:

https://jira.atlassian.com/browse/JRA-59303

https://ecosystem.atlassian.net/browse/JCHART-462

(and JRA-44608, but that's just a duplicate of the JCHART issue)

Since the error is occurring in the finalizer, and since it is being caught and logged rather than propagating, it is probably harmless except for the log spam.  Figuring out why you are seeing this error in this particular circumstance is pretty difficult, as we would need to know what query created the connection that is getting closed abnormally.