search

spring-projects / spring-framework

Spring Framework
https://spring.io/projects/spring-framework
Apache License 2.0
56.46k stars 38.09k forks source link

Blocking call when loading a FreeMarker template #26802

Closed pmendelski closed 4 months ago

pmendelski commented 3 years ago

There is a blocking call detected by BlockHound when FreeMarker template is loaded Spring Boot WebFlux 2.4.4 application. Program was run with JDK 11 on Ubuntu 20.04.1.

I created a sample project that contains basic configuration with single FreeMarker template and two endpoints. When page is fetched Blockhound detects an error.

In most cases each template is loaded once and is stored in the FreeMarker cache, but what about a case when cache is deliberately disabled or templates are loaded from DB?

wilkinsona commented 3 years ago

Thanks for the sample. BlockHound has detected two blocking calls:

Reading bytes from a FileInputStream during FreeMarker template parsing ``` Error has been observed at the following site(s): |_ checkpoint ⇢ Handler com.sandbox.HomeController#home() [DispatcherHandler] |_ checkpoint ⇢ HTTP GET "/" [ExceptionHandlingWebHandler] Stack trace: at java.base/java.io.FileInputStream.readBytes(FileInputStream.java) at java.base/java.io.FileInputStream.read(FileInputStream.java:279) at java.base/java.io.BufferedInputStream.read1(BufferedInputStream.java:290) at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:351) at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284) at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326) at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178) at java.base/java.io.InputStreamReader.read(InputStreamReader.java:181) at java.base/java.io.BufferedReader.read1(BufferedReader.java:210) at java.base/java.io.BufferedReader.read(BufferedReader.java:287) at freemarker.template.Template$LineTableBuilder.read(Template.java:863) at freemarker.core.SimpleCharStream.FillBuff(SimpleCharStream.java:116) at freemarker.core.SimpleCharStream.readChar(SimpleCharStream.java:198) at freemarker.core.SimpleCharStream.BeginToken(SimpleCharStream.java:138) at freemarker.core.FMParserTokenManager.getNextToken(FMParserTokenManager.java:8124) at freemarker.core.FMParser.jj_scan_token(FMParser.java:5989) at freemarker.core.FMParser.jj_3_17(FMParser.java:5085) at freemarker.core.FMParser.jj_2_17(FMParser.java:4809) at freemarker.core.FMParser.Root(FMParser.java:4660) at freemarker.template.Template.(Template.java:252) at freemarker.cache.TemplateCache.loadTemplate(TemplateCache.java:548) at freemarker.cache.TemplateCache.getTemplateInternal(TemplateCache.java:439) at freemarker.cache.TemplateCache.getTemplate(TemplateCache.java:292) at freemarker.template.Configuration.getTemplate(Configuration.java:2836) at freemarker.template.Configuration.getTemplate(Configuration.java:2694) at org.springframework.web.reactive.result.view.freemarker.FreeMarkerView.getTemplate(FreeMarkerView.java:312) at org.springframework.web.reactive.result.view.freemarker.FreeMarkerView.checkResourceExists(FreeMarkerView.java:196) at org.springframework.web.reactive.result.view.UrlBasedViewResolver.resolveViewName(UrlBasedViewResolver.java:242) at org.springframework.web.reactive.result.view.ViewResolutionResultHandler.lambda$resolveViews$2(ViewResolutionResultHandler.java:274) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:374) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:218) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:164) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:73) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2193) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2067) at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1815) at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79) at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:210) at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:210) at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1815) at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onNext(MonoIgnoreThen.java:305) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397) at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onSubscribe(MonoIgnoreThen.java:294) at reactor.core.publisher.FluxFlatMap.trySubscribeScalarMap(FluxFlatMap.java:192) at reactor.core.publisher.MonoFlatMap.subscribeOrReturn(MonoFlatMap.java:53) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:57) at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:154) at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:73) at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:82) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:281) at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:860) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:180) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.request(MonoPeekTerminal.java:139) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2193) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2067) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onSubscribe(MonoPeekTerminal.java:152) at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) at reactor.core.publisher.Mono.subscribe(Mono.java:4099) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:448) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:218) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:164) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) at reactor.core.publisher.Mono.subscribe(Mono.java:4099) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:173) at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.netty.http.server.HttpServer$HttpServerHandle.onStateChange(HttpServer.java:915) at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:654) at reactor.netty.transport.ServerTransport$ChildObserver.onStateChange(ServerTransport.java:478) at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:526) 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 reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:209) 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.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) 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:834) ```
A call to Unsafe#park when accessing a ConcurrentLruCache during mime type parsing ``` 09:00:44.173 [reactor-http-nio-2] ERROR o.s.w.s.a.HttpWebHandlerAdapter - [cfc0878a-1] 500 Server Error for HTTP GET "/" reactor.blockhound.BlockingOperationError: Blocking call! jdk.internal.misc.Unsafe#park at java.base/jdk.internal.misc.Unsafe.park(Unsafe.java) at java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:885) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:917) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1240) at java.base/java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:959) at org.springframework.util.ConcurrentLruCache.get(ConcurrentLruCache.java:96) at org.springframework.util.MimeTypeUtils.parseMimeType(MimeTypeUtils.java:195) at org.springframework.http.MediaType.parseMediaType(MediaType.java:617) at org.springframework.http.MediaType.parseMediaTypes(MediaType.java:646) at org.springframework.http.MediaType.parseMediaTypes(MediaType.java:666) at org.springframework.http.HttpHeaders.getAccept(HttpHeaders.java:466) at org.springframework.http.ReadOnlyHttpHeaders.getAccept(ReadOnlyHttpHeaders.java:72) at org.springframework.web.reactive.function.server.DefaultServerRequest$DefaultHeaders.accept(DefaultServerRequest.java:272) at org.springframework.boot.autoconfigure.web.reactive.error.DefaultErrorWebExceptionHandler.lambda$acceptsTextHtml$1(DefaultErrorWebExceptionHandler.java:256) at org.springframework.web.reactive.function.server.RouterFunctions$DefaultRouterFunction.route(RouterFunctions.java:1075) at org.springframework.web.reactive.function.server.RouterFunctions$SameComposedRouterFunction.route(RouterFunctions.java:975) at org.springframework.boot.autoconfigure.web.reactive.error.AbstractErrorWebExceptionHandler.handle(AbstractErrorWebExceptionHandler.java:325) at org.springframework.web.server.handler.ExceptionHandlingWebHandler.lambda$handle$0(ExceptionHandlingWebHandler.java:77) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:94) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onError(FluxOnAssembly.java:392) at reactor.core.publisher.Operators.error(Operators.java:197) at reactor.core.publisher.MonoError.subscribe(MonoError.java:52) at reactor.core.publisher.Mono.subscribe(Mono.java:4099) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) 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 reactor.core.publisher.Operators.error(Operators.java:197) at reactor.core.publisher.FluxFlatMap.trySubscribeScalarMap(FluxFlatMap.java:135) at reactor.core.publisher.MonoFlatMap.subscribeOrReturn(MonoFlatMap.java:53) at reactor.core.publisher.Mono.subscribe(Mono.java:4084) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onError(FluxOnAssembly.java:392) 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.onError(MonoFlatMap.java:172) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onError(FluxMapFuseable.java:140) at reactor.core.publisher.MonoCollectList$MonoCollectListSubscriber.onError(MonoCollectList.java:113) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:381) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:218) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:164) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:73) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2193) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2067) at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1815) at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79) at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:210) at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:210) at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1815) at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onNext(MonoIgnoreThen.java:305) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397) at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onSubscribe(MonoIgnoreThen.java:294) at reactor.core.publisher.FluxFlatMap.trySubscribeScalarMap(FluxFlatMap.java:192) at reactor.core.publisher.MonoFlatMap.subscribeOrReturn(MonoFlatMap.java:53) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:57) at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:154) at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:157) at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:73) at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:82) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:281) at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:860) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:127) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:180) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2397) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.request(MonoPeekTerminal.java:139) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:169) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2193) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2067) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:96) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onSubscribe(MonoPeekTerminal.java:152) at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54) at reactor.core.publisher.Mono.subscribe(Mono.java:4099) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:448) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:218) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:164) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:52) at reactor.core.publisher.Mono.subscribe(Mono.java:4099) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:173) at reactor.core.publisher.MonoIgnoreThen.subscribe(MonoIgnoreThen.java:56) at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64) at reactor.netty.http.server.HttpServer$HttpServerHandle.onStateChange(HttpServer.java:915) at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:654) at reactor.netty.transport.ServerTransport$ChildObserver.onStateChange(ServerTransport.java:478) at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:526) 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 reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:209) 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.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) 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:834) ```

Both of these are triggered from Spring Framework code. We'll transfer this issue to the Framework repository so that they can take a look.

pmendelski commented 3 years ago

Perfect, thanks

poutsma commented 3 years ago

I am not able to reproduce this particular issue.

When I clone the project, BlockHound does not appear to be used.

After adding BlockHound.install() in the main method, I get a different BlockHound error:

Caused by: reactor.blockhound.BlockingOperationError: Blocking call! java.io.RandomAccessFile#readBytes
        at java.base/java.io.RandomAccessFile.readBytes(RandomAccessFile.java)
        at java.base/java.io.RandomAccessFile.read(RandomAccessFile.java:406)
        at java.base/java.io.RandomAccessFile.readFully(RandomAccessFile.java:470)
        at java.base/java.util.zip.ZipFile$Source.readFullyAt(ZipFile.java:1318)
        at java.base/java.util.zip.ZipFile$ZipFileInputStream.initDataOffset(ZipFile.java:1003)
        at java.base/java.util.zip.ZipFile$ZipFileInputStream.read(ZipFile.java:1018)
        at java.base/java.util.zip.ZipFile$ZipFileInflaterInputStream.fill(ZipFile.java:468)
        at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:159)
        at java.base/java.util.zip.InflaterInputStream.read(InflaterInputStream.java:123)
        at java.base/java.io.FilterInputStream.read(FilterInputStream.java:83)
        at java.base/java.io.DataInputStream.readInt(DataInputStream.java:392)
        at kotlin.reflect.jvm.internal.impl.metadata.builtins.BuiltInsBinaryVersion$Companion.readFrom(BuiltInsBinaryVersion.kt:29)
        at kotlin.reflect.jvm.internal.impl.serialization.deserialization.builtins.BuiltInsPackageFragmentImpl$Companion.create(BuiltInsPackageFragmentImpl.kt:38)
        at kotlin.reflect.jvm.internal.impl.builtins.jvm.JvmBuiltInsPackageFragmentProvider.findPackage(JvmBuiltInsPackageFragmentProvider.kt:61)
        at kotlin.reflect.jvm.internal.impl.serialization.deserialization.AbstractDeserializedPackageFragmentProvider$fragments$1.invoke(AbstractDeserializedPackageFragmentProvider.kt:35)
        at kotlin.reflect.jvm.internal.impl.serialization.deserialization.AbstractDeserializedPackageFragmentProvider$fragments$1.invoke(AbstractDeserializedPackageFragmentProvider.kt:34)
        at kotlin.reflect.jvm.internal.impl.storage.LockBasedStorageManager$MapBasedMemoizedFunction.invoke(LockBasedStorageManager.java:578)
        at kotlin.reflect.jvm.internal.impl.serialization.deserialization.AbstractDeserializedPackageFragmentProvider.collectPackageFragments(AbstractDeserializedPackageFragmentProvider.kt:43)
        at kotlin.reflect.jvm.internal.impl.descriptors.PackageFragmentProviderKt.collectPackageFragmentsOptimizedIfPossible(PackageFragmentProvider.kt:50)
        at kotlin.reflect.jvm.internal.impl.descriptors.impl.CompositePackageFragmentProvider.collectPackageFragments(CompositePackageFragmentProvider.kt:47)
        at kotlin.reflect.jvm.internal.impl.descriptors.PackageFragmentProviderKt.collectPackageFragmentsOptimizedIfPossible(PackageFragmentProvider.kt:50)
        at kotlin.reflect.jvm.internal.impl.descriptors.impl.CompositePackageFragmentProvider.collectPackageFragments(CompositePackageFragmentProvider.kt:47)
        at kotlin.reflect.jvm.internal.impl.descriptors.PackageFragmentProviderKt.collectPackageFragmentsOptimizedIfPossible(PackageFragmentProvider.kt:50)

This error appears to be coming from Kotlin itself, not Spring. I am running on macOS, not Ubuntu.

Could you please verify that the sample reproduces the issue?

wilkinsona commented 3 years ago

It reproduced it for me, @poutsma. Did you check out the blockhound-error branch? IIRC, I was tripped up initially as I forgot to do so and the default branch doesn't reproduce the problem.

poutsma commented 3 years ago

Thanks for pointing that out, @wilkinsona. I must have read over that branch name.

I can reproduce the issue now, but do not think it's possible to solve without changing the contract of AbstractUrlBasedView::checkResourceExists(Locale) and FreeMarkerView::getTemplate(Locale). If these would return a Mono instead of a concrete type, we could schedule them to occur on the bounded elastic scheduler, like we do with other blocking code.

Do you see another way to solve this, @rstoyanchev ?

poutsma commented 3 years ago

Here a WIP commit that fixes the Blockhound error, but changes the signature of several protected methods:

https://github.com/poutsma/spring-framework/commit/e1989e81e3536d5b844fb84d44f265c40fd48949

pmendelski commented 3 years ago

Thanks for looking at this problem.

I can see that you moved the blocking operation to Schedulers.boundedElastic(). There is one edge case though. When template uses a lazy import to another template, the imported template is read in resolution phase. I'm not a pro in FreeMarker but I would test it.

poutsma commented 4 months ago

Closed in favor of #30903.