Add test to validate debug log statement doesn't have errors

Signed-off-by: Peter Nied <[email protected]>

server/src/test/java/org/opensearch/index/store/RemoteSegmentStoreDirectoryTests.java

@@ -8,6 +8,7 @@
 
 package org.opensearch.index.store;
 
+import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
 import org.apache.lucene.codecs.CodecUtil;
@@ -41,6 +42,8 @@
 import org.opensearch.index.store.remote.metadata.RemoteSegmentMetadata;
 import org.opensearch.index.store.remote.metadata.RemoteSegmentMetadataHandler;
 import org.opensearch.indices.replication.common.ReplicationType;
+import org.opensearch.test.MockLogAppender;
+import org.opensearch.test.junit.annotations.TestLogging;
 import org.opensearch.threadpool.ThreadPool;
 import org.junit.After;
 import org.junit.Before;
@@ -58,6 +61,8 @@
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.TimeUnit;
+import java.util.regex.Pattern;
+import java.util.stream.Collectors;
 
 import org.mockito.Mockito;
 
@@ -971,21 +976,52 @@ public void testDeleteStaleCommitsWithinThreshold() throws Exception {
         verify(remoteMetadataDirectory, times(0)).openInput(any(String.class), eq(IOContext.DEFAULT));
     }
 
+    @TestLogging(value = "_root:debug", reason = "Validate logging output")
     public void testDeleteStaleCommitsActualDelete() throws Exception {
-        Map<String, Map<String, String>> metadataFilenameContentMapping = populateMetadata();
-        remoteSegmentStoreDirectory.init();
-
-        // popluateMetadata() adds stub to return 3 metadata files
-        // We are passing lastNMetadataFilesToKeep=2 here so that oldest 1 metadata file will be deleted
-        remoteSegmentStoreDirectory.deleteStaleSegmentsAsync(2);
-
-        for (String metadata : metadataFilenameContentMapping.get(metadataFilename3).values()) {
-            String uploadedFilename = metadata.split(RemoteSegmentStoreDirectory.UploadedSegmentMetadata.SEPARATOR)[1];
-            verify(remoteDataDirectory).deleteFile(uploadedFilename);
+        try (final MockLogAppender appender = MockLogAppender.createForLoggers(LogManager.getRootLogger())) {
+            appender.addExpectation(
+                new MockLogAppender.PatternSeenWithLoggerPrefixExpectation(
+                    "Metadata files to delete message",
+                    "org.opensearch.index.store.RemoteSegmentStoreDirectory",
+                    Level.DEBUG,
+                    "metadataFilesEligibleToDelete=\\[" + metadataFilename3 + "\\] metadataFilesToBeDeleted=\\[" + metadataFilename3 + "\\]"
+                )
+            );
+
+            final Map<String, Map<String, String>> metadataFilenameContentMapping = populateMetadata();
+            final List<String> filesToBeDeleted = metadataFilenameContentMapping.get(metadataFilename3)
+                .values()
+                .stream()
+                .map(metadata -> metadata.split(RemoteSegmentStoreDirectory.UploadedSegmentMetadata.SEPARATOR)[1])
+                .collect(Collectors.toList());
+
+            final String allFilesPattern = filesToBeDeleted.stream()
+                .map(Pattern::quote) // Make sure filenames are matched literally
+                .map(file -> "(?=.*?" + file + ")") // Allow for matches in any order
+                .collect(Collectors.joining("", "deletedSegmentFiles=\\[", ".*\\]"));
+
+            appender.addExpectation(
+                new MockLogAppender.PatternSeenWithLoggerPrefixExpectation(
+                    "Deleted file segments message",
+                    "org.opensearch.index.store.RemoteSegmentStoreDirectory",
+                    Level.DEBUG,
+                    allFilesPattern
+                )
+            );
+
+            remoteSegmentStoreDirectory.init();
+
+            // popluateMetadata() adds stub to return 3 metadata files
+            // We are passing lastNMetadataFilesToKeep=2 here so that oldest 1 metadata file will be deleted
+            remoteSegmentStoreDirectory.deleteStaleSegmentsAsync(2);
+
+            for (final String file : filesToBeDeleted) {
+                verify(remoteDataDirectory).deleteFile(file);
+            }
+            assertBusy(() -> assertThat(remoteSegmentStoreDirectory.canDeleteStaleCommits.get(), is(true)));
+            verify(remoteMetadataDirectory).deleteFile(metadataFilename3);
+            appender.assertAllExpectationsMatched();
         }
-        ;
-        assertBusy(() -> assertThat(remoteSegmentStoreDirectory.canDeleteStaleCommits.get(), is(true)));
-        verify(remoteMetadataDirectory).deleteFile(metadataFilename3);
     }
 
     public void testDeleteStaleCommitsActualDeleteWithLocks() throws Exception {

test/framework/src/main/java/org/opensearch/test/MockLogAppender.java

@@ -40,14 +40,17 @@
 import org.opensearch.common.logging.Loggers;
 import org.opensearch.common.regex.Regex;
 
+import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.Collections;
 import java.util.List;
 import java.util.concurrent.CopyOnWriteArrayList;
+import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.regex.Pattern;
 
 import static org.hamcrest.CoreMatchers.equalTo;
 import static org.hamcrest.MatcherAssert.assertThat;
+import static org.junit.Assert.fail;
 
 /**
  * Test appender that can be used to verify that certain events were logged correctly
@@ -259,6 +262,61 @@ public void assertMatched() {
 
     }
 
+    /**
+     * Used for cases when the logger is dynamically named such as to include an index name or shard id
+     *
+     * Best used in conjunction with the root logger:
+     *     @TestLogging(value = "_root:debug", reason = "Validate logging output")
+     *
+     * */
+    public static class PatternSeenWithLoggerPrefixExpectation implements LoggingExpectation {
+        private final String expectationName;
+        private final String loggerPrefix;
+        private final Level level;
+        private final String messageMatchingRegex;
+
+        private final List<String> loggerMatches = new ArrayList<>();
+        private final AtomicBoolean eventSeen = new AtomicBoolean(false);
+
+        public PatternSeenWithLoggerPrefixExpectation(
+            final String expectationName,
+            final String loggerPrefix,
+            final Level level,
+            final String messageMatchingRegex
+        ) {
+            this.expectationName = expectationName;
+            this.loggerPrefix = loggerPrefix;
+            this.level = level;
+            this.messageMatchingRegex = messageMatchingRegex;
+        }
+
+        @Override
+        public void match(final LogEvent event) {
+            if (event.getLevel() == level && event.getLoggerName().startsWith(loggerPrefix)) {
+                final String formattedMessage = event.getMessage().getFormattedMessage();
+                loggerMatches.add(formattedMessage);
+                if (formattedMessage.matches(messageMatchingRegex)) {
+                    eventSeen.set(true);
+                }
+            }
+        }
+
+        @Override
+        public void assertMatched() {
+            if (!eventSeen.get()) {
+                final StringBuilder failureMessage = new StringBuilder();
+                failureMessage.append(
+                    String.format("%s was not seen, found %d messages matching the logger.", expectationName, loggerMatches.size())
+                );
+                failureMessage.append("\r\nMessage matching regex: " + messageMatchingRegex);
+                if (!loggerMatches.isEmpty()) {
+                    failureMessage.append("\r\nMessage details:\r\n" + String.join("\r\n", loggerMatches));
+                }
+                fail(failureMessage.toString());
+            }
+        }
+    }
+
     private static String getLoggerName(String name) {
         if (name.startsWith("org.opensearch.")) {
             name = name.substring("org.opensearch.".length());