Lucene index corruption short time after upgrade to CE 3.3g

[rays]

After only two days in use, our Community Edition 3.3g server is unable to start, despite moving the lucene-indexes file out of the way and re-starting with a FULL re-indexing option selected.

Below is an extract of the appearing outputs in catalina.out. Is there any hope of a recovery from this situation or am I forced to fall back to the pre-upgrade state from back-ups taken then?

Thanks, in advance, for any prompt advice!

16:44:12,000  INFO  [node.index.FullIndexRecoveryComponent] Index recovery started: 7,724 transactions.
16:44:12,130  INFO  [node.index.FullIndexRecoveryComponent]    10 % complete.
16:47:19,363  INFO  [node.index.FullIndexRecoveryComponent]    20 % complete.
16:49:56,404  ERROR [repo.transaction.AlfrescoTransactionSupport] After completion (committed) Lucene exception
org.alfresco.repo.search.impl.lucene.LuceneIndexException: 06280000 Commit failed
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerImpl.commit(AbstractLuceneIndexerImpl.java:421)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerAndSearcherFactory.commit(AbstractLuceneIndexerAndSearcherFactory.java:766)
   at org.alfresco.repo.transaction.AlfrescoTransactionSupport$TransactionSynchronizationImpl.afterCompletion(AlfrescoTransactionSupport.java:842)
   at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion(TransactionSynchronizationUtils.java:168)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.invokeAfterCompletion(AbstractPlatformTransactionManager.java:996)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerAfterCompletion(AbstractPlatformTransactionManager.java:971)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:799)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
   at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:394)
   at org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:472)
   at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:343)
   at org.alfresco.repo.node.index.AbstractReindexComponent$ReindexWorkerRunnable.run(AbstractReindexComponent.java:874)
   at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
   at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: Bad file descriptor
   at java.io.FileOutputStream.close0(Native Method)
   at java.io.FileOutputStream.close(FileOutputStream.java:279)
   at java.io.FilterOutputStream.close(FilterOutputStream.java:143)
   at java.io.FilterOutputStream.close(FilterOutputStream.java:143)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.setPreparedState(IndexInfo.java:1130)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneBase.setInfo(AbstractLuceneBase.java:256)
   at org.alfresco.repo.search.impl.lucene.ADMLuceneIndexerImpl.doCommit(ADMLuceneIndexerImpl.java:1678)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerImpl.commit(AbstractLuceneIndexerImpl.java:413)
   … 14 more
16:51:18,229  ERROR [repo.transaction.AlfrescoTransactionSupport] After completion (committed) Lucene exception
org.alfresco.repo.search.impl.lucene.LuceneIndexException: 06280005 Commit failed
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerImpl.commit(AbstractLuceneIndexerImpl.java:421)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerAndSearcherFactory.commit(AbstractLuceneIndexerAndSearcherFactory.java:766)
   at org.alfresco.repo.transaction.AlfrescoTransactionSupport$TransactionSynchronizationImpl.afterCompletion(AlfrescoTransactionSupport.java:842)
   at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion(TransactionSynchronizationUtils.java:168)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.invokeAfterCompletion(AbstractPlatformTransactionManager.java:996)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerAfterCompletion(AbstractPlatformTransactionManager.java:971)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:799)
   at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
   at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:394)
   at org.alfresco.util.transaction.SpringAwareUserTransaction.commit(SpringAwareUserTransaction.java:472)
   at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:343)
   at org.alfresco.repo.node.index.AbstractReindexComponent$ReindexWorkerRunnable.run(AbstractReindexComponent.java:874)
   at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
   at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: Bad file descriptor
   at java.io.FileOutputStream.close0(Native Method)
   at java.io.FileOutputStream.close(FileOutputStream.java:279)
   at java.io.FilterOutputStream.close(FilterOutputStream.java:143)
   at java.io.FilterOutputStream.close(FilterOutputStream.java:143)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.setPreparedState(IndexInfo.java:1130)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneBase.setInfo(AbstractLuceneBase.java:256)
   at org.alfresco.repo.search.impl.lucene.ADMLuceneIndexerImpl.doCommit(ADMLuceneIndexerImpl.java:1678)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerImpl.commit(AbstractLuceneIndexerImpl.java:413)
   … 14 more
16:51:19,829  ERROR [index.AbstractReindexComponent.threads] Reindexer    16 failed with error: 06280004 Failed to prepare: requires rollback.
16:51:44,259  ERROR [index.AbstractReindexComponent.threads] Reindexer    17 failed with error: after flush: fdx size mismatch: 1 docs vs 0 length in bytes of _0.fdx.
16:51:44,698  ERROR [index.AbstractReindexComponent.threads] Reindexer    19 failed with error: after flush: fdx size mismatch: 263 docs vs 0 length in bytes of _0.fdx.
16:51:45,400  INFO  [node.index.FullIndexRecoveryComponent]    30 % complete.
### Excluding compile: org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger::mergeDeletions
16:53:24,036  INFO  [node.index.FullIndexRecoveryComponent]    40 % complete.
16:53:24,037  INFO  [node.index.FullIndexRecoveryComponent]    50 % complete.
16:55:01,909  ERROR [repo.transaction.AlfrescoTransactionSupport] After completion (committed) Lucene exception
org.alfresco.repo.search.impl.lucene.LuceneIndexException: 06280008 rollback failed 
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerImpl.rollback(AbstractLuceneIndexerImpl.java:525)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerImpl.commit(AbstractLuceneIndexerImpl.java:420)
   at org.alfresco.repo.search.impl.lucene.AbstractLuceneIndexerAndSearcherFactory.commit(AbstractLuceneIndexerAndSearcherFactory.java:766)
   at org.alfresco.repo.transaction.AlfrescoTransactionSupport$TransactionSynchronizationImpl.afterCompletion(AlfrescoTransactionSupport.java:842)
   at org.springframework.transaction.support.TransactionSynchronizationUtils.invokeAfterCompletion(TransactionSynchronizationUtils.java:168)
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

And entries of this type

6:59:04,952  ERROR [lucene.index.IndexInfo] Index merger failed to recover - suspending 
java.lang.RuntimeException: Error during run with lock.
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.doWithFileLock(IndexInfo.java:2462)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.access$4800(IndexInfo.java:141)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger.recoverImpl(IndexInfo.java:3372)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo$AbstractSchedulable.run(IndexInfo.java:3214)
   at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
   at java.lang.Thread.run(Thread.java:619)
Caused by: java.io.IOException: No sub-file with id _0.fnm found
   at org.apache.lucene.index.CompoundFileReader.openInput(CompoundFileReader.java:137)
   at org.apache.lucene.index.CompoundFileReader.openInput(CompoundFileReader.java:126)
   at org.apache.lucene.index.FieldInfos.<init>(FieldInfos.java:58)
   at org.apache.lucene.index.SegmentReader.initialize(SegmentReader.java:341)
   at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:306)
   at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:269)
   at org.apache.lucene.index.DirectoryIndexReader$1.doBody(DirectoryIndexReader.java:100)
   at org.apache.lucene.index.SegmentInfos$FindSegmentsFile.run(SegmentInfos.java:653)
   at org.apache.lucene.index.DirectoryIndexReader.open(DirectoryIndexReader.java:115)
   at org.apache.lucene.index.IndexReader.open(IndexReader.java:316)
   at org.apache.lucene.index.IndexReader.open(IndexReader.java:227)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.buildReferenceCountingIndexReader(IndexInfo.java:2134)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.access$2000(IndexInfo.java:141)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo$Merger$2.doWork(IndexInfo.java:3431)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.doWithFileLock(IndexInfo.java:2531)
   at org.alfresco.repo.search.impl.lucene.index.IndexInfo.doWithFileLock(IndexInfo.java:2451)
   … 6 more
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Alfresco is running on CentOS 5.+ Server

17:11:57,129  INFO  [service.descriptor.DescriptorService] Alfresco JVM - v1.6.0_14-b08; maximum heap size 755.563MB
17:11:57,129  INFO  [service.descriptor.DescriptorService] Alfresco started (Community): Current version 3.3.0 (g 2860) schema 4100 - Originally installed version 3.2.0 (2039) schema 2019
‍‍‍

Is it possible that the direct upgrade from 3.2.0 to 3.3g (without passing through the intermittent stages may have played a part in this?

Any qualified advice on the best course of action to take now would be highly appreciated.

Thanks.

[rays]

In view of the references in catalina.out to "lock" issues, I am wondering whether this JIRA issue is at the source of our current difficulties?

http://issues.alfresco.com/jira/browse/ALF-2641 "WebDav Permission Issues - MAC OSX Finder"

We have uploaded files to the affected server using webdav from Mac OS X Finder yesterday. Could the "lock" issues I report in that JIRA bug be related to these type of entries I'm seeing today during start-up? Bearing in mind that Lucene would have backed-up its indexes between then and now.

6:59:04,952  ERROR [lucene.index.IndexInfo] Index merger failed to recover - suspending
java.lang.RuntimeException: Error during run with lock.‍‍

Again, all qualified advice would be welcomed.

[sibe]

Hello

Have you find a solution for the problem ?

Thank I have the some probleme using alfresco community 3.3g

Thank for your answer

[andy]

Hi

It looks like the index is confused and missing files.

More than one repo pointing at teh same index location?
Some remote protocol caching stuffed up (could be the protocol itself, time sync on machines etc etc)

Andy

[rivarola]

Hi,

We got the same error on 3.3g during a bulk import and after having changed the merger options to

lucene.indexer.mergerMergeFactor=10
lucene.indexer.mergerRamBufferSizeMb=32
lucene.indexer.writerMergeFactor=10
lucene.indexer.writerRamBufferSizeMb=32
lucene.indexer.maxRamInMbForInMemoryMerge=32
lucene.indexer.maxRamInMbForInMemoryIndex=32‍‍‍‍‍‍

It seems the merger recovered from the error because the server is still alive and Lucene queries are still working.