Closed thekalinga closed 1 year ago
Hey, interesting problem. Can you please put
logging.level.io.netty=TRACE
in your application.properties
? Maybe the netty logs will tell us the cause of this.
So, i can reproduce it on a Fedora 35 Linux.
After i added a ton of hints to clean the netty trace output:
@TypeHint(typeNames= {
"io.netty.channel.DefaultChannelPipeline$TailContext",
"io.netty.channel.DefaultChannelPipeline$HeadContext",
"io.netty.handler.ssl.SslHandler",
"io.netty.handler.codec.http.HttpClientCodec",
"io.netty.resolver.dns.DnsNameResolver$1",
"io.netty.resolver.dns.DnsNameResolver$3",
"io.netty.handler.codec.dns.DatagramDnsQueryEncoder",
"io.netty.resolver.dns.DnsNameResolver$DnsResponseHandler",
"reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer",
"reactor.netty.transport.TransportConfig$TransportChannelInitializer",
"reactor.netty.transport.logging.ReactorNettyLoggingHandler",
"reactor.netty.channel.ChannelOperationsHandler",
"reactor.netty.tcp.SslProvider$SslReadHandler"
}, access = { TypeAccess.PUBLIC_METHODS })
I now get this log after building the image, verifying that it works until reboot, reboot and then it fails with:
2022-08-22 11:36:16.774 INFO 2504 --- [ main] o.s.nativex.NativeListener : AOT mode enabled
2022-08-22 11:36:16.775 INFO 2504 --- [ main] com.acme.DemoApplication : Starting DemoApplication using Java 17.0.4 on fedora with PID 2504 (/home/moe/Downloads/issue-projects/gh-1698/build/native/nativeCompile/spring-native-netty-timeout-bug started by moe in /home/moe/Downloads/issue-projects/gh-1698)
2022-08-22 11:36:16.775 DEBUG 2504 --- [ main] com.acme.DemoApplication : Running with Spring Boot v2.7.1, Spring v5.3.21
2022-08-22 11:36:16.775 INFO 2504 --- [ main] com.acme.DemoApplication : No active profile set, falling back to 1 default profile: "default"
2022-08-22 11:36:16.796 INFO 2504 --- [ main] com.acme.DemoApplication : Started DemoApplication in 0.033 seconds (JVM running for 0.081)
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@1b6f9dda
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@451553f0
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@230754b
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@518815f9
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@758d51aa
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@6f122867
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@11731641
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@272b7d46
2022-08-22 11:36:16.800 TRACE 2504 --- [ main] io.netty.channel.nio.NioEventLoop : instrumented a special java.util.Set into: sun.nio.ch.EPollSelectorImpl@472d096e
2022-08-22 11:36:16.801 DEBUG 2504 --- [ main] io.netty.channel.DefaultChannelId : -Dio.netty.processId: 2504 (auto-detected)
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.channel.DefaultChannelId : -Dio.netty.machineId: 00:0c:29:ff:fe:8a:cd:55 (auto-detected)
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.numHeapArenas: 18
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.numDirectArenas: 18
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.pageSize: 8192
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.maxOrder: 9
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.chunkSize: 4194304
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.smallCacheSize: 256
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.normalCacheSize: 64
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.cacheTrimInterval: 8192
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.useCacheForAllThreads: false
2022-08-22 11:36:16.802 DEBUG 2504 --- [ main] io.netty.buffer.PooledByteBufAllocator : -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2022-08-22 11:36:16.803 DEBUG 2504 --- [ main] io.netty.buffer.ByteBufUtil : -Dio.netty.allocator.type: pooled
2022-08-22 11:36:16.803 DEBUG 2504 --- [ main] io.netty.buffer.ByteBufUtil : -Dio.netty.threadLocalDirectBufferSize: 0
2022-08-22 11:36:16.803 DEBUG 2504 --- [ main] io.netty.buffer.ByteBufUtil : -Dio.netty.maxThreadLocalCharBufferSize: 16384
2022-08-22 11:36:16.804 DEBUG 2504 --- [ctor-http-nio-2] com.acme.ApiAccessor : [e9657467] REGISTERED
2022-08-22 11:36:16.804 DEBUG 2504 --- [ctor-http-nio-1] i.n.util.ResourceLeakDetectorFactory : Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@16f0ef6
2022-08-22 11:36:16.805 DEBUG 2504 --- [ctor-http-nio-1] io.netty.resolver.dns.DnsQueryContext : [id: 0x7fa99b43] WRITE: UDP, [12958: /127.0.0.53:53], DefaultDnsQuestion(httpbin.org. IN A)
2022-08-22 11:36:16.807 DEBUG 2504 --- [ctor-http-nio-1] io.netty.resolver.dns.DnsQueryContext : [id: 0x7fa99b43] WRITE: UDP, [32900: /127.0.0.53:53], DefaultDnsQuestion(httpbin.org. IN AAAA)
2022-08-22 11:36:16.831 DEBUG 2504 --- [ctor-http-nio-1] io.netty.resolver.dns.DnsNameResolver : [id: 0x7fa99b43] RECEIVED: UDP [32900: /127.0.0.53:53], DatagramDnsResponse(from: /127.0.0.53:53, to: /[0:0:0:0:0:0:0:0]:33579, 32900, QUERY(0), NoError(0), RD RA)
DefaultDnsQuestion(httpbin.org. IN AAAA)
DefaultDnsRawRecord(httpbin.org. 153 IN SOA 70B)
DefaultDnsRawRecord(OPT flags:0 udp:65494 0B)
2022-08-22 11:36:16.831 DEBUG 2504 --- [ctor-http-nio-2] com.acme.ApiAccessor : [e9657467] CLOSE
2022-08-22 11:36:16.831 DEBUG 2504 --- [ctor-http-nio-2] com.acme.ApiAccessor : [e9657467] UNREGISTERED
2022-08-22 11:36:16.833 ERROR 2504 --- [ main] o.s.boot.SpringApplication : Application run failed
java.lang.IllegalStateException: Failed to execute ApplicationRunner
at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:765) ~[spring-native-netty-timeout-bug:2.7.1]
at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:752) ~[spring-native-netty-timeout-bug:2.7.1]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:315) ~[spring-native-netty-timeout-bug:2.7.1]
at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:164) ~[na:na]
at com.acme.DemoApplication.main(DemoApplication.java:37) ~[spring-native-netty-timeout-bug:na]
Caused by: org.springframework.web.reactive.function.client.WebClientRequestException: Failed to resolve 'httpbin.org' and search domain query for configured domains failed as well: [.]; nested exception is io.netty.resolver.dns.DnsResolveContext$SearchDomainUnknownHostException: Failed to resolve 'httpbin.org' and search domain query for configured domains failed as well: [.]
at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141) ~[na:na]
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
*__checkpoint ⇢ Request to GET https://httpbin.org/get [DefaultWebClient]
Original Stack Trace:
at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$9(ExchangeFunctions.java:141) ~[na:na]
at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:55) ~[na:na]
at reactor.core.publisher.Mono.subscribe(Mono.java:4397) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) ~[na:na]
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) ~[na:na]
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) ~[na:na]
at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:222) ~[na:na]
at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:93) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onError(MonoFlatMapMany.java:204) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.SerializedSubscriber.onError(SerializedSubscriber.java:124) ~[na:na]
at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.whenError(FluxRetryWhen.java:225) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.FluxRetryWhen$RetryWhenOtherSubscriber.onError(FluxRetryWhen.java:274) ~[na:na]
at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:415) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:251) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:537) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:343) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.SinkManySerialized.tryEmitNext(SinkManySerialized.java:100) ~[na:na]
at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onError(FluxRetryWhen.java:190) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:201) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.netty.http.client.HttpClientConnect$MonoHttpConnect$ClientTransportSubscriber.onError(HttpClientConnect.java:308) ~[na:na]
at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:201) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onError(DefaultPooledConnectionProvider.java:158) ~[na:na]
at reactor.netty.internal.shaded.reactor.pool.AbstractPool$Borrower.fail(AbstractPool.java:475) ~[spring-native-netty-timeout-bug:1.0.20]
at reactor.netty.internal.shaded.reactor.pool.SimpleDequePool.lambda$drainLoop$9(SimpleDequePool.java:431) ~[spring-native-netty-timeout-bug:1.0.20]
at reactor.core.publisher.FluxDoOnEach$DoOnEachSubscriber.onError(FluxDoOnEach.java:186) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.MonoCreate$DefaultMonoSink.error(MonoCreate.java:201) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnectionAllocator$PooledConnectionInitializer.onError(DefaultPooledConnectionProvider.java:548) ~[spring-native-netty-timeout-bug:1.0.20]
at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:192) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:259) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:106) ~[na:na]
at reactor.core.publisher.Operators.error(Operators.java:198) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.MonoError.subscribe(MonoError.java:53) ~[na:na]
at reactor.core.publisher.Mono.subscribe(Mono.java:4397) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:103) ~[na:na]
at reactor.netty.transport.TransportConnector$MonoChannelPromise.tryFailure(TransportConnector.java:534) ~[spring-native-netty-timeout-bug:1.0.20]
at reactor.netty.transport.TransportConnector.lambda$doResolveAndConnect$11(TransportConnector.java:341) ~[na:na]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setFailure(DefaultPromise.java:109) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.InetSocketAddressResolver$2.operationComplete(InetSocketAddressResolver.java:86) ~[na:na]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext$1.operationComplete(DnsResolveContext.java:236) ~[na:na]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext.finishResolve(DnsResolveContext.java:1055) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(DnsResolveContext.java:1000) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext.query(DnsResolveContext.java:418) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext.access$600(DnsResolveContext.java:66) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext$2.operationComplete(DnsResolveContext.java:467) ~[na:na]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsQueryContext.tryFailure(DnsQueryContext.java:256) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsQueryContext$4.run(DnsQueryContext.java:208) ~[na:na]
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:153) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) ~[na:na]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[na:na]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[na:na]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[na:na]
at java.lang.Thread.run(Thread.java:833) ~[spring-native-netty-timeout-bug:na]
at com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:705) ~[spring-native-netty-timeout-bug:na]
at com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:202) ~[na:na]
Suppressed: java.lang.Exception: #block terminated with an error
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:99) ~[spring-native-netty-timeout-bug:3.4.19]
at reactor.core.publisher.Mono.block(Mono.java:1707) ~[spring-native-netty-timeout-bug:3.4.19]
at com.acme.DemoApplication.lambda$onInit$0(DemoApplication.java:42) ~[spring-native-netty-timeout-bug:na]
at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:762) ~[spring-native-netty-timeout-bug:2.7.1]
at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:752) ~[spring-native-netty-timeout-bug:2.7.1]
at org.springframework.boot.SpringApplication.run(SpringApplication.java:315) ~[spring-native-netty-timeout-bug:2.7.1]
at org.springframework.boot.builder.SpringApplicationBuilder.run(SpringApplicationBuilder.java:164) ~[na:na]
at com.acme.DemoApplication.main(DemoApplication.java:37) ~[spring-native-netty-timeout-bug:na]
Caused by: io.netty.resolver.dns.DnsResolveContext$SearchDomainUnknownHostException: Failed to resolve 'httpbin.org' and search domain query for configured domains failed as well: [.]
at io.netty.resolver.dns.DnsResolveContext.finishResolve(DnsResolveContext.java:1047) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext.tryToFinishResolve(DnsResolveContext.java:1000) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext.query(DnsResolveContext.java:418) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext.access$600(DnsResolveContext.java:66) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsResolveContext$2.operationComplete(DnsResolveContext.java:467) ~[na:na]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsQueryContext.tryFailure(DnsQueryContext.java:256) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.resolver.dns.DnsQueryContext$4.run(DnsQueryContext.java:208) ~[na:na]
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:153) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) ~[spring-native-netty-timeout-bug:4.1.78.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500) ~[na:na]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[na:na]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[na:na]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[na:na]
at java.lang.Thread.run(Thread.java:833) ~[spring-native-netty-timeout-bug:na]
at com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:705) ~[spring-native-netty-timeout-bug:na]
at com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:202) ~[na:na]
Caused by: io.netty.resolver.dns.DnsNameResolverTimeoutException: [/127.0.0.53:53] query via UDP timed out after 5000 milliseconds (no stack trace available)
2022-08-22 11:36:16.834 DEBUG 2504 --- [ctor-http-nio-1] io.netty.resolver.dns.DnsNameResolver : [id: 0x7fa99b43] RECEIVED: UDP [12958: /127.0.0.53:53], DatagramDnsResponse(from: /127.0.0.53:53, to: /[0:0:0:0:0:0:0:0]:33579, 12958, QUERY(0), NoError(0), RD RA)
DefaultDnsQuestion(httpbin.org. IN A)
DefaultDnsRawRecord(httpbin.org. 59 IN A 4B)
DefaultDnsRawRecord(httpbin.org. 59 IN A 4B)
DefaultDnsRawRecord(httpbin.org. 59 IN A 4B)
DefaultDnsRawRecord(httpbin.org. 59 IN A 4B)
DefaultDnsRawRecord(OPT flags:0 udp:65494 0B)
2022-08-22 11:36:16.834 DEBUG 2504 --- [ctor-http-nio-1] io.netty.resolver.dns.DnsNameResolver : Received a DNS response with an unknown ID: UDP [[id: 0x7fa99b43]: 12958]
2022-08-22 11:36:18.844 DEBUG 2504 --- [ctor-http-nio-1] io.netty.buffer.PoolThreadCache : Freed 3 thread-local buffer(s) from thread: reactor-http-nio-1
Strange.
I'll check if this still happens with SB3 / SF6. I have a suspicion that this is caused by netty build time init.
Whats SB3 & SF6?
PS: I'll try the log options & let you know what I see in my system.
Okay. Got it. Spring Boot & Spring Framework :)
Yes, sorry, you are correct.
I think I have to restart my machine. Binary is working now :D
Something has changed in system state that made this executable run without errors now. I'll restart and let you know what I see.
I get same error after system restart. I have attached the log for
spring-native-netty-timeout-bug --logging.level.io.netty=TRACE
Strangely, now same executable is running without exception (I dint restart since I shared last log). Not sure if browser/some other application changed system state in ways that make this error go away.
Here is the new log.
I dint access httpbin.org in browser/thru any other mechanism (I dint run the jar version aswell). So, the issue is most likely not related to domain resolution but something to do with the System state that netty/webflux is relying on.
It looks like there are some hints missing in Netty which lead to the DNS response being dropped. I saw something similar with Redis. There's quite some work going on related to Netty and SB3 / SF6. We can backport the fix when we have a working solution.
Sure. Thanks.
Couple of qns
Thanks for the prompt responses.
What you can do to get this running: attach the native-image agent to your application, run it in JVM mode and try if those captured hints fix the problem until we have found the root cause.
Thanks. Will try.
@thekalinga did you find out which hints are needed? I'm having the same issue
Currently using 0.11.5 with spring boot 2.6.7 instead of 0.12.1 with 2.7.1 seems to bypass the issue
It's a variation of this bug: https://github.com/oracle/graal/issues/4809
There are hints for Netty handlers missing. Run your application with the native-image agent attached and look in the JSON for ChannelHandler
classes. These are the classes Netty uses in their pipeline for your use case (i think they even depend on your operating system, but not sure). You can then use those classes to add @TypeHint
in your code.
@steincodabox Sorry. No, not yet. I havent yet tried (it requires a decent amount of trial & error) as I am stuck with some other work.
If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.
Shouldnt this issue be kept open till oracle fixed the issue from their end & netty + spring + graalvm integration works without issues?
The related issue has been fixed in GraalVM 22.3.0 which will be used as of Spring Boot 3 RC1, so please test with Spring Boot 3 RC1 + GraalVM 22.3.0 once available. If you still face an issue with those, please create an issue on https://github.com/spring-projects/spring-boot/issues.
Currently using 0.11.5 with spring boot 2.6.7 instead of 0.12.1 with 2.7.1 seems to bypass the issue
This saved my day
I am seeing a strange issue with native image when using webclient. Its consistently happening in my system
When I run same program with jar, I get following output
I see this consistently happening after I restart the system. The binary doesnt work even after multiple runs. I even tried running it after I ran jar version on JVM (to see if DNS resolution at OS level caused this issue — my uneducated guess work as I am not sure if netty does DNS resolution by itself/delegates to OS :D). But it ran successfully when I created the image initally using
./gradlew nativeCompile
before I restarted the system.Version info
Ubuntu 20.04.4 LTS
22.2.r17-grl