IndexCopier warnings on upgraded AEM from 6.3 to 6.5 sp 10

[mtobiasz]

Hi,

On AEM 6.5 SP 10 after upgrading it from 6.3 with in-place method from time to time I can see this type of WARN. The name of file changes

*WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da_Lucene41_0.pos doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data

Below log shows one of Index Update flow when such warrning is showing up (Is trimmed due to characters limitations)

30.01.2022 06:58:33.778 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.writer.DefaultIndexWriter IndexWriterConfig for index [/oak:index/lucene] is matchVersion=LUCENE_47
analyzer=org.apache.lucene.analysis.miscellaneous.PerFieldAnalyzerWrapper
ramBufferSizeMB=16.0
maxBufferedDocs=-1
maxBufferedDeleteTerms=-1
mergedSegmentWarmer=null
readerTermsIndexDivisor=1
termIndexInterval=32
delPolicy=org.apache.lucene.index.KeepOnlyLastCommitDeletionPolicy
commit=null
openMode=CREATE_OR_APPEND
similarity=org.apache.lucene.search.similarities.DefaultSimilarity
mergeScheduler=ConcurrentMergeScheduler: maxThreadCount=1, maxMergeCount=2, mergeThreadPriority=-1
default WRITE_LOCK_TIMEOUT=1000
writeLockTimeout=1000
codec=Lucene46
infoStream=org.apache.lucene.util.InfoStream$NoOutput
mergePolicy=[TieredMergePolicy: maxMergeAtOnce=10, maxMergeAtOnceExplicit=30, maxMergedSegmentMB=5120.0, floorSegmentMB=2.0, forceMergeDeletesPctAllowed=10.0, segmentsPerTier=10.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1
indexerThreadPool=org.apache.lucene.index.ThreadAffinityDocumentsWriterThreadPool@7d53f3ae
readerPooling=false
perThreadHardLimitMB=1945
useCompoundFile=true
writer=org.apache.lucene.util.SetOnce@577569a0
30.01.2022 06:58:33.778 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.writer.LuceneIndexWriter.perf Created IndexWriter for directory Fulltext Index : /oak:index/lucene [took 34ms]
30.01.2022 06:58:33.779 *TRACE* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.search.IndexDefinition Registering rule 'IndexRule: cq:Tag' for name 'cq:Tag'
30.01.2022 06:58:33.779 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.writer.DefaultIndexWriter Directory overall size: 519.9 MB, files: _11az.si:248, _hk9.fdx:20677, _b4d.nvd:192104, _b4d.nvm:46, _b4d.fnm:74212, _33e_gi.del:40853, _6hy_Lucene41_0.pos:26111773, _vtv_1.del:35, _j6e.cfe:300, _hk9_Lucene41_0.doc:12217663, _vts.cfe:300, _6hy_Lucene41_0.doc:19259301, _hk9.si:411, _b4d_Lucene41_0.doc:8486038, _c5r_ey.del:39393, _j6e.cfs:2413759, _c5r_Lucene41_0.doc:14820026, _vts.cfs:319420, _hk9.fdt:26559657, _hk9_Lucene41_0.pos:17140849, _j3u.si:283, _11aq.cfe:300, _6hy_Lucene41_0.tip:777633, _qxe.si:283, _vtr.cfs:1235483, _vtr.si:283, _6hy_Lucene41_0.tim:22859946, _11az.cfe:300, _vtr.cfe:300, _11aq.cfs:3129, _ki1.si:283, _c5r_Lucene41_0.pos:35473968, _11az.cfs:1581, _vtw.cfe:300, _6hy_ob.del:46753, _vtw.si:245, _33e_Lucene41_0.pay:3044103, _pgr.cfs:1247368, _vtw.cfs:8162, _pgr.cfe:300, _6hy.si:409, _z4k.si:245, _33e_Lucene41_0.tip:586398, _b4d_Lucene41_0.pay:3324045, _hk9_Lucene41_0.tim:18628633, _33e_Lucene41_0.tim:25307390, _hk9_Lucene41_0.tip:360018, _pgr.si:283, _ki1.cfe:300, _c5r.nvd:314923, _33e.si:409, _z4k.cfs:2745, _vtv.cfs:15850, _vtt.si:245, _b4d_Lucene41_0.tim:12877177, _hk9_Lucene41_0.pay:4430316, _c5r_Lucene41_0.tim:21788891, _ki1.cfs:1641241, _qxe_4.del:296, _c5r_Lucene41_0.tip:417280, _z4k.cfe:300, _vtr_3.del:526, _vtv.cfe:300, segments_1059:808, _c5r.fnm:107849, _c5r.nvm:46, _b4d_Lucene41_0.tip:322860, _vtt.cfs:2047, _c5r_Lucene41_0.pay:16318499, _11d9.cfe:300, _11da.fdt:0, _11da.fdx:0, _c5r.fdx:22389, _vb9_8.del:541, _c5r.fdt:49476328, _vtt.cfe:300, _vts_2.del:126, _j3u.cfe:300, _11d9.cfs:3880, _11aq.si:248, _6hy_Lucene41_0.pay:10011577, _j3u.cfs:33369644, _vb9.si:283, _6hy.fdx:25783, _6hy.fdt:35054826, _qxe.cfe:300, _33e.fdx:24469, _vtv.si:245, _j6e.si:283, _b4d_Lucene41_0.pos:10688227, _33e.fdt:30326761, _j3u_1d.del:16798, _j6e_j.del:1060, _33e_Lucene41_0.pos:17448942, _b4d.fdx:13863, segments.gen:20, _c5r.si:410, _b4d.fdt:16903222, _6hy.nvd:373808, _vb9.cfe:300, _hk9_7p.del:30851, _b4d.si:409, _b4d_hy.del:24040, _33e_Lucene41_0.doc:13408995, _hk9.nvm:46, _33e.nvm:46, _33e.fnm:303326, _6hy.fnm:56397, _6hy.nvm:46, _pgr_i.del:491, _hk9.fnm:133155, _11d9.si:248, _hk9.nvd:246588, _vts.si:245, _33e.nvd:326606, _vb9.cfs:1624425, _qxe.cfs:1117447, _ki1_g.del:851, 
30.01.2022 06:58:33.779 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output _11da_Lucene41_0.doc
30.01.2022 06:58:33.779 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output _11da_Lucene41_0.pos
30.01.2022 06:58:33.779 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output _11da_Lucene41_0.pay
30.01.2022 06:58:33.779 *TRACE* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.search.IndexDefinition Found rule 'IndexRule: rep:Token' for NodeType 'rep:Token'
30.01.2022 06:58:33.779 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output _11da_Lucene41_0.tim
30.01.2022 06:58:33.779 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output _11da_Lucene41_0.tip
30.01.2022 06:58:33.780 *TRACE* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.search.IndexDefinition Registering rule 'IndexRule: rep:Token' for name 'rep:Token'
30.01.2022 06:58:33.780 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output _11da.nvd
30.01.2022 06:58:33.780 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11da_Lucene41_0.pos
30.01.2022 06:58:33.780 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11da.nvd
30.01.2022 06:58:33.780 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11da.fdx
30.01.2022 06:58:33.780 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11da_Lucene41_0.tip
30.01.2022 06:58:33.780 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_11d9.cfs)
30.01.2022 06:58:33.783 *DEBUG* [async-index-update-async] org.apache.jackrabbit.oak.plugins.observation.ChangeCollectorProvider Collected changeSet for commit CommitInfo{sessionId=oak:unknown, userId=oak:unknown, external=false, date=1643522313782, info={oak.commitAttributes=CommitContext[attrs={oak.observation.changeSet=ChangeSet{paths[maxDepth:9]=[/:async], propertyNames=[async, async-LastIndexedTo], parentNodeNames=[:async], parentNodeTypes=[], allNodeTypes=[], any overflow: false, hits max path depth: false}}]}} is ChangeSet{paths[maxDepth:9]=[/:async], propertyNames=[async, async-LastIndexedTo], parentNodeNames=[:async], parentNodeTypes=[], allNodeTypes=[], any overflow: false, hits max path depth: false}
30.01.2022 06:58:33.783 *DEBUG* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.ActiveDeletedBlobCollectorFactory$ActiveDeletedBlobCollectorImpl Added 0 (out of 0 tried) to be flushed. QSize: 0
30.01.2022 06:58:33.783 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vts_2.del)
30.01.2022 06:58:33.783 *DEBUG* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.ActiveDeletedBlobCollectorFactory$ActiveDeletedBlobCollectorImpl Added 0 (out of 0 tried) to be flushed. QSize: 0
30.01.2022 06:58:33.783 *TRACE* [sling-oak-observation-17] org.apache.jackrabbit.oak.plugins.observation.EventGenerator.perf generate: Starting event generation
30.01.2022 06:58:33.783 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vtr.cfs)
30.01.2022 06:58:33.783 *TRACE* [sling-oak-observation-17] org.apache.jackrabbit.oak.plugins.observation.EventGenerator.perf generate: Generated 1 events [took 0ms]
30.01.2022 06:58:33.783 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vtr.cfe)
30.01.2022 06:58:33.784 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vtr.cfs)
30.01.2022 06:58:33.784 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vtr.cfe)
30.01.2022 06:58:33.783 *DEBUG* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.ActiveDeletedBlobCollectorFactory$ActiveDeletedBlobCollectorImpl Added 0 (out of 0 tried) to be flushed. QSize: 0
30.01.2022 06:58:33.784 *DEBUG* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.ActiveDeletedBlobCollectorFactory$ActiveDeletedBlobCollectorImpl Added 0 (out of 0 tried) to be flushed. QSize: 0
30.01.2022 06:58:33.784 *DEBUG* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.ActiveDeletedBlobCollectorFactory$ActiveDeletedBlobCollectorImpl Added 0 (out of 0 tried) to be flushed. QSize: 0
30.01.2022 06:58:33.784 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vtr_3.del)
30.01.2022 06:58:33.784 *DEBUG* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate [async] AsyncIndex update run completed in 57.35 ms. Indexed 0 nodes, changedNodeCount 9, changedPropertyCount 1
30.01.2022 06:58:33.784 *TRACE* [async-index-update-async] org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate Switching thread name back to sling-oak-5-org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate-async
30.01.2022 06:58:33.785 *TRACE* [sling-oak-observation-9] org.apache.jackrabbit.oak.plugins.observation.EventGenerator.perf generate: Starting event generation
30.01.2022 06:58:33.785 *DEBUG* [sling-oak-5-org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate-async] org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate [async] Cleaning up orphaned checkpoints
30.01.2022 06:58:33.785 *DEBUG* [sling-oak-5-org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate-async] org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate Getting checkpoint info for 96914f58-74e3-4cd1-b71f-890ed3e37eed
30.01.2022 06:58:33.785 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vb9.cfs)
30.01.2022 06:58:33.785 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vb9.cfe)
30.01.2022 06:58:33.785 *TRACE* [sling-oak-observation-9] org.apache.jackrabbit.oak.plugins.observation.EventGenerator.perf generate: Generated 1 events [took 0ms]
30.01.2022 06:58:33.785 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vb9.cfs)
30.01.2022 06:58:33.785 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_vb9.cfe)
30.01.2022 06:58:33.860 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]fileLength(_33e_gi.del)
30.01.2022 06:58:33.860 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11d9_1.del
30.01.2022 06:58:33.861 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output segments_105a
30.01.2022 06:58:33.871 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Creating output segments.gen
30.01.2022 06:58:33.873 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file segments_1059
30.01.2022 06:58:33.873 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11d9.cfe
30.01.2022 06:58:33.873 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11d9.cfs
30.01.2022 06:58:33.873 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Deleted file _11d9.si
30.01.2022 06:58:33.873 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.writer.LuceneIndexWriter.perf Closed writer for directory Fulltext Index : /oak:index/lucene [took 94ms]
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69523] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Skip copying of deleted file _11da.fdt
30.01.2022 06:58:33.895 *DEBUG* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]listAll()
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69523] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Skip copying of deleted file _11da.fdx
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69523] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Skip copying of deleted file _11da_Lucene41_0.tim
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69523] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Skip copying of deleted file _11da_Lucene41_0.tip
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69521] org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker No changed detected in async indexer state. Skipping further diff
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69520] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Skip copying of deleted file _11da_Lucene41_0.doc
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69520] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Skip copying of deleted file _11da_Lucene41_0.pos
30.01.2022 06:58:33.895 *TRACE* [oak-lucene-69520] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] Skip copying of deleted file _11da_Lucene41_0.pay
30.01.2022 06:58:33.896 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory.perf [COW][/oak:index/lucene] Completed pending copying task 32 [took 23ms]
30.01.2022 06:58:33.897 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] CopyOnWrite stats : Skipped copying 11 files with total size 3.9 kB
30.01.2022 06:58:33.897 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]listAll()
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da_Lucene41_0.pos doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da.nvm doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.CopyOnWriteDirectory [COW][/oak:index/lucene] File listing - Upon completion [_11aq.cfe, _11aq.cfs, _11aq.si, _11az.cfe, _11az.cfs, _11az.si, _11da.cfe, _11da.cfs, _11da.si, _33e.fdt, _33e.fdx, _33e.fnm, _33e.nvd, _33e.nvm, _33e.si, _33e_Lucene41_0.doc, _33e_Lucene41_0.pay, _33e_Lucene41_0.pos, _33e_Lucene41_0.tim, _33e_Lucene41_0.tip, _33e_gi.del, _6hy.fdt, _6hy.fdx, _6hy.fnm, _6hy.nvd, _6hy.nvm, _6hy.si, _6hy_Lucene41_0.doc, _6hy_Lucene41_0.pay, _6hy_Lucene41_0.pos, _6hy_Lucene41_0.tim, _6hy_Lucene41_0.tip, _6hy_ob.del, _b4d.fdt, _b4d.fdx, _b4d.fnm, _b4d.nvd, _b4d.nvm, _b4d.si, _b4d_Lucene41_0.doc, _b4d_Lucene41_0.pay, _b4d_Lucene41_0.pos, _b4d_Lucene41_0.tim, _b4d_Lucene41_0.tip, _b4d_hy.del, _c5r.fdt, _c5r.fdx, _c5r.fnm, _c5r.nvd, _c5r.nvm, _c5r.si, _c5r_Lucene41_0.doc, _c5r_Lucene41_0.pay, _c5r_Lucene41_0.pos, _c5r_Lucene41_0.tim, _c5r_Lucene41_0.tip, _c5r_ey.del, _hk9.fdt, _hk9.fdx, _hk9.fnm, _hk9.nvd, _hk9.nvm, _hk9.si, _hk9_7p.del, _hk9_Lucene41_0.doc, _hk9_Lucene41_0.pay, _hk9_Lucene41_0.pos, _hk9_Lucene41_0.tim, _hk9_Lucene41_0.tip, _j3u.cfe, _j3u.cfs, _j3u.si, _j3u_1d.del, _j6e.cfe, _j6e.cfs, _j6e.si, _j6e_j.del, _ki1.cfe, _ki1.cfs, _ki1.si, _ki1_g.del, _pgr.cfe, _pgr.cfs, _pgr.si, _pgr_i.del, _qxe.cfe, _qxe.cfs, _qxe.si, _qxe_4.del, _vb9.cfe, _vb9.cfs, _vb9.si, _vb9_8.del, _vtr.cfe, _vtr.cfs, _vtr.si, _vtr_3.del, _vts.cfe, _vts.cfs, _vts.si, _vts_2.del, _vtt.cfe, _vtt.cfs, _vtt.si, _vtv.cfe, _vtv.cfs, _vtv.si, _vtv_1.del, _vtw.cfe, _vtw.cfs, _vtw.si, _z4k.cfe, _z4k.cfs, _z4k.si, segments.gen, segments_105a]
30.01.2022 06:58:33.897 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.directory.BufferedOakDirectory [/oak:index/lucene]close()
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da.fnm doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da.fdt doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da.nvd doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11d9_1.del doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.writer.LuceneIndexWriter.perf Closed directory for directory Fulltext Index : /oak:index/lucene [took 117ms]
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da_Lucene41_0.tim doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.search.spi.editor.FulltextIndexEditorContext.perf Closed writer for directory Fulltext Index : /oak:index/lucene [took 118ms]
30.01.2022 06:58:33.897 *WARN* [oak-lucene-69522] org.apache.jackrabbit.oak.plugins.index.lucene.IndexCopier File _11da_Lucene41_0.tip doesn't exist in PATH_TO_QUICKSTART/repository/index/lucene-1507546163234/data
30.01.2022 06:58:33.897 *TRACE* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.search.spi.editor.FulltextIndexEditorContext.perf Overall Closed IndexWriter for directory Fulltext Index : /oak:index/lucene [took 118ms]
30.01.2022 06:58:33.897 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.search.spi.binary.TextExtractionStats Text extraction stats  0 (Time Taken 0 min, 0 sec, Bytes Read 0 B, Extracted text size 0 B)
30.01.2022 06:58:33.897 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.lucene.LuceneIndexEditor [/oak:index/lucene] => Indexed 1 nodes, done.
30.01.2022 06:58:33.897 *DEBUG* [async-index-update-fulltext-async] org.apache.jackrabbit.oak.plugins.index.IndexUpdate Indexing report
    - /oak:index/lucene(1)

The questions is if we should worry about this WARN and if yes any ideas what can cause that and what steps to do to avoid that WARN?
We did offline reindexation of lucene index after the upgrade. Also checked consistency using checkConsistency from /system/console/jmx/org.apache.jackrabbit.oak%3Aname%3DLucene+Index+statistics%2Ctype%3DLuceneIndex

[Nitin_laad]

Hi @mtobiasz 

Rebuild indexes, start with your local environment.  

Rebuild Indexes in AEM with Oak Index (perficient.com)

[mtobiasz]

Hi @Nitin_laad

Thanks for response but I have executed offline reindexation of this index and also online one by changing reindex property and still warning is showing up.

[Nitin_laad]

Hi @mtobiasz 

Not sure if you have already performed inconsistency check at server startup, 

"Sometimes it can happen that the Lucene index of a repository gets into an inconsistent state, especially if the repository is shutdown abnormally or the corresponding Java process is killed unexpectedly"

Ref:

How to check and repair search index inconsistencies (adobe.com)

Tuning Your Lucene Index for AEM (netcentric.biz)

[mtobiasz]

Hi @Nitin_laad 

I was executing checkConsistency(java.lang.String indexPath, boolean fullCheck) from "/system/console/jmx/org.apache.jackrabbit.oak%3Aname%3DLucene+Index+statistics%2Ctype%3DLuceneIndex"

Based on How to check and repair search index inconsistencies (adobe.com) could you please clarifi this step:

"In order to trigger an index consistency-check, simply reconfigure the corresponding

workspace.xml configuration file of the workspace in question, e.g. <crx_home>/crx-quickstart/repository/workspaces/crx.default/workspace.xml:"

The "workspaces" directory doesn't exist in the AEM 6.5. Isn't that part of the guide related to older version of the AEM?

[Nitin_laad · Accepted solution]

Hey @mtobiasz, I am just trying to help you here to resolve your issue. 

See if you get any help on below link... 

Index inconsistency check on AEM 6.3 - Adobe Experience League Community - 292863

[mtobiasz]

Hi @Nitin_laad 

Sorry for late response but I wanted to try methods from the links. Unfortunatly I still see warning in the log connected to /oak:index/lucene

What was done:

•  after in place upgrade - remove "crx-quickstart/repository/index" and TarMK Offline indexing with oak-run.jar most of indexes including /oak:index/lucene
• In crx/de for /oak:index/lucene remove seed and set reindex to true and save changes
• TarMK Offline indexing with oak-run.jar for /oak:index/lucene

What was checked:
Index Consistency Check with oak-run - indicates VALID

/system/console/jmx/org.apache.jackrabbit.oak%3Aname%3Dasync%2Ctype%3DIndexStats - No errors

/system/console/jmx/org.apache.jackrabbit.oak%3Aname%3Dasync-reindex%2Ctype%3DIndexStats - No errors

/system/console/jmx/org.apache.jackrabbit.oak%3Aname%3Dfulltext-async%2Ctype%3DIndexStats - No errors

/system/console/jmx/org.apache.jackrabbit.oak%3Aname%3DLucene+Index+statistics%2Ctype%3DLuceneIndex -

/oak:index/lucene => VALID
        Size : 176.1 MB
Directory : :data
        Size     : 176.1 MB
        Num docs : 867953
        CheckIndex status : true
Time taken : 16.47 s

/libs/granite/operations/content/diagnosistools/queryPerformance.html

Check slow queries - no slow queries

Explain Query for SELECT * FROM [nt:base] AS s WHERE CONTAINS(jcr_title, 'Equipment') -

Indexes Used lucene(/oak:index/lucene)

[Nitin_laad]

Raise a day care ticket and see if you can get any help. 

[this-that-the-otter]

Hi mtobiasz,

Did you ever resolve this issue? You can unmark the "correct answer" by toggling that option within the vertical ... menu.

I have also done an in-place 6.3 to 6.5 upgrade and see similar warnings after removing (rm-all) all checkpoints with oak-run.jar as well as deleting everything in the repository/index folder - restarting - and seeing "AsyncIndex update run completed"

I also see failed runaway queries (more than 10,000 nodes, consider creating an index type errors) when trying to delete a replication agent in classic ui (it can't be deleted there)  - deleting the agent works when done within crxde /etc/replication/... folder?

It seems the in place upgrade option can leave a somewhat messed up upgraded instance, at least in terms of indexes.

It would be great to get some guidance on how to deal with. To understand what the actual issue is, etc.

[this-that-the-otter]

It seems the indexcopier warnings will go away once the index is rebuilt?

The warning logs don't mention it's being rebuilt but I think that may be happening as the warnings are not repeated (for me) on subsequent restarts of AEM.

My particular warning was on a relatively newly created index and on an instance that had been transferred via scp or rsync. I think newly cloned or transferred instances may be likely to exhibit this or similar behavior.