Skip to content

Commit a9432ba

Browse files
authored
Limit the log line length for s3 deletion error (#123953)
If all items fail to delete, the current warning log builds a huge string to include all of them (up to 1000). This PR limits the string length to first 10 entries. Relates: #123630
1 parent 521f044 commit a9432ba

File tree

2 files changed

+80
-11
lines changed

2 files changed

+80
-11
lines changed

modules/repository-s3/src/main/java/org/elasticsearch/repositories/s3/S3BlobStore.java

Lines changed: 21 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,6 @@
5555
import java.util.concurrent.atomic.LongAdder;
5656
import java.util.stream.Collectors;
5757

58-
import static org.elasticsearch.core.Strings.format;
5958
import static org.elasticsearch.rest.RestStatus.REQUESTED_RANGE_NOT_SATISFIED;
6059

6160
class S3BlobStore implements BlobStore {
@@ -398,16 +397,7 @@ private void deletePartition(OperationPurpose purpose, List<String> partition, D
398397
} catch (MultiObjectDeleteException e) {
399398
// We are sending quiet mode requests so we can't use the deleted keys entry on the exception and instead
400399
// first remove all keys that were sent in the request and then add back those that ran into an exception.
401-
logger.warn(
402-
() -> format(
403-
"Failed to delete some blobs %s",
404-
e.getErrors()
405-
.stream()
406-
.map(err -> "[" + err.getKey() + "][" + err.getCode() + "][" + err.getMessage() + "]")
407-
.toList()
408-
),
409-
e
410-
);
400+
logger.warn(buildDeletionErrorMessage(e), e);
411401
deletionExceptions.useOrMaybeSuppress(e);
412402
return;
413403
} catch (AmazonClientException e) {
@@ -430,6 +420,26 @@ private void deletePartition(OperationPurpose purpose, List<String> partition, D
430420
}
431421
}
432422

423+
private String buildDeletionErrorMessage(MultiObjectDeleteException e) {
424+
final var sb = new StringBuilder("Failed to delete some blobs ");
425+
final var errors = e.getErrors();
426+
for (int i = 0; i < errors.size() && i < MAX_DELETE_EXCEPTIONS; i++) {
427+
final var err = errors.get(i);
428+
sb.append("[").append(err.getKey()).append("][").append(err.getCode()).append("][").append(err.getMessage()).append("]");
429+
if (i < errors.size() - 1) {
430+
sb.append(",");
431+
}
432+
}
433+
if (errors.size() > MAX_DELETE_EXCEPTIONS) {
434+
sb.append("... (")
435+
.append(errors.size())
436+
.append(" in total, ")
437+
.append(errors.size() - MAX_DELETE_EXCEPTIONS)
438+
.append(" omitted)");
439+
}
440+
return sb.toString();
441+
}
442+
433443
/**
434444
* If there are remaining retries, pause for the configured interval then return true
435445
*

modules/repository-s3/src/test/java/org/elasticsearch/repositories/s3/S3BlobContainerRetriesTests.java

Lines changed: 59 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121
import com.sun.net.httpserver.HttpHandler;
2222

2323
import org.apache.http.HttpStatus;
24+
import org.apache.logging.log4j.Level;
2425
import org.apache.lucene.index.CorruptIndexException;
2526
import org.apache.lucene.store.AlreadyClosedException;
2627
import org.elasticsearch.ExceptionsHelper;
@@ -51,10 +52,12 @@
5152
import org.elasticsearch.repositories.RepositoriesMetrics;
5253
import org.elasticsearch.repositories.blobstore.AbstractBlobContainerRetriesTestCase;
5354
import org.elasticsearch.repositories.blobstore.BlobStoreTestUtil;
55+
import org.elasticsearch.rest.RestStatus;
5456
import org.elasticsearch.telemetry.InstrumentType;
5557
import org.elasticsearch.telemetry.Measurement;
5658
import org.elasticsearch.telemetry.RecordingMeterRegistry;
5759
import org.elasticsearch.test.ESTestCase;
60+
import org.elasticsearch.test.MockLog;
5861
import org.elasticsearch.watcher.ResourceWatcherService;
5962
import org.hamcrest.Matcher;
6063
import org.junit.After;
@@ -65,6 +68,7 @@
6568
import java.io.FilterInputStream;
6669
import java.io.IOException;
6770
import java.io.InputStream;
71+
import java.io.InputStreamReader;
6872
import java.net.InetSocketAddress;
6973
import java.net.SocketTimeoutException;
7074
import java.net.UnknownHostException;
@@ -83,6 +87,7 @@
8387
import java.util.concurrent.atomic.AtomicLong;
8488
import java.util.concurrent.atomic.AtomicReference;
8589
import java.util.function.IntConsumer;
90+
import java.util.regex.Pattern;
8691

8792
import static org.elasticsearch.repositories.blobstore.BlobStoreTestUtil.randomNonDataPurpose;
8893
import static org.elasticsearch.repositories.blobstore.BlobStoreTestUtil.randomPurpose;
@@ -1106,6 +1111,60 @@ public void testSuppressedDeletionErrorsAreCapped() {
11061111
assertThat(exception.getCause().getSuppressed().length, lessThan(S3BlobStore.MAX_DELETE_EXCEPTIONS));
11071112
}
11081113

1114+
public void testTrimmedLogAndCappedSuppressedErrorOnMultiObjectDeletionException() {
1115+
final TimeValue readTimeout = TimeValue.timeValueMillis(randomIntBetween(100, 500));
1116+
int maxBulkDeleteSize = randomIntBetween(10, 30);
1117+
final BlobContainer blobContainer = createBlobContainer(1, readTimeout, true, null, maxBulkDeleteSize);
1118+
1119+
final Pattern pattern = Pattern.compile("<Key>(.+?)</Key>");
1120+
httpServer.createContext("/", exchange -> {
1121+
if (exchange.getRequestMethod().equals("POST") && exchange.getRequestURI().toString().startsWith("/bucket/?delete")) {
1122+
final String requestBody = Streams.copyToString(new InputStreamReader(exchange.getRequestBody(), StandardCharsets.UTF_8));
1123+
final var matcher = pattern.matcher(requestBody);
1124+
final StringBuilder deletes = new StringBuilder();
1125+
deletes.append("<?xml version=\"1.0\" encoding=\"UTF-8\"?>");
1126+
deletes.append("<DeleteResult>");
1127+
while (matcher.find()) {
1128+
final String key = matcher.group(1);
1129+
deletes.append("<Error>");
1130+
deletes.append("<Code>").append(randomAlphaOfLength(10)).append("</Code>");
1131+
deletes.append("<Key>").append(key).append("</Key>");
1132+
deletes.append("<Message>").append(randomAlphaOfLength(40)).append("</Message>");
1133+
deletes.append("</Error>");
1134+
}
1135+
deletes.append("</DeleteResult>");
1136+
1137+
byte[] response = deletes.toString().getBytes(StandardCharsets.UTF_8);
1138+
exchange.getResponseHeaders().add("Content-Type", "application/xml");
1139+
exchange.sendResponseHeaders(RestStatus.OK.getStatus(), response.length);
1140+
exchange.getResponseBody().write(response);
1141+
exchange.close();
1142+
} else {
1143+
fail("expected only deletions");
1144+
}
1145+
});
1146+
var blobs = randomList(maxBulkDeleteSize, maxBulkDeleteSize, ESTestCase::randomIdentifier);
1147+
try (var mockLog = MockLog.capture(S3BlobStore.class)) {
1148+
mockLog.addExpectation(
1149+
new MockLog.SeenEventExpectation(
1150+
"deletion log",
1151+
S3BlobStore.class.getCanonicalName(),
1152+
Level.WARN,
1153+
blobs.size() > S3BlobStore.MAX_DELETE_EXCEPTIONS
1154+
? "Failed to delete some blobs [*... (* in total, * omitted)"
1155+
: "Failed to delete some blobs [*]"
1156+
)
1157+
);
1158+
var exception = expectThrows(
1159+
IOException.class,
1160+
"deletion should not succeed",
1161+
() -> blobContainer.deleteBlobsIgnoringIfNotExists(randomPurpose(), blobs.iterator())
1162+
);
1163+
assertThat(exception.getCause().getSuppressed().length, lessThan(S3BlobStore.MAX_DELETE_EXCEPTIONS));
1164+
mockLog.awaitAllExpectationsMatched();
1165+
}
1166+
}
1167+
11091168
@Override
11101169
protected Matcher<Integer> getMaxRetriesMatcher(int maxRetries) {
11111170
// some attempts make meaningful progress and do not count towards the max retry limit

0 commit comments

Comments
 (0)