Spring boot version: 2.3.1.RELEASE
Description: BlockHound detects blocking code when Spring Boot Data (Hibernate) is used together with Validation API for WebFlux project.
To reproduce run the application that contains these 4 files: - build.gradle - DemoApplication.java - Body.java - MyController.java
And run the curl command:
curl --location --request POST 'localhost:8080/body' \
--header 'Content-Type: application/json' \
--data-raw '{
"id": ""
}'
Actual result: Blocking code is detected (full log check below in the ticket)
reactor.blockhound.BlockingOperationError: Blocking call! java.io.RandomAccessFile#readBytes
at java.base/java.io.RandomAccessFile.readBytes(RandomAccessFile.java) ~[na:na]
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
build.gradle
plugins {
id 'org.springframework.boot' version '2.3.1.RELEASE'
id 'io.spring.dependency-management' version '1.0.9.RELEASE'
id 'java'
}
group = 'com.example'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = '11'
repositories {
mavenCentral()
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-webflux'
implementation 'org.springframework.boot:spring-boot-starter-validation'
implementation 'io.projectreactor.tools:blockhound:1.0.4.RELEASE'
implementation 'org.springframework.boot:spring-boot-starter-data-jpa'
runtimeOnly 'com.h2database:h2'
}
DemoApplication.java
package com.example.demo;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import reactor.blockhound.BlockHound;
@SpringBootApplication
public class DemoApplication {
public static void main(String[] args) {
BlockHound.install();
SpringApplication.run(DemoApplication.class, args);
}
}
Body.java
package com.example.demo;
import javax.validation.constraints.NotBlank;
public class Body {
@NotBlank(message = "should not be blank")
private String id;
public String getId() {
return id;
}
public void setId(String id) {
this.id = id;
}
}
MyController.java
package com.example.demo;
import org.springframework.http.HttpStatus;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RestController;
import reactor.core.publisher.Mono;
import javax.validation.Valid;
@RestController
public class MyController {
@PostMapping(path = "/body")
public Mono<ResponseEntity<Body>> post(@Valid @RequestBody Body body) {
return Mono.just(ResponseEntity.status(HttpStatus.OK).body(body));
}
}
Log:
2020-07-04 15:40:19.871 DEBUG 19986 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations : [id: 0x9a0e29ca, L:/0:0:0:0:0:0:0:1:8080 - R:/0:0:0:0:0:0:0:1:65367] Increasing pending responses, now 1
2020-07-04 15:40:19.871 DEBUG 19986 --- [ctor-http-nio-3] reactor.netty.http.server.HttpServer : [id: 0x9a0e29ca, L:/0:0:0:0:0:0:0:1:8080 - R:/0:0:0:0:0:0:0:1:65367] Handler is being applied: org.springframework.http.server.reactive.ReactorHttpHandlerAdapter@522dd5db
2020-07-04 15:40:19.871 DEBUG 19986 --- [ctor-http-nio-3] o.s.w.s.adapter.HttpWebHandlerAdapter : [9a0e29ca-2] HTTP POST "/body"
2020-07-04 15:40:19.872 DEBUG 19986 --- [ctor-http-nio-3] s.w.r.r.m.a.RequestMappingHandlerMapping : [9a0e29ca-2] Mapped to com.example.demo.MyController#post(Body)
2020-07-04 15:40:19.872 DEBUG 19986 --- [ctor-http-nio-3] .r.m.a.RequestBodyMethodArgumentResolver : [9a0e29ca-2] Content-Type:application/json
2020-07-04 15:40:19.872 DEBUG 19986 --- [ctor-http-nio-3] .r.m.a.RequestBodyMethodArgumentResolver : [9a0e29ca-2] 0..1 [com.example.demo.Body]
2020-07-04 15:40:19.872 DEBUG 19986 --- [ctor-http-nio-3] reactor.netty.channel.FluxReceive : [id: 0x9a0e29ca, L:/0:0:0:0:0:0:0:1:8080 - R:/0:0:0:0:0:0:0:1:65367] Subscribing inbound receiver [pending: 0, cancelled:false, inboundDone: false]
2020-07-04 15:40:19.872 DEBUG 19986 --- [ctor-http-nio-3] o.s.http.codec.json.Jackson2JsonDecoder : [9a0e29ca-2] Decoded [com.example.demo.Body@63d1d635]
2020-07-04 15:40:19.873 DEBUG 19986 --- [ctor-http-nio-3] o.s.w.r.r.method.InvocableHandlerMethod : [9a0e29ca-2] Could not resolve parameter [0] in public reactor.core.publisher.Mono<org.springframework.http.ResponseEntity<com.example.demo.Body>> com.example.demo.MyController.post(com.example.demo.Body): Blocking call! java.io.RandomAccessFile#readBytes
2020-07-04 15:40:19.874 DEBUG 19986 --- [ctor-http-nio-3] a.w.r.e.AbstractErrorWebExceptionHandler : [9a0e29ca-2] Resolved [BlockingOperationError: Blocking call! java.io.RandomAccessFile#readBytes] for HTTP POST /body
2020-07-04 15:40:19.875 ERROR 19986 --- [ctor-http-nio-3] a.w.r.e.AbstractErrorWebExceptionHandler : [9a0e29ca-2] 500 Server Error for HTTP POST "/body"
reactor.blockhound.BlockingOperationError: Blocking call! java.io.RandomAccessFile#readBytes
at java.base/java.io.RandomAccessFile.readBytes(RandomAccessFile.java) ~[na:na]
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
|_ checkpoint ⇢ HTTP POST "/body" [ExceptionHandlingWebHandler]
Stack trace:
at java.base/java.io.RandomAccessFile.readBytes(RandomAccessFile.java) ~[na:na]
at java.base/java.io.RandomAccessFile.read(RandomAccessFile.java:406) ~[na:na]
at java.base/java.io.RandomAccessFile.readFully(RandomAccessFile.java:470) ~[na:na]
at java.base/java.util.zip.ZipFile$Source.readFullyAt(ZipFile.java:1298) ~[na:na]
at java.base/java.util.zip.ZipFile$ZipFileInputStream.initDataOffset(ZipFile.java:997) ~[na:na]
at java.base/java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:1012) ~[na:na]
at java.base/java.util.zip.ZipFile$ZipFileInflaterInputStream.fill(ZipFile.java:467) ~[na:na]
at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:159) ~[na:na]
at java.base/java.io.InputStream.readNBytes(InputStream.java:396) ~[na:na]
at java.base/java.io.InputStream.readAllBytes(InputStream.java:333) ~[na:na]
at java.base/java.util.jar.JarFile.getBytes(JarFile.java:807) ~[na:na]
at java.base/java.util.jar.JarFile.checkForSpecialAttributes(JarFile.java:1005) ~[na:na]
at java.base/java.util.jar.JarFile.isMultiRelease(JarFile.java:388) ~[na:na]
at java.base/java.util.jar.JarFile.getEntry(JarFile.java:507) ~[na:na]
at java.base/sun.net.www.protocol.jar.URLJarFile.getEntry(URLJarFile.java:131) ~[na:na]
at java.base/sun.net.www.protocol.jar.JarURLConnection.connect(JarURLConnection.java:137) ~[na:na]
at java.base/sun.net.www.protocol.jar.JarURLConnection.getInputStream(JarURLConnection.java:155) ~[na:na]
at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.parse(ServiceLoader.java:1164) ~[na:na]
at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.nextProviderClass(ServiceLoader.java:1205) ~[na:na]
at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNextService(ServiceLoader.java:1220) ~[na:na]
at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNext(ServiceLoader.java:1264) ~[na:na]
at java.base/java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1299) ~[na:na]
at java.base/java.util.ServiceLoader$3.hasNext(ServiceLoader.java:1384) ~[na:na]
at javax.persistence.spi.PersistenceProviderResolverHolder$DefaultPersistenceProviderResolver.getPersistenceProviders(PersistenceProviderResolverHolder.java:110) ~[jakarta.persistence-api-2.2.3.jar:2.2.3]
at javax.persistence.Persistence$PersistenceUtilImpl.isLoaded(Persistence.java:142) ~[jakarta.persistence-api-2.2.3.jar:2.2.3]
at org.hibernate.validator.internal.engine.resolver.JPATraversableResolver.isReachable(JPATraversableResolver.java:52) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.resolver.CachingJPATraversableResolverForSingleValidation.lambda$isReachable$0(CachingJPATraversableResolverForSingleValidation.java:43) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at java.base/java.util.HashMap.computeIfAbsent(HashMap.java:1133) ~[na:na]
at org.hibernate.validator.internal.engine.resolver.CachingJPATraversableResolverForSingleValidation.isReachable(CachingJPATraversableResolverForSingleValidation.java:43) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.isReachable(ValidatorImpl.java:1307) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.isValidationRequired(ValidatorImpl.java:1291) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.validateMetaConstraint(ValidatorImpl.java:549) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.validateConstraintsForSingleDefaultGroupElement(ValidatorImpl.java:518) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.validateConstraintsForDefaultGroup(ValidatorImpl.java:488) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.validateConstraintsForCurrentGroup(ValidatorImpl.java:450) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.validateInContext(ValidatorImpl.java:400) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.hibernate.validator.internal.engine.ValidatorImpl.validate(ValidatorImpl.java:172) ~[hibernate-validator-6.1.5.Final.jar:6.1.5.Final]
at org.springframework.validation.beanvalidation.SpringValidatorAdapter.validate(SpringValidatorAdapter.java:117) ~[spring-context-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.boot.autoconfigure.validation.ValidatorAdapter.validate(ValidatorAdapter.java:70) ~[spring-boot-autoconfigure-2.3.1.RELEASE.jar:2.3.1.RELEASE]
at org.springframework.validation.DataBinder.validate(DataBinder.java:889) ~[spring-context-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.reactive.result.method.annotation.AbstractMessageReaderArgumentResolver.validate(AbstractMessageReaderArgumentResolver.java:256) ~[spring-webflux-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.reactive.result.method.annotation.AbstractMessageReaderArgumentResolver.lambda$readBody$6(AbstractMessageReaderArgumentResolver.java:198) ~[spring-webflux-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:177) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1782) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:144) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxContextStart$ContextStartSubscriber.onNext(FluxContextStart.java:96) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxMapFuseable$MapFuseableConditionalSubscriber.onNext(FluxMapFuseable.java:287) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxFilterFuseable$FilterFuseableConditionalSubscriber.onNext(FluxFilterFuseable.java:330) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1782) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.MonoCollect$CollectSubscriber.onComplete(MonoCollect.java:152) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:252) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136) ~[reactor-core-3.3.6.RELEASE.jar:3.3.6.RELEASE]
at reactor.netty.channel.FluxReceive.onInboundComplete(FluxReceive.java:365) ~[reactor-netty-0.9.8.RELEASE.jar:0.9.8.RELEASE]
at reactor.netty.channel.ChannelOperations.onInboundComplete(ChannelOperations.java:368) ~[reactor-netty-0.9.8.RELEASE.jar:0.9.8.RELEASE]
at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:495) ~[reactor-netty-0.9.8.RELEASE.jar:0.9.8.RELEASE]
at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:96) ~[reactor-netty-0.9.8.RELEASE.jar:0.9.8.RELEASE]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:214) ~[reactor-netty-0.9.8.RELEASE.jar:0.9.8.RELEASE]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) ~[netty-codec-4.1.50.Final.jar:4.1.50.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) ~[netty-codec-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) ~[netty-transport-4.1.50.Final.jar:4.1.50.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) ~[netty-common-4.1.50.Final.jar:4.1.50.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.50.Final.jar:4.1.50.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.50.Final.jar:4.1.50.Final]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
2020-07-04 15:40:19.876 DEBUG 19986 --- [ctor-http-nio-3] o.s.http.codec.json.Jackson2JsonEncoder : [9a0e29ca-2] Encoding [{timestamp=Sat Jul 04 15:40:19 CEST 2020, path=/body, status=500, error=Internal Server Error, messa (truncated)...]
2020-07-04 15:40:19.878 DEBUG 19986 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations : [id: 0x9a0e29ca, L:/0:0:0:0:0:0:0:1:8080 - R:/0:0:0:0:0:0:0:1:65367] Decreasing pending responses, now 0
2020-07-04 15:40:19.879 DEBUG 19986 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations : [id: 0x9a0e29ca, L:/0:0:0:0:0:0:0:1:8080 - R:/0:0:0:0:0:0:0:1:65367] Last HTTP packet was sent, terminating the channel
2020-07-04 15:40:19.879 DEBUG 19986 --- [ctor-http-nio-3] o.s.w.s.adapter.HttpWebHandlerAdapter : [9a0e29ca-2] Completed 500 INTERNAL_SERVER_ERROR
2020-07-04 15:40:19.879 DEBUG 19986 --- [ctor-http-nio-3] r.n.http.server.HttpServerOperations : [id: 0x9a0e29ca, L:/0:0:0:0:0:0:0:1:8080 - R:/0:0:0:0:0:0:0:1:65367] Last HTTP response frame
2020-07-04 15:40:20.846 DEBUG 19986 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2020-07-04 15:40:20.847 DEBUG 19986 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
Comment From: wilkinsona
Thanks for the report but this is out of Spring Boot’s control.
Hibernate Validator is triggering the use of the JVM’s ServiceLoader. It is performing some file IO which may be blocking. Bean Validation isn’t a reactive API so there’s no guarantee that it can be safely used in a reactive application. You may want to look at using something like Yavi instead.
I also noticed that you have Spring Data JPA and H2 in your dependencies. Please note that neither of these can be safely used in a reactive application either unless you jump through some hoops to move the work onto a separate thread. You may want to look at R2DBC instead.
/cc @bsideup who maintains BlockHound