Core: separately log file deletions

Today, you can turn on lucene.iw TRACE logging, but that produces tons
of output.  This changes breaks out separate lucene.iw.ifd and
index.store.deletes logger components (TRACE), disabled by default, to
see what part of Elasticsearch is deleting index files.

Closed #8662

Closed #8603

src/main/java/org/elasticsearch/common/lucene/LoggerInfoStream.java

@@ -26,23 +26,38 @@ import org.elasticsearch.common.settings.Settings;
 import org.elasticsearch.index.shard.ShardId;
 
 /** An InfoStream (for Lucene's IndexWriter) that redirects
- *  messages to Logger.trace. */
+ *  messages to "lucene.iw.ifd" and "lucene.iw" Logger.trace. */
 
 public final class LoggerInfoStream extends InfoStream {
+    /** Used for component-specific logging: */
+
+    /** Logger for everything */
     private final ESLogger logger;
 
+    /** Logger for IndexFileDeleter */
+    private final ESLogger ifdLogger;
+
     public LoggerInfoStream(Settings settings, ShardId shardId) {
         logger = Loggers.getLogger("lucene.iw", settings, shardId);
+        ifdLogger = Loggers.getLogger("lucene.iw.ifd", settings, shardId);
     }
 
     public void message(String component, String message) {
-        logger.trace("{} {}: {}", Thread.currentThread().getName(), component, message);
+        getLogger(component).trace("{} {}: {}", Thread.currentThread().getName(), component, message);
     }
   
     public boolean isEnabled(String component) {
         // TP is a special "test point" component; we don't want
         // to log it:
-        return logger.isTraceEnabled() && component.equals("TP") == false;
+        return getLogger(component).isTraceEnabled() && component.equals("TP") == false;
+    }
+
+    private ESLogger getLogger(String component) {
+        if (component.equals("IFD")) {
+            return ifdLogger;
+        } else {
+            return logger;
+        }
     }
 
     @Override

src/main/java/org/elasticsearch/index/snapshots/blobstore/BlobStoreIndexShardRepository.java

@@ -806,6 +806,7 @@ public class BlobStoreIndexShardRepository extends AbstractComponent implements
                     for (String storeFile : store.directory().listAll()) {
                         if (!Store.isChecksum(storeFile) && !snapshot.containPhysicalIndexFile(storeFile)) {
                             try {
+                                store.logDeleteFile("restore", storeFile);
                                 store.directory().deleteFile(storeFile);
                             } catch (IOException e) {
                                 // ignore

src/main/java/org/elasticsearch/index/store/Store.java

@@ -537,8 +537,11 @@ public class Store extends AbstractIndexShardComponent implements Closeable, Ref
      */
     public final class StoreDirectory extends FilterDirectory {
 
+        public final ESLogger deletesLogger;
+
         StoreDirectory(Directory delegateDirectory) throws IOException {
             super(delegateDirectory);
+            deletesLogger = Loggers.getLogger("index.store.deletes", indexSettings, shardId);
         }
 
         public ShardId shardId() {
@@ -551,6 +554,12 @@ public class Store extends AbstractIndexShardComponent implements Closeable, Ref
             assert false : "Nobody should close this directory except of the Store itself";
         }
 
+        @Override
+        public void deleteFile(String name) throws IOException {
+            logDeleteFile("StoreDirectory.deleteFile", name);
+            super.deleteFile(name);
+        }
+
         private void innerClose() throws IOException {
             super.close();
         }
@@ -561,8 +570,22 @@ public class Store extends AbstractIndexShardComponent implements Closeable, Ref
         }
     }
 
+    /** Log that we are about to delete this file, to the index.store.deletes component. */
+    public void logDeleteFile(String message, String fileName) {
+        logDeleteFile(directory(), message, fileName);
+    }
+
+    /** Log that we are about to delete this file, to the index.store.deletes component. */
+    public static void logDeleteFile(Directory dir, String message, String fileName) {
+        assert dir instanceof StoreDirectory;
+        if (dir instanceof StoreDirectory) {
+            ((StoreDirectory) dir).deletesLogger.trace("{}: delete file {}", message, fileName);
+        }
+        // else what to do...?
+    }
+
     /**
-     * Represents a snaphshot of the current directory build from the latest Lucene commit.
+     * Represents a snapshot of the current directory build from the latest Lucene commit.
      * Only files that are part of the last commit are considered in this datastrucutre.
      * For backwards compatibility the snapshot might include legacy checksums that
      * are derived from a dedicated checksum file written by older elasticsearch version pre 1.3

src/main/java/org/elasticsearch/indices/recovery/RecoveryTarget.java

@@ -385,6 +385,7 @@ public class RecoveryTarget extends AbstractComponent {
                     // don't delete snapshot file, or the checksums file (note, this is extra protection since the Store won't delete checksum)
                     if (!request.snapshotFiles().contains(existingFile) && !Store.isChecksum(existingFile)) {
                         try {
+                            store.logDeleteFile("recovery CleanFilesRequestHandler", existingFile);
                             store.directory().deleteFile(existingFile);
                         } catch (Exception e) {
                             // ignore, we don't really care, will get deleted later on

src/test/java/org/elasticsearch/index/engine/internal/InternalEngineIntegrationTest.java

@@ -57,6 +57,8 @@ public class InternalEngineIntegrationTest extends ElasticsearchIntegrationTest
     private void assertTotalCompoundSegments(int i, int t, String index) {
         IndicesSegmentResponse indicesSegmentResponse = client().admin().indices().prepareSegments(index).get();
         IndexSegments indexSegments = indicesSegmentResponse.getIndices().get(index);
+        assertNotNull(indexSegments);
+        assertNotNull(indexSegments.getShards());
         Collection<IndexShardSegments> values = indexSegments.getShards().values();
         int compounds = 0;
         int total = 0;

src/test/java/org/elasticsearch/index/engine/internal/InternalEngineTests.java

@@ -1254,16 +1254,19 @@ public class InternalEngineTests extends ElasticsearchTestCase {
 
     private static class MockAppender extends AppenderSkeleton {
         public boolean sawIndexWriterMessage;
+        public boolean sawIndexWriterIFDMessage;
 
         @Override
         protected void append(LoggingEvent event) {
-        if (event.getLevel() == Level.TRACE &&
+            if (event.getLevel() == Level.TRACE && event.getMessage().toString().contains("[index][1] ")) {
-            event.getLoggerName().endsWith("lucene.iw") &&
+                if (event.getLoggerName().endsWith("lucene.iw") &&
-            event.getMessage().toString().contains("IW: apply all deletes during flush") &&
+                    event.getMessage().toString().contains("IW: apply all deletes during flush")) {
-            event.getMessage().toString().contains("[index][1] ")) {
-
                     sawIndexWriterMessage = true;
                 }
+                if (event.getLoggerName().endsWith("lucene.iw.ifd")) {
+                    sawIndexWriterIFDMessage = true;
+                }
+            }
         }
 
         @Override
@@ -1307,6 +1310,36 @@ public class InternalEngineTests extends ElasticsearchTestCase {
         }
     }
 
+    // #8603: make sure we can separately log IFD's messages
+    public void testIndexWriterIFDInfoStream() {
+        MockAppender mockAppender = new MockAppender();
+
+        Logger iwIFDLogger = Logger.getLogger("lucene.iw.ifd");
+        Level savedLevel = iwIFDLogger.getLevel();
+        iwIFDLogger.addAppender(mockAppender);
+        iwIFDLogger.setLevel(Level.DEBUG);
+
+        try {
+            // First, with DEBUG, which should NOT log IndexWriter output:
+            ParsedDocument doc = testParsedDocument("1", "1", "test", null, -1, -1, testDocumentWithTextField(), Lucene.STANDARD_ANALYZER, B_1, false);
+            engine.create(new Engine.Create(null, newUid("1"), doc));
+            engine.flush(new Engine.Flush());        
+            assertFalse(mockAppender.sawIndexWriterMessage);
+            assertFalse(mockAppender.sawIndexWriterIFDMessage);
+
+            // Again, with TRACE, which should only log IndexWriter IFD output:
+            iwIFDLogger.setLevel(Level.TRACE);
+            engine.create(new Engine.Create(null, newUid("2"), doc));
+            engine.flush(new Engine.Flush());        
+            assertFalse(mockAppender.sawIndexWriterMessage);
+            assertTrue(mockAppender.sawIndexWriterIFDMessage);
+
+        } finally {
+            iwIFDLogger.removeAppender(mockAppender);
+            iwIFDLogger.setLevel(null);
+        }
+    }
+
     @Slow
     @Test
     public void testEnableGcDeletes() throws Exception {