ava.lang.IllegalStateException: The OpTimer has been re-used. end() can only be called once!

Atlassian JIRA | Ignat Alexeyenko | 8 months ago
tip
Do you know that we can give you better hits? Get more relevant results from Samebug’s stack trace search.
  1. 0

    Summary Calling rest api in-parallel causes JIRA to return 500 error.   h3. Steps to reproduce Call JIRA rest api for JQL search in parallel (5 threads or more)   h3. Actual results Server starts returning 500 response codes h3. Expected Result Server response without error.   h3. Environment   Script that was used: {code:java} var rest = require('rest'); var mime = require('rest/interceptor/mime'); var client = rest.wrap(mime); var baseUrl = "https://jira.example.com/rest/api/latest/"; client({path: baseUrl + "field?"}).then(function(){ return client({ path: baseUrl + 'project' }); }).then(function (data) { for (var i in data.entity) { var e = data.entity[i]; client({ path: baseUrl + 'search', method: 'POST', headers: { 'Content-Type': 'application/json' }, entity: { jql: 'project = ' + e.key} }).then(function(data) { return client({ path: baseUrl + 'issue/' + data.entity.issues[0].key}); }).then(function(data) { if (!data.entity.key) { console.log(data); } console.log(data.entity.key); }); } }); {code} Running this in parallel (5 times) sometimes returns a 500 server error. The log is full of errors like these:   {code:java} com.atlassian.jira.ofbiz.ConnectionPoolHealthSqlInterceptor: Dangerous use of multiple connections: replaced => count=-1; marks=[-2-0]; pool=-39/-1 com.atlassian.jira.ofbiz.ChainedSQLInterceptor: Unexpected exception in com.atlassian.jira.ofbiz.InstrumentedSQLInterceptor@1c27bb8 The OpTimer has been re-used. end() can only be called once! ava.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) at com.atlassian.jira.ofbiz.ChainedSQLInterceptor.lambda$onConnectionReplaced$445(ChainedSQLInterceptor.java:78) at com.atlassian.jira.ofbiz.ChainedSQLInterceptor$$Lambda$11/6379058.accept(Unknown Source) at com.atlassian.jira.ofbiz.ChainedSQLInterceptor.forEach(ChainedSQLInterceptor.java:107) at com.atlassian.jira.ofbiz.ChainedSQLInterceptor.onConnectionReplaced(ChainedSQLInterceptor.java:77) at org.ofbiz.core.entity.jdbc.interceptors.connection.SafeDelegatingSqlConnectionInterceptor.onConnectionReplaced(SafeDelegatingSqlConnectionInterceptor.java:47) at org.ofbiz.core.entity.jdbc.interceptors.connection.ConnectionTracker$DelegatingConnectionImpl.close(ConnectionTracker.java:99) at org.ofbiz.core.entity.jdbc.ConnectionGuard.closeAbandonedConnection(ConnectionGuard.java:124) at org.ofbiz.core.entity.jdbc.ConnectionGuard.closeAbandonedProcessor(ConnectionGuard.java:112) at org.ofbiz.core.entity.jdbc.ConnectionGuard.closeAbandonedProcessors(ConnectionGuard.java:150) at org.ofbiz.core.entity.jdbc.SQLProcessor.getConnection(SQLProcessor.java:390) at org.ofbiz.core.entity.jdbc.SQLProcessor.prepareStatement(SQLProcessor.java:544) at org.ofbiz.core.entity.jdbc.SQLProcessor.prepareStatement(SQLProcessor.java:522) at com.atlassian.jira.ext.charting.field.AbstractSingleDateDAO.calculateDate(AbstractSingleDateDAO.java:54) at com.atlassian.jira.ext.charting.field.DateOfFirstResponseCFType.calculateFirstResponseDate(DateOfFirstResponseCFType.java:77) at com.atlassian.jira.ext.charting.field.DateOfFirstResponseCFType.getJsonFromIssue(DateOfFirstResponseCFType.java:93) at com.atlassian.jira.issue.fields.CustomFieldImpl.getJsonFromIssue(CustomFieldImpl.java:2260) at com.atlassian.jira.rest.v2.issue.IssueBeanBuilder2.getRepresentationForFields(IssueBeanBuilder2.java:289) at com.atlassian.jira.rest.v2.issue.IssueBeanBuilder2.access$400(IssueBeanBuilder2.java:67) at com.atlassian.jira.rest.v2.issue.IssueBeanBuilder2$8.apply(IssueBeanBuilder2.java:271) at com.atlassian.jira.rest.v2.issue.IssueBeanBuilder2$8.apply(IssueBeanBuilder2.java:264) at com.atlassian.fugue.Iterables$CollectingIterable$Iter.computeNext(Iterables.java:714) at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143) at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138) at com.google.common.collect.Iterators$5.hasNext(Iterators.java:547) at com.google.common.collect.Maps.uniqueIndex(Maps.java:1162) at com.google.common.collect.Maps.uniqueIndex(Maps.java:1140) at com.atlassian.jira.rest.v2.issue.IssueBeanBuilder2.createFieldsData(IssueBeanBuilder2.java:239) at com.atlassian.jira.rest.v2.issue.IssueBeanBuilder2.build(IssueBeanBuilder2.java:163) at com.atlassian.jira.rest.v2.search.SearchResource$IssueToIssueBean.apply(SearchResource.java:323) at com.atlassian.jira.rest.v2.search.SearchResource$IssueToIssueBean.apply(SearchResource.java:304) at com.google.common.collect.Lists$TransformingRandomAccessList$1.transform(Lists.java:617) at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48) at java.util.AbstractCollection.toArray(AbstractCollection.java:141) at java.util.ArrayList.<init>(ArrayList.java:177) at com.google.common.collect.Lists.newArrayList(Lists.java:144) at com.atlassian.jira.rest.v2.search.SearchResource.asResultsBean(SearchResource.java:235) at com.atlassian.jira.rest.v2.search.SearchResource.search(SearchResource.java:183) at com.atlassian.jira.rest.v2.search.SearchResource.searchUsingSearchRequest(SearchResource.java:220) ... 2 filtered at java.lang.reflect.Method.invoke(Method.java:497) ... 5 filtered at com.atlassian.jira.rest.exception.ExceptionInterceptor.intercept(ExceptionInterceptor.java:59) ... 1 filtered at com.atlassian.jira.rest.v2.issue.scope.RequestScopeInterceptor.intercept(RequestScopeInterceptor.java:43) ... 14 filtered at com.atlassian.plugins.rest.module.RestDelegatingServletFilter$JerseyOsgiServletContainer.doFilter(RestDelegatingServletFilter.java:178) ... 1 filtered at com.atlassian.plugins.rest.module.RestDelegatingServletFilter.doFilter(RestDelegatingServletFilter.java:73) ... 40 filtered at com.atlassian.plugins.cors.CorsFilter.doFilter(CorsFilter.java:65) ... 24 filtered at com.atlassian.jira.plugins.rest.HOT25715FixServletFilter.doFilter(HOT25715FixServletFilter.java:46) ... 52 filtered at com.atlassian.plugins.rest.module.servlet.RestSeraphFilter.doFilter(RestSeraphFilter.java:40) ... 92 filtered at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745) org.ofbiz.core.entity.jdbc.SQLProcessor: !!! ABANDONED SQLProcessor DETECTED !!! This probably means that somebody forgot to close an EntityListIterator. Connection: DelegatingConnectionImpl[connectionPoolInfo=ConnectionPoolInfo{maxSize=-1, minSize=-1, initialSize=null, maxIdle=-1, maxWait=-1, sleepTime=-1, lifeTime=-1, deadLockMaxWait=-1, deadLockRetryWait=-1, validationQuery=null, minEvictableTimeMillis=-1, timeBetweenEvictionRunsMillis=-1, poolPreparedStatements=null, testOnBorrow=null, testOnReturn=null, testWhileIdle=null, maxOpenPreparedStatements=null, numTestsPerEvictionRun=null, removeAbandonedTimeout=null, validationQueryTimeout=null, defaultCatalog=null},sqlConnectionInterceptor=org.ofbiz.core.entity.jdbc.interceptors.connection.SafeDelegatingSqlConnectionInterceptor@17df3ad] SQL: select min( act.CREATED) from public.jiraaction act , public.jiraissue it where act.issueid = ? and act.issueid = it.ID and act.actiontype = 'comment' and it.REPORTER != act.AUTHOR {code} Copied from [https://ecosystem.atlassian.net/browse/ACJIRA-486?focusedCommentId=177849&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-177849]

    Atlassian JIRA | 8 months ago | Ignat Alexeyenko
    ava.lang.IllegalStateException: The OpTimer has been re-used. end() can only be called once!

    Root Cause Analysis

    1. ava.lang.IllegalStateException

      The OpTimer has been re-used. end() can only be called once!

      at com.atlassian.instrumentation.operations.SimpleOpTimer.end()
    2. com.atlassian.instrumentation
      SimpleOpTimer.end
      1. com.atlassian.instrumentation.operations.SimpleOpTimer.end(SimpleOpTimer.java:142)
      2. com.atlassian.instrumentation.operations.SimpleOpTimer.end(SimpleOpTimer.java:99)
      3. com.atlassian.instrumentation.operations.SimpleOpTimer.end(SimpleOpTimer.java:117)
      3 frames
    3. com.atlassian.jira
      ChainedSQLInterceptor.lambda$onConnectionReplaced$445
      1. com.atlassian.jira.ofbiz.InstrumentedSQLInterceptor.onConnectionReplaced(InstrumentedSQLInterceptor.java:39)
      2. com.atlassian.jira.ofbiz.ChainedSQLInterceptor.lambda$onConnectionReplaced$445(ChainedSQLInterceptor.java:78)
      2 frames