IllegalStateException after read timeout

denyskonakhevych commented 1 year ago

Spring Boot Admin Server information

Version: 3.1.6
Spring Boot version: 3.1.3
Configured Security: no auth, service is not exposed outside
Webflux or Servlet application: Webflux

Client information

Spring Boot versions: 3.1.3

Used discovery mechanism: self registration

spring.boot.admin.client.url: ...
spring.boot.admin.client.instance.service-host-type: ip

Webflux or Servlet application: Servlet

Description

Following exception is observed:

[registrationTask1] WARN d.c.b.a.c.r.ApplicationRegistrator@register:91 - Failed to register application as Application(name=Agent-Registration-Handler, managementUrl=http://10.0.42.76:8081/actuator, healthUrl=http://10.0.42.76:8081/actuator/health, serviceUrl=http://10.0.42.76:8080/) at spring-boot-admin ([http://application-admin-service:80/instances]): java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 5000ms in 'flatMap' (and no fallback has been configured). Further attempts are logged on DEBUG level
[reactor-http-epoll-1] ERROR reactor.core.publisher.Operators@error:324 - Operator called default onErrorDropped
java.lang.IllegalStateException: The client response body has been released already due to cancellation.
    at org.springframework.http.client.reactive.ReactorClientHttpResponse.lambda$getBody$0(ReactorClientHttpResponse.java:117)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onSubscribe(FluxPeek.java:162)
    at reactor.core.publisher.FluxMap$MapSubscriber.onSubscribe(FluxMap.java:92)
    at reactor.netty.channel.FluxReceive.startReceiver(FluxReceive.java:170)
    at reactor.netty.channel.FluxReceive.subscribe(FluxReceive.java:145)
    at reactor.core.publisher.InternalFluxOperator.subscribe(InternalFluxOperator.java:62)
    at reactor.netty.ByteBufFlux.subscribe(ByteBufFlux.java:340)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
    at reactor.core.publisher.MonoDeferContextual.subscribe(MonoDeferContextual.java:55)
    at reactor.core.publisher.InternalMonoOperator.subscribe(InternalMonoOperator.java:64)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:165)
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
    at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onNext(FluxDoFinally.java:113)
    at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:180)
    at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
    at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onNext(FluxOnAssembly.java:539)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:200)
    at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)
    at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:200)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:200)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:200)
    at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:82)
    at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:250)
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2545)
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.request(FluxContextWrite.java:136)
    at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onSubscribeInner(MonoFlatMapMany.java:150)
    at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onSubscribe(MonoFlatMapMany.java:245)
    at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onSubscribe(FluxContextWrite.java:101)
    at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68)
    at reactor.core.publisher.Flux.subscribe(Flux.java:8773)
    at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onNext(MonoFlatMapMany.java:195)
    at reactor.core.publisher.SerializedSubscriber.onNext(SerializedSubscriber.java:99)
    at reactor.core.publisher.FluxRetryWhen$RetryWhenMainSubscriber.onNext(FluxRetryWhen.java:174)
    at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:172)
    at reactor.netty.http.client.HttpClientConnect$HttpIOHandlerObserver.onStateChange(HttpClientConnect.java:435)
    at reactor.netty.ReactorNetty$CompositeConnectionObserver.onStateChange(ReactorNetty.java:710)
    at reactor.netty.resources.DefaultPooledConnectionProvider$DisposableAcquire.onStateChange(DefaultPooledConnectionProvider.java:195)
    at reactor.netty.resources.DefaultPooledConnectionProvider$PooledConnection.onStateChange(DefaultPooledConnectionProvider.java:456)
    at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:647)
    at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:114)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
    at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:333)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:454)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
    at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
    at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:509)
    at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
    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:833)
[registrationTask1] INFO d.c.b.a.c.r.ApplicationRegistrator@register:82 - Application registered itself as 897a49352c41

But, as I understand, expected behaviour should be timeout exception

erikpetzold commented 11 months ago

Hi @denyskonakhevych

first we have some questions regarding your issue:

is there any problem besides the log message?
does it appear on a regular basis or was this just once?

This is our current understanding:

The first log message is a warning, that the registration failed due to TimeoutException. But as the client is continuing to try to register, this is just a warning, not error and the stacktrace is not logged. Also the same error will not be logged again as warning, just debug (as the message says). So there may be more failing tries.

The last log message is the successful registration.

In between, there is something trying to access a response which is aleady closed. As the connection is closed, the response is in an invalid state for the requested operation and the Exception is thrown. This probably belongs to the connection timeout. As there are no timestamps we cannot say if is belonging to the first warning or to a later try that is not logged. Anyways, in the stacktrace there is nothing from spring boot admin, so we cannot say if we are causing this and what we can do to prevent this log message.

denyskonakhevych commented 11 months ago

@erikpetzold Timestamps in logs were omitted, but it looked like there was a failed attempt to register application. It happens from time to time. We have alert mechanism that reacts on unhandled exceptions and that's the case for us

Well.. it looks like in ReactiveRegistrationClient::register you use .timeout() method from Mono but, but probably that somehow unexpected behaviour for webClient. Maybe instead timeout for http connection would be more expected behaviour?

denyskonakhevych commented 11 months ago

Added PR that should fix this issue https://github.com/codecentric/spring-boot-admin/pull/2845

codecentric / spring-boot-admin