Rebuild indexes that fail to open

If an index that should be online fails to open on startup we would not
be able to apply updates to it, and it would thus become inconsistent
with the database. Should the index then be possible to open after a
restart of the database we would end up with an inconsistent index.

The situation described above is now handled by treating the index as
permanently failed, and then taking actions to correct it. The first and
possibly most important action is to log the failure, something that was
not done before. Then we recognise that the only thing a user could do
to restore the index would be to either drop it and recreate it, or
stop the database, delete the index store files from disk, then restart
the database. By automating this second option we can avoid the need for
a restart. Since we are already in the startup phase when this happens,
we can simply treat the index as incompletely populated instead, forcing
the database to rebuild the index without any further intervention.

community/consistency-check-legacy/src/main/java/org/neo4j/legacy/consistency/ConsistencyCheckService.java

@@ -147,7 +147,7 @@ public PrintWriter get()
                         .build();
                 SchemaIndexProvider indexes = new LuceneSchemaIndexProvider(
                         fileSystem, DirectoryFactory.PERSISTENT,
-                        storeDir, tuningConfiguration, operationalMode );
+                        storeDir, logProvider, tuningConfiguration, operationalMode );
                 DirectStoreAccess stores = new DirectStoreAccess( store, labelScanStore, indexes );
                 FullCheck check = new FullCheck( tuningConfiguration, progressFactory );
                 summary = check.execute( stores, new DuplicatingLog( log, reportLog ) );

community/consistency-check-legacy/src/test/java/org/neo4j/legacy/consistency/checking/GraphStoreFixture.java

@@ -62,6 +62,7 @@
 import org.neo4j.kernel.impl.transaction.log.TransactionIdStore;
 import org.neo4j.kernel.impl.transaction.tracing.CommitEvent;
 import org.neo4j.logging.FormattedLogProvider;
+import org.neo4j.logging.NullLogProvider;
 import org.neo4j.test.PageCacheRule;
 import org.neo4j.test.TargetDirectory;
 import org.neo4j.test.TestGraphDatabaseFactory;
@@ -106,8 +107,8 @@ public DirectStoreAccess directStoreAccess()
     private SchemaIndexProvider createIndexes( FileSystemAbstraction fileSystem, Config config,
             OperationalMode operationalMode )
     {
-        return new LuceneSchemaIndexProvider( fileSystem, DirectoryFactory.PERSISTENT, directory, config,
-                operationalMode );
+        return new LuceneSchemaIndexProvider( fileSystem, DirectoryFactory.PERSISTENT, directory,
+                NullLogProvider.getInstance(), config, operationalMode );
     }
 
     public File directory()

community/consistency-check/src/main/java/org/neo4j/consistency/ConsistencyCheckService.java

@@ -152,7 +152,7 @@ public PrintWriter get()
                 SchemaIndexProvider indexes = new LuceneSchemaIndexProvider(
                         fileSystem,
                         DirectoryFactory.PERSISTENT,
-                        storeDir, consistencyCheckerConfig, operationalMode );
+                        storeDir, logProvider, consistencyCheckerConfig, operationalMode );
 
                 int numberOfThreads = defaultConsistencyCheckThreadsNumber();
                 Statistics statistics;

community/consistency-check/src/test/java/org/neo4j/consistency/checking/GraphStoreFixture.java

@@ -142,7 +142,8 @@ public DirectStoreAccess directStoreAccess()
     private SchemaIndexProvider createIndexes( FileSystemAbstraction fileSystem, Config config,
             OperationalMode operationalMode )
     {
-        return new LuceneSchemaIndexProvider( fileSystem, DirectoryFactory.PERSISTENT, directory, config, operationalMode );
+        return new LuceneSchemaIndexProvider( fileSystem, DirectoryFactory.PERSISTENT, directory,
+                FormattedLogProvider.toOutputStream( System.out ), config, operationalMode );
     }
 
     public File directory()

community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/IndexProxyFactory.java

@@ -21,5 +21,5 @@
 
 public interface IndexProxyFactory
 {
-    IndexProxy create();
+    IndexProxy create() throws Exception;
 }

community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/IndexProxySetup.java

@@ -31,10 +31,10 @@
 import org.neo4j.kernel.impl.api.UpdateableSchemaState;
 import org.neo4j.kernel.impl.api.index.sampling.IndexSamplingConfig;
 import org.neo4j.kernel.impl.util.JobScheduler;
+import org.neo4j.logging.Log;
 import org.neo4j.logging.LogProvider;
 
 import static java.lang.String.format;
-
 import static org.neo4j.kernel.impl.api.index.IndexPopulationFailure.failure;
 
 public class IndexProxySetup
@@ -75,7 +75,7 @@ public IndexProxy createPopulatingIndexProxy( final long ruleId,
         // TODO: This is here because there is a circular dependency from PopulatingIndexProxy to FlippableIndexProxy
         final String indexUserDescription = indexUserDescription( descriptor, providerDescriptor );
         final IndexConfiguration config = new IndexConfiguration( constraint );
-        IndexPopulator populator = populatorFromProvider( providerDescriptor, ruleId, descriptor, config,
+        final IndexPopulator populator = populatorFromProvider( providerDescriptor, ruleId, descriptor, config,
                 samplingConfig );
 
         FailedIndexProxyFactory failureDelegateFactory = new FailedPopulatingIndexProxyFactory(
@@ -97,25 +97,17 @@ public IndexProxy createPopulatingIndexProxy( final long ruleId,
         flipper.setFlipTarget( new IndexProxyFactory()
         {
             @Override
-            public IndexProxy create()
+            public IndexProxy create() throws Exception
             {
-                try
-                {
-                    monitor.populationCompleteOn( descriptor );
-                    OnlineIndexProxy onlineProxy = new OnlineIndexProxy(
-                            descriptor, config, onlineAccessorFromProvider( providerDescriptor, ruleId,
-                            config, samplingConfig ), storeView, providerDescriptor
-                    );
-                    if ( constraint )
-                    {
-                        return new TentativeConstraintIndexProxy( flipper, onlineProxy );
-                    }
-                    return onlineProxy;
-                }
-                catch ( IOException e )
+                monitor.populationCompleteOn( descriptor );
+                OnlineIndexProxy onlineProxy = new OnlineIndexProxy(
+                        descriptor, config, onlineAccessorFromProvider( providerDescriptor, ruleId,
+                        config, samplingConfig ), storeView, providerDescriptor );
+                if ( constraint )
                 {
-                    return createFailedIndexProxy( ruleId, descriptor, providerDescriptor, constraint, failure( e ) );
+                    return new TentativeConstraintIndexProxy( flipper, onlineProxy );
                 }
+                return onlineProxy;
             }
         } );
 
@@ -151,7 +143,10 @@ public IndexProxy createOnlineIndexProxy( long ruleId,
         }
         catch ( IOException e )
         {
-            return createFailedIndexProxy( ruleId, descriptor, providerDescriptor, unique, failure( e ) );
+            logProvider.getLog( getClass() ).error( "Failed to open index: " + ruleId +
+                    " (" + descriptor.userDescription( tokenNameLookup ) +
+                    "), requesting re-population.", e );
+            return createRecoveringIndexProxy( descriptor, providerDescriptor, unique );
         }
     }
 

community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/IndexingService.java

@@ -234,7 +234,6 @@ public void init()
                     break;
                 case POPULATING:
                     // The database was shut down during population, or a crash has occurred, or some other sad thing.
-
                     indexProxy = proxySetup.createRecoveringIndexProxy( descriptor, providerDescriptor, constraint );
                     break;
                 case FAILED:

community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/IndexingServiceTest.java

@@ -19,12 +19,6 @@
  */
 package org.neo4j.kernel.impl.api.index;
 
-import org.junit.Rule;
-import org.junit.Test;
-import org.mockito.InOrder;
-import org.mockito.invocation.InvocationOnMock;
-import org.mockito.stubbing.Answer;
-
 import java.io.File;
 import java.io.IOException;
 import java.util.Arrays;
@@ -34,6 +28,16 @@
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.concurrent.atomic.AtomicLong;
 
+import org.hamcrest.Description;
+import org.hamcrest.Matcher;
+import org.hamcrest.TypeSafeMatcher;
+import org.junit.Rule;
+import org.junit.Test;
+import org.mockito.ArgumentCaptor;
+import org.mockito.InOrder;
+import org.mockito.invocation.InvocationOnMock;
+import org.mockito.stubbing.Answer;
+
 import org.neo4j.collection.primitive.PrimitiveLongSet;
 import org.neo4j.graphdb.ResourceIterator;
 import org.neo4j.helpers.collection.ArrayIterator;
@@ -71,6 +75,7 @@
 import org.neo4j.register.Register.DoubleLongRegister;
 import org.neo4j.test.DoubleLatch;
 
+import static java.util.Arrays.asList;
 import static org.hamcrest.CoreMatchers.containsString;
 import static org.hamcrest.CoreMatchers.startsWith;
 import static org.hamcrest.Matchers.equalTo;
@@ -94,15 +99,13 @@
 import static org.mockito.Mockito.verifyNoMoreInteractions;
 import static org.mockito.Mockito.verifyZeroInteractions;
 import static org.mockito.Mockito.when;
-
-import static java.util.Arrays.asList;
-
 import static org.neo4j.collection.primitive.PrimitiveLongCollections.setOf;
 import static org.neo4j.helpers.collection.IteratorUtil.asCollection;
 import static org.neo4j.helpers.collection.IteratorUtil.asResourceIterator;
 import static org.neo4j.helpers.collection.IteratorUtil.asSet;
 import static org.neo4j.helpers.collection.IteratorUtil.iterator;
 import static org.neo4j.helpers.collection.IteratorUtil.loop;
+import static org.neo4j.kernel.api.index.InternalIndexState.FAILED;
 import static org.neo4j.kernel.api.index.InternalIndexState.ONLINE;
 import static org.neo4j.kernel.api.index.InternalIndexState.POPULATING;
 import static org.neo4j.kernel.impl.api.index.IndexUpdateMode.BATCHED;
@@ -801,6 +804,108 @@ public void awaitingPopulationOfRecoveredIndex( long index, IndexDescriptor desc
         assertEquals( ONLINE, indexing.getIndexProxy( indexId.get() ).getState() );
     }
 
+    @Test
+    public void shouldStoreIndexFailureWhenFailingToCreateOnlineAccessorAfterPopulating() throws Exception
+    {
+        // given
+        long indexId = 1;
+        IndexingService indexing = newIndexingServiceWithMockedDependencies( populator, accessor, withData() );
+
+        IOException exception = new IOException( "Expected failure" );
+        when( nameLookup.labelGetName( labelId ) ).thenReturn( "TheLabel" );
+        when( nameLookup.propertyKeyGetName( propertyKeyId ) ).thenReturn( "propertyKey" );
+
+        when( indexProvider.getOnlineAccessor(
+                eq( indexId ), any( IndexConfiguration.class ), any( IndexSamplingConfig.class ) ) )
+                .thenThrow( exception );
+
+        life.start();
+        ArgumentCaptor<Boolean> closeArgs = ArgumentCaptor.forClass( Boolean.class );
+
+        // when
+        indexing.createIndex( indexRule( indexId, labelId, propertyKeyId, PROVIDER_DESCRIPTOR ) );
+        verify( populator, timeout( 1000 ).times( 2 ) ).close( closeArgs.capture() );
+
+        // then
+        assertEquals( FAILED, indexing.getIndexProxy( 1 ).getState() );
+        assertEquals( asList( true, false ), closeArgs.getAllValues() );
+        assertThat( storedFailure(), containsString( "java.io.IOException: Expected failure\n\tat " ) );
+        logProvider.assertAtLeastOnce( inLog( IndexPopulationJob.class ).error( equalTo(
+                "Failed to populate index: [:TheLabel(propertyKey) [provider: {key=quantum-dex, version=25.0}]]" ),
+                causedBy( exception ) ) );
+        logProvider.assertNone( inLog( IndexPopulationJob.class ).info(
+                "Index population completed. Index is now online: [%s]",
+                ":TheLabel(propertyKey) [provider: {key=quantum-dex, version=25.0}]" ) );
+    }
+
+    @Test
+    public void shouldStoreIndexFailureWhenFailingToCreateOnlineAccessorAfterRecoveringPopulatingIndex() throws Exception
+    {
+        // given
+        long indexId = 1;
+        IndexingService indexing = newIndexingServiceWithMockedDependencies( populator, accessor, withData(),
+                indexRule( indexId, labelId, propertyKeyId, PROVIDER_DESCRIPTOR ) );
+
+        IOException exception = new IOException( "Expected failure" );
+        when( nameLookup.labelGetName( labelId ) ).thenReturn( "TheLabel" );
+        when( nameLookup.propertyKeyGetName( propertyKeyId ) ).thenReturn( "propertyKey" );
+
+        when( indexProvider.getInitialState( indexId ) ).thenReturn( POPULATING );
+        when( indexProvider.getOnlineAccessor(
+                eq( indexId ), any( IndexConfiguration.class ), any( IndexSamplingConfig.class ) ) )
+                .thenThrow( exception );
+
+        life.start();
+        ArgumentCaptor<Boolean> closeArgs = ArgumentCaptor.forClass( Boolean.class );
+
+        // when
+        verify( populator, timeout( 1000 ).times( 2 ) ).close( closeArgs.capture() );
+
+        // then
+        assertEquals( FAILED, indexing.getIndexProxy( 1 ).getState() );
+        assertEquals( asList( true, false ), closeArgs.getAllValues() );
+        assertThat( storedFailure(), containsString( "java.io.IOException: Expected failure\n\tat " ) );
+        logProvider.assertAtLeastOnce( inLog( IndexPopulationJob.class ).error( equalTo(
+                "Failed to populate index: [:TheLabel(propertyKey) [provider: {key=quantum-dex, version=25.0}]]" ),
+                causedBy( exception ) ) );
+        logProvider.assertNone( inLog( IndexPopulationJob.class ).info(
+                "Index population completed. Index is now online: [%s]",
+                ":TheLabel(propertyKey) [provider: {key=quantum-dex, version=25.0}]" ) );
+    }
+
+    static Matcher<? extends Throwable> causedBy( final Throwable exception )
+    {
+        return new TypeSafeMatcher<Throwable>()
+        {
+            @Override
+            protected boolean matchesSafely( Throwable item )
+            {
+                while ( item != null )
+                {
+                    if ( item == exception )
+                    {
+                        return true;
+                    }
+                    item = item.getCause();
+                }
+                return false;
+            }
+
+            @Override
+            public void describeTo( Description description )
+            {
+                description.appendText( "exception caused by " ).appendValue( exception );
+            }
+        };
+    }
+
+    private String storedFailure() throws IOException
+    {
+        ArgumentCaptor<String> reason = ArgumentCaptor.forClass( String.class );
+        verify( populator ).markAsFailed( reason.capture() );
+        return reason.getValue();
+    }
+
     private static class ControlledIndexPopulator extends IndexPopulator.Adapter
     {
         private final DoubleLatch latch;

community/lucene-index/pom.xml

@@ -64,6 +64,13 @@ the relevant Commercial Agreement.
       <type>test-jar</type>
       <scope>test</scope>
     </dependency>
+    <dependency>
+      <groupId>org.neo4j</groupId>
+      <artifactId>neo4j-logging</artifactId>
+      <version>${project.version}</version>
+      <type>test-jar</type>
+      <scope>test</scope>
+    </dependency>
     <dependency>
       <groupId>org.neo4j</groupId>
       <artifactId>neo4j-io</artifactId>