Issue Summary

Import triggered before and while startup Insight indexing is running, creating duplicate objects.

Insight index consistency check and potential reindex would occur before the import event happens, but in rare and specific occasions, this does not happen.

Steps to Reproduce

Not all circumstances of successful reproduction are known, but the general steps to reproduce this are:

1. Stop Jira node where Insight is installed, making sure the Insight cache is not stored on shutdown (or the Insight cache has been deleted before the startup).
2. Start Jira
3. During the startup, a scheduled import task starts to run
4. Insight re-indexing kicks in

Expected Results

Re-indexing is done first, then the imports can start executing afterwards.

Logs excerpt:

• The latest occurrence of the problem in the logs is visible during Jira startup. We see the Insight cache / index is not present:

  2021-04-27 04:06:22,774 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight Object Cache file not found /data/application/jira/caches/insight_indexes/objectschema
  2021-04-27 04:06:22,774 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight Object Cache file not found /data/application//jira/caches/insight_indexes/objecttype
  2021-04-27 04:06:22,774 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight Object Cache file not found /data/application/jira/caches/insight_indexes/objecttypeattribute
  2021-04-27 04:06:22,774 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight Object Cache file not found /data/application/jira/caches/insight_indexes/objects
  2021-04-27 04:06:22,774 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight Object Cache file not found /data/application/jira/caches/insight_indexes/objectConnection
  ...
  2021-04-27 04:06:23,295 InsightLauncherThread WARN anonymous     [c.r.j.p.i.services.core.InsightIndexServiceImpl] Integrity check failed, number of objects mismatched, database: 196277, index: 0
  ...
  

• At similar timing, we see the import job kicks in, which is kind of unexpected since Insight cache consistency hasn't been yet verified:

  2021-04-27 04:06:25,731 [Caesium-1-4] | ============ Start import of module type rlabs-import-type-json, importSourceId: 137, number of sequential steps: 6 at time 2021-04-27T02:06:25.731Z
  2021-04-27 04:06:25,820 [Caesium-1-4] | Started import in new thread, importSourceId: 137
  2021-04-27 04:06:25,823 [insight-InsightThreadGroup-worker-thread-0] | 18.) xxx >>> Starting import 18.) xxx with id 137 of type rlabs-import-type-json with number of workers 12 at time 2021-04-27T04:06:25.823
  2021-04-27 04:06:25,826 [insight-InsightThreadGroup-worker-thread-0] | 18.) xxx >>> Number of enabled ImportSourceOTs: 1
  2021-04-27 04:06:25,832 [insight-InsightThreadGroup-worker-thread-0] | Updating missing objects for object type 1 with object type attribute to update: ObjectTypeAttributeBean [id=2142, name=xxx, type=DEFAULT, defaultType=TEXT], with newValue yyy
  2021-04-27 04:06:25,834 [insight-InsightThreadGroup-worker-thread-0] | 18.) xxx >>> Number of enabled ImportSourceOTs: 1
  2021-04-27 04:06:25,867 [insight-InsightImportThreadGroup-worker-thread-1] | 18.) xxx >>> Started reading data for configured object type id 1
  2021-04-27 04:06:25,873 [insight-InsightImportThreadGroup-worker-thread-1] | >>> readDataToTable()...
  2021-04-27 04:06:25,873 [insight-InsightImportThreadGroup-worker-thread-1] | import from: url
  2021-04-27 04:06:25,873 [insight-InsightImportThreadGroup-worker-thread-1] | url: file:///data/application/jira/import/insight/file.json
  2021-04-27 04:06:25,873 [insight-InsightImportThreadGroup-worker-thread-1] | fileId: null
  2021-04-27 04:06:25,929 [insight-InsightImportThreadGroup-worker-thread-1] | <<< readDataToTable().
  2021-04-27 04:06:25,936 [insight-InsightImportThreadGroup-worker-thread-1] | 18.) xxx >>> Completed reading data for configured object type id 1 in 69 ms
  2021-04-27 04:06:25,939 [insight-InsightImportThreadGroup-worker-thread-1] | 18.) xxx >>Using memory backed import for import source object type 148
  2021-04-27 04:06:25,939 [insight-InsightThreadGroup-worker-thread-0] | 18.) xxx >>> Fetched all data locators from external source in 102 ms
  2021-04-27 04:06:26,163 [insight-InsightThreadGroup-worker-thread-0] | 18.) xxx >>> Mapped all data to internal objects in 222 ms
  2021-04-27 04:06:26,192 [insight-InsightThreadGroup-worker-thread-0] | 18.) xxx >>> Decided actions for all objects in 29 ms
  2021-04-27 04:06:26,193 [insight-InsightThreadGroup-worker-thread-0] | 18.) xxx >>> Objects to import 1035
  

• Then, as the import is running, it logs errors due to missing data from the index and since Insight is currently indexing, but in the end, it will still create new and duplicated objects:

  2021-04-27 04:06:30,365 [insight-InsightImportThreadGroup-worker-thread-10] | Failed to create new object: test (null), ObjectTypeId: 1, Attributes: (AttributeTypeId: 2, value(s):[null(value0)],AttributeTypeId: 13, value(s):[null(value1)],AttributeTypeId: 2142, value(s):[null(value2)],AttributeTypeId: 2143, value(s):[null(value3)],AttributeTypeId: 2144, value(s):[null(value4)]), avatar: false with actions: [CREATE] due to InsightRuntimeException: java.lang.NullPointerException; nested exception is: null
  2021-04-27 04:06:30,527 [insight-InsightImportThreadGroup-worker-thread-10] | Failed to create new object: value5 (null), ObjectTypeId: 1, Attributes: (AttributeTypeId: 2, value(s):[null(value6)],AttributeTypeId: 13, value(s):[null(value7)],AttributeTypeId: 2142, value(s):[null(value8)],AttributeTypeId: 2143, value(s):[null(value9)],AttributeTypeId: 2144, value(s):[null(value10)]), avatar: false with actions: [CREATE] due to InsightLockedException: Action not possible while Insight is indexing
  

Actual Results

Import starts before the indexing, and at some point, they will run concurrently. Since Import relies on the data from the index, missing or corrupted index will cause the import task to create duplicated objects.

Import triggered before and while startup reindexing procedure is running, creating duplicate objects.

Workaround

• Make sure Insight index (cache) is stored before Jira triggers "force shutdown" command - refer to this guide that explains how to do this.
• Otherwise, manually copy the index as follows:
  1. In Jira, go to settings > Apps > Manage apps > Indexing Insight > Persist Insight Index to file
  2. Copy the index directory ($JIRA_HOME/caches/insight_indexes) to a backup location
  3. Before the next Jira startup event, restore the copied index directory over the existing one.

Notes

So far, we have seen this behaviour only during startup event. It does not happen regularly, but only under rare and specific circumstances. However, it not yet known whether this behaviour can occur while Insight indexing and import are running outside a startup event (i.e. while Jira and Insight are running and import / index are supposed to kick in).