[JSDSERVER-11153] Insight full re-index on restart, even after Index / cache was persisted to file

Type: Bug
Resolution: Fixed
Priority: High
Fix Version/s: 5.1.0
Affects Version/s: 4.20.2, Insight 9.1.8, Insight 8.9.8
Component/s: Assets - Core experiences
Labels:
- PS

Support reference count:
7
Symptom Severity:
Severity 2 - Major
UIS:
15
Bug Fix Policy:
View Atlassian Server bug fix policy

Issue Summary

By default, "Restore Insight index from file" and "Store cache on shutdown" is enabled.

Additionally - even if "store Cache on shutdown" is disabled, one can also manually persist the Insight index to file, after re-index.

(UI shows Persisting file was successful. )

Reference: Configuring global Jira settings

On Jira shutdown, Insight will persist the index on disk for faster startup and on the Jira start up, Insight will load the objects into memory from the file instead of doing a full Insight Re-index.

While this worked in the past (For customer and local test instance), an active instance, with many imports, and Objects constantly being created and deleted:
While persisting the Index / Cache seems to include the correct number of objects - restarting Jira will fail the consistency check - showing less objects in the Index file, than the correct number in the DB.
In some instances - ~~JSDSERVER-7251~~ is also showing (where the index file saved has 0KB), but other files are saved with wrong number of Objects.

As a result - Insight will always re-index on restart.

Steps to Reproduce

Make sure the option "Restore Insight index from file" is set to true (Insight Configuration)
Make sure the option to Store Insight cache on shutdown is set to true (Insight Configuration)
Run a Clean Re-index of Insight - persist the Index to file
Confirm there is no Action in Insight at this point
Shutdown Jira, and allow the process to end.
Restart Jira, check the logs

Expected Results

Insight is restarting, Consistency check is running - and finding the DB and Index totals match, hence no Insight re-index is initiating

Actual Results

Persisting the Cache / index shows an Error in deleting partial files.
Index files saved seem to be incomplete.

Upon restart - consistency Check fails, and Insight is always re-indexing:

// Insight Clean Re-index:
2022-02-22 14:26:46,862-0500 http-nio-8080-exec-5 DEBUG anonymous 866x3x1 - 0:0:0:0:0:0:0:1 /secure/admin/InsightPluginShowIndex.jspa [c.a.activeobjects.osgi.ActiveObjectsServiceFactory] getService bundle [com.atlassian.jira.plugins.webhooks.jira-webhooks-plugin] 2022-02-22 14:26:49,078-0500 http-nio-8080-exec-5 DEBUG yinon 866x3x1 1yvcu2a 0:0:0:0:0:0:0:1 /secure/admin/InsightPluginShowIndex.jspa [c.a.activeobjects.osgi.ActiveObjectsServiceFactory] getService bundle [com.atlassian.whisper.atlassian-whisper-plugin] 2022-02-22 14:26:58,485-0500 insight-InsightThreadGroup-worker-thread-12 WARN yinon 866x17x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/reindex/start [c.r.j.p.i.s.core.impl.ClusterAwareReindexServiceImpl] Cluster lock acquired Insight reindex started 2022-02-22 14:26:58,492-0500 insight-InsightThreadGroup-worker-thread-12 WARN yinon 866x17x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/reindex/start [c.r.j.p.i.s.core.index.ReindexServiceImpl] Starting Insight reindex in 12 threads 2022-02-22 14:26:58,498-0500 insight-InsightThreadGroup-worker-thread-12 WARN yinon 866x17x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/reindex/start [c.r.j.p.i.s.core.impl.ClusterAwareReindexServiceImpl] Insight is locked for reindex 2022-02-22 14:27:00,815-0500 insight-InsightThreadGroup-worker-thread-12 WARN yinon 866x17x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/reindex/start [c.r.j.p.i.s.core.impl.ClusterAwareReindexServiceImpl] Insight is unlocked after reindex 2022-02-22 14:27:00,816-0500 insight-InsightThreadGroup-worker-thread-12 WARN yinon 866x17x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/reindex/start [c.r.j.p.i.s.core.impl.ClusterAwareReindexServiceImpl] Cluster lock released Insight clean reindex complete 2022-02-22 14:27:24,364-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_1813340422325511217.part 2022-02-22 14:27:24,397-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectBean on disk done..... time: 689 ms, size: 433.5 kB. Number of objects persisted: 1334 2022-02-22 14:27:24,404-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_9218739486292209833.part 2022-02-22 14:27:24,404-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectSchemaBean on disk done..... time: 6 ms, size: 843 B. Number of objects persisted: 2 2022-02-22 14:27:24,414-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_8580306275073078730.part 2022-02-22 14:27:24,414-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectTypeBean on disk done..... time: 10 ms, size: 4.6 kB. Number of objects persisted: 46 2022-02-22 14:27:24,426-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_2659304018899685762.part 2022-02-22 14:27:24,426-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectTypeAttributeBean on disk done..... time: 12 ms, size: 29.3 kB. Number of objects persisted: 515 2022-02-22 14:27:24,436-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_6753607900056470961.part 2022-02-22 14:27:24,436-0500 http-nio-8080-exec-6 WARN yinon 867x25x1 1yvcu2a 0:0:0:0:0:0:0:1 /rest/insight/1.0/index/persist [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectTicketConnection on disk done..... time: 10 ms, size: 554 B. Number of objects persisted: 5 2022-02-22 14:28:31,769-0500 localhost-startStop-2 INFO      [c.a.jira.startup.DefaultJiraLauncher] Stopping launchers

// Insight Save Cache on shutdown
2022-02-22 14:28:31,831-0500 localhost-startStop-2 INFO      [c.a.plugin.manager.DefaultPluginManager] Preparing to shut down the plugin system 2022-02-22 14:28:31,847-0500 localhost-startStop-2 WARN      [c.r.j.p.i.services.launcher.InsightLauncher] Insight on stop 2022-02-22 14:28:31,909-0500 localhost-startStop-2 WARN      [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_4628368177852150512.part 2022-02-22 14:28:31,909-0500 localhost-startStop-2 WARN      [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectBean on disk done..... time: 62 ms, size: 433.5 kB. Number of objects persisted: 1334 2022-02-22 14:28:31,909-0500 localhost-startStop-2 WARN      [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_9216698603176971947.part 2022-02-22 14:28:31,909-0500 localhost-startStop-2 WARN      [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectSchemaBean on disk done..... time: 0 ms, size: 843 B. Number of objects persisted: 2 2022-02-22 14:28:31,925-0500 localhost-startStop-2 WARN      [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_6858324643863392015.part 2022-02-22 14:28:31,925-0500 localhost-startStop-2 WARN      [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectTypeBean on disk done..... time: 16 ms, size: 4.6 kB. Number of objects persisted: 46 2022-02-22 14:28:31,925-0500 localhost-startStop-2 WARN      [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_6704619885201711958.part 2022-02-22 14:28:31,925-0500 localhost-startStop-2 WARN      [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectTypeAttributeBean on disk done..... time: 0 ms, size: 29.3 kB. Number of objects persisted: 515 2022-02-22 14:28:31,925-0500 localhost-startStop-2 WARN      [i.r.insight.persistence.FileManagerImpl] Could not delete temporary file: D:\Attlasian Installed Versions\JSW_8.13\temp\temporary_8497480007015393866.part 2022-02-22 14:28:31,925-0500 localhost-startStop-2 WARN      [i.r.i.index.model.InsightPersistedIndexManager] Write object cache ObjectTicketConnection on disk done..... time: 0 ms, size: 554 B. Number of objects persisted: 5

// Jira shutdown
*** //Jira restart: 
***
2022-02-22 14:34:40,491-0500 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight cache will be restored from file for ObjectSchemaBean 2022-02-22 14:34:40,523-0500 InsightLauncherThread ERROR anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Unable to read objects from file D:\Attlasian Installed Versions\Application Data\JSW_8.13\caches\insight_indexes\objectschema java.io.EOFException: Stream ended prematurely     at net.jpountz.lz4.LZ4BlockInputStream.readFully(LZ4BlockInputStream.java:218)     at net.jpountz.lz4.LZ4BlockInputStream.refill(LZ4BlockInputStream.java:150)     at net.jpountz.lz4.LZ4BlockInputStream.read(LZ4BlockInputStream.java:117)     at java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2781)     at java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2797)     at java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:3274)     at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:934)     at java.io.ObjectInputStream.<init>(ObjectInputStream.java:396)     at io.riada.insight.index.model.InsightPersistedIndexManager.restoreCacheFromDisk(InsightPersistedIndexManager.java:104)     at io.riada.insight.index.model.InsightIndexBase.restoreCacheFromDisk(InsightIndexBase.java:156)     at io.riada.insight.index.model.ObjectSchemaIndexImpl.restoreCacheFromDisk(ObjectSchemaIndexImpl.java:91)     at com.riadalabs.jira.plugins.insight.services.core.InsightIndexServiceImpl.restoreCacheFromDisk(InsightIndexServiceImpl.java:536)     at com.riadalabs.jira.plugins.insight.services.launcher.InsightLauncher.restoreInsightCache(InsightLauncher.java:480)     at com.riadalabs.jira.plugins.insight.services.launcher.InsightLauncher.initialInsightIndex(InsightLauncher.java:320)     at com.riadalabs.jira.plugins.insight.services.launcher.InsightLauncher.lambda$onLifecycleEvent$0(InsightLauncher.java:299)     at com.atlassian.sal.core.executor.ThreadLocalDelegateRunnable.run(ThreadLocalDelegateRunnable.java:34)     at java.lang.Thread.run(Thread.java:748) 2022-02-22 14:34:40,523-0500 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight cache will be restored from file for ObjectTypeBean 2022-02-22 14:34:40,523-0500 InsightLauncherThread ERROR anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Unable to read objects from file D:\Attlasian Installed Versions\Application Data\JSW_8.13\caches\insight_indexes\objecttype java.io.EOFException: Stream ended prematurely     at net.jpountz.lz4.LZ4BlockInputStream.readFully(LZ4BlockInputStream.java:218)     at net.jpountz.lz4.LZ4BlockInputStream.refill(LZ4BlockInputStream.java:150)     at net.jpountz.lz4.LZ4BlockInputStream.read(LZ4BlockInputStream.java:117)     at java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2781)     at java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2797)     at java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:3274)     at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:934)     at java.io.ObjectInputStream.<init>(ObjectInputStream.java:396)     at io.riada.insight.index.model.InsightPersistedIndexManager.restoreCacheFromDisk(InsightPersistedIndexManager.java:104)     at io.riada.insight.index.model.InsightIndexBase.restoreCacheFromDisk(InsightIndexBase.java:156)     at io.riada.insight.index.model.ObjectTypeIndexImpl.restoreCacheFromDisk(ObjectTypeIndexImpl.java:88)     at com.riadalabs.jira.plugins.insight.services.core.InsightIndexServiceImpl.restoreCacheFromDisk(InsightIndexServiceImpl.java:537)     at com.riadalabs.jira.plugins.insight.services.launcher.InsightLauncher.restoreInsightCache(InsightLauncher.java:480)     at com.riadalabs.jira.plugins.insight.services.launcher.InsightLauncher.initialInsightIndex(InsightLauncher.java:320)     at com.riadalabs.jira.plugins.insight.services.launcher.InsightLauncher.lambda$onLifecycleEvent$0(InsightLauncher.java:299)     at com.atlassian.sal.core.executor.ThreadLocalDelegateRunnable.run(ThreadLocalDelegateRunnable.java:34)     at java.lang.Thread.run(Thread.java:748) 2022-02-22 14:34:40,523-0500 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight cache will be restored from file for ObjectTypeAttributeBean 2022-02-22 14:34:40,585-0500 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] ObjectTypeAttributeBean found in cache after file reload. Time: 62 ms. Number of entries restored: 444 2022-02-22 14:34:40,585-0500 InsightLauncherThread WARN anonymous     [i.r.i.index.model.InsightPersistedIndexManager] Insight cache will be restored from file for ObjectBean

Workaround

Currently there is no known workaround for this behavior. A workaround will be added here when available

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List

Temp files vs. Index files.png
22/Feb/2022 7:45 PM
40 kB
Yinon Negev

mentioned in: Page Failed to load; Page Failed to load; Page Failed to load; Page Failed to load; Page Failed to load; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...; Page Loading...

(20 mentioned in)

Form Name

Iz added a comment - 23/Jan/2024 12:33 PM

Issue is still reproducible on Jira 9.12.1, JSM 5.12.1

Iz added a comment - 23/Jan/2024 12:33 PM Issue is still reproducible on Jira 9.12.1, JSM 5.12.1

Madhu Kiran Yalamanchili added a comment - 20/Dec/2022 7:25 AM - edited

Issue is still reproducible on Jira 9.4.0, JSM 5.4.0 and Asset 10.4.0

Madhu Kiran Yalamanchili added a comment - 20/Dec/2022 7:25 AM - edited Issue is still reproducible on Jira 9.4.0, JSM 5.4.0 and Asset 10.4.0

Babu R added a comment - 10/Oct/2022 12:19 PM

We're able to reproduce the issue in below version. (i.e., still freetext-reindex is being triggered on every restart of Jira application)

Jira Software v9.3.0
Jira Service Management v5.3.0
Insight/Assets version is v10.0.17

Babu R added a comment - 10/Oct/2022 12:19 PM We're able to reproduce the issue in below version. ( i.e., still freetext-reindex is being triggered on every restart of Jira application) Jira Software v9.3.0 Jira Service Management v5.3.0 Insight/Assets version is v10.0.17

Assignee:: Benjamin Suess

Reporter:: Yinon Negev

Affected customers:: 3 This affects my team

Watchers:: 25 Start watching this issue

Created:: 22/Feb/2022 7:44 PM

Updated:: 01/Jul/2024 9:30 AM

Resolved:: 21/Jul/2022 8:35 AM

Details

Description

Issue Summary

Steps to Reproduce

Expected Results

Actual Results

Workaround

Attachments

Attachments

Issue Links

Forms

Activity

Collapse comment: Iz added a comment - 23/Jan/2024 12:33 PM

Expand comment: Iz added a comment - 23/Jan/2024 12:33 PM

Collapse comment: Madhu Kiran Yalamanchili added a comment - 20/Dec/2022 7:25 AM, Edited by Madhu Kiran Yalamanchili - 20/Dec/2022 7:26 AM

Expand comment: Madhu Kiran Yalamanchili added a comment - 20/Dec/2022 7:25 AM, Edited by Madhu Kiran Yalamanchili - 20/Dec/2022 7:26 AM

Collapse comment: Babu R added a comment - 10/Oct/2022 12:19 PM

Expand comment: Babu R added a comment - 10/Oct/2022 12:19 PM

People

Dates

Backbone Issue Sync