[JAVA-4210] MongoDb returns message length larger than the max message length Created: 27/Jun/21  Updated: 15/Mar/23  Resolved: 15/Sep/21

Status: Closed
Project: Java Driver
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: 运军 蒋 Assignee: Valentin Kavalenka
Resolution: Won't Do Votes: 0
Labels: external-user
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File error_0.log     Text File error_1.log     Text File error_2.log     Text File first_error.log     File mongodb-driver-core-4.0.5-JAVA-4210.jar     File mongodb-driver-core-4.0.5-dddab108d.jar    
Issue Links:
Cloners
is cloned by JAVA-4387 MongoDb returns message length larger... Closed
Issue split
split to JAVA-4294 InternalStreamConnection must close i... Closed
Related
related to JAVA-4122 Getting Exceptions when CPU starving ... Closed
related to JAVA-3061 Re-enable check for requestId matchin... Closed
Case:
Documentation Changes: Not Needed

 Description   

Hi guys,

We are facing an issue that happened several times a day.  Our java driver version is 4.0.5 and Mongo DB version is 4.0.9. We have 2 routers and several nodes. And we are using reactive stream.  This issue only happens in our production env. It usually first occurred while MongodbHealthIndicator checking the connections with mongo db. Please see the stacktrace as below:

org.springframework.dao.InvalidDataAccessResourceUsageException: The reply message length 1013281644 is greater than the maximum message length 48000000; nested exception is com.mongodb.MongoInternalException: The reply message length 1013281644 is greater than the maximum message length 48000000org.springframework.dao.InvalidDataAccessResourceUsageException: The reply message length 1013281644 is greater than the maximum message length 48000000; nested exception is com.mongodb.MongoInternalException: The reply message length 1013281644 is greater than the maximum message length 48000000 at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92) Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Error has been observed at the following site(s): |_ checkpoint ⇢ com.active.platform.modules.pos.service.config.ContextFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.authorization.AuthorizationWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.authorization.ExceptionTranslationWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.authentication.logout.LogoutWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.savedrequest.ServerRequestCacheWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.context.SecurityContextServerWebExchangeWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.authentication.AuthenticationWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.context.ReactorContextWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.header.HttpHeaderWriterWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.config.web.server.ServerHttpSecurity$ServerWebExchangeReactorContextWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.security.web.server.WebFilterChainProxy [DefaultWebFilterChain] |_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilterChain] |_ checkpoint ⇢ HTTP GET "/agencies/f953b9de-2260-4833-bf32-d7be2a9ae945/catalogs" [ExceptionHandlingWebHandler]Stack trace: at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92) at org.springframework.data.mongodb.core.ReactiveMongoTemplate.potentiallyConvertRuntimeException(ReactiveMongoTemplate.java:2814) at org.springframework.data.mongodb.core.ReactiveMongoTemplate.lambda$translateException$90(ReactiveMongoTemplate.java:2797) at reactor.core.publisher.Mono.lambda$onErrorMap$30(Mono.java:3286) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:88) at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:185) at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:251) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onError(MonoFlatMap.java:165) at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:87) at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:87) at com.mongodb.reactivestreams.client.internal.AbstractSubscription.onError(AbstractSubscription.java:142) at com.mongodb.reactivestreams.client.internal.SingleResultCallbackSubscription.lambda$requestInitialData$0(SingleResultCallbackSubscription.java:41) at com.mongodb.internal.async.client.AsyncFindIterableImpl$1.onResult(AsyncFindIterableImpl.java:188) at com.mongodb.internal.async.client.AsyncFindIterableImpl$1.onResult(AsyncFindIterableImpl.java:184) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48) at com.mongodb.internal.async.client.OperationExecutorImpl$1$1$1.onResult(OperationExecutorImpl.java:92) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48) at com.mongodb.internal.operation.FindOperation$3.onResult(FindOperation.java:724) at com.mongodb.internal.operation.OperationHelper$ReferenceCountedReleasingWrappedCallback.onResult(OperationHelper.java:411) at com.mongodb.internal.operation.CommandOperationHelper$10.checkRetryableException(CommandOperationHelper.java:493) at com.mongodb.internal.operation.CommandOperationHelper$10.onResult(CommandOperationHelper.java:478) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48) at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor$2.onResult(DefaultServer.java:248) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48) at com.mongodb.internal.connection.CommandProtocolImpl$1.onResult(CommandProtocolImpl.java:82) at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:517) at com.mongodb.internal.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:111) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48) at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:380) at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:375) at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:635) at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618) at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513) at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510) at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232) at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510) at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75) at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375) at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48) at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467) at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464) at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187) at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604) at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104) at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48) at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717) at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272) at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352) at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414) at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354) at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898) at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372) at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750) at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765) at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) 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.lang.Thread.run(Thread.java:748)Caused by: com.mongodb.MongoInternalException: The reply message length 1013281644 is greater than the maximum message length 48000000 at com.mongodb.internal.connection.MessageHeader.<init>(MessageHeader.java:41) at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:632) at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618) at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513) at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510) at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232) at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510) at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75) at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375) at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364) at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48) at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467) at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464) at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187) at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604) at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104) at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48) at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717) at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272) at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352) at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414) at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934) at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354) at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898) at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372) at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750) at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765) at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) 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.lang.Thread.run(Thread.java:748)

 
After about 20+ times of this error(the reply message length is different every time). The error will become

 
The responseTo (2342443) in the response does not match the requestId (2342522) in the request

*The responseTo is always smaller than the request id *

The full stack trace is

org.springframework.dao.InvalidDataAccessResourceUsageException: The responseTo (2342443) in the response does not match the requestId (2342522) in the request; nested exception is com.mongodb.MongoInternalException: The responseTo (2342443) in the response does not match the requestId (2342522) in the request
	at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
	|_ checkpoint ⇢ com.active.platform.modules.pos.service.config.ContextFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.authorization.AuthorizationWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.authorization.ExceptionTranslationWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.authentication.logout.LogoutWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.savedrequest.ServerRequestCacheWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.context.SecurityContextServerWebExchangeWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.authentication.AuthenticationWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.context.ReactorContextWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.header.HttpHeaderWriterWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.config.web.server.ServerHttpSecurity$ServerWebExchangeReactorContextWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.security.web.server.WebFilterChainProxy [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ HTTP POST "/agencies/3c91bc7d-2581-46b8-ac39-9b46cdbb7bc4/catalogs" [ExceptionHandlingWebHandler]
Stack trace:
		at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92)
		at org.springframework.data.mongodb.core.ReactiveMongoTemplate.potentiallyConvertRuntimeException(ReactiveMongoTemplate.java:2814)
		at org.springframework.data.mongodb.core.ReactiveMongoTemplate.lambda$translateException$90(ReactiveMongoTemplate.java:2797)
		at reactor.core.publisher.Mono.lambda$onErrorMap$30(Mono.java:3286)
		at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:88)
		at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondError(MonoFlatMap.java:185)
		at reactor.core.publisher.MonoFlatMap$FlatMapInner.onError(MonoFlatMap.java:251)
		at reactor.core.publisher.MonoFlatMap$FlatMapMain.onError(MonoFlatMap.java:165)
		at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:87)
		at reactor.core.publisher.MonoNext$NextSubscriber.onError(MonoNext.java:87)
		at com.mongodb.reactivestreams.client.internal.AbstractSubscription.onError(AbstractSubscription.java:142)
		at com.mongodb.reactivestreams.client.internal.SingleResultCallbackSubscription.lambda$requestInitialData$0(SingleResultCallbackSubscription.java:41)
		at com.mongodb.internal.async.client.AsyncFindIterableImpl$1.onResult(AsyncFindIterableImpl.java:188)
		at com.mongodb.internal.async.client.AsyncFindIterableImpl$1.onResult(AsyncFindIterableImpl.java:184)
		at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
		at com.mongodb.internal.async.client.OperationExecutorImpl$1$1$1.onResult(OperationExecutorImpl.java:92)
		at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
		at com.mongodb.internal.operation.FindOperation$3.onResult(FindOperation.java:724)
		at com.mongodb.internal.operation.OperationHelper$ReferenceCountedReleasingWrappedCallback.onResult(OperationHelper.java:411)
		at com.mongodb.internal.operation.CommandOperationHelper$10.checkRetryableException(CommandOperationHelper.java:493)
		at com.mongodb.internal.operation.CommandOperationHelper$10.onResult(CommandOperationHelper.java:478)
		at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
		at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor$2.onResult(DefaultServer.java:248)
		at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
		at com.mongodb.internal.connection.CommandProtocolImpl$1.onResult(CommandProtocolImpl.java:82)
		at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:517)
		at com.mongodb.internal.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:111)
		at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
		at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:400)
		at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:375)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:676)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:643)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
		at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
		at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
		at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:633)
		at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
		at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
		at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
		at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
		at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
		at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375)
		at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364)
		at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
		at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467)
		at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464)
		at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187)
		at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181)
		at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
		at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551)
		at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
		at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)
		at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604)
		at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
		at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
		at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717)
		at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272)
		at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352)
		at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414)
		at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934)
		at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
		at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898)
		at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372)
		at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
		at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
		at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071)
		at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
		at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
		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.lang.Thread.run(Thread.java:748)
Caused by: com.mongodb.MongoInternalException: The responseTo (2342443) in the response does not match the requestId (2342522) in the request
	at com.mongodb.internal.connection.ReplyMessage.<init>(ReplyMessage.java:65)
	at com.mongodb.internal.connection.ReplyMessage.<init>(ReplyMessage.java:43)
	at com.mongodb.internal.connection.ResponseBuffers.getResponseDocument(ResponseBuffers.java:47)
	at com.mongodb.internal.connection.LoggingCommandEventSender.sendSucceededEvent(LoggingCommandEventSender.java:141)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:395)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:676)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:643)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:633)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
	at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
	at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717)
	at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272)
	at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352)
	at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
	at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	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.lang.Thread.run(Thread.java:748)

I investigated the related source code, I guess that when the first error happened. It seems that mongo has replied an unknown message to the driver. When the driver decode the message follow the wire protocol, it found that the message length is too big(reading the first 16 bytes from the stream) and throw an exception then ignored the rest bytes. The following requests will keep doing the same until meeting the first correct reply message but the responseTo in the reply message will be smaller than the current request id.

I can't reproduce this on my laptop. I'm wondering why the driver needs to check the message size or the responseTo is matching the request id. Is there a concern regarding this? Why not check if the reply message is matching the wire protocol?
I guess this issue is more likely a network issue or protocol issue. Could you advise me on how to find the root cause?



 Comments   
Comment by 运军 蒋 [ 22/Sep/21 ]

Hi, Valentin Kavalenka,

Thanks for your effort on this. Just want you to know that I have done another two experiment to see how our service will behave.

  1. Using non-reactive driver instead of reactive-stream. No such error was raised.
  2. Force the driver using AsynchronousChannelStream instead of NettyStream. We still met the same error.

I also captured the packages to find out the corruptions, but I failed to find any corrupted packages in Wireshark. Wireshark can identify all the packages send from Mongodb to our service are valid mongo wire protocol ones.

Both the NettyStream and AsynchronousChannelStream are back by JDK NIO. I don't know if NeuVector is just a trigger that caused this error. Now we do have a workaround if the NeuVector team identifies that this is not an issue from their side.

I understand nothing that MongoDB driver could do to help this. Just want you to know about this in case other Mongo users meet the same issue.

Comment by Valentin Kavalenka [ 15/Sep/21 ]

Hi, gloojiang86@gmail.com

Enabling TLS in the MongoDB driver will allow to detect corruption of the data coming from a TCP socket earlier. This means you will start seeing errors different from those you are currently observing, and will probably not have a situation when the driver sometimes attempts to use a TCP connection after failing to read from it (it is still the case in 4.0.5, but is fixed in 4.4.0). However, this will not hide the errors caused by the data corruption from your application, which means it is not a workaround.

I am closing this report as "declined" because the evidence suggests the driver is not the culprit.

Comment by 运军 蒋 [ 15/Sep/21 ]

We are seeking help from NeuVector team. But I'm still thinking is there a workaround as we can't rely on NeuVector to fix this in a short period of time? Can we enable TLS to avoid message corruption?

Comment by Valentin Kavalenka [ 02/Sep/21 ]

Hi gloojiang86@gmail.com,

Thanks for conducting the experiment one more time. From the data gathered I can see, that you are not using TLS, and the junk header appears to be actually coming from a TCP stream as opposed to be a result of the driver reading from an incorrect position in a TCP stream. Here are highlights from the combined history (the history of TCP stream operations combined with the history of higher-level operations) captured in first_error.log:

// begin reading from a TCP stream
504:OperationEvent{mode=a, code=READ, type=B, attachments=[a{IoData{successReads=167, successReadBytes=1190278, msgHeaders=84, msgHeaderMessageLengthBytes=1205875, failReads=0, failReadBytes=0, startNegativeReads=0, failNegativeReads=0, successWrites=84, failWrites=0}}]},
// successfully decoded the read message header
240:OperationEvent{mode=u, code=DECODE_MESSAGE_HEADER, type=S, attachments=[a{StreamReadPosition{successReadBytes=1190278, msgHeaderMessageLengthBytes=1205875}}, a{MessageHeader{messageLength=15613, requestId=7636948, responseTo=2869, opCode=2013}}]},
...
 
// begin reading from a TCP stream
510:OperationEvent{mode=a, code=READ, type=B, attachments=[a{IoData{successReads=169, successReadBytes=1205891, msgHeaders=85, msgHeaderMessageLengthBytes=1221633, failReads=0, failReadBytes=0, startNegativeReads=0, failNegativeReads=0, successWrites=85, failWrites=0}}]},
// successfully decoded the read message header
243:OperationEvent{mode=u, code=DECODE_MESSAGE_HEADER, type=S, attachments=[a{StreamReadPosition{successReadBytes=1205891, msgHeaderMessageLengthBytes=1221633}}, a{MessageHeader{messageLength=15758, requestId=7636954, responseTo=2871, opCode=2013}}]},
...
 
// no corresponding "begin reading from a TCP stream" event in the history because the recorded history size is limited
// failed to decode the read message header, `messageLength` is too large
246:OperationEvent{mode=u, code=DECODE_MESSAGE_HEADER, type=F, attachments=[a{StreamReadPosition{successReadBytes=1221649, msgHeaderMessageLengthBytes=1221633}}, a{MessageHeader{messageLength=1449487458, requestId=1634300513, responseTo=1852795252, opCode=1530536563}}, a{threadName=nioEventLoopGroup-3-2}, a{com.mongodb.internal.connection.debug.MongoDebuggingException: Detected an invalid reply message header MessageHeader{messageLength=1449487458, requestId=1634300513, responseTo=1852795252, opCode=1530536563}

In this history we can see that the first captured message header was read after reading 1190278 bytes from the TCP stream. It specifies message length of 15613 bytes, which includes the length of the header itself. This means that the next header is expected to be read after reading 1190278 + 15613 = 1205891 bytes, and this matches what we see for the second captured DECODE_MESSAGE_HEADER event. The second header specifies message length of 15758 bytes, hence the next (third) header must be read after reading 1205891 + 15758 = 1221649 bytes, which is exactly what we see in the history. I.e., the driver did read the third captured header from the right position in the TCP stream, but it contains junk in all four of its 4-byte fields:

MessageHeader{messageLength=1449487458, requestId=1634300513, responseTo=1852795252, opCode=1530536563}

Taking the above analysis and your observation about Neuvector into account, I do not see a reason to think that the problem is in the driver. The problem is likely caused by something, e.g., Neuvector, which I am not familiar with, that corrupts inbound TCP data.

I will merge the fix of a bug when the driver does not close a TCP connection is some cases when failing to read from it, that was discovered earlier. Other than this, it does not seem like there is something else to do in the driver with regard to the problem.

You may want to contact the Neuvector's support. Additionally, enabling TLS in the Java driver should detect situations when inbound TCP data is corrupted, i.e., it may be used to further confirm the hypothesis.

Comment by 运军 蒋 [ 31/Aug/21 ]

Here is the first error log using the updated driver first_error.log
Meanwhile, our services are running in k8s and we choose Neuvector to secure our containers. Recently we found that this error will only occur when our Neuvector mode is PROTECT. When we switch the Neuvector mode to DISCOVER or MONITOR no error will raise.

Comment by Valentin Kavalenka [ 27/Aug/21 ]

Hi gloojiang86@gmail.com,

Thank you for the attached log messages. They all belong to different TCP connections. error_2.log helped me to identify a place where the driver does not close a connection after failing to read a negative number of bytes, i.e., the experiment has already proven to be helpful.

Of all the messages, only error_0.log corresponds to the root cause problem that happened while using a connection (messageSequenceNumber=1), i.e., there is no data with regard to what was the root cause for problems reported in error_1.log, error_2.log.

For error_0.log the root cause is reading the message header with messageLength=1936613746. The debugger records a short history of both reads from / writes to a TCP connection and corresponding driver commands. Unfortunately, I mistakenly made that history too short (it contained only two last events), which means I cannot reasonably see what the driver was doing before reading messageLength=1936613746 in error_0.log.

As a result of analyzing the data you provided, I did the following:

  1. Fixed the discovered place where the driver did not close a TCP connection after failing to read from it. For now the fix is only in the custom branch JAVA-4210_r4.0.5 from which the custom artifacts for you are built. This fix does not solve the main problem you reported, but it should reduce the number of consecutive errors you observe, because the driver now closes connections after trying to read a negative number of bytes.
  2. Increased the size of the recorded history to what it was supposed to be in the first place. Note that the overhead reported here was originally measured with the correct history size, i.e., it is still relevant. However, I then changed and mistakenly committed a smaller size.

Here is how we may proceed further:

  1. Judging from the observations we have so far, it is conceivable that you have a network interface controller (NIC) that rarely corrupts some inbound bits of data. Usually if this happens, the TCP implementation that operates on a higher level detects this by looking at the TCP checksums. However, if your OS and NIC are set up such that this work is offloaded to the NIC, then bytes corrupted by the NIC may stay unnoticed. There was a case like that in the history of MongoDB support. There are at least two ways this hypothesis may be disproved / confirmed:
    1. If you have TLS enabled in the MongoDB Java driver, then regardless of the TCP offloading, TLS should have detected the corruption, i.e., the hypothesis can be rejected.
    2. If you do not have TLS enabled, then you can try to find out whether the machines where your observe the errors have TCP offloading enabled. If yes, you may try to disable it and see if those same errors are still present.
  2. You may try to repeat the experiment with the updated custom build: dddab108d, mongodb-driver-core-4.0.5-dddab108d.jar. Maybe seeing larger history with the new build will result in another hypothesis.
    1. I understand that you provided only a subset of messages produced by the org.mongodb.driver.connection.debugger logger, probably because there were too many of them. If you decide to conduct the experiment with the new custom build, I would like to ask you to look at the messageSequenceNumber=1 parts of messages, to include the very first message per TCP connection.
Comment by 运军 蒋 [ 20/Aug/21 ]

Hi Valentin, we have applied this driver to our production env and collect 3 types of error logs.
error_0.log error_1.log
The above two logs show that the driver received junk messages.

After several these logs, the debugger logs the 3rd type of log.
error_2.log

Hopes these logs could help.

Comment by 运军 蒋 [ 09/Aug/21 ]

We'll use this version to do the debugging and upload the logs.

Comment by Valentin Kavalenka [ 06/Aug/21 ]

Hi gloojiang86@gmail.com,

Thank you for your willingness to help us by collecting additional data. mongodb-driver-core-4.0.5-JAVA-4210.jar is a drop-in replacement for org.mongodb:mongodb-driver-core:4.0.5 that contains debugging code introduced in 2516c194a. No customization to org.mongodb:mongodb-driver-reactivestreams:4.0.5 is needed.

When you enable the debugger as specified here, you can confirm that the debugger is actually active by observing a single message "Reporting mode changed from OFF to LOG" logged by the org.mongodb.driver.connection.debugger logger.

We are interested in messages and stack traces logged by the org.mongodb.driver.connection.debugger logger, but if you are be able to provide complete driver logs, MongoDB server logs corresponding to the time intervals when errors happen, that would be even more valuable.

Comment by 运军 蒋 [ 02/Aug/21 ]

Yeah, we still use this version. We'd like to do the debugging if you can provide a custom driver build.

Comment by Valentin Kavalenka [ 29/Jul/21 ]

Hi gloojiang86@gmail.com,

I do not have a working hypothesis of what specific bug may cause the errors, you may find the details in the comment above. Having more detailed data may help with developing a hypothesis, so I wrote debugging code that gathers more data while likely having negligible overhead. Would you be willing to try using a custom driver build in the environment where the reported errors are reproducible, with the debugging code enabled to help us gather more data?

The debugging code is enabled by setting the level of the org.mongodb.driver.connection.debugger logger to DEBUG. If any of the reported errors happen with the debugger enabled, the debugger logs an ERROR-level message that contains both the additional data and the stack trace. Enabling the debugging code should not change the driver's behavior, and the exceptions you reported are still expected to be thrown.

Please note again that it is not guaranteed that the data gathered by the debugger will necessarily help us to come up with a plausible hypothesis, and that the build we will provide would not be a released version of the Java driver. If you are willing to participate, could you please confirm that you are still using org.mongodb:mongodb-driver-reactivestreams:4.0.5?

Comment by 运军 蒋 [ 29/Jul/21 ]

@Valentin Kavalenka Any good news on this?

Comment by Valentin Kavalenka [ 14/Jul/21 ]

Analysis of the data at hand

Errors

The errors

  • "message length 1953853033 is greater than the maximum message length 48000000"
  • "response does not match the requestId"
  • IllegalArgumentException: minimumReadableBytes: -1484841841 (expected: >= 0))

from this bug report and the errors

  • "IllegalArgumentException: capacity < 0: (-16 < 0)"
  • "message length 680237824 is greater than the maximum message length 48000000"
  • "Unexpected reply message opCode 50361199"

error from JAVA-4122 are manifestations of incorrect fields (messageLength, responseTo, opCode) in the standard message header, a.k.a. MsgHeader, which is represented in the code as MessageHeader. MsgHeader is never compressed, in fact, its opCode field specifies (see OP_COMPRESSED) whether the rest of the data in the response is compressed or not. Thus, I think it is safe to say that compression may be eliminated out of the equation and observing junk in MsgHeader means that we read junk from a TCP stream. Following is a list of what may cause the driver to read junk:

  • reason1: we read MsgHeader bytes from an incorrect position in the TCP stream
  • reason2: the data in the TCP stream is corrupted
  • reason3: the server sent junk

Reason 3 is unlikely as all drivers would have experienced the bug. Reason 2 is even less likely because even more people would have experienced the bug, which means it would have been likely fixed. Reason 1 is the most likely reason so far.

Other observations

Since the reporter of the current bug report uses NettyStream, and the reporter of JAVA-4122 uses AsynchronousChannelStream with AsynchronousTlsChannel from tls-channel, it is highly likely that the bug is

  1. either in the code higher in the abstraction levels than the Stream abstraction, i.e. in the InternalStreamConnection or above; this corresponds to reason 1
  2. or is lower than the Stream abstraction and Netty, tls-channel, i.e., in JDK TLS implementation, JDK TCP implementation or below; this corresponds to reason 2
  3. or on the server side; this corresponds to reason 3

The fact that both this bug report and JAVA-4122 signify that they use asynchronous driver API, and that we do not have similar bug reports when synchronous API is used, suggests that the bug may be caused by either a race condition or a data race. However, since we are aware of only two such bug reports, the sample is not representative.

Failing to come up with a working hypothesis

So far I expressed that I think reason 1 is the most likely reason of reading junk and that it is likely caused by a bug in InternalStreamConnection or above and is related to asynchronous API.

Not closing a Stream after failing to do I/O

I checked the code to make sure we always close the stream if we fail to asynchronously read from or write to it--we do. This is easy to check and I rely on the result. If we were to continue to use a stream after failing to read from it, then this would be what causes us to read MsgHeader bytes from an incorrect position in the TCP stream (reason 1). However, now I can remove this possibility from the equation.

Reading concurrently from the same Stream

Another way to read MsgHeader bytes from an incorrect position in the TCP stream is to have more than one outstanding read operation on the same Stream. Stream.readAsync is a stateful operation, and multiple outstanding read operations may (and most likely will) corrupt each other's state unless the implementation does preventive checks and rejects to initiate multiple outstanding operations.

Neither NettyStream nor AsynchronousChannelStream has such checks (neither in r4.0.5 nor in the current master), which makes multiple outstanding read operations possible. However, AsynchronousChannelStream further delegates the operation to either AsynchronousSocketChannel (JDK) or AsynchronousTlsChannel (tls-channel). AsynchronousSocketChannel.read throws ReadPendingException if a read operation is already in progress on the channel. So if the driver indeed sometimes does concurrent reads on the same Stream, users that use AsynchronousSocketChannel should sometimes observe ReadPendingException, yet it has never been reported. Also, since AsynchronousTlsChannel is used in JAVA-4122, I would expect to see ReadPendingException there instead of the exceptions that are provided, but this is also not the case.

However much I would like this hypothesis to be plausible, it does not fit the data we have.

Introducing a mechanism to gather more data

It is difficult to gather useful data when there is no hypothesis one would like to check. As a result, the additional data we gather may help getting new ideas and coming up with a plausible hypothesis that we then may have to check by gathering more data, now with the hypothesis in mind. I.e., this may result in a multi-step investigation process, and does not guarantee a successful outcome.

Comment by 运军 蒋 [ 29/Jun/21 ]

I copy the log from our Kibana.
The max message error related log is as below:

{"@timestamp":"2021-06-28T07:41:25.923Z","@version":"1","message":"Mongo health check failed","logger":"o.s.b.a.m.MongoReactiveHealthIndicator","thread":"nioEventLoopGroup-3-1","level":"WARN","levelVal":30000,"stacktrace":"org.springframework.dao.InvalidDataAccessResourceUsageException: The reply message length 1953853033 is greater than the maximum message length 48000000; nested exception is com.mongodb.MongoInternalException: The reply message length 1953853033 is greater than the maximum message length 48000000
	at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.potentiallyConvertRuntimeException(ReactiveMongoTemplate.java:2814)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.lambda$translateException$90(ReactiveMongoTemplate.java:2797)
	at reactor.core.publisher.Flux.lambda$onErrorMap$28(Flux.java:6504)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:88)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onError(MonoFlatMapMany.java:247)
	at com.mongodb.reactivestreams.client.internal.AbstractSubscription.onError(AbstractSubscription.java:142)
	at com.mongodb.reactivestreams.client.internal.SingleResultCallbackSubscription.lambda$requestInitialData$0(SingleResultCallbackSubscription.java:41)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.async.client.OperationExecutorImpl$1$1$1.onResult(OperationExecutorImpl.java:92)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.operation.OperationHelper$ReferenceCountedReleasingWrappedCallback.onResult(OperationHelper.java:411)
	at com.mongodb.internal.operation.CommandOperationHelper$10.checkRetryableException(CommandOperationHelper.java:493)
	at com.mongodb.internal.operation.CommandOperationHelper$10.onResult(CommandOperationHelper.java:478)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor$2.onResult(DefaultServer.java:248)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.CommandProtocolImpl$1.onResult(CommandProtocolImpl.java:82)
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:517)
	at com.mongodb.internal.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:111)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:380)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:635)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
	at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
	at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717)
	at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272)
	at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352)
	at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
	at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	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.lang.Thread.run(Thread.java:748)\nCaused by: com.mongodb.MongoInternalException: The reply message length 1953853033 is greater than the maximum message length 48000000
	at com.mongodb.internal.connection.MessageHeader.<init>(MessageHeader.java:41)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:632)
	... 38 common frames omitted\n","pid":"6"}

The request id not matching error log is:

{"@timestamp":"2021-06-28T07:46:02.868Z","@version":"1","message":"Mongo health check failed","logger":"o.s.b.a.m.MongoReactiveHealthIndicator","thread":"nioEventLoopGroup-3-2","level":"WARN","levelVal":30000,"stacktrace":"org.springframework.dao.InvalidDataAccessResourceUsageException: The responseTo (1448) in the response does not match the requestId (1547) in the request; nested exception is com.mongodb.MongoInternalException: The responseTo (1448) in the response does not match the requestId (1547) in the request
	at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.potentiallyConvertRuntimeException(ReactiveMongoTemplate.java:2814)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.lambda$translateException$90(ReactiveMongoTemplate.java:2797)
	at reactor.core.publisher.Flux.lambda$onErrorMap$28(Flux.java:6504)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:88)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onError(MonoFlatMapMany.java:247)
	at com.mongodb.reactivestreams.client.internal.AbstractSubscription.onError(AbstractSubscription.java:142)
	at com.mongodb.reactivestreams.client.internal.SingleResultCallbackSubscription.lambda$requestInitialData$0(SingleResultCallbackSubscription.java:41)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.async.client.OperationExecutorImpl$1$1$1.onResult(OperationExecutorImpl.java:92)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.operation.OperationHelper$ReferenceCountedReleasingWrappedCallback.onResult(OperationHelper.java:411)
	at com.mongodb.internal.operation.CommandOperationHelper$10.checkRetryableException(CommandOperationHelper.java:493)
	at com.mongodb.internal.operation.CommandOperationHelper$10.onResult(CommandOperationHelper.java:478)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor$2.onResult(DefaultServer.java:248)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.CommandProtocolImpl$1.onResult(CommandProtocolImpl.java:82)
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:517)
	at com.mongodb.internal.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:111)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:400)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:676)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:643)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:633)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
	at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
	at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717)
	at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272)
	at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352)
	at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
	at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	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.lang.Thread.run(Thread.java:748)\nCaused by: com.mongodb.MongoInternalException: The responseTo (1448) in the response does not match the requestId (1547) in the request
	at com.mongodb.internal.connection.ReplyMessage.<init>(ReplyMessage.java:65)
	at com.mongodb.internal.connection.ReplyMessage.<init>(ReplyMessage.java:43)
	at com.mongodb.internal.connection.ResponseBuffers.getResponseDocument(ResponseBuffers.java:47)
	at com.mongodb.internal.connection.LoggingCommandEventSender.sendSucceededEvent(LoggingCommandEventSender.java:141)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:395)
	... 47 common frames omitted\n","pid":"6"}

The minimumReadableBytes error log is as below:

{"@timestamp":"2021-06-28T07:41:55.897Z","@version":"1","message":"Mongo health check failed","logger":"o.s.b.a.m.MongoReactiveHealthIndicator","thread":"nioEventLoopGroup-3-1","level":"WARN","levelVal":30000,"stacktrace":"org.springframework.dao.InvalidDataAccessResourceUsageException: Unexpected runtime exception; nested exception is com.mongodb.MongoInternalException: Unexpected runtime exception
	at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.potentiallyConvertRuntimeException(ReactiveMongoTemplate.java:2814)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.lambda$translateException$90(ReactiveMongoTemplate.java:2797)
	at reactor.core.publisher.Flux.lambda$onErrorMap$28(Flux.java:6504)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:88)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onError(MonoFlatMapMany.java:247)
	at com.mongodb.reactivestreams.client.internal.AbstractSubscription.onError(AbstractSubscription.java:142)
	at com.mongodb.reactivestreams.client.internal.SingleResultCallbackSubscription.lambda$requestInitialData$0(SingleResultCallbackSubscription.java:41)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.async.client.OperationExecutorImpl$1$1$1.onResult(OperationExecutorImpl.java:92)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.operation.OperationHelper$ReferenceCountedReleasingWrappedCallback.onResult(OperationHelper.java:411)
	at com.mongodb.internal.operation.CommandOperationHelper$10.checkRetryableException(CommandOperationHelper.java:493)
	at com.mongodb.internal.operation.CommandOperationHelper$10.onResult(CommandOperationHelper.java:478)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor$2.onResult(DefaultServer.java:248)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.CommandProtocolImpl$1.onResult(CommandProtocolImpl.java:82)
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:517)
	at com.mongodb.internal.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:111)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:380)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:653)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:643)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:523)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:633)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
	at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
	at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717)
	at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272)
	at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352)
	at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
	at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	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.lang.Thread.run(Thread.java:748)\nCaused by: com.mongodb.MongoInternalException: Unexpected runtime exception
	at com.mongodb.internal.connection.InternalStreamConnection.translateReadException(InternalStreamConnection.java:570)
	... 41 common frames omitted\nCaused by: java.lang.IllegalArgumentException: minimumReadableBytes: -1484841841 (expected: >= 0)
	at io.netty.util.internal.ObjectUtil.checkPositiveOrZero(ObjectUtil.java:66)
	at io.netty.buffer.AbstractByteBuf.checkReadableBytes(AbstractByteBuf.java:1464)
	at io.netty.buffer.AbstractByteBuf.readSlice(AbstractByteBuf.java:881)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:214)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	... 40 common frames omitted\n","pid":"6"}

These errors throw every day by the MongoReactiveHealthIndicator. Since we haven't had much production traffic, rarely customers will meet the 500 error on our website or IOS app. Our pod will restart after detecting this error consecutively three times.

Hope these logs can help.
BTW, the log format is JSON. But the display in jira is wired.

Comment by 运军 蒋 [ 29/Jun/21 ]

I found another error related to this:

org.springframework.dao.InvalidDataAccessResourceUsageException: Unexpected runtime exception; nested exception is com.mongodb.MongoInternalException: Unexpected runtime exception
	at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:92)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.potentiallyConvertRuntimeException(ReactiveMongoTemplate.java:2814)
	at org.springframework.data.mongodb.core.ReactiveMongoTemplate.lambda$translateException$90(ReactiveMongoTemplate.java:2797)
	at reactor.core.publisher.Flux.lambda$onErrorMap$28(Flux.java:6504)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:88)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onError(MonoFlatMapMany.java:247)
	at com.mongodb.reactivestreams.client.internal.AbstractSubscription.onError(AbstractSubscription.java:142)
	at com.mongodb.reactivestreams.client.internal.SingleResultCallbackSubscription.lambda$requestInitialData$0(SingleResultCallbackSubscription.java:41)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.async.client.OperationExecutorImpl$1$1$1.onResult(OperationExecutorImpl.java:92)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.operation.OperationHelper$ReferenceCountedReleasingWrappedCallback.onResult(OperationHelper.java:411)
	at com.mongodb.internal.operation.CommandOperationHelper$10.checkRetryableException(CommandOperationHelper.java:493)
	at com.mongodb.internal.operation.CommandOperationHelper$10.onResult(CommandOperationHelper.java:478)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor$2.onResult(DefaultServer.java:248)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.CommandProtocolImpl$1.onResult(CommandProtocolImpl.java:82)
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection$2.onResult(DefaultConnectionPool.java:517)
	at com.mongodb.internal.connection.UsageTrackingInternalConnection$2.onResult(UsageTrackingInternalConnection.java:111)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:380)
	at com.mongodb.internal.connection.InternalStreamConnection$2$1.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:653)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:643)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:523)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:633)
	at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback.onResult(InternalStreamConnection.java:618)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:513)
	at com.mongodb.internal.connection.InternalStreamConnection$5.completed(InternalStreamConnection.java:510)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:232)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	at com.mongodb.internal.connection.InternalStreamConnection.access$1000(InternalStreamConnection.java:75)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:375)
	at com.mongodb.internal.connection.InternalStreamConnection$2.onResult(InternalStreamConnection.java:364)
	at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:48)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:467)
	at com.mongodb.internal.connection.InternalStreamConnection$3.completed(InternalStreamConnection.java:464)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:187)
	at com.mongodb.connection.netty.NettyStream$2.operationComplete(NettyStream.java:181)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604)
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
	at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
	at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:717)
	at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:272)
	at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352)
	at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:414)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:934)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372)
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:750)
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:765)
	at io.netty.channel.AbstractChannelHandlerContext$WriteTask.run(AbstractChannelHandlerContext.java:1071)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	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.lang.Thread.run(Thread.java:748)
Caused by: com.mongodb.MongoInternalException: Unexpected runtime exception
	at com.mongodb.internal.connection.InternalStreamConnection.translateReadException(InternalStreamConnection.java:570)
	... 41 common frames omitted
Caused by: java.lang.IllegalArgumentException: minimumReadableBytes: -6 (expected: >= 0)
	at io.netty.util.internal.ObjectUtil.checkPositiveOrZero(ObjectUtil.java:66)
	at io.netty.buffer.AbstractByteBuf.checkReadableBytes(AbstractByteBuf.java:1464)
	at io.netty.buffer.AbstractByteBuf.readSlice(AbstractByteBuf.java:881)
	at com.mongodb.connection.netty.NettyStream.readAsync(NettyStream.java:214)
	at com.mongodb.internal.connection.InternalStreamConnection.readAsync(InternalStreamConnection.java:510)
	... 40 common frames omitted

I guess that when the max message length error happened, this connection will be polluted. If no more traffic on this polluted connection, this error will be thrown out when the "message length"(first 4 bytes) is lukily less than the max message length.
Hope this log will help.

Comment by Valentin Kavalenka [ 29/Jun/21 ]

Thanks for reporting this issue, gloojiang86@gmail.com. We will investigate the problem and come back to you with the findings.

Since the problem happens only in production, and you cannot reproduce it in other environments, I am guessing it is not possible to provide client logs with TRACE level. Could you please attach relevant client logs from the environment where the error is reproducible?

Generated at Thu Feb 08 09:01:30 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.