Index Failed and had to abort almost completed update

[Deleted user]

Sunday night I ran an update to our JIRA Core (8.4.2)/Server/Service Desk and Confluence applications (all on the same server). The updates went swimmingly, and I also updated all plug-ins for both platforms and ran through our fairly comprehensive checklist to make sure the functionality we depend on was in place.

The final step I performed, since I noted it hadn’t been completed, ever I think, was to manually re-index JIRA.

This is where things went off the rails. Firstly, we’re a small organization, with about 10,000 issues total across a half dozen projects in JIRA. Thus, we use a low-powered Amazon instance to run it (using a m5a.large 2vcpu/8GB RAM) which I upgraded recently from a smaller instance with half the RAM that served both systems for 3+ years. Running Amazon's AMI Linux (which is a variant of CentOS) btw.

The re-index reported it would take “minutes” to run, and since background re-indexes usually take 15 min….I expected the same or less. Boy was I in for a 11:30pm-on-a-Sunday-night surprise when it C R A W L E D to 1% in 10 minutes, 2% in 20 minutes (or something like this…I extrapolated a 6-7 hour re-index). I let it run and did some other things and checked on it an hour later to have found it was now reporting there was no index at all.

“wut?”

JIRA was working despite this…but I had to decide now what vulnerability would I be exposing our company to Monday morning if I didn’t resolve this. Now…JAVA is pretty poorly designed imho and I have in the past ran into issues with memory, and I did see that the index operation chews up a fair amount of cpu. So, I stopped the instance and bumped it up to one with 12vCPU and 32GB RAM, hoping this would let it finish. This time it progressed pretty quickly, but at 13% if stopped again. Nothing in the web interface to explain the failure.

Now, real talk, JIRA’s logging is the most verbose, noisy logging I have ever seen in my 15+ years in IT. But yeah, I guess you get used to it since there are just so many problems with this software over the years, but for the life of me I couldn’t ascertain any specifics to the problem.

As I searched for others having the same issues...they always seemed to have some specific cause in their /var/atlassian/application-data/jira/log/atlassian-jira.log file. Maybe it's just me, but there wasn't much to go on here:

2019-10-21 00:04:48,751 hipchat-client:thread-5 WARN [c.a.p.h.connect.synchronise.ModifyDescriptorSynchronisationActivity] Unable to upgrade capabilities - will retry after 480000 milli
seconds...
2019-10-21 00:04:55,722 IssueIndexer:thread-5 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing
is 8% complete. Current index: Issue
2019-10-21 00:05:06,254 plugin-transaction-0 INFO [c.a.jira.plugin.PluginTransactionListener] [plugin-transaction] numberStartEvents:715, numberEndEvents:715, numberSendEvents:398, numb
erEventsInTransactions:13327, numberOfPluginEnableEvents:304
2019-10-21 00:05:23,808 IssueIndexer:thread-1 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing
is 9% complete. Current index: Issue
2019-10-21 00:06:05,176 IssueIndexer:thread-11 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexin
g is 10% complete. Current index: Issue
2019-10-21 00:06:17,125 indexing-stats-0 INFO [c.a.j.issue.index.IndexingStatsManager] [indexing-stats] Top 10 addIndex total (noFieldIndexers: 203, sum: 4609082ms): [{field: customfiel
d_11300 (Approvals), addIndex: {sum/allSum:10.4%, sum:479113ms, avg:372.6ms, max:10512ms, count:1286}}, {field: customfield_10304 (Time to resolution), addIndex: {sum/allSum:7.1%, sum:327676
ms, avg:254.8ms, max:13488ms, count:1286}}, {field: customfield_10006 (Epic Link), addIndex: {sum/allSum:5.9%, sum:271053ms, avg:211.9ms, max:6328ms, count:1279}}, {field: customfield_12400
(JQLComment), addIndex: {sum/allSum:5.6%, sum:256855ms, avg:199.4ms, max:5345ms, count:1288}}, {field: issuelinks, addIndex: {sum/allSum:4.8%, sum:221652ms, avg:173.7ms, max:6106ms, count:12
76}}, {field: customfield_10009 (Rank), addIndex: {sum/allSum:3.5%, sum:159312ms, avg:124.8ms, max:3534ms, count:1277}}, {field: customfield_10004 (Sprint), addIndex: {sum/allSum:3.0%, sum:1
40324ms, avg:110.1ms, max:3222ms, count:1274}}, {field: attachment, addIndex: {sum/allSum:2.6%, sum:121119ms, avg:94.8ms, max:2934ms, count:1278}}, {field: customfield_10001 (Epic/Theme), ad
dIndex: {sum/allSum:2.6%, sum:120625ms, avg:94.8ms, max:3786ms, count:1272}}, {field: labels, addIndex: {sum/allSum:2.4%, sum:110888ms, avg:87.1ms, max:5352ms, count:1273}}]
2019-10-21 00:06:17,126 indexing-stats-0 INFO [c.a.j.issue.index.IndexingStatsManager] [indexing-stats] Top 10 addIndex snapshot (noFieldIndexers: 203, sum: 2913827ms): [{field: customf
ield_11300 (Approvals), addIndex: {sum/allSum:11.2%, sum:327679ms, avg:337.1ms, max:6372ms, count:972}}, {field: customfield_10304 (Time to resolution), addIndex: {sum/allSum:6.7%, sum:19621
5ms, avg:202.1ms, max:4455ms, count:971}}, {field: customfield_10006 (Epic Link), addIndex: {sum/allSum:6.3%, sum:182182ms, avg:188.4ms, max:3654ms, count:967}}, {field: customfield_12400 (J
QLComment), addIndex: {sum/allSum:5.7%, sum:165620ms, avg:170.2ms, max:2476ms, count:973}}, {field: issuelinks, addIndex: {sum/allSum:4.8%, sum:140798ms, avg:145.8ms, max:5447ms, count:966}}
, {field: customfield_10009 (Rank), addIndex: {sum/allSum:3.6%, sum:104641ms, avg:108.2ms, max:3094ms, count:967}}, {field: customfield_10004 (Sprint), addIndex: {sum/allSum:3.2%, sum:93904m
s, avg:97.2ms, max:3222ms, count:966}}, {field: attachment, addIndex: {sum/allSum:2.8%, sum:81372ms, avg:84.1ms, max:2603ms, count:967}}, {field: fixVersions, addIndex: {sum/allSum:2.5%, sum
:72796ms, avg:75.4ms, max:2323ms, count:966}}, {field: watcher, addIndex: {sum/allSum:2.5%, sum:72769ms, avg:75.1ms, max:2272ms, count:969}}]
2019-10-21 00:06:34,370 automation-queue-claimer:thread-1 WARN [c.c.j.p.automation.queue.JiraAutomationQueueExecutor] JQL search indexes are currently not available (Indexing: false, Sc
heduler: STANDBY). No automation items were claimed from the queue for processing on this node since most automation rules depend on JQL indexes being available.
2019-10-21 00:07:00,112 IssueIndexer:thread-16 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexin
g is 11% complete. Current index: Issue
2019-10-21 00:07:26,015 IssueIndexer:thread-15 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexin
g is 12% complete. Current index: Issue
2019-10-21 00:07:46,732 JiraTaskExecutionThread-1 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.jira.index.MonitoringIndexWriter] [lucene
-stats] flush stats: snapshotCount=48, totalCount=88, periodSec=275, flushIntervalMillis=5744, indexDirectory=/var/atlassian/application-data/jira/caches/indexesV1/comments, indexWriterId=co
m.atlassian.jira.index.MonitoringIndexWriter@221f3a6a, indexDirectoryId=MMapDirectory@/var/atlassian/application-data/jira/caches/indexesV1/comments lockFactory=org.apache.lucene.store.Nativ
eFSLockFactory@7f846bef
2019-10-21 00:07:47,685 JiraTaskExecutionThread-1 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.jira.index.MonitoringIndexWriter] [lucene
-stats] flush stats: snapshotCount=190, totalCount=285, periodSec=289, flushIntervalMillis=1521, indexDirectory=/var/atlassian/application-data/jira/caches/indexesV1/issues, indexWriterId=co
m.atlassian.jira.index.MonitoringIndexWriter@425fa656, indexDirectoryId=MMapDirectory@/var/atlassian/application-data/jira/caches/indexesV1/issues lockFactory=org.apache.lucene.store.NativeF
SLockFactory@7f846bef
2019-10-21 00:07:47,686 JiraTaskExecutionThread-1 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.jira.index.MonitoringIndexWriter] [lucene
-stats] flush stats: snapshotCount=44, totalCount=70, periodSec=276, flushIntervalMillis=6288, indexDirectory=/var/atlassian/application-data/jira/caches/indexesV1/changes, indexWriterId=com
.atlassian.jira.index.MonitoringIndexWriter@5e76112e, indexDirectoryId=MMapDirectory@/var/atlassian/application-data/jira/caches/indexesV1/changes lockFactory=org.apache.lucene.store.NativeF
SLockFactory@7f846bef

019-10-21 00:07:47,688 JiraTaskExecutionThread-1 ERROR <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.j.util.index.CompositeIndexLifecycleMana
ger] Reindex All FAILED. Indexer: DefaultIndexManager: paths: [/var/atlassian/application-data/jira/caches/indexesV1/comments, /var/atlassian/application-data/jira/caches/indexesV1/issues,
/var/atlassian/application-data/jira/caches/indexesV1/changes, /var/atlassian/application-data/jira/caches/indexesV1/worklogs, /var/atlassian/application-data/jira/caches/indexesV1/plugins/s
ervicedeskcannedresponses]
org.ofbiz.core.util.GeneralRuntimeException: Error getting the next result (Operation not allowed after ResultSet closed)
at org.ofbiz.core.entity.EntityListIterator.next(EntityListIterator.java:272)
at com.atlassian.jira.ofbiz.DefaultOfBizListIterator.next(DefaultOfBizListIterator.java:100)
at com.atlassian.jira.ofbiz.WrappingOfBizListIterator.next(WrappingOfBizListIterator.java:68)
at com.atlassian.jira.issue.util.DatabaseIssuesIterator.pullNextIssue(DatabaseIssuesIterator.java:97)
at com.atlassian.jira.issue.util.DatabaseIssuesIterator.populateNextIssueIfNull(DatabaseIssuesIterator.java:68)
at com.atlassian.jira.issue.util.DatabaseIssuesIterator.hasNext(DatabaseIssuesIterator.java:51)
at com.atlassian.jira.issue.util.DatabaseIssuesIterable.foreach(DatabaseIssuesIterable.java:55)
at com.atlassian.jira.issue.index.DefaultIssueIndexer.perform(DefaultIssueIndexer.java:335)
at com.atlassian.jira.issue.index.DefaultIssueIndexer.indexIssuesBatchMode(DefaultIssueIndexer.java:182)
at com.atlassian.jira.issue.index.DefaultIssueIndexer.indexIssuesBatchMode(DefaultIssueIndexer.java:198)
at com.atlassian.jira.issue.index.DefaultIndexManager.doIndexIssuesInBatchMode(DefaultIndexManager.java:1023)
at com.atlassian.jira.issue.index.DefaultIndexManager.doStopTheWorldReindex(DefaultIndexManager.java:1002)
at com.atlassian.jira.issue.index.DefaultIndexManager.lambda$reIndexAll$0(DefaultIndexManager.java:331)
at com.atlassian.jira.issue.index.DefaultIndexManager.withReindexLock(DefaultIndexManager.java:378)
at com.atlassian.jira.issue.index.DefaultIndexManager.reIndexAll(DefaultIndexManager.java:331)
at com.atlassian.jira.issue.index.DefaultIndexManager.reIndexAll(DefaultIndexManager.java:264)
... 3 filtered
at java.lang.reflect.Method.invoke(Method.java:498)
at com.atlassian.jira.config.component.SwitchingInvocationHandler.invoke(SwitchingInvocationHandler.java:38)
at com.sun.proxy.$Proxy8.reIndexAll(Unknown Source)
at com.atlassian.jira.util.index.CompositeIndexLifecycleManager.reIndexAll(CompositeIndexLifecycleManager.java:66)
at com.atlassian.jira.util.index.CompositeIndexLifecycleManager.reIndexAll(CompositeIndexLifecycleManager.java:49)
at com.atlassian.jira.web.action.admin.index.ReIndexAsyncIndexerCommand.doReindex(ReIndexAsyncIndexerCommand.java:27)
at com.atlassian.jira.web.action.admin.index.AbstractAsyncIndexerCommand.call(AbstractAsyncIndexerCommand.java:63)
at com.atlassian.jira.web.action.admin.index.ReIndexAsyncIndexerCommand.call(ReIndexAsyncIndexerCommand.java:18)
at com.atlassian.jira.web.action.admin.index.AbstractAsyncIndexerCommand.call(AbstractAsyncIndexerCommand.java:26)
at com.atlassian.jira.task.TaskManagerImpl$TaskCallableDecorator.call(TaskManagerImpl.java:537)
at com.atlassian.jira.task.TaskManagerImpl$TaskCallableDecorator.call(TaskManagerImpl.java:495)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at com.atlassian.jira.task.ForkedThreadExecutor$ForkedRunnableDecorator.run(ForkedThreadExecutor.java:216)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.sql.SQLException: Operation not allowed after ResultSet closed
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:963)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:896)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:885)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)
at com.mysql.jdbc.ResultSetImpl.checkClosed(ResultSetImpl.java:743)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
at org.ofbiz.core.entity.EntityListIterator.next(EntityListIterator.java:266)
... 34 more
2019-10-21 00:07:47,705 JiraTaskExecutionThread-1 INFO <USER REDACTED> 1437x97x1 10ktc1z 66.229.209.124 /secure/admin/IndexReIndex!reindex.jspa [c.a.jira.index.MonitoringIndexWriter] [lucene
-stats] flush stats: snapshotCount=2, totalCount=2, periodSec=0, flushIntervalMillis=4, indexDirectory=/var/atlassian/application-data/jira/caches/indexesV1/entities/searchrequest, indexWrit
erId=com.atlassian.jira.index.MonitoringIndexWriter@7b72af27, indexDirectoryId=MMapDirectory@/var/atlassian/application-data/jira/caches/indexesV1/entities/searchrequest lockFactory=org.apac
he.lucene.store.NativeFSLockFactory@7f846bef

com.atlassian.jira.index.IndexingFailureException: Indexing completed with 1 errors
at com.atlassian.jira.util.index.CompositeIndexLifecycleManager.reIndexAll(CompositeIndexLifecycleManager.java:83)
at com.atlassian.jira.util.index.CompositeIndexLifecycleManager.reIndexAll(CompositeIndexLifecycleManager.java:49)
at com.atlassian.jira.web.action.admin.index.ReIndexAsyncIndexerCommand.doReindex(ReIndexAsyncIndexerCommand.java:27)
at com.atlassian.jira.web.action.admin.index.AbstractAsyncIndexerCommand.call(AbstractAsyncIndexerCommand.java:63)
at com.atlassian.jira.web.action.admin.index.ReIndexAsyncIndexerCommand.call(ReIndexAsyncIndexerCommand.java:18)
at com.atlassian.jira.web.action.admin.index.AbstractAsyncIndexerCommand.call(AbstractAsyncIndexerCommand.java:26)
at com.atlassian.jira.task.TaskManagerImpl$TaskCallableDecorator.call(TaskManagerImpl.java:537)
at com.atlassian.jira.task.TaskManagerImpl$TaskCallableDecorator.call(TaskManagerImpl.java:495)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at com.atlassian.jira.task.ForkedThreadExecutor$ForkedRunnableDecorator.run(ForkedThreadExecutor.java:216)
at java.lang.Thread.run(Thread.java:748)

At 12:45am Monday I had to bail. I could not find any meaningful explanation for this and since our small company committed to this software before the bait and switch to community support a couple years ago it’s not like I could open a real support ticket. Fortunately, part of this upgrade process is to make a snapshot of the server/db/db dumps…so I successfully reverted to the pre-upgrade snapshots…there’s 3-4 hours of my life and an upgrade window I won’t get back.

My next step is to snapshot and manually re-index on our current installed version (7.13.2) when I can find a maintenance window (because in the real world its hard to make time to put the project management and service desk in an inaccessible state) to see if that works, but before I did that I was hoping someone more knowledgeable in these things could help me more fully understand the necessity and/or ramifications of this. Maybe it was dumb to push the button right after an upgrade? Any input is appreciated.

[Earl McCutcheon]

Hi Nick,

Thanks for all the details and looking over the error stacks the one that is sticking out to me the most is the error:

Reindex All FAILED.

This particular error has the following KB article with some troubleshooting steps to look at for a few different possible causes:

• Troubleshoot a reindex failure in Jira server

and from that KB a few of the errors were from older versions of the application and have already been fixed but the listed BUG: JSWSERVER-16473  is the most likely culprit where a NULL value has somehow occurred for a issuenum value in the database, but check out the troubleshooting steps in the KB and let me know what you find.

Regards,
Earl

[Deleted user]

Hi Earl,

I've tested all but one of the potential causes (one remains simply because I haven't been able to give it proper focus because of current workloads). Hopefully I can do that later today or Sunday night.

I'll let you know then.

Thanks!

-Nick

[BetterLife]

Hi Nick

Any luck in getting this resolved?  I'm experiencing a similar problem when upgrading from 7.13.0 to 8.5.2 - also getting Error getting the next result (The result set is closed.) that you have in your logs.

Any help will be greatly appreciated.

Thanks

Willie

[Chris Purser]

Sorry Willie...I haven't tried it again yet.

Atlassian's products are the only software we have that require full outages to upgrade...and it just hasn't been convenient to schedule lately.

[BetterLife]

Thanks for the response, Chris.  Will post a solution when/if I find one.