Skip to content

Log Warning on Failed Blob Deletes in BlobStoreRepository #40188

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
Mar 21, 2019
Merged

Log Warning on Failed Blob Deletes in BlobStoreRepository #40188

Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
30a5280
Log Warning on Failed Blob Deletes in BlobStoreRepository
original-brownbear Mar 19, 2019
8114d7c
Merge remote-tracking branch 'elastic/master' into louder-logging-blo…
original-brownbear Mar 20, 2019
5f636ad
don't warn when blob did not exist
original-brownbear Mar 20, 2019
a6d0362
Merge remote-tracking branch 'elastic/master' into louder-logging-blo…
original-brownbear Mar 20, 2019
aaa39fc
Merge remote-tracking branch 'elastic/master' into louder-logging-blo…
original-brownbear Mar 21, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 6 additions & 6 deletions server/src/main/java/org/elasticsearch/repositories/blobstore/BlobStoreRepository.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -472,17 +472,17 @@ public void deleteSnapshot(SnapshotId snapshotId, long repositoryStateId) {
final BlobContainer indicesBlobContainer = blobStore().blobContainer(basePath().add("indices"));
for (final IndexId indexId : indicesToCleanUp) {
try {
indicesBlobContainer.deleteBlob(indexId.getId());
indicesBlobContainer.deleteBlobIgnoringIfNotExists(indexId.getId());
} catch (DirectoryNotEmptyException dnee) {
// if the directory isn't empty for some reason, it will fail to clean up;
// we'll ignore that and accept that cleanup didn't fully succeed.
// since we are using UUIDs for path names, this won't be an issue for
// snapshotting indices of the same name
logger.debug(() -> new ParameterizedMessage("[{}] index [{}] no longer part of any snapshots in the repository, " +
logger.warn(() -> new ParameterizedMessage("[{}] index [{}] no longer part of any snapshots in the repository, " +
Copy link
Contributor Author

@original-brownbear original-brownbear Mar 19, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ywelsch This spot is really bad, we should take action here to delete the index folder when we know it must be deleted and not just quietly (or now not so quietly :D) skip it because we made mistake earlier.
I'll raise a PR to deal with this situation once I know if we want to proceed on #40144 (having the threadpool here would be very helpful in creating a reasonable solution that won't further slow this code down and block deletes).

"but failed to clean up its index folder due to the directory not being empty.", metadata.name(), indexId), dnee);
} catch (IOException ioe) {
// a different IOException occurred while trying to delete - will just log the issue for now
logger.debug(() -> new ParameterizedMessage("[{}] index [{}] no longer part of any snapshots in the repository, " +
logger.warn(() -> new ParameterizedMessage("[{}] index [{}] no longer part of any snapshots in the repository, " +
Copy link
Contributor

@ywelsch ywelsch Mar 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if we should continue to log NoSuchFileException with debug (this happens if an earlier clean-up failed), otherwise we might quite a bit of noisy logs. Same applies to other places that were changed in this PR

Copy link
Contributor Author

@original-brownbear original-brownbear Mar 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ywelsch is that actually true though? Looking at the code we're delete shard data files (which is the only place where we would really have an explosion in the log lines) via org.elasticsearch.common.blobstore.BlobContainer#deleteBlobIgnoringIfNotExists so we have that exception filtered already anyway?

Copy link
Contributor

@ywelsch ywelsch Mar 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This effectively tries to delete folders, which does not make sense for the blob stores (e.g. Azure, GCP, ...) and will throw a NoSuchFileException as the blob key won't be found.

Copy link
Contributor Author

@original-brownbear original-brownbear Mar 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yea, but it seems that that will happen at a low enough rate so that it's fine because we don't have that many folders? (I see it's a hand-waving argument, but given that it just took way too long to find #39852 (comment) when that was totally trivial with this change I'm gonna stand by it :D)

Copy link
Contributor

@ywelsch ywelsch Mar 19, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it will happen every time a user deletes a snapshot with an index that's not referenced by any other snapshot anymore. Yes, that's not happening at a high rate, but logging warnings for something that happens under normal operations is not good, especially if we can avoid it (which we can I think).

Copy link
Contributor Author

@original-brownbear original-brownbear Mar 19, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But we use the repository data to determine which indices to delete (that's the whole problem in the first place leading to stale files since we simply stop touching stale index directories) so we won't ever try to delete an index "folder" twice will we?

Copy link
Contributor

@ywelsch ywelsch Mar 20, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not following your argument. Are you saying that because this is only erroneously logged as warning once (under normal operations) that it is therefore harmless? Or are you saying that under normal operations we will never log this as a warning?

Copy link
Contributor Author

@original-brownbear original-brownbear Mar 20, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ywelsch

Or are you saying that under normal operations we will never log this as a warning?

This should never happen under normal operations imo. If we run into this, we failed to delete all the index files in the above which is clearly a bug (+ every time this happens we leak blobs that are never cleaned up).

Copy link
Contributor

@ywelsch ywelsch Mar 20, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This will happen under normal operations. Run GoogleCloudStorageBlobStoreRepositoryTests#testSnapshotAndRestore and see for yourself:

[2019-03-20T08:19:50,218][WARN ][o.e.r.b.BlobStoreRepository] [node_sm0] [krciqciev] index [[ftvgcjc/28AyZ3zgRMmGbTEfac6I7Q]] no longer part of any snapshots in the repository, but failed to clean up its index folder.
java.nio.file.NoSuchFileException: Blob [GoogleCloudStorageBlobStoreRepositoryTests/indices/28AyZ3zgRMmGbTEfac6I7Q] does not exist
	at org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobStore.deleteBlob(GoogleCloudStorageBlobStore.java:289) ~[main/:?]
	at org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobContainer.deleteBlob(GoogleCloudStorageBlobContainer.java:78) ~[main/:?]
	at org.elasticsearch.repositories.blobstore.BlobStoreRepository.deleteSnapshot(BlobStoreRepository.java:475) [main/:?]
	at org.elasticsearch.snapshots.SnapshotsService.lambda$deleteSnapshotFromRepository$10(SnapshotsService.java:1314) [main/:?]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:677) [main/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]
[2019-03-20T08:19:50,224][WARN ][o.e.r.b.BlobStoreRepository] [node_sm0] [krciqciev] index [[ddrevic/URmsihElTxi3pfkgeDb4ag]] no longer part of any snapshots in the repository, but failed to clean up its index folder.
java.nio.file.NoSuchFileException: Blob [GoogleCloudStorageBlobStoreRepositoryTests/indices/URmsihElTxi3pfkgeDb4ag] does not exist
	at org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobStore.deleteBlob(GoogleCloudStorageBlobStore.java:289) ~[main/:?]
	at org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobContainer.deleteBlob(GoogleCloudStorageBlobContainer.java:78) ~[main/:?]
	at org.elasticsearch.repositories.blobstore.BlobStoreRepository.deleteSnapshot(BlobStoreRepository.java:475) [main/:?]
	at org.elasticsearch.snapshots.SnapshotsService.lambda$deleteSnapshotFromRepository$10(SnapshotsService.java:1314) [main/:?]
	at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingRunnable.run(ThreadContext.java:677) [main/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

Copy link
Contributor Author

@original-brownbear original-brownbear Mar 20, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🤦‍♂️ sorry about that, obviously my head didn't think about the blob stores and only about the FS implementation ... adjusted the code accordingly in 5f636ad.

I think the other spots adjusted here are safe though because they already use org.elasticsearch.common.blobstore.BlobContainer#deleteBlobIgnoringIfNotExists for "folder" deletes right?

"but failed to clean up its index folder.", metadata.name(), indexId), ioe);
}
}
Expand Down Expand Up @@ -832,7 +832,7 @@ private long listBlobsToGetLatestIndexId() throws IOException {
} catch (NumberFormatException nfe) {
// the index- blob wasn't of the format index-N where N is a number,
// no idea what this blob is but it doesn't belong in the repository!
logger.debug("[{}] Unknown blob in the repository: {}", metadata.name(), blobName);
logger.warn("[{}] Unknown blob in the repository: {}", metadata.name(), blobName);
}
}
return latest;
Expand Down Expand Up @@ -975,7 +975,7 @@ public void delete() {
try {
indexShardSnapshotFormat.delete(blobContainer, snapshotId.getUUID());
} catch (IOException e) {
logger.debug("[{}] [{}] failed to delete shard snapshot file", shardId, snapshotId);
logger.warn(new ParameterizedMessage("[{}] [{}] failed to delete shard snapshot file", shardId, snapshotId), e);
}

// Build a list of snapshots that should be preserved
Expand Down Expand Up @@ -1135,7 +1135,7 @@ protected Tuple<BlobStoreIndexShardSnapshots, Integer> buildBlobStoreIndexShardS
logger.warn(() -> new ParameterizedMessage("failed to read index file [{}]", file), e);
}
} else if (blobKeys.isEmpty() == false) {
logger.debug("Could not find a readable index-N file in a non-empty shard snapshot directory [{}]", blobContainer.path());
logger.warn("Could not find a readable index-N file in a non-empty shard snapshot directory [{}]", blobContainer.path());
}

// We couldn't load the index file - falling back to loading individual snapshots
Expand Down