Skip to content
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.

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

com.example.spanner.EncryptionKeyIT: testEncryptedDatabaseAndBackupAndRestore failed #1019

Closed
flaky-bot bot opened this issue Mar 25, 2021 · 9 comments · Fixed by #1092, #1109 or #1117
Closed

com.example.spanner.EncryptionKeyIT: testEncryptedDatabaseAndBackupAndRestore failed #1019

flaky-bot bot opened this issue Mar 25, 2021 · 9 comments · Fixed by #1092, #1109 or #1117
Assignees
Labels
api: spanner flakybot: flaky flakybot: issue priority: p2 type: bug

Comments

@flaky-bot
Copy link

@flaky-bot flaky-bot bot commented Mar 25, 2021

This test failed!

To configure my behavior, see the Flaky Bot documentation.

If I'm commenting on this issue too often, add the flakybot: quiet label and
I will stop commenting.


commit: 9132c21
buildURL: Build Status, Sponge
status: failed

Test output
com.google.cloud.spanner.SpannerException: FAILED_PRECONDITION: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-a278a61d7c5e487286dfd) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:283)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:61)
	at com.google.cloud.spanner.SpannerExceptionFactory.fromApiException(SpannerExceptionFactory.java:298)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:174)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:110)
	at com.google.cloud.spanner.DatabaseAdminClientImpl$2.apply(DatabaseAdminClientImpl.java:125)
	at com.google.cloud.spanner.DatabaseAdminClientImpl$2.apply(DatabaseAdminClientImpl.java:122)
	at com.google.api.core.ApiFutures$GaxFunctionToGuavaFunction.apply(ApiFutures.java:240)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:224)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:212)
	at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:124)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:724)
	at com.google.common.util.concurrent.FluentFuture$TrustedFuture.addListener(FluentFuture.java:108)
	at com.google.common.util.concurrent.ForwardingListenableFuture.addListener(ForwardingListenableFuture.java:45)
	at com.google.api.core.ApiFutureToListenableFuture.addListener(ApiFutureToListenableFuture.java:52)
	at com.google.common.util.concurrent.AbstractCatchingFuture.create(AbstractCatchingFuture.java:41)
	at com.google.common.util.concurrent.Futures.catching(Futures.java:282)
	at com.google.api.core.ApiFutures.catching(ApiFutures.java:99)
	at com.google.api.gax.longrunning.OperationFutureImpl.(OperationFutureImpl.java:97)
	at com.google.cloud.spanner.DatabaseAdminClientImpl.restoreDatabase(DatabaseAdminClientImpl.java:121)
	at com.example.spanner.RestoreBackupWithEncryptionKey.restoreBackupWithEncryptionKey(RestoreBackupWithEncryptionKey.java:69)
	at com.example.spanner.EncryptionKeyIT.lambda$testEncryptedDatabaseAndBackupAndRestore$2(EncryptionKeyIT.java:121)
	at com.example.spanner.SampleRunner.runSample(SampleRunner.java:32)
	at com.example.spanner.EncryptionKeyIT.testEncryptedDatabaseAndBackupAndRestore(EncryptionKeyIT.java:120)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:364)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:272)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:237)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:158)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548)
Caused by: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-a278a61d7c5e487286dfd) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
	at io.grpc.Status.asRuntimeException(Status.java:535)
	at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1$1.onClose(SpannerErrorInterceptor.java:100)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:553)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:68)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:739)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:718)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
@flaky-bot flaky-bot bot added flakybot: issue priority: p1 type: bug labels Mar 25, 2021
@product-auto-label product-auto-label bot added the api: spanner label Mar 25, 2021
@flaky-bot
Copy link
Author

@flaky-bot flaky-bot bot commented Mar 26, 2021

Looks like this issue is flaky. 😟

I'm going to leave this open and stop commenting.

A human should fix and close this.


When run at the same commit (9132c21), this test passed in one build (Build Status, Sponge) and failed in another build (Build Status, Sponge).

@flaky-bot flaky-bot bot added the flakybot: flaky label Mar 26, 2021
@yoshi-automation yoshi-automation added the 🚨 label Mar 31, 2021
@zoercai zoercai added priority: p2 and removed priority: p1 labels Apr 13, 2021
@yoshi-automation yoshi-automation removed the 🚨 label Apr 14, 2021
@olavloite olavloite self-assigned this Apr 23, 2021
olavloite added a commit that referenced this issue Apr 23, 2021
Retry backup operations during tests that fail because too many other backup
operations are pending at that moment.

Fixes #1019
olavloite added a commit that referenced this issue Apr 26, 2021
#1092)

* test: retry backup operations on failure because of pending operations

Retry backup operations during tests that fail because too many other backup
operations are pending at that moment.

Fixes #1019

* docs: add javadoc
@flaky-bot
Copy link
Author

@flaky-bot flaky-bot bot commented Apr 26, 2021

Oops! Looks like this issue is still flaky. It failed again. 😬

I reopened the issue, but a human will need to close it again.


commit: e013df7
buildURL: Build Status, Sponge
status: failed

Test output
com.google.cloud.spanner.SpannerException: DEADLINE_EXCEEDED: Operation did not complete in the given time
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:283)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:61)
	at com.google.cloud.spanner.SpannerExceptionFactory.propagateTimeout(SpannerExceptionFactory.java:87)
	at com.example.spanner.RestoreBackupWithEncryptionKey.restoreBackupWithEncryptionKey(RestoreBackupWithEncryptionKey.java:84)
	at com.example.spanner.EncryptionKeyIT.lambda$testEncryptedDatabaseAndBackupAndRestore$2(EncryptionKeyIT.java:126)
	at com.example.spanner.SampleRunner.runSampleWithRetry(SampleRunner.java:44)
	at com.example.spanner.EncryptionKeyIT.testEncryptedDatabaseAndBackupAndRestore(EncryptionKeyIT.java:125)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:364)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:272)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:237)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:158)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548)
Caused by: java.util.concurrent.TimeoutException: Waited 1600 seconds (plus 131790 nanoseconds delay) for CatchingFuture@300f715[status=PENDING, info=[inputFuture=[com.google.api.core.ApiFutureToListenableFuture@448ca967], exceptionType=[class java.lang.Exception], fallback=[com.google.api.core.ApiFutures$GaxFunctionToGuavaFunction@400a5164]]]
	at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:508)
	at com.google.common.util.concurrent.FluentFuture$TrustedFuture.get(FluentFuture.java:93)
	at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:68)
	at com.google.api.gax.longrunning.OperationFutureImpl.get(OperationFutureImpl.java:133)
	at com.example.spanner.RestoreBackupWithEncryptionKey.restoreBackupWithEncryptionKey(RestoreBackupWithEncryptionKey.java:74)
	... 33 more

@flaky-bot flaky-bot bot reopened this Apr 26, 2021
olavloite added a commit that referenced this issue Apr 28, 2021
The restore operation should use the default timeout of a restore operation.
Although that timeout is long, the tests for the samples are only executed as
part of the nightly build, which means that a long-running restore will not
slow down PR builds.

Fixes #1019
@olavloite
Copy link
Contributor

@olavloite olavloite commented Apr 28, 2021

The last build error (on 26 April 2021) is a different error than the initial error for this issue. The error is now DEADLINE_EXCEEDED, which seems to be caused by a custom timeout that was set to prevent the tests from running too long. That is no longer a real issue, as these tests are now only run as part of the nightly builds.

thiagotnunes pushed a commit that referenced this issue Apr 29, 2021
The restore operation should use the default timeout of a restore operation.
Although that timeout is long, the tests for the samples are only executed as
part of the nightly build, which means that a long-running restore will not
slow down PR builds.

Fixes #1019
@flaky-bot
Copy link
Author

@flaky-bot flaky-bot bot commented Apr 29, 2021

Oops! Looks like this issue is still flaky. It failed again. 😬

I reopened the issue, but a human will need to close it again.


commit: b1e3e2c
buildURL: Build Status, Sponge
status: failed

Test output
com.google.cloud.spanner.SpannerException: FAILED_PRECONDITION: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-f4f975bf75e7424bbd8a5) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:284)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:61)
	at com.google.cloud.spanner.SpannerExceptionFactory.fromApiException(SpannerExceptionFactory.java:299)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:174)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:110)
	at com.google.cloud.spanner.DatabaseAdminClientImpl$2.apply(DatabaseAdminClientImpl.java:125)
	at com.google.cloud.spanner.DatabaseAdminClientImpl$2.apply(DatabaseAdminClientImpl.java:122)
	at com.google.api.core.ApiFutures$ApiFunctionToGuavaFunction.apply(ApiFutures.java:240)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:224)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:212)
	at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:124)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:771)
	at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:100)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:771)
	at com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:200)
	at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:135)
	at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:117)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:771)
	at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:100)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:771)
	at com.google.api.gax.retrying.BasicRetryingFuture.handleAttempt(BasicRetryingFuture.java:200)
	at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.handle(CallbackChainRetryingFuture.java:135)
	at com.google.api.gax.retrying.CallbackChainRetryingFuture$AttemptCompletionListener.run(CallbackChainRetryingFuture.java:117)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:771)
	at com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:95)
	at com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:77)
	at com.google.api.gax.grpc.GrpcExceptionCallable$ExceptionTransformingFuture.onFailure(GrpcExceptionCallable.java:97)
	at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:68)
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1041)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
	at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:771)
	at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:563)
	at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1$1.onClose(SpannerErrorInterceptor.java:100)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:553)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:68)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:739)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:718)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-f4f975bf75e7424bbd8a5) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
	at io.grpc.Status.asRuntimeException(Status.java:535)
	... 18 more

@flaky-bot flaky-bot bot reopened this Apr 29, 2021
@flaky-bot flaky-bot bot reopened this Apr 29, 2021
@flaky-bot
Copy link
Author

@flaky-bot flaky-bot bot commented Apr 29, 2021

Oops! Looks like this issue is still flaky. It failed again. 😬

I reopened the issue, but a human will need to close it again.


commit: b1e3e2c
buildURL: Build Status, Sponge
status: failed

Test output
com.google.cloud.spanner.SpannerException: FAILED_PRECONDITION: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-03c35975cab2403f9d65b) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:284)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:61)
	at com.google.cloud.spanner.SpannerExceptionFactory.fromApiException(SpannerExceptionFactory.java:299)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:174)
	at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:110)
	at com.google.cloud.spanner.DatabaseAdminClientImpl$2.apply(DatabaseAdminClientImpl.java:125)
	at com.google.cloud.spanner.DatabaseAdminClientImpl$2.apply(DatabaseAdminClientImpl.java:122)
	at com.google.api.core.ApiFutures$ApiFunctionToGuavaFunction.apply(ApiFutures.java:240)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:224)
	at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:212)
	at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:124)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
	at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:724)
	at com.google.common.util.concurrent.FluentFuture$TrustedFuture.addListener(FluentFuture.java:108)
	at com.google.common.util.concurrent.ForwardingListenableFuture.addListener(ForwardingListenableFuture.java:45)
	at com.google.api.core.ApiFutureToListenableFuture.addListener(ApiFutureToListenableFuture.java:52)
	at com.google.common.util.concurrent.AbstractCatchingFuture.create(AbstractCatchingFuture.java:41)
	at com.google.common.util.concurrent.Futures.catching(Futures.java:282)
	at com.google.api.core.ApiFutures.catching(ApiFutures.java:99)
	at com.google.api.gax.longrunning.OperationFutureImpl.(OperationFutureImpl.java:97)
	at com.google.cloud.spanner.DatabaseAdminClientImpl.restoreDatabase(DatabaseAdminClientImpl.java:121)
	at com.example.spanner.RestoreBackupWithEncryptionKey.restoreBackupWithEncryptionKey(RestoreBackupWithEncryptionKey.java:67)
	at com.example.spanner.EncryptionKeyIT.lambda$testEncryptedDatabaseAndBackupAndRestore$2(EncryptionKeyIT.java:126)
	at com.example.spanner.SampleRunner.runSampleWithRetry(SampleRunner.java:44)
	at com.example.spanner.EncryptionKeyIT.testEncryptedDatabaseAndBackupAndRestore(EncryptionKeyIT.java:125)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:364)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:272)
	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:237)
	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:158)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548)
Caused by: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-03c35975cab2403f9d65b) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
	at io.grpc.Status.asRuntimeException(Status.java:535)
	at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1$1.onClose(SpannerErrorInterceptor.java:100)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:553)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:68)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:739)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:718)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

@olavloite
Copy link
Contributor

@olavloite olavloite commented Apr 30, 2021

Based on the execution time, it seems that it retried 10 times and then gave up.

olavloite added a commit that referenced this issue Apr 30, 2021
The backup operations can still fail because of too many pending
operations. It would retry 10 times with waiting 60 seconds between
each attempt, but that does not seem to be enough. The max attempts
has therefore been increased to 20 and better logging has been
created by throwing a custom exception when it happens. The previous
log was not visible, because the sample runners are redirecting the
standard out to a string.

Fixes #1019
thiagotnunes pushed a commit that referenced this issue May 3, 2021
The backup operations can still fail because of too many pending
operations. It would retry 10 times with waiting 60 seconds between
each attempt, but that does not seem to be enough. The max attempts
has therefore been increased to 20 and better logging has been
created by throwing a custom exception when it happens. The previous
log was not visible, because the sample runners are redirecting the
standard out to a string.

Fixes #1019
@flaky-bot flaky-bot bot reopened this May 7, 2021
@flaky-bot
Copy link
Author

@flaky-bot flaky-bot bot commented May 7, 2021

Oops! Looks like this issue is still flaky. It failed again. 😬

I reopened the issue, but a human will need to close it again.


commit: 91cb003
buildURL: Build Status, Sponge
status: failed

Test output
com.google.cloud.spanner.SpannerException: 
DEADLINE_EXCEEDED: Operation failed 20 times because of other pending operations. Giving up operation.
at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:284)
at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:61)
at spanner.snapshot@1.0.22/com.example.spanner.EncryptionKeyIT$ShouldRetryBackupOperation.test(EncryptionKeyIT.java:153)
at spanner.snapshot@1.0.22/com.example.spanner.EncryptionKeyIT$ShouldRetryBackupOperation.test(EncryptionKeyIT.java:142)
at spanner.snapshot@1.0.22/com.example.spanner.SampleRunner.runSampleWithRetry(SampleRunner.java:47)
at spanner.snapshot@1.0.22/com.example.spanner.EncryptionKeyIT.testEncryptedDatabaseAndBackupAndRestore(EncryptionKeyIT.java:126)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:364)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:272)
at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:237)
at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:158)
at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:428)
at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:162)
at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:562)
at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:548)

Caused by: com.google.cloud.spanner.SpannerException: FAILED_PRECONDITION: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-9b45b2af73d54dda9583e) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerExceptionPreformatted(SpannerExceptionFactory.java:284)
at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:61)
at com.google.cloud.spanner.SpannerExceptionFactory.fromApiException(SpannerExceptionFactory.java:299)
at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:174)
at com.google.cloud.spanner.SpannerExceptionFactory.newSpannerException(SpannerExceptionFactory.java:110)
at com.google.cloud.spanner.DatabaseAdminClientImpl.lambda$restoreDatabase$1(DatabaseAdminClientImpl.java:117)
at com.google.api.core.ApiFutures$ApiFunctionToGuavaFunction.apply(ApiFutures.java:240)
at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:224)
at com.google.common.util.concurrent.AbstractCatchingFuture$CatchingFuture.doFallback(AbstractCatchingFuture.java:212)
at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:124)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1215)
at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:724)
at com.google.common.util.concurrent.FluentFuture$TrustedFuture.addListener(FluentFuture.java:108)
at com.google.common.util.concurrent.ForwardingListenableFuture.addListener(ForwardingListenableFuture.java:45)
at com.google.api.core.ApiFutureToListenableFuture.addListener(ApiFutureToListenableFuture.java:52)
at com.google.common.util.concurrent.AbstractCatchingFuture.create(AbstractCatchingFuture.java:41)
at com.google.common.util.concurrent.Futures.catching(Futures.java:282)
at com.google.api.core.ApiFutures.catching(ApiFutures.java:99)
at com.google.api.gax.longrunning.OperationFutureImpl.(OperationFutureImpl.java:97)
at com.google.cloud.spanner.DatabaseAdminClientImpl.restoreDatabase(DatabaseAdminClientImpl.java:115)
at spanner.snapshot@1.0.22/com.example.spanner.RestoreBackupWithEncryptionKey.restoreBackupWithEncryptionKey(RestoreBackupWithEncryptionKey.java:67)
at spanner.snapshot@1.0.22/com.example.spanner.EncryptionKeyIT.lambda$testEncryptedDatabaseAndBackupAndRestore$2(EncryptionKeyIT.java:127)
at spanner.snapshot@1.0.22/com.example.spanner.SampleRunner.runSampleWithRetry(SampleRunner.java:44)
... 31 more
Caused by: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot restore database (projects/gcloud-devel/instances/spanner-testing/databases/mysample-9b45b2af73d54dda9583e) because the maximum number of pending restores (1) for the instance (projects/gcloud-devel/instances/spanner-testing) has been reached. Please retry the operation once the pending restores complete.
at io.grpc.Status.asRuntimeException(Status.java:535)
at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533)
at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
at com.google.cloud.spanner.spi.v1.SpannerErrorInterceptor$1$1.onClose(SpannerErrorInterceptor.java:100)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:553)
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:68)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:739)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:718)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)

@olavloite
Copy link
Contributor

@olavloite olavloite commented May 11, 2021

@thiagotnunes This test failed again, and this time with the clear error message that it gave up because it got the same 'too many pending backup operations' error 20 times. That is not something the client can do very much about, other than continue to retry even longer. I can see a couple of options here:

  1. Remove / disable the test altogether.
  2. Increase the number of retries to 30 (or even more).
  3. Ignore, close this issue and hope that it does not happen too often.
  4. Accept this error as a possible outcome of the operation and let the test succeed when this happens.

I lean towards a combination of 2 and 4. WDYT?

olavloite added a commit that referenced this issue May 17, 2021
The encrypted database/backup/restore tests sometimes fail because of
other (parallel) backup operations. To reduce the probability of this,
we will try to move these integration tests into the monolitic test
run that tests all samples serially.

Updates #1019
olavloite added a commit that referenced this issue May 17, 2021
* test: move encrypted tests to monolith tests

The encrypted database/backup/restore tests sometimes fail because of
other (parallel) backup operations. To reduce the probability of this,
we will try to move these integration tests into the monolitic test
run that tests all samples serially.

Updates #1019

* fix: linting issues
@olavloite
Copy link
Contributor

@olavloite olavloite commented May 19, 2021

The last nightly build succeeded, so it seems that this solution is working (for now).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: spanner flakybot: flaky flakybot: issue priority: p2 type: bug
Projects
None yet
4 participants