com.google.cloud.storage.GapicUnbufferedWritableByteChannelTest#resumableUpload flake?

[BenWhitehead]

Inexplicably this unit test which has been running successfully for multiple months failed today during a CI run of main with jdk 17.

The error

[ERROR] com.google.cloud.storage.GapicUnbufferedWritableByteChannelTest.resumableUpload  Time elapsed: 0.043 s  <<< ERROR!
com.google.cloud.storage.StorageException: PERMISSION_DENIED
	at com.google.cloud.storage.StorageException.asStorageException(StorageException.java:145)
	at com.google.cloud.storage.StorageException.coalesce(StorageException.java:117)
	at com.google.cloud.storage.Retrying.lambda$run$0(Retrying.java:106)
	at com.google.api.gax.retrying.DirectRetryingExecutor.submit(DirectRetryingExecutor.java:103)
	at com.google.cloud.RetryHelper.run(RetryHelper.java:76)
	at com.google.cloud.RetryHelper.runWithRetries(RetryHelper.java:50)
	at com.google.cloud.storage.Retrying.run(Retrying.java:94)
	at com.google.cloud.storage.WriteFlushStrategy$FsyncEveryFlusher.flush(WriteFlushStrategy.java:136)
	at com.google.cloud.storage.GapicUnbufferedWritableByteChannel.write(GapicUnbufferedWritableByteChannel.java:119)
	at com.google.cloud.storage.GapicUnbufferedWritableByteChannel.write(GapicUnbufferedWritableByteChannel.java:72)
	at com.google.cloud.storage.GapicUnbufferedWritableByteChannel.write(GapicUnbufferedWritableByteChannel.java:67)
	at com.google.cloud.storage.GapicUnbufferedWritableByteChannelTest.resumableUpload(GapicUnbufferedWritableByteChannelTest.java:188)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	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.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:27)
	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.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
	at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:158)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)
	Suppressed: com.google.cloud.storage.StorageException: PERMISSION_DENIED
		at com.google.cloud.storage.StorageException.asStorageException(StorageException.java:145)
		at com.google.cloud.storage.StorageException.coalesce(StorageException.java:117)
		at com.google.cloud.storage.Retrying.lambda$run$0(Retrying.java:106)
		at com.google.api.gax.retrying.DirectRetryingExecutor.submit(DirectRetryingExecutor.java:103)
		at com.google.cloud.RetryHelper.run(RetryHelper.java:76)
		at com.google.cloud.RetryHelper.runWithRetries(RetryHelper.java:50)
		at com.google.cloud.storage.Retrying.run(Retrying.java:94)
		at com.google.cloud.storage.WriteFlushStrategy$FsyncEveryFlusher.flush(WriteFlushStrategy.java:136)
		at com.google.cloud.storage.WriteFlushStrategy$FsyncEveryFlusher.close(WriteFlushStrategy.java:163)
		at com.google.cloud.storage.GapicUnbufferedWritableByteChannel.close(GapicUnbufferedWritableByteChannel.java:147)
		at com.google.cloud.storage.GapicUnbufferedWritableByteChannelTest.resumableUpload(GapicUnbufferedWritableByteChannelTest.java:177)
		... 39 more
	Caused by: com.google.api.gax.rpc.PermissionDeniedException: io.grpc.StatusRuntimeException: PERMISSION_DENIED
		at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:98)
		at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:41)
		at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:86)
		at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:66)
		at com.google.api.gax.grpc.GrpcExceptionTranslatingStreamObserver.onError(GrpcExceptionTranslatingStreamObserver.java:60)
		at com.google.api.gax.grpc.ApiStreamObserverDelegate.onError(ApiStreamObserverDelegate.java:55)
		at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:487)
		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.api.gax.grpc.ChannelPool$ReleasingClientCall$1.onClose(ChannelPool.java:535)
		at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:563)
		at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:70)
		at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:744)
		at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:723)
		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(ThreadPoolExecutor.java:1136)
		at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
		at java.base/java.lang.Thread.run(Thread.java:833)
	Caused by: io.grpc.StatusRuntimeException: PERMISSION_DENIED
		at io.grpc.Status.asRuntimeException(Status.java:539)
		... 14 more
Caused by: com.google.api.gax.rpc.PermissionDeniedException: io.grpc.StatusRuntimeException: PERMISSION_DENIED
	at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:98)
	at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:41)
	at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:86)
	at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:66)
	at com.google.api.gax.grpc.GrpcExceptionTranslatingStreamObserver.onError(GrpcExceptionTranslatingStreamObserver.java:60)
	at com.google.api.gax.grpc.ApiStreamObserverDelegate.onError(ApiStreamObserverDelegate.java:55)
	at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:487)
	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.api.gax.grpc.ChannelPool$ReleasingClientCall$1.onClose(ChannelPool.java:535)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:563)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:70)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:744)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:723)
	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(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: io.grpc.StatusRuntimeException: PERMISSION_DENIED
	at io.grpc.Status.asRuntimeException(Status.java:539)
	... 14 more

I only supposed to happen in the case of an unexpected request making it to the "server".

First observed in https://github.com/googleapis/java-storage/actions/runs/3347056726/jobs/5544620712

[BenWhitehead]

New failure debug info from https://github.com/googleapis/java-storage/actions/runs/3896958731/jobs/6654096716

Jan 11, 2023 9:44:12 PM com.google.cloud.storage.GapicUnbufferedWritableByteChannelTest$DirectWriteService logUnexpectedRequest
WARNING: Unexpected Request Chain.
expected one of: [
	[{"upload_id":"upload-id","checksummed_data":{"content":"QUJDREVGR0hJSg=="}}],
	[{"upload_id":"upload-id","write_offset":"10","checksummed_data":{"content":"S0xNTk9QUVJTVA=="}}],
	[{"upload_id":"upload-id","write_offset":"20","checksummed_data":{"content":"VVZXWFlaYWJjZA=="}}],
	[{"upload_id":"upload-id","write_offset":"30","checksummed_data":{"content":"ZWZnaGlqa2xtbg=="}}],
	[{"upload_id":"upload-id","write_offset":"40","finish_write":true}]
]
        but was: [
	{"upload_id":"upload-id","checksummed_data":{"content":"QUJDREVGR0hJSg=="}},{"upload_id":"upload-id","write_offset":"10","checksummed_data":{"content":"S0xNTk9QUVJTVA=="}}
]

It seems, somehow the first two requests are being packed together rather separately.