From 49367369b95a8d268a5f5fe7cff2d53624c3f30e Mon Sep 17 00:00:00 2001 From: Peter Nied Date: Thu, 15 Feb 2024 00:09:06 +0000 Subject: [PATCH 1/6] Fix error in RemoteSegmentStoreDirectory when debug logging is enabled Signed-off-by: Peter Nied --- .../store/RemoteSegmentStoreDirectory.java | 8 +++--- .../opensearch/test/OpenSearchTestCase.java | 28 +++++++++++++++++++ 2 files changed, 32 insertions(+), 4 deletions(-) diff --git a/server/src/main/java/org/opensearch/index/store/RemoteSegmentStoreDirectory.java b/server/src/main/java/org/opensearch/index/store/RemoteSegmentStoreDirectory.java index dab99fd25b192..bfab9f8c18aa2 100644 --- a/server/src/main/java/org/opensearch/index/store/RemoteSegmentStoreDirectory.java +++ b/server/src/main/java/org/opensearch/index/store/RemoteSegmentStoreDirectory.java @@ -45,6 +45,7 @@ import java.io.IOException; import java.io.InputStream; import java.nio.file.NoSuchFileException; +import java.util.ArrayList; import java.util.Collection; import java.util.Collections; import java.util.HashMap; @@ -745,9 +746,8 @@ public void deleteStaleSegments(int lastNMetadataFilesToKeep) throws IOException return; } - List metadataFilesEligibleToDelete = sortedMetadataFileList.subList( - lastNMetadataFilesToKeep, - sortedMetadataFileList.size() + List metadataFilesEligibleToDelete = new ArrayList<>( + sortedMetadataFileList.subList(lastNMetadataFilesToKeep, sortedMetadataFileList.size()) ); Set allLockFiles; try { @@ -764,7 +764,7 @@ public void deleteStaleSegments(int lastNMetadataFilesToKeep) throws IOException logger.debug( "metadataFilesEligibleToDelete={} metadataFilesToBeDeleted={}", metadataFilesEligibleToDelete, - metadataFilesEligibleToDelete + metadataFilesToBeDeleted ); Map activeSegmentFilesMetadataMap = new HashMap<>(); diff --git a/test/framework/src/main/java/org/opensearch/test/OpenSearchTestCase.java b/test/framework/src/main/java/org/opensearch/test/OpenSearchTestCase.java index 96bffcf2d3692..aac3fca9e1e16 100644 --- a/test/framework/src/main/java/org/opensearch/test/OpenSearchTestCase.java +++ b/test/framework/src/main/java/org/opensearch/test/OpenSearchTestCase.java @@ -145,6 +145,8 @@ import java.io.IOException; import java.io.InputStream; +import java.io.PrintWriter; +import java.io.StringWriter; import java.math.BigInteger; import java.net.InetAddress; import java.net.UnknownHostException; @@ -170,6 +172,7 @@ import java.util.concurrent.atomic.AtomicInteger; import java.util.function.BooleanSupplier; import java.util.function.Consumer; +import java.util.function.Function; import java.util.function.IntFunction; import java.util.function.Predicate; import java.util.function.Supplier; @@ -639,7 +642,32 @@ protected static void checkStaticState(boolean afterClass) throws Exception { try { // ensure that there are no status logger messages which would indicate a problem with our Log4j usage; we map the // StatusData instances to Strings as otherwise their toString output is useless + + final Function statusToString = (statusData) -> { + try (final StringWriter sw = new StringWriter(); final PrintWriter pw = new PrintWriter(sw)) { + + pw.print(statusData.getLevel()); + pw.print(":"); + pw.print(statusData.getMessage().getFormattedMessage()); + + if (statusData.getStackTraceElement() != null) { + final var messageSource = statusData.getStackTraceElement(); + pw.println("Source:"); + pw.println(messageSource.getFileName() + "@" + messageSource.getLineNumber()); + } + + if (statusData.getThrowable() != null) { + pw.println("Throwable:"); + statusData.getThrowable().printStackTrace(pw); + } + return sw.toString(); + } catch (IOException ioe) { + throw new RuntimeException(ioe); + } + }; + assertThat( + statusData.stream().map(statusToString::apply).collect(Collectors.joining("\r\n")), statusData.stream().map(status -> status.getMessage().getFormattedMessage()).collect(Collectors.toList()), empty() ); From 8c39071a1708fe8a1b5c2c5b5b6622341355384b Mon Sep 17 00:00:00 2001 From: Peter Nied Date: Thu, 15 Feb 2024 00:10:57 +0000 Subject: [PATCH 2/6] Add changelog entry Signed-off-by: Peter Nied --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 82ef8d647c819..b095da6673d89 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -87,6 +87,7 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), - Update supported version for must_exist parameter in update aliases API ([#11872](https://github.com/opensearch-project/OpenSearch/pull/11872)) - [Bug] Check phase name before SearchRequestOperationsListener onPhaseStart ([#12035](https://github.com/opensearch-project/OpenSearch/pull/12035)) - Fix Span operation names generated from RestActions ([#12005](https://github.com/opensearch-project/OpenSearch/pull/12005)) +- Fix error in RemoteSegmentStoreDirectory when debug logging is enabled ([#12328](https://github.com/opensearch-project/OpenSearch/pull/12328)) ### Security From 0dd44f76671f0d0bbf5580cd55231f75cd49c6af Mon Sep 17 00:00:00 2001 From: Peter Nied Date: Thu, 15 Feb 2024 19:28:56 +0000 Subject: [PATCH 3/6] Add test to validate debug log statement doesn't have errors Signed-off-by: Peter Nied --- .../RemoteSegmentStoreDirectoryTests.java | 62 +++++++++++++++---- .../org/opensearch/test/MockLogAppender.java | 58 +++++++++++++++++ 2 files changed, 107 insertions(+), 13 deletions(-) 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()); From fc600acf327563dd25da57dbaaa320cc82dde4d0 Mon Sep 17 00:00:00 2001 From: Peter Nied Date: Thu, 15 Feb 2024 20:45:26 +0000 Subject: [PATCH 4/6] Dial back the level of detail validated for the segments that are deleted Signed-off-by: Peter Nied --- .../store/RemoteSegmentStoreDirectoryTests.java | 15 --------------- .../java/org/opensearch/test/MockLogAppender.java | 4 +--- 2 files changed, 1 insertion(+), 18 deletions(-) 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 09bbad04408f5..e2ebb2e642bfe 100644 --- a/server/src/test/java/org/opensearch/index/store/RemoteSegmentStoreDirectoryTests.java +++ b/server/src/test/java/org/opensearch/index/store/RemoteSegmentStoreDirectoryTests.java @@ -61,7 +61,6 @@ 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; @@ -995,20 +994,6 @@ public void testDeleteStaleCommitsActualDelete() throws Exception { .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 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 d5d7c6d301032..e52358030322c 100644 --- a/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java +++ b/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java @@ -305,9 +305,7 @@ public void match(final LogEvent event) { 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(expectationName + " was not seen, found " + loggerMatches.size() + " messages matching the logger."); failureMessage.append("\r\nMessage matching regex: " + messageMatchingRegex); if (!loggerMatches.isEmpty()) { failureMessage.append("\r\nMessage details:\r\n" + String.join("\r\n", loggerMatches)); From dfcfe005470153bfc8365a335b948c8b0acfaf0f Mon Sep 17 00:00:00 2001 From: Peter Nied Date: Thu, 15 Feb 2024 21:26:35 +0000 Subject: [PATCH 5/6] Fix javadoc reference Signed-off-by: Peter Nied --- .../src/main/java/org/opensearch/test/MockLogAppender.java | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) 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 e52358030322c..02c3bfbf2ee9e 100644 --- a/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java +++ b/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java @@ -39,6 +39,7 @@ import org.apache.logging.log4j.core.filter.RegexFilter; import org.opensearch.common.logging.Loggers; import org.opensearch.common.regex.Regex; +import org.opensearch.test.junit.annotations.TestLogging; import java.util.ArrayList; import java.util.Arrays; @@ -266,8 +267,10 @@ 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: + * {@code * @TestLogging(value = "_root:debug", reason = "Validate logging output") - * + * } + * @see TestLogging * */ public static class PatternSeenWithLoggerPrefixExpectation implements LoggingExpectation { private final String expectationName; From 673e4ab98bf61fb09a3172357ba9e9006356ff10 Mon Sep 17 00:00:00 2001 From: Peter Nied Date: Thu, 15 Feb 2024 21:42:22 +0000 Subject: [PATCH 6/6] Make the code annotation a single line in the javadoc Signed-off-by: Peter Nied --- .../src/main/java/org/opensearch/test/MockLogAppender.java | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) 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 02c3bfbf2ee9e..6d6199833b25b 100644 --- a/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java +++ b/test/framework/src/main/java/org/opensearch/test/MockLogAppender.java @@ -267,9 +267,7 @@ 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: - * {@code - * @TestLogging(value = "_root:debug", reason = "Validate logging output") - * } + * {@code @TestLogging(value = "_root:debug", reason = "Validate logging output");} * @see TestLogging * */ public static class PatternSeenWithLoggerPrefixExpectation implements LoggingExpectation {