OpTimer error while executing post-function scripts

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

2 answers

1 vote
Chris Fuller Atlassian Team Feb 28, 2016

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.

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.

Chris Fuller Atlassian Team Feb 28, 2016

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.

Suggest an answer

Log in or Sign up to answer
How to earn badges on the Atlassian Community

How to earn badges on the Atlassian Community

Badges are a great way to show off community activity, whether you’re a newbie or a Champion.

Learn more
Community showcase
Published Thursday in Confluence

Three common content challenges + how to manage them

An efficient enterprise content management system, or ECM, is a must-have for companies that create work online (cough   cough, all companies). If content calendars, marketing plans, and bu...

82 views 0 5
Read article

Atlassian User Groups

Connect with like-minded Atlassian users at free events near you!

Find a group

Connect with like-minded Atlassian users at free events near you!

Find my local user group

Unfortunately there are no AUG chapters near you at the moment.

Start an AUG

You're one step closer to meeting fellow Atlassian users at your local meet up. Learn more about AUGs

Groups near you