diff --git a/server/src/test/java/org/opensearch/index/store/RemoteSegmentStoreDirectoryTests.java b/server/src/test/java/org/opensearch/index/store/RemoteSegmentStoreDirectoryTests.java index 7944ee681f5fc..09bbad04408f5 100644 --- a/server/src/test/java/org/opensearch/index/store/RemoteSegmentStoreDirectoryTests.java +++ b/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> 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> metadataFilenameContentMapping = populateMetadata(); + final List 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 { diff --git a/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java b/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java index 59eda7a665d4c..d5d7c6d301032 100644 --- a/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java +++ b/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 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());