[CI] GoogleCloudStorageBlobRepositoryTests Failures (and Slowness)

[original-brownbear]

Build Scan: https://gradle-enterprise.elastic.co/s/ua5pqoxpzjces

This is a bit of strange failure. It seems that the mocked GCS simulated a failure on a bulk delete action during snapshot delete but it was not retried as expected (or the failure simulation misfired somehow).

com.google.cloud.storage.StorageException: Error writing request body to serverClose stacktrace
at __randomizedtesting.SeedInfo.seed([ED3C81C2EDCEF7BA:26D30512855F2828]:0)
at com.google.cloud.storage.spi.v1.HttpStorageRpc.translate(HttpStorageRpc.java:227)
at com.google.cloud.storage.spi.v1.HttpStorageRpc.access$300(HttpStorageRpc.java:86)
at com.google.cloud.storage.spi.v1.HttpStorageRpc$DefaultRpcBatch.submit(HttpStorageRpc.java:203)
at com.google.cloud.storage.StorageBatch.submit(StorageBatch.java:149)
at org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobStore.lambda$deleteBlobsIgnoringIfNotExists$12(GoogleCloudStorageBlobStore.java:358)
at java.security.AccessController.doPrivileged(Native Method)
at org.elasticsearch.repositories.gcs.SocketAccess.doPrivilegedIOException(SocketAccess.java:44)
at org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobStore.deleteBlobsIgnoringIfNotExists(GoogleCloudStorageBlobStore.java:337)
at org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobContainer.deleteBlobsIgnoringIfNotExists(GoogleCloudStorageBlobContainer.java:87)
at org.elasticsearch.repositories.blobstore.BlobStoreRepository.deleteSnapshot(BlobStoreRepository.java:409)
at org.elasticsearch.snapshots.SnapshotsService.lambda$deleteSnapshotFromRepository$12(SnapshotsService.java:1344)
at org.elasticsearch.action.ActionRunnable$1.doRun(ActionRunnable.java:45)
at org.elasticsearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:769)
at org.elasticsearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:37)
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)
Caused by: java.io.IOException: Error writing request body to serverOpen stacktrace

Moreover though, this should not have failed the snapshot delete call (and subsequently the whole test) and instead only have lead to a WARN log.

Moreover, running this test-(suite) with the seed that failed here:

./gradlew ':plugins:repository-gcs:test' --tests "org.elasticsearch.repositories.gcs.GoogleCloudStorageBlobStoreRepositoryTests.testIndicesDeletedFromRepository" -Dtests.seed=ED3C81C2EDCEF7BA -Dtests.security.manager=true -Dtests.locale=vun-TZ -Dtests.timezone=America/Chicago -Dcompiler.java=12 -Druntime.java=11

is very slow. It takes about a minute on very fast hardware for each test, making me wonder if maybe there's some timeout interaction here.

I'll investigate this a little as well to make sure nothing evil snuck into the snapshot state machine and now fails the deletes, but as discussed assigning you @tlrx since you're already working on the GCS mock.

[elasticmachine]

Pinging @elastic/es-distributed

[tlrx]

Moreover though, this should not have failed the snapshot delete call (and subsequently the whole test) and instead only have lead to a WARN log.

This is a bug, I've opened #46832.

[tlrx]

They are few different things in this issue:

• a bug that might left the snapshot deletion process stucked (GCS deleteBlobsIgnoringIfNotExists should catch StorageException #46832)
• the slowness of the tests, which has been introduced when replacing mocked objects by the internal HTTP server. I think this is also the case for Azure and S3 repository tests. I'll investigate a bit more to see what can be done but I don't think timeouts are in cause.
• the origin of the Error writing request body, which is still unknown (I'll investigate too)

[tlrx]

* a bug that might left the snapshot deletion process stucked (#46832)

This has been fixed and merged.

* the slowness of the tests, which has been introduced when replacing mocked objects by the internal HTTP server. I think this is also the case for Azure and S3 repository tests. I'll investigate a bit more to see what can be done but I don't think timeouts are in cause.

I investigated the slowness of the test and it appears that blob uploads take much more time in the Google tests than in the Azure or S3 tests. The Google SDK client uses multipart requests to upload blob content (both blob metadata and blob content are embedded in a multipart request body) while S3/Azure use most of the time single upload (the blob content is the request body). This adds extra parsing time on both server and client side, resulting in each blob upload taking 100-300ms in Google test and only 50-100ms in Azure/S3 tests.

@original-brownbear I'm not sure I can do much to optimize these tests for now (maybe lower the variables used in tests?)

the origin of the Error writing request body, which is still unknown (I'll investigate too)

This happens only once and does not reproduce after hundreds of execution. I'm going to leave this for now too and reinvestigate if it occurs another time.

[original-brownbear]

Thanks Tanguy!

I'm not sure I can do much to optimize these tests for now (maybe lower the variables used in tests?)

Thanks for explaining :) I think we're good here then. I mainly pointed out the slowness as it was confusing me and I figured it might be the cause for the failing test.

This happens only once and does not reproduce after hundreds of execution. I'm going to leave this for now too and reinvestigate if it occurs another time.

Sounds good :) I'll close this issue then. I couldn't reproduce it again either and I did run this through a lot more than 100 executions :D The thing is too, we won't even see this in failing test so easily now since we correctly handle bulk delete failures and just warn log them ... nothing will fail potentially :)

[tlrx]

I think we're good here then. I mainly pointed out the slowness as it was confusing me and I figured it might be the cause for the failing test.

I think so. I should have also mention that I suspected the HTTP handler executor and tried a cached thread pool with no benefits; I quickly optimized the server side parsing but not much real gain there too and I checked the timeouts and concluded that they were not involved.

Thanks for reporting the issue :)