Uploaded image for project: 'Jira Data Center'
  1. Jira Data Center
  2. JRASERVER-70248

Jira is trying to do index recovery on invalid issue data coming from Lucene indexes

    XMLWordPrintable

Details

    Description

      Issue Summary

      Jira is trying to do index recovery every time Jira is restarted in Standalone mode by reconciling the issues difference against DB.
      It has been noticed since Jira 8 was released, that logging for index recovery happens after every Jira restart.
      The recovery process does kick in even if the indexes are not corrupted and tries to recover issues with null keys and thus is returning zero ids.

      Steps to Reproduce

      1. Install Jira 8.5.0
      2. create a project and start creating issues, transition one of them and add comments.
      3. run a background re-indexing on the instance.
      4. check the background reindexing logs.
      5. enable debug logging on the package: com.atlassian.jira.ofbiz.IssueGenericValue in the log4j.properties
      6. do a restart and check the logs.

      Expected Results

      Jira should have a clean start up, index recovery shouldn't be trying to deindex issues with zero ids.
      Background reindex number should match up without any discripancy.

      Actual Results

      On start up Jira is trying to deindex issues with zero ids even though the database doesn't have any issues with zero ids.
      The below messages are shown in the Jira start up logs in atlassian-jira.log:

      2019-11-13 14:42:34,466 Caesium-1-1 INFO      [c.a.jira.startup.IndexRecoveryLauncher] Running start-index-recovery
2019-11-13 14:42:34,789 Caesium-1-1 INFO      [c.a.j.index.ha.DefaultIndexRecoveryManager] Latest index date: {2019-11-04 13:30:15}, Latest DB date: {2019-11-04 13:30:15}
2019-11-13 14:42:34,790 Caesium-1-1 INFO      [c.a.jira.startup.IndexRecoveryLauncher] Indexing issues from=2019-11-04 13:30:15.0 to=Mon Nov 04 13:30:15 CET 2019 (time span of 314ms)
2019-11-13 14:42:34,791 Caesium-1-1 INFO      [c.a.j.index.ha.DefaultIndexRecoveryManager] Re-indexing issues from: 2019-11-04 13:30:15.0 to: Mon Nov 04 13:30:15 CET 2019 ...
...
2019-11-13 14:42:35,439 ForkJoinPool.commonPool-worker-1 INFO      [c.a.j.cache.soy.SoyCacheWarmer] Warming 41 soy modules
2019-11-13 14:42:35,439 Caesium-1-1 INFO      [c.a.j.index.ha.DefaultIndexRecoveryManager] Done re-indexing: 1 issues from: 2019-11-04 13:30:15.0 to: Mon Nov 04 13:30:15 CET 2019.
2019-11-13 14:42:35,439 Caesium-1-1 INFO      [c.a.jira.startup.IndexRecoveryLauncher] Progress=60%, task=Recovering, message=Recovered added and updated issues
2019-11-13 14:42:35,505 Caesium-1-1 WARN      [c.a.jira.ofbiz.IssueGenericValue] Issue (id=0) has empty field 'num'. Returning null for 'key'.
2019-11-13 14:42:35,505 Caesium-1-1 WARN      [c.a.jira.ofbiz.IssueGenericValue] Issue (id=0) has empty field 'num'. Returning null for 'key'.
2019-11-13 14:42:35,507 Caesium-1-1 DEBUG      [c.a.jira.ofbiz.IssueGenericValue] Issue (id=0) has empty field 'num'. Returning null for 'key'.
java.lang.RuntimeException
        at com.atlassian.jira.ofbiz.IssueGenericValue.get(IssueGenericValue.java:56)
        at org.ofbiz.core.entity.GenericEntity.getString(GenericEntity.java:462)
        at com.atlassian.jira.issue.IssueImpl.getKey(IssueImpl.java:810)
        at com.atlassian.jira.issue.index.DefaultIssueIndexer.lambda$deindexIssues$0(DefaultIssueIndexer.java:137)
        at com.atlassian.jira.issue.index.DefaultIssueIndexer.lambda$null$2(DefaultIssueIndexer.java:365)
        at com.atlassian.jira.index.SimpleIndexingStrategy.apply(SimpleIndexingStrategy.java:7)
        at com.atlassian.jira.index.SimpleIndexingStrategy.apply(SimpleIndexingStrategy.java:5)
        at com.atlassian.jira.issue.index.DefaultIssueIndexer.lambda$perform$3(DefaultIssueIndexer.java:363)
        at com.atlassian.jira.util.collect.CollectionUtil.foreach(CollectionUtil.java:39)
        at com.atlassian.jira.util.collect.CollectionUtil.foreach(CollectionUtil.java:52)
        at com.atlassian.jira.issue.util.IssueObjectIssuesIterable.foreach(IssueObjectIssuesIterable.java:24)
        at com.atlassian.jira.issue.index.DefaultIssueIndexer.perform(DefaultIssueIndexer.java:335)
        at com.atlassian.jira.issue.index.DefaultIssueIndexer.deindexIssues(DefaultIssueIndexer.java:136)
        at com.atlassian.jira.index.ha.DefaultIndexRecoveryManager.deIndexDeletedIssues(DefaultIndexRecoveryManager.java:251)
        at com.atlassian.jira.index.ha.DefaultIndexRecoveryManager.reindexIssuesIn(DefaultIndexRecoveryManager.java:193)
        at com.atlassian.jira.startup.IndexRecoveryLauncher.handleIndexRecoveryInServerMode(IndexRecoveryLauncher.java:100)

      On doing background reindexing, the numbers reported doesn't seem to match.
      Lucene API reports more issues that what is actually existing in the database:

      2019-11-13 17:28:51,306 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing started
2019-11-13 17:28:51,306 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.util.index.CompositeIndexLifecycleManager] Reindex All In Background starting...
2019-11-13 17:28:51,306 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 0% complete. Current index: Issue
2019-11-13 17:28:51,307 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.issue.index.DefaultIndexManager] ReindexAll in background: {indexIssues=true, indexChangeHistory=false, indexComments=false, indexWorklogs=false, forceReloadFromDatabase=false}
2019-11-13 17:28:51,307 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.issue.index.IndexingStatsManager] [indexing-stats] Resetting stats.
2019-11-13 17:28:51,307 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.issue.index.DefaultIndexManager] Reindexing 21 issues in the background.
2019-11-13 17:28:51,331 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 5% complete. Current index: Issue
2019-11-13 17:28:51,334 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 10% complete. Current index: Issue
2019-11-13 17:28:51,350 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 15% complete. Current index: Issue
2019-11-13 17:28:51,361 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 20% complete. Current index: Issue
2019-11-13 17:28:51,373 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 25% complete. Current index: Issue
2019-11-13 17:28:51,384 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 30% complete. Current index: Issue
2019-11-13 17:28:51,395 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 35% complete. Current index: Issue
2019-11-13 17:28:51,408 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 40% complete. Current index: Issue
2019-11-13 17:28:51,419 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 45% complete. Current index: Issue
2019-11-13 17:28:51,429 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 50% complete. Current index: Issue
2019-11-13 17:28:51,445 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 55% complete. Current index: Issue
2019-11-13 17:28:51,454 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 60% complete. Current index: Issue
2019-11-13 17:28:51,479 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 65% complete. Current index: Issue
2019-11-13 17:28:51,501 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 70% complete. Current index: Issue
2019-11-13 17:28:51,510 ISSUE-indexQueue:thread-1 INFO      [c.a.j.w.a.admin.index.IndexAdminImpl] Re-indexing is 75% complete. Current index: Issue
2019-11-13 17:28:51,513 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.issue.index.DefaultIndexManager] 21 issues reindexed in the background, in 205 millis.
2019-11-13 17:28:51,538 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.issue.index.DefaultIndexManager] 0 concurrently modified issues reindexed in 26 millis.
2019-11-13 17:28:51,542 JiraTaskExecutionThread-6 INFO sherif 1048x467x1 12rzh2a 0:0:0:0:0:0:0:1 /secure/admin/jira/IndexReIndex!reindex.jspa [c.a.j.issue.index.DefaultIndexManager] Reindexing 15 issues in the background completed in 234 millis
      • note: 
        [c.a.j.issue.index.DefaultIndexManager] Reindexing 21 issues in the background.
[c.a.j.issue.index.DefaultIndexManager] 21 issues reindexed in the background, in 205 millis.
[c.a.j.issue.index.DefaultIndexManager] Reindexing 15 issues in the background completed in 234 millis
      • actual number of issues - 15 (vs 21 in logs).

      Note:

      The start-up logs don't appear all the time, though it could be reproduced eventually especially with large instances.
      Doing a Full foreground re-indexing helps to restore the index into a more tidy state, but changes to Jira issues will eventually cause indexes to have entries with null issue keys.

      Workaround: 

      A background reindex should resolve the JQL search issues, but the ongoing task is to periodically clear the null values out of the DB. 

      You can clear these out of the database by either:

      1. running the integrity checker
      2. deleting the null entries from the database:
        As always make sure you test these types of changes in a lower environment and make sure to back up the DB prior!
        validate the issues: 
        SELECT id,issuenum,project FROM jiraissue WHERE issuenum IS NULL;

        delete the issues

        delete FROM jiraissue WHERE issuenum IS NULL;

      Attachments

        Issue Links

          causes

          Bug - A problem which impairs or prevents the functions of the product. JRASERVER-70242 On startup, Jira logs "Issue X has empty field 'num'. Returning null for 'key'."

          • High - High priority issues
          • Closed
          is caused by

          Bug - A problem which impairs or prevents the functions of the product. JRASERVER-61339 IndexRecoveryLauncher reindexes everytime at startup

          • Medium - Medium priority issues
          • Gathering Impact
          mentioned in

          Page Loading...

          Page Loading...

          Activity

            People

              655e9ad13484 Daria Misiowiec
              sabdelfattah Sherif Abdelfattah (Inactive)
              Votes:
              10 Vote for this issue
              Watchers:
              21 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: