[BUG] BlobStore copy : Unexpected header value. Expected response to echo 'x-ms-client-request-id'...

[daolis]

Scenario
Copy content of selected source containers to a target blobstore with targetBlobClient.copyFromUrlWithResponse with a spring boot application.

Now and then copyFromUrlWithResponse throws a RuntimeException:
Unexpected header value. Expected response to echo 'x-ms-client-request-id: b5b11cab-21b6-4462-a66e-1f16ef7b9498'. Got value '0d7bded4-c93c-4837-a65b-c2b9023abaf0'.

BUT The file was successfully copied even if the exception occurs..

Full Exception

java.lang.RuntimeException: Unexpected header value. Expected response to echo `x-ms-client-request-id: b5b11cab-21b6-4462-a66e-1f16ef7b9498`. Got value `0d7bded4-c93c-4837-a65b-c2b9023abaf0`.
	at com.azure.storage.common.policy.ResponseValidationPolicyBuilder.lambda$addOptionalEcho$0(ResponseValidationPolicyBuilder.java:45) ~[azure-storage-common-12.0.0.jar:na]
	at com.azure.storage.common.policy.ResponseValidationPolicyBuilder$ResponseValidationPolicy.lambda$process$0(ResponseValidationPolicyBuilder.java:81) ~[azure-storage-common-12.0.0.jar:na]
	at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:107) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:173) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1592) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:144) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1592) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onNext(MonoIgnoreThen.java:296) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1592) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:144) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1592) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:171) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2150) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onSubscribeInner(MonoFlatMapMany.java:143) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onNext(MonoFlatMapMany.java:182) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.FluxRetryPredicate$RetryPredicateSubscriber.onNext(FluxRetryPredicate.java:82) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:156) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
	at reactor.netty.http.client.HttpClientConnect$HttpObserver.onStateChange(HttpClientConnect.java:397) ~[reactor-netty-0.9.0.RELEASE.jar:0.9.0.RELEASE]
	at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:473) ~[reactor-netty-0.9.0.RELEASE.jar:0.9.0.RELEASE]
	at reactor.netty.resources.PooledConnectionProvider$DisposableAcquire.onStateChange(PooledConnectionProvider.java:525) ~[reactor-netty-0.9.0.RELEASE.jar:0.9.0.RELEASE]
	at reactor.netty.resources.PooledConnectionProvider$PooledConnection.onStateChange(PooledConnectionProvider.java:434) ~[reactor-netty-0.9.0.RELEASE.jar:0.9.0.RELEASE]
	at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:522) ~[reactor-netty-0.9.0.RELEASE.jar:0.9.0.RELEASE]
	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:91) ~[reactor-netty-0.9.0.RELEASE.jar:0.9.0.RELEASE]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:438) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:328) ~[netty-codec-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:302) ~[netty-codec-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:253) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1475) ~[netty-handler-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1224) ~[netty-handler-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1271) ~[netty-handler-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:505) ~[netty-codec-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:444) ~[netty-codec-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:283) ~[netty-codec-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931) ~[netty-transport-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:792) ~[netty-transport-native-epoll-4.1.42.Final-linux-x86_64.jar:4.1.42.Final]
	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:483) ~[netty-transport-native-epoll-4.1.42.Final-linux-x86_64.jar:4.1.42.Final]
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:383) ~[netty-transport-native-epoll-4.1.42.Final-linux-x86_64.jar:4.1.42.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044) ~[netty-common-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.42.Final.jar:4.1.42.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.42.Final.jar:4.1.42.Final]
	at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
	Suppressed: java.lang.Exception: #block terminated with an error
		at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:93) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
		at reactor.core.publisher.Mono.block(Mono.java:1663) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
		at com.azure.storage.common.implementation.StorageImplUtils.blockWithOptionalTimeout(StorageImplUtils.java:94) ~[azure-storage-common-12.0.0.jar:na]
		at com.azure.storage.blob.specialized.BlobClientBase.copyFromUrlWithResponse(BlobClientBase.java:359) ~[azure-storage-blob-12.0.0.jar:na]
		at de.hybris.hcsjobs.copyblobstore.CopyBlobWriter.lambda$triggerServerSideCopy$0(CopyBlobWriter.java:241) ~[classes/:na]
		at reactor.core.publisher.MonoCallable.subscribe(MonoCallable.java:56) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
		at reactor.core.publisher.Mono.subscribe(Mono.java:4087) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
		at reactor.core.publisher.MonoZip.subscribe(MonoZip.java:128) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
		at reactor.core.publisher.Mono.subscribe(Mono.java:4087) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
		at reactor.core.publisher.Mono.block(Mono.java:1662) ~[reactor-core-3.3.0.RELEASE.jar:3.3.0.RELEASE]
		at de.hybris.hcsjobs.copyblobstore.CopyBlobWriter.waitForCopyToComplete(CopyBlobWriter.java:374) ~[classes/:na]

To Reproduce
Does not happen every time. But it always happend when i tried to copy a lot of files from blobstore a to blobstore b

Expected behavior
Triggered copy process without exception

Setup:

• OS: Linux
• IDE : IntelliJ
• com.azure:azure-storage-blob:12.0.0

[rickle-msft]

Hi, @daolis. Thanks for sharing this. I am fairly certain the root cause of this is a race condition in the scrub etag policy header which is erroneously holding onto some state in the latest release. At high levels of parallelism, a race condition manifests which sets the wrong value for the request field on the response object and that the causes the request ID validation to fail a few steps later. I think this is fixed in this merged PR here. If you think this is not the case and there is a different root cause, please let me know.

[daolis]

Hi @rickle-msft. I tried to build the latest version on master to test it, but maven cannot download com.azure:sdk-build-tools:jar:1.0.0
Is it somewhere public available?

I tried to build it with mvn -f pom.client.xml -Dgpg.skip -DskipTests clean install described in CONTRIBUTING.md

Thanks

[alzimmermsft]

Hi @daolis,

The sdk-build-tools doesn't get released to Maven, to install it you'll need to have the eng folder copied locally and install eng/code-quality-reports/pom.xml. This should unblock you on this issue, please let us know if you run into additional issues and we'll be happy to help.

[daolis]

Tested it with latest latest version from master. Error did not occur anymore!
#6185 fixed it
Thank you all!

[ghost]

Thanks for working with Microsoft on GitHub! Tell us how you feel about your experience using the reactions on this comment.