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.

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

Jump to bottom

Upload failure using --experimental_remote_cache_async and flaky test retries #14008

Closed
brentleyjones opened this issue Sep 17, 2021 · 5 comments
Closed

Upload failure using --experimental_remote_cache_async and flaky test retries #14008

brentleyjones opened this issue Sep 17, 2021 · 5 comments
Assignees
@coeuvre
Labels
P1 I'll work on this now. (Assignee required) team-Remote-Exec Issues and PRs for the Execution (Remote) team type: bug

Comments

@brentleyjones
Copy link
Contributor

brentleyjones commented Sep 17, 2021 •
edited
Loading

Description of the problem / feature request:

When using the new --experimental_remote_cache_async flag, we get upload failures that don't happen without the flag. It seems to be related to how the test log for flaky tests are generated.

Bugs: what's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.

(07:53:16) FAIL: //Modules/CanvasUI:CanvasUITests (see /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test_attempts/attempt_1.log)
(07:53:16) WARNING: Writing to Remote Cache: /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test.xml (No such file or directory)
  | com.google.devtools.build.lib.remote.common.BulkTransferException: /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test.xml (No such file or directory)
  | at com.google.devtools.build.lib.remote.util.RxUtils$BulkTransferExceptionCollector.onResult(RxUtils.java:91)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableCollectSingle$CollectSubscriber.onNext(FlowableCollectSingle.java:93)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.innerSuccess(FlowableFlatMapSingle.java:173)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber$InnerObserver.onSuccess(FlowableFlatMapSingle.java:342)
  | at io.reactivex.rxjava3.internal.observers.ResumeSingleObserver.onSuccess(ResumeSingleObserver.java:46)
  | at io.reactivex.rxjava3.internal.operators.single.SingleJust.subscribeActual(SingleJust.java:30)
  | at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813)
  | at io.reactivex.rxjava3.internal.operators.single.SingleResumeNext$ResumeMainSingleObserver.onError(SingleResumeNext.java:80)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableToSingle$ToSingle.onError(CompletableToSingle.java:73)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate$Emitter.tryOnError(CompletableCreate.java:91)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate$Emitter.onError(CompletableCreate.java:77)
  | at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe$1.onFailure(RxFutures.java:102)
  | at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1074)
  | at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
  | at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
  | at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:724)
  | at com.google.common.util.concurrent.Futures.addCallback(Futures.java:1047)
  | at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe.subscribe(RxFutures.java:80)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
  | at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2856)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableToSingle.subscribeActual(CompletableToSingle.java:37)
  | at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813)
  | at io.reactivex.rxjava3.internal.operators.single.SingleResumeNext.subscribeActual(SingleResumeNext.java:39)
  | at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onNext(FlowableFlatMapSingle.java:131)
  | at io.reactivex.rxjava3.internal.operators.single.SingleFlatMapPublisher$SingleFlatMapPublisherObserver.onNext(SingleFlatMapPublisher.java:107)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$IteratorSubscription.fastPath(FlowableFromIterable.java:185)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:129)
  | at io.reactivex.rxjava3.internal.subscriptions.SubscriptionHelper.deferredSetOnce(SubscriptionHelper.java:202)
  | at io.reactivex.rxjava3.internal.operators.single.SingleFlatMapPublisher$SingleFlatMapPublisherObserver.onSubscribe(SingleFlatMapPublisher.java:102)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:69)
  | at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47)
  | at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15838)
  | at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15784)
  | at io.reactivex.rxjava3.internal.operators.single.SingleFlatMapPublisher$SingleFlatMapPublisherObserver.onSuccess(SingleFlatMapPublisher.java:96)
  | at io.reactivex.rxjava3.internal.operators.single.SingleCreate$Emitter.onSuccess(SingleCreate.java:68)
  | at com.google.devtools.build.lib.remote.util.RxFutures$OnceSingleOnSubscribe$1.onSuccess(RxFutures.java:156)
  | at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1080)
  | at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
  | at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
  | at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
  | at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
  | at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:110)
  | at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
  | at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
  | at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
  | at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
  | at com.google.common.util.concurrent.CombinedFuture$CallableInterruptibleTask.setValue(CombinedFuture.java:188)
  | at com.google.common.util.concurrent.CombinedFuture$CombinedFutureInterruptibleTask.afterRanInterruptibly(CombinedFuture.java:134)
  | at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:133)
  | at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
  | at com.google.common.util.concurrent.CombinedFuture$CombinedFutureInterruptibleTask.execute(CombinedFuture.java:104)
  | at com.google.common.util.concurrent.CombinedFuture.handleAllCompleted(CombinedFuture.java:62)
  | at com.google.common.util.concurrent.AggregateFuture.processCompleted(AggregateFuture.java:283)
  | at com.google.common.util.concurrent.AggregateFuture.decrementCountAndMaybeComplete(AggregateFuture.java:265)
  | at com.google.common.util.concurrent.AggregateFuture.access$200(AggregateFuture.java:42)
  | at com.google.common.util.concurrent.AggregateFuture$1.run(AggregateFuture.java:147)
  | at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
  | at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
  | at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
  | at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
  | at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:110)
  | at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
  | at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
  | at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
  | at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
  | at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:110)
  | at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
  | at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
  | at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
  | at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
  | at io.grpc.stub.ClientCalls$GrpcFuture.set(ClientCalls.java:558)
  | at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:531)
  | 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.devtools.build.lib.remote.NetworkTimeInterceptor$NetworkTimeCall$1.onClose(NetworkTimeInterceptor.java:81)
  | 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.devtools.build.lib.remote.ReferenceCountedChannel$ConnectionCleanupCall$1.onClose(ReferenceCountedChannel.java:90)
  | 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.devtools.build.lib.remote.logging.LoggingInterceptor$LoggingForwardingCall$1.onClose(LoggingInterceptor.java:157)
  | at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:617)
  | at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:70)
  | at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:803)
  | at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:782)
  | at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
  | at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
  | at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  | at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  | at java.base/java.lang.Thread.run(Unknown Source)
  | Suppressed: java.io.FileNotFoundException: /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test.xml (No such file or directory)
  | at java.base/java.io.FileInputStream.open0(Native Method)
  | at java.base/java.io.FileInputStream.open(Unknown Source)
  | at java.base/java.io.FileInputStream.<init>(Unknown Source)
  | at com.google.devtools.build.lib.unix.UnixFileSystem.createFileInputStream(UnixFileSystem.java:470)
  | at com.google.devtools.build.lib.vfs.AbstractFileSystem.createMaybeProfiledInputStream(AbstractFileSystem.java:82)
  | at com.google.devtools.build.lib.vfs.AbstractFileSystem.getInputStream(AbstractFileSystem.java:51)
  | at com.google.devtools.build.lib.vfs.Path.getInputStream(Path.java:779)
  | at com.google.devtools.build.lib.remote.Chunker$Builder.lambda$setInput$2(Chunker.java:268)
  | at com.google.devtools.build.lib.remote.Chunker.maybeInitialize(Chunker.java:229)
  | at com.google.devtools.build.lib.remote.Chunker.seek(Chunker.java:148)
  | at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.call(ByteStreamUploader.java:511)
  | at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.callAndQueryOnFailure(ByteStreamUploader.java:433)
  | at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.lambda$start$0(ByteStreamUploader.java:399)
  | at com.google.devtools.build.lib.remote.Retrier.executeAsync(Retrier.java:277)
  | at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.lambda$start$1(ByteStreamUploader.java:396)
  | at com.google.devtools.build.lib.remote.util.Utils.refreshIfUnauthenticatedAsync(Utils.java:462)
  | at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.start(ByteStreamUploader.java:394)
  | at com.google.devtools.build.lib.remote.ByteStreamUploader.startAsyncUpload(ByteStreamUploader.java:328)
  | at com.google.devtools.build.lib.remote.ByteStreamUploader.uploadBlobAsync(ByteStreamUploader.java:249)
  | at com.google.devtools.build.lib.remote.GrpcCacheClient.uploadFile(GrpcCacheClient.java:402)
  | at com.google.devtools.build.lib.remote.RemoteCache.lambda$doUploadFile$5(RemoteCache.java:174)
  | at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe.subscribe(RxFutures.java:79)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
  | at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2856)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableUsing.subscribeActual(CompletableUsing.java:83)
  | at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2856)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableToSingle.subscribeActual(CompletableToSingle.java:37)
  | at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813)
  | at com.google.devtools.build.lib.remote.util.AsyncTaskCache$Execution.subscribeActual(AsyncTaskCache.java:156)
  | at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813)
  | at com.google.devtools.build.lib.remote.util.AsyncTaskCache.lambda$execute$1(AsyncTaskCache.java:291)
  | at io.reactivex.rxjava3.internal.operators.single.SingleCreate.subscribeActual(SingleCreate.java:40)
  | at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4813)
  | at io.reactivex.rxjava3.internal.operators.completable.CompletableFromSingle.subscribeActual(CompletableFromSingle.java:29)
  | at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2856)
  | at com.google.devtools.build.lib.remote.util.RxFutures.toListenableFuture(RxFutures.java:196)
  | at com.google.devtools.build.lib.remote.RemoteCache.uploadFile(RemoteCache.java:196)
  | at com.google.devtools.build.lib.remote.UploadManifest.lambda$upload$0(UploadManifest.java:358)
  | at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe.subscribe(RxFutures.java:79)
  | ... 76 more
(07:54:20) WARNING: /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test.log was modified during execution
(07:54:20) FAIL: //Modules/CanvasUI:CanvasUITests (see /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test_attempts/attempt_2.log)
(07:55:03) FAIL: //Modules/CanvasUI:CanvasUITests (see /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test.log)
--
  |  
  | FAILED: //Modules/CanvasUI:CanvasUITests (Summary)
  | /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test.log
  | /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test_attempts/attempt_1.log
  | /private/var/tmp/_bazel_iosci/4e42b9deccb34ad74b7f834bbab2cb1e/execroot/project/bazel-out/darwin-fastbuild/testlogs/Modules/CanvasUI/CanvasUITests/test_attempts/attempt_2.log

What operating system are you running Bazel on?

macOS 11.6

What's the output of bazel info release?

release 5.0.0-pre.20210907.1
@brentleyjones
Copy link
Contributor Author

cc: @coeuvre

@philwo philwo added P1 I'll work on this now. (Assignee required) team-Remote-Exec Issues and PRs for the Execution (Remote) team type: bug labels Sep 21, 2021
@brentleyjones
Copy link
Contributor Author

This constantly confuses our users, as it dumps a massive stack trace right after the warning.

@coeuvre
Copy link
Member

coeuvre commented Nov 2, 2021

Sorry for the error. I am looking into this and try to make the fix into 5.0. It would help if you can also provide a minimal repro.

@brentleyjones brentleyjones changed the title Upload failure using --experimental_cache_async and flaky test retries Upload failure using --experimental_remote_cache_async and flaky test retries Nov 2, 2021
@brentleyjones
Copy link
Contributor Author

Sure: https://github.com/brentleyjones/bazel-async-upload-failed-tests-bug. Run bazelisk test //... and you will get something like this:

INFO: Invocation ID: 70b410e8-bb33-4c41-b5ca-42f95fbd0789
INFO: Analyzed target //:swtest (0 packages loaded, 0 targets configured).
INFO: Found 1 test target...
FAIL: //:swtest (see /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test_attempts/attempt_1.log)
WARNING: Writing to Remote Cache: /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test.xml (No such file or directory)
com.google.devtools.build.lib.remote.common.BulkTransferException: /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test.xml (No such file or directory)
        at com.google.devtools.build.lib.remote.util.RxUtils$BulkTransferExceptionCollector.onResult(RxUtils.java:91)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableCollectSingle$CollectSubscriber.onNext(FlowableCollectSingle.java:94)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.innerSuccess(FlowableFlatMapSingle.java:173)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber$InnerObserver.onSuccess(FlowableFlatMapSingle.java:342)
        at io.reactivex.rxjava3.internal.operators.single.SingleDoFinally$DoFinallyObserver.onSuccess(SingleDoFinally.java:73)
        at io.reactivex.rxjava3.internal.observers.ResumeSingleObserver.onSuccess(ResumeSingleObserver.java:46)
        at io.reactivex.rxjava3.internal.operators.single.SingleJust.subscribeActual(SingleJust.java:30)
        at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4855)
        at io.reactivex.rxjava3.internal.operators.single.SingleResumeNext$ResumeMainSingleObserver.onError(SingleResumeNext.java:80)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableToSingle$ToSingle.onError(CompletableToSingle.java:73)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate$Emitter.tryOnError(CompletableCreate.java:91)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate$Emitter.onError(CompletableCreate.java:77)
        at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe$1.onFailure(RxFutures.java:103)
        at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1074)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
        at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:724)
        at com.google.common.util.concurrent.Futures.addCallback(Futures.java:1047)
        at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe.subscribe(RxFutures.java:81)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
        at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2859)
        at io.reactivex.rxjava3.internal.operators.completable.CompletableToSingle.subscribeActual(CompletableToSingle.java:37)
        at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4855)
        at io.reactivex.rxjava3.internal.operators.single.SingleResumeNext.subscribeActual(SingleResumeNext.java:39)
        at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4855)
        at io.reactivex.rxjava3.internal.operators.single.SingleDoFinally.subscribeActual(SingleDoFinally.java:44)
        at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4855)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFlatMapSingle$FlatMapSingleSubscriber.onNext(FlowableFlatMapSingle.java:131)
        at io.reactivex.rxjava3.internal.operators.single.SingleFlatMapPublisher$SingleFlatMapPublisherObserver.onNext(SingleFlatMapPublisher.java:107)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$IteratorSubscription.fastPath(FlowableFromIterable.java:185)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable$BaseRangeSubscription.request(FlowableFromIterable.java:129)
        at io.reactivex.rxjava3.internal.subscriptions.SubscriptionHelper.deferredSetOnce(SubscriptionHelper.java:202)
        at io.reactivex.rxjava3.internal.operators.single.SingleFlatMapPublisher$SingleFlatMapPublisherObserver.onSubscribe(SingleFlatMapPublisher.java:102)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribe(FlowableFromIterable.java:69)
        at io.reactivex.rxjava3.internal.operators.flowable.FlowableFromIterable.subscribeActual(FlowableFromIterable.java:47)
        at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15917)
        at io.reactivex.rxjava3.core.Flowable.subscribe(Flowable.java:15863)
        at io.reactivex.rxjava3.internal.operators.single.SingleFlatMapPublisher$SingleFlatMapPublisherObserver.onSuccess(SingleFlatMapPublisher.java:96)
        at io.reactivex.rxjava3.internal.operators.single.SingleDoOnSuccess$DoOnSuccess.onSuccess(SingleDoOnSuccess.java:60)
        at io.reactivex.rxjava3.internal.operators.single.SingleDoOnDispose$DoOnDisposeObserver.onSuccess(SingleDoOnDispose.java:84)
        at io.reactivex.rxjava3.internal.operators.single.SingleDoOnError$DoOnError.onSuccess(SingleDoOnError.java:52)
        at io.reactivex.rxjava3.internal.operators.single.SingleDoOnSubscribe$DoOnSubscribeSingleObserver.onSuccess(SingleDoOnSubscribe.java:77)
        at io.reactivex.rxjava3.internal.operators.single.SingleCreate$Emitter.onSuccess(SingleCreate.java:68)
        at com.google.devtools.build.lib.remote.util.RxFutures$OnceSingleOnSubscribe$1.onSuccess(RxFutures.java:157)
        at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1080)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
        at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
        at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
        at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:110)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
        at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
        at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
        at com.google.common.util.concurrent.CombinedFuture$CallableInterruptibleTask.setValue(CombinedFuture.java:188)
        at com.google.common.util.concurrent.CombinedFuture$CombinedFutureInterruptibleTask.afterRanInterruptibly(CombinedFuture.java:134)
        at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:133)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at com.google.common.util.concurrent.CombinedFuture$CombinedFutureInterruptibleTask.execute(CombinedFuture.java:104)
        at com.google.common.util.concurrent.CombinedFuture.handleAllCompleted(CombinedFuture.java:62)
        at com.google.common.util.concurrent.AggregateFuture.processCompleted(AggregateFuture.java:283)
        at com.google.common.util.concurrent.AggregateFuture.decrementCountAndMaybeComplete(AggregateFuture.java:265)
        at com.google.common.util.concurrent.AggregateFuture.access$200(AggregateFuture.java:42)
        at com.google.common.util.concurrent.AggregateFuture$1.run(AggregateFuture.java:147)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
        at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
        at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
        at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:110)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
        at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
        at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
        at com.google.common.util.concurrent.AbstractCatchingFuture.run(AbstractCatchingFuture.java:110)
        at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1213)
        at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:983)
        at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:746)
        at io.grpc.stub.ClientCalls$GrpcFuture.set(ClientCalls.java:558)
        at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:531)
        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.devtools.build.lib.remote.NetworkTimeInterceptor$NetworkTimeCall$1.onClose(NetworkTimeInterceptor.java:81)
        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.devtools.build.lib.remote.ReferenceCountedChannel$ConnectionCleanupCall$1.onClose(ReferenceCountedChannel.java:90)
        at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:557)
        at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:69)
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:738)
        at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:717)
        at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.base/java.lang.Thread.run(Unknown Source)
        Suppressed: java.io.FileNotFoundException: /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test.xml (No such file or directory)
                at java.base/java.io.FileInputStream.open0(Native Method)
                at java.base/java.io.FileInputStream.open(Unknown Source)
                at java.base/java.io.FileInputStream.<init>(Unknown Source)
                at com.google.devtools.build.lib.unix.UnixFileSystem.createFileInputStream(UnixFileSystem.java:470)
                at com.google.devtools.build.lib.vfs.AbstractFileSystem.createMaybeProfiledInputStream(AbstractFileSystem.java:90)
                at com.google.devtools.build.lib.vfs.AbstractFileSystem.getInputStream(AbstractFileSystem.java:59)
                at com.google.devtools.build.lib.vfs.Path.getInputStream(Path.java:780)
                at com.google.devtools.build.lib.remote.Chunker$Builder.lambda$setInput$2(Chunker.java:268)
                at com.google.devtools.build.lib.remote.Chunker.maybeInitialize(Chunker.java:229)
                at com.google.devtools.build.lib.remote.Chunker.seek(Chunker.java:148)
                at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.call(ByteStreamUploader.java:521)
                at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.callAndQueryOnFailure(ByteStreamUploader.java:443)
                at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.lambda$start$0(ByteStreamUploader.java:409)
                at com.google.devtools.build.lib.remote.Retrier.executeAsync(Retrier.java:277)
                at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.lambda$start$1(ByteStreamUploader.java:406)
                at com.google.devtools.build.lib.remote.util.Utils.refreshIfUnauthenticatedAsync(Utils.java:485)
                at com.google.devtools.build.lib.remote.ByteStreamUploader$AsyncUpload.start(ByteStreamUploader.java:404)
                at com.google.devtools.build.lib.remote.ByteStreamUploader.startAsyncUpload(ByteStreamUploader.java:338)
                at com.google.devtools.build.lib.remote.ByteStreamUploader.uploadBlobAsync(ByteStreamUploader.java:259)
                at com.google.devtools.build.lib.remote.GrpcCacheClient.uploadFile(GrpcCacheClient.java:402)
                at com.google.devtools.build.lib.remote.RemoteCache.lambda$uploadFile$1(RemoteCache.java:149)
                at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe.subscribe(RxFutures.java:80)
                at io.reactivex.rxjava3.internal.operators.completable.CompletableCreate.subscribeActual(CompletableCreate.java:40)
                at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2859)
                at io.reactivex.rxjava3.internal.operators.completable.CompletableToSingle.subscribeActual(CompletableToSingle.java:37)
                at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4855)
                at com.google.devtools.build.lib.remote.util.AsyncTaskCache$Execution.subscribeActual(AsyncTaskCache.java:156)
                at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4855)
                at com.google.devtools.build.lib.remote.util.AsyncTaskCache.lambda$execute$1(AsyncTaskCache.java:291)
                at io.reactivex.rxjava3.internal.operators.single.SingleCreate.subscribeActual(SingleCreate.java:40)
                at io.reactivex.rxjava3.core.Single.subscribe(Single.java:4855)
                at io.reactivex.rxjava3.internal.operators.completable.CompletableFromSingle.subscribeActual(CompletableFromSingle.java:29)
                at io.reactivex.rxjava3.core.Completable.subscribe(Completable.java:2859)
                at com.google.devtools.build.lib.remote.util.RxFutures.toListenableFuture(RxFutures.java:197)
                at com.google.devtools.build.lib.remote.RemoteCache.uploadFile(RemoteCache.java:151)
                at com.google.devtools.build.lib.remote.UploadManifest.lambda$upload$0(UploadManifest.java:367)
                at com.google.devtools.build.lib.remote.util.RxFutures$OnceCompletableOnSubscribe.subscribe(RxFutures.java:80)
                ... 78 more
FAIL: //:swtest (see /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test.log)

FAILED: //:swtest (Summary)
      /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test.log
      /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test_attempts/attempt_1.log
Target //:swtest up-to-date:
  bazel-bin/swtest.test-runner.sh
  bazel-bin/swtest.xctest/Contents/MacOS/swtest
INFO: Elapsed time: 0.615s, Critical Path: 0.38s
INFO: 2 processes: 4 darwin-sandbox.
//:swtest                                                                FAILED in 2 out of 2 in 0.1s
  Stats over 2 runs: max = 0.1s, min = 0.1s, avg = 0.1s, dev = 0.0s
  /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test.log
  /private/var/tmp/_bazel_brentleyjones/eb6027c3f473f8afe8d7b78acaebb05a/execroot/__main__/bazel-out/darwin_arm64-fastbuild/testlogs/swtest/test_attempts/attempt_1.log

Executed 1 out of 1 test: 1 fails locally.
INFO: Build completed, 1 test FAILED, 2 total actions

@coeuvre coeuvre mentioned this issue Nov 3, 2021
Closed
@coeuvre
Copy link
Member

coeuvre commented Nov 3, 2021

Thanks for the repro. It helps a lot!

coeuvre added a commit to coeuvre/bazel that referenced this issue Nov 8, 2021
@coeuvre
Remote: Fixes an issue when --experimental_remote_cache_async encount…
f825e19 
…er flaky tests.

When `--experimental_remote_cache_async` is set, the uploads happened in the background -- usually after spawn execution.

When the test is failed and there is another test attempt, the outputs of previous test attempt are moved to other places immediately after spawn execution. This fine when combining `--experimental_remote_cache_async`  because outputs of failed action don't get uploaded.

However, there is an exception that `test.xml` is generated with another spawn before the "move" happens. The result of the spawn used to generate `test.xml` is usually "succeed" which means Bazel will attempt upload `test.xml` even if the test itself is failed.

This PR makes the `test.xml` generation spawn ignores remote cache if the test itself is failed.

Fixes bazelbuild#14008.

Closes bazelbuild#14220.

PiperOrigin-RevId: 408237437
coeuvre added a commit to coeuvre/bazel that referenced this issue Nov 8, 2021
@coeuvre
Remote: Fixes an issue when --experimental_remote_cache_async encount…
3d07ece 
…er flaky tests.

When `--experimental_remote_cache_async` is set, the uploads happened in the background -- usually after spawn execution.

When the test is failed and there is another test attempt, the outputs of previous test attempt are moved to other places immediately after spawn execution. This fine when combining `--experimental_remote_cache_async`  because outputs of failed action don't get uploaded.

However, there is an exception that `test.xml` is generated with another spawn before the "move" happens. The result of the spawn used to generate `test.xml` is usually "succeed" which means Bazel will attempt upload `test.xml` even if the test itself is failed.

This PR makes the `test.xml` generation spawn ignores remote cache if the test itself is failed.

Fixes bazelbuild#14008.

Closes bazelbuild#14220.

PiperOrigin-RevId: 408237437
Wyverald pushed a commit that referenced this issue Nov 8, 2021
@coeuvre
Remote: Fixes an issue when --experimental_remote_cache_async encount…
6a93237 
…er flaky tests. (#14241)

When `--experimental_remote_cache_async` is set, the uploads happened in the background -- usually after spawn execution.

When the test is failed and there is another test attempt, the outputs of previous test attempt are moved to other places immediately after spawn execution. This fine when combining `--experimental_remote_cache_async`  because outputs of failed action don't get uploaded.

However, there is an exception that `test.xml` is generated with another spawn before the "move" happens. The result of the spawn used to generate `test.xml` is usually "succeed" which means Bazel will attempt upload `test.xml` even if the test itself is failed.

This PR makes the `test.xml` generation spawn ignores remote cache if the test itself is failed.

Fixes #14008.

Closes #14220.

PiperOrigin-RevId: 408237437
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@coeuvre coeuvre

Labels
P1 I'll work on this now. (Assignee required) team-Remote-Exec Issues and PRs for the Execution (Remote) team type: bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Remote: Fixes an issue when --experimental_remote_cache_async encounter flaky tests. coeuvre/bazel
3 participants
@brentleyjones @philwo @coeuvre