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

Blockhound error when running with transaction with a TransactionOperator #26955

Closed
alexanderlindholm opened this issue May 19, 2021 · 3 comments
Closed

Blockhound error when running with transaction with a TransactionOperator #26955

alexanderlindholm opened this issue May 19, 2021 · 3 comments
Assignees
@jhoeller
Labels
in: data Issues in data modules (jdbc, orm, oxm, tx) type: enhancement A general enhancement
Milestone
5.3.9

Comments

@alexanderlindholm
Copy link

alexanderlindholm commented May 19, 2021 •
edited by sbrannen

When running Blockhound on my project it detects this UUID generation as a blocking call. I am thinking that it should be updated and maybe you can set the creation of this class on a separate thread pool or fix the issue with generating the id of the TransactionContext.

spring-framework/spring-tx/src/main/java/org/springframework/transaction/reactive/TransactionContext.java

Line 43 in 360f555

private final UUID contextId = UUID.randomUUID();

This is the stack trace from Blockhound

reactor.blockhound.BlockingOperationError: Blocking call! java.io.FileInputStream#readBytes
	at java.base/java.io.FileInputStream.readBytes(FileInputStream.java)
	at java.base/java.io.FileInputStream.read(FileInputStream.java:273)
	at java.base/java.io.FilterInputStream.read(FilterInputStream.java:133)
	at java.base/sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
	at java.base/sun.security.provider.NativePRNG$RandomIO.ensureBufferValid(NativePRNG.java:526)
	at java.base/sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:545)
	at java.base/sun.security.provider.NativePRNG$NonBlocking.engineNextBytes(NativePRNG.java:318)
	at java.base/java.security.SecureRandom.nextBytes(SecureRandom.java:741)
	at java.base/java.util.UUID.randomUUID(UUID.java:150)
	at org.springframework.transaction.reactive.TransactionContext.<init>(TransactionContext.java:43)
	at org.springframework.transaction.reactive.TransactionContext.<init>(TransactionContext.java:60)
	at org.springframework.transaction.reactive.TransactionContextHolder.createContext(TransactionContextHolder.java:63)
	at org.springframework.transaction.reactive.TransactionContextManager.lambda$getOrCreateContext$2(TransactionContextManager.java:91)
	at reactor.core.publisher.MonoContextWrite.subscribeOrReturn(MonoContextWrite.java:38)
	at reactor.core.publisher.Mono.subscribe(Mono.java:4135)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onError(FluxContextWrite.java:121)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onError(ReactorContextTestExecutionListener.java:125)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onError(MonoIgnoreThen.java:270)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:227)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete(MonoFlatMap.java:196)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete(MonoFlatMap.java:268)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete(MonoFlatMap.java:196)
	at reactor.core.publisher.MonoFlatMap$FlatMapInner.onComplete(MonoFlatMap.java:268)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:259)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209)
	at reactor.pool.SimpleDequePool$QueuePoolRecyclerInner.onComplete(SimpleDequePool.java:690)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
	at reactor.core.publisher.Operators.complete(Operators.java:136)
	at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
	at reactor.core.publisher.Mono.subscribe(Mono.java:4150)
	at reactor.pool.SimpleDequePool$QueuePoolRecyclerMono.subscribe(SimpleDequePool.java:802)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:236)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:259)
	at reactor.core.publisher.Operators.complete(Operators.java:136)
	at reactor.core.publisher.MonoEmpty.subscribe(MonoEmpty.java:45)
	at reactor.core.publisher.Mono.subscribe(Mono.java:4150)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:255)
	at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51)
	at org.springframework.cloud.sleuth.instrument.reactor.SleuthMonoLift.subscribe(ReactorHooksHelper.java:225)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:236)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
	at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:88)
	at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:201)
	at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1815)
	at reactor.core.publisher.MonoSupplier.subscribe(MonoSupplier.java:61)
	at reactor.core.publisher.Mono.subscribe(Mono.java:4150)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:255)
	at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51)
	at org.springframework.cloud.sleuth.instrument.reactor.SleuthMonoLift.subscribe(ReactorHooksHelper.java:225)
	at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157)
	at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:120)
	at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397)
	at reactor.core.publisher.FluxMap$MapSubscriber.request(FluxMap.java:162)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onSubscribe(MonoFlatMap.java:110)
	at reactor.core.publisher.FluxMap$MapSubscriber.onSubscribe(FluxMap.java:92)
	at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)
	at reactor.core.publisher.MonoDeferContextual.subscribe(MonoDeferContextual.java:55)
	at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:236)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209)
	at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:88)
	at io.r2dbc.postgresql.util.FluxDiscardOnCancel$FluxDiscardOnCancelSubscriber.onComplete(FluxDiscardOnCancel.java:99)
	at reactor.core.publisher.Operators.complete(Operators.java:136)
	at reactor.core.publisher.FluxEmpty.subscribe(FluxEmpty.java:41)
	at reactor.core.publisher.FluxDefer.subscribe(FluxDefer.java:54)
	at io.r2dbc.postgresql.util.FluxDiscardOnCancel.subscribe(FluxDiscardOnCancel.java:49)
	at reactor.core.publisher.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:81)
	at org.springframework.cloud.sleuth.instrument.reactor.SleuthMonoLift.subscribe(ReactorHooksHelper.java:225)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:236)
	at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51)
	at org.springframework.cloud.sleuth.instrument.reactor.SleuthMonoLift.subscribe(ReactorHooksHelper.java:225)
	at reactor.core.publisher.Mono.subscribe(Mono.java:4150)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:255)
	at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:51)
	at org.springframework.cloud.sleuth.instrument.reactor.SleuthMonoLift.subscribe(ReactorHooksHelper.java:225)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:236)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209)
	at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:88)
	at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onComplete(FluxContextWrite.java:126)
	at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:366)
	at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onComplete(FluxConcatMap.java:275)
	at reactor.core.publisher.Operators.complete(Operators.java:136)
	at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:147)
	at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86)
	at reactor.core.publisher.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:81)
	at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.subscribeNext(MonoIgnoreThen.java:236)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:203)
	at org.springframework.security.test.context.support.ReactorContextTestExecutionListener$DelegateTestExecutionListener$SecuritySubContext.onComplete(ReactorContextTestExecutionListener.java:130)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.onComplete(MonoIgnoreThen.java:209)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:259)
	at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:88)
	at io.r2dbc.postgresql.util.FluxDiscardOnCancel$FluxDiscardOnCancelSubscriber.onComplete(FluxDiscardOnCancel.java:99)
	at io.r2dbc.postgresql.util.FluxDiscardOnCancel$FluxDiscardOnCancelSubscriber.onComplete(FluxDiscardOnCancel.java:99)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onComplete(FluxHandle.java:212)
	at reactor.core.publisher.FluxCreate$BaseSink.complete(FluxCreate.java:439)
	at reactor.core.publisher.FluxCreate$BufferAsyncSink.drain(FluxCreate.java:784)
	at reactor.core.publisher.FluxCreate$BufferAsyncSink.complete(FluxCreate.java:732)
	at reactor.core.publisher.FluxCreate$SerializedFluxSink.drainLoop(FluxCreate.java:240)
	at reactor.core.publisher.FluxCreate$SerializedFluxSink.drain(FluxCreate.java:206)
	at reactor.core.publisher.FluxCreate$SerializedFluxSink.complete(FluxCreate.java:197)
	at io.r2dbc.postgresql.client.ReactorNettyClient$Conversation.complete(ReactorNettyClient.java:719)
	at io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.emit(ReactorNettyClient.java:984)
	at io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.onNext(ReactorNettyClient.java:860)
	at io.r2dbc.postgresql.client.ReactorNettyClient$BackendMessageSubscriber.onNext(ReactorNettyClient.java:767)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:118)
	at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
	at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:220)
	at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:220)
	at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:280)
	at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:389)
	at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:401)
	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:830)
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged or decided on label May 19, 2021
@sbrannen sbrannen added the in: data Issues in data modules (jdbc, orm, oxm, tx) label May 19, 2021
@jhoeller jhoeller self-assigned this May 22, 2021
@jhoeller jhoeller added type: enhancement A general enhancement and removed status: waiting-for-triage An issue we've not yet triaged or decided on labels May 22, 2021
@jhoeller jhoeller added this to the 5.3.8 milestone May 22, 2021
@jhoeller jhoeller modified the milestones: 5.3.8, 5.3.9 Jun 4, 2021
@jhoeller jhoeller mentioned this issue Jun 8, 2021
Closed
@jhoeller
Copy link
Contributor

jhoeller commented Jul 9, 2021

Since we're only using that UUID for logging purposes, even just synchronization trace logging that we could get rid of completely (with standard as well as reactive transactions), I'm inclined to make UUID generation lazy there - and to deprecate its accessors.

@mp911de what's your take on this? Are you aware of any use of the context id (or the name including the context id) outside of the core transaction module?

@mp911de
Copy link
Member

mp911de commented Jul 9, 2021

I'm not aware of any outside usage, even Spring Data R2DBC doesn't use the context. In retrospect, using a UUID seems to be not an ideal choice because of the blocking access to the random source. Let's revisit this arrangement for the next major release.

@jhoeller
Copy link
Contributor

jhoeller commented Jul 9, 2021

Alright, I'll proceed with the steps above then. Let's revisit the transaction identification problem in Spring Framework 6 indeed, and simply keep the current mechanism in deprecated form for the time being. Most importantly, by lazily creating the UUID, we'll avoid the overhead (and the potential blocking) for every created transaction. With the trace log statements removed, this effectively means that we'll never trigger that UUID to begin with, unless some custom code calls getContextId()/getName(). That should deliver significant benefit in 5.3.9 already and not constrain use for 6 either.

@sync-by-unito sync-by-unito bot mentioned this issue Jul 14, 2021
Merged
@sbrannen sbrannen mentioned this issue Aug 13, 2021
Closed
Zoran0104 pushed a commit to Zoran0104/spring-framework that referenced this issue Aug 20, 2021
@jhoeller @Zoran0104
Lazy initialization of transaction UUID (with deprecated getter methods)
33a8ef5 
Includes removal of trace logging for individual synchronization steps.

Closes spring-projectsgh-26955
lxbzmy pushed a commit to lxbzmy/spring-framework that referenced this issue Mar 26, 2022
@jhoeller @lxbzmy
Lazy initialization of transaction UUID (with deprecated getter methods)
22686fb 
Includes removal of trace logging for individual synchronization steps.

Closes spring-projectsgh-26955
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jhoeller jhoeller

Labels
in: data Issues in data modules (jdbc, orm, oxm, tx) type: enhancement A general enhancement
Projects
None yet
Milestone
5.3.9
Development

No branches or pull requests
5 participants
@sbrannen @mp911de @jhoeller @spring-projects-issues @alexanderlindholm