[BUG] IllegalStateException block()/blockFirst()/blockLast() are blocking, which is not supported in thread

[rvervaek]

Describe the bug
When uploading content via a BlobOutputStream an IllegalStateException is thrown from reactor-core's BlockingSingleSubscriber class.

Exception or Stack Trace
IllegalStateException: block()/blockFirst()/blockLast() are blocking, which is not supported in thread reactor-http-nio-4

0 = {StackTraceElement@19693} "reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:77)"
1 = {StackTraceElement@19694} "reactor.core.publisher.Mono.block(Mono.java:1494)"
2 = {StackTraceElement@19695} "com.azure.core.implementation.RestProxy.createResponse(RestProxy.java:456)"
3 = {StackTraceElement@19696} "com.azure.core.implementation.RestProxy.handleRestResponseReturnType(RestProxy.java:393)"
4 = {StackTraceElement@19697} "com.azure.core.implementation.RestProxy.lambda$handleRestReturnType$9(RestProxy.java:528)"
5 = {StackTraceElement@19698} "reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:118)"
6 = {StackTraceElement@19699} "reactor.core.publisher.FluxContextStart$ContextStartSubscriber.onNext(FluxContextStart.java:103)"
7 = {StackTraceElement@19700} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
8 = {StackTraceElement@19701} "reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onNext(FluxDoOnEach.java:159)"
9 = {StackTraceElement@19702} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
10 = {StackTraceElement@19703} "reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1515)"
11 = {StackTraceElement@19704} "reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241)"
12 = {StackTraceElement@19705} "reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2071)"
13 = {StackTraceElement@19706} "reactor.core.publisher.MonoFlatMap$FlatMapInner.onSubscribe(MonoFlatMap.java:230)"
14 = {StackTraceElement@19707} "reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)"
15 = {StackTraceElement@19708} "reactor.core.publisher.MonoLiftFuseable.subscribe(MonoLiftFuseable.java:55)"
16 = {StackTraceElement@19709} "reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150)"
17 = {StackTraceElement@19710} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
18 = {StackTraceElement@19711} "reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:114)"
19 = {StackTraceElement@19712} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
20 = {StackTraceElement@19713} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
21 = {StackTraceElement@19714} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
22 = {StackTraceElement@19715} "reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73)"
23 = {StackTraceElement@19716} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
24 = {StackTraceElement@19717} "reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1515)"
25 = {StackTraceElement@19718} "reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241)"
26 = {StackTraceElement@19719} "reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2071)"
27 = {StackTraceElement@19720} "reactor.core.publisher.MonoFlatMap$FlatMapInner.onSubscribe(MonoFlatMap.java:230)"
28 = {StackTraceElement@19721} "reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)"
29 = {StackTraceElement@19722} "reactor.core.publisher.MonoLiftFuseable.subscribe(MonoLiftFuseable.java:55)"
30 = {StackTraceElement@19723} "reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150)"
31 = {StackTraceElement@19724} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
32 = {StackTraceElement@19725} "reactor.core.publisher.FluxDelaySubscription$DelaySubscriptionMainSubscriber.onNext(FluxDelaySubscription.java:179)"
33 = {StackTraceElement@19726} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
34 = {StackTraceElement@19727} "reactor.core.publisher.SerializedSubscriber.onNext(SerializedSubscriber.java:89)"
35 = {StackTraceElement@19728} "reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.onNext(FluxTimeout.java:173)"
36 = {StackTraceElement@19729} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
37 = {StackTraceElement@19730} "reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:204)"
38 = {StackTraceElement@19731} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
39 = {StackTraceElement@19732} "reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1515)"
40 = {StackTraceElement@19733} "reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241)"
41 = {StackTraceElement@19734} "reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2071)"
42 = {StackTraceElement@19735} "reactor.core.publisher.MonoFlatMap$FlatMapInner.onSubscribe(MonoFlatMap.java:230)"
43 = {StackTraceElement@19736} "reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)"
44 = {StackTraceElement@19737} "reactor.core.publisher.MonoLiftFuseable.subscribe(MonoLiftFuseable.java:55)"
45 = {StackTraceElement@19738} "reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:150)"
46 = {StackTraceElement@19739} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
47 = {StackTraceElement@19740} "reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1515)"
48 = {StackTraceElement@19741} "reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onNext(MonoIgnoreThen.java:296)"
49 = {StackTraceElement@19742} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
50 = {StackTraceElement@19743} "reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1515)"
51 = {StackTraceElement@19744} "reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:171)"
52 = {StackTraceElement@19745} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onComplete(ScopePassingSpanSubscriber.java:112)"
53 = {StackTraceElement@19746} "reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onComplete(MonoFlatMapMany.java:248)"
54 = {StackTraceElement@19747} "reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2073)"
55 = {StackTraceElement@19748} "reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onSubscribeInner(MonoFlatMapMany.java:140)"
56 = {StackTraceElement@19749} "reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onSubscribe(MonoFlatMapMany.java:233)"
57 = {StackTraceElement@19750} "reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)"
58 = {StackTraceElement@19751} "reactor.core.publisher.MonoLiftFuseable.subscribe(MonoLiftFuseable.java:55)"
59 = {StackTraceElement@19752} "reactor.core.publisher.FluxSourceMonoFuseable.subscribe(FluxSourceMonoFuseable.java:38)"
60 = {StackTraceElement@19753} "reactor.core.publisher.Flux.subscribe(Flux.java:7921)"
61 = {StackTraceElement@19754} "reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onNext(MonoFlatMapMany.java:184)"
62 = {StackTraceElement@19755} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
63 = {StackTraceElement@19756} "reactor.core.publisher.FluxRetryPredicate$RetryPredicateSubscriber.onNext(FluxRetryPredicate.java:81)"
64 = {StackTraceElement@19757} "org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber.onNext(ScopePassingSpanSubscriber.java:96)"
65 = {StackTraceElement@19758} "reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:156)"
66 = {StackTraceElement@19759} "reactor.netty.http.client.HttpClientConnect$HttpObserver.onStateChange(HttpClientConnect.java:409)"
67 = {StackTraceElement@19760} "reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:470)"
68 = {StackTraceElement@19761} "reactor.netty.resources.PooledConnectionProvider$DisposableAcquire.onStateChange(PooledConnectionProvider.java:512)"
69 = {StackTraceElement@19762} "reactor.netty.resources.PooledConnectionProvider$PooledConnection.onStateChange(PooledConnectionProvider.java:451)"
70 = {StackTraceElement@19763} "reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:521)"
71 = {StackTraceElement@19764} "reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:91)"
72 = {StackTraceElement@19765} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)"
73 = {StackTraceElement@19766} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)"
74 = {StackTraceElement@19767} "io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)"
75 = {StackTraceElement@19768} "io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:438)"
76 = {StackTraceElement@19769} "io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:328)"
77 = {StackTraceElement@19770} "io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:302)"
78 = {StackTraceElement@19771} "io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:253)"
79 = {StackTraceElement@19772} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)"
80 = {StackTraceElement@19773} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)"
81 = {StackTraceElement@19774} "io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)"
82 = {StackTraceElement@19775} "io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1475)"
83 = {StackTraceElement@19776} "io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1224)"
84 = {StackTraceElement@19777} "io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1271)"
85 = {StackTraceElement@19778} "io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:505)"
86 = {StackTraceElement@19779} "io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:444)"
87 = {StackTraceElement@19780} "io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:283)"
88 = {StackTraceElement@19781} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)"
89 = {StackTraceElement@19782} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)"
90 = {StackTraceElement@19783} "io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)"
91 = {StackTraceElement@19784} "io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1421)"
92 = {StackTraceElement@19785} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)"
93 = {StackTraceElement@19786} "io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)"
94 = {StackTraceElement@19787} "io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:930)"
95 = {StackTraceElement@19788} "io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)"
96 = {StackTraceElement@19789} "io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:697)"
97 = {StackTraceElement@19790} "io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:632)"
98 = {StackTraceElement@19791} "io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:549)"
99 = {StackTraceElement@19792} "io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:511)"

To Reproduce

1. Create a BlockBlobClient from a ContainerClient.
2. Call method getBlobOutputStream() on the BlockBlobClient instance.
3. Write some bytes to the outputstream.

Code Snippet

    final UUID id = UUID.randomUUID();
    BlockBlobClient client = containerClient.getBlockBlobClient(id.toString());
    try (BlobOutputStream blobOutputStream = client.getBlobOutputStream()) {
            IOUtils.copy(content, blobOutputStream);
     } catch (IOException e) {
            throw new StorageException(e);
     }

Expected behavior
No exceptions occur during write to the outputstream.

Setup:

• OS: Windows 10 Enterprise
• IDE : Intellij 2019.1.3
• Java: 8
• azure-core: 1.0.0-preview.3
• azure-storage-blob: 12.0.0-preview.2
• reactor-core: 3.2.11.RELEASE (via spring-integration-core 5.1.7.RELEASE)
• reactor-netty: 0.8.10.RELEASE
• spring boot: 2.1.7.RELEASE

[jaschrep-msft]

Hi @rvervaek, thank you for reporting this issue. I'm having trouble reproducing this issue based on the given information. Do you know if this is a transient error, or does this happen every time you try to use BlobOutputStream this way?

Additionally, we have recently published our preview 3 package. There are many signature changes in this preview, so if you are already using this library heavily, upgrading may not be trivial. But, if possible, could you try upgrading and see if the issue persists?

[rvervaek]

The error occurs every time I use the BlobOutputStream this way. Using the preview 3 package didn't help.

I wrote a seperate test project. The problem seems to be related to spring-cloud-sleuth since the problem occurs only when this dependency is added and autoconfigured by Spring Boot. You can find the failing test here

[joshfree]

@sima-zhu could you help debug the repro that @rvervaek provided?

[sima-zhu]

Taking a look

[sima-zhu]

Thanks @rvervaek for reporting this issue.

The root cause here is Reactor core does not allow any block() operation inside of non-blocking thread. More details refer here: reactor/reactor-core#1102

Inside of Azure core, the dependency of storage v12 which provides standard infrastructure and helper all across the Azure service, uses block() inside of an Async call which cause the problem.

I have submitted a fix(#5376) and will push the changes to fix the issue.

[ghost]

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

[sima-zhu]

The issue is fixed by 4bb9450

It will be available at next Azure Storage and Azure Core release.
I will close the issue for now. @rvervaek Please feel free to reopen if it does not fix the issue.