-
Type:
Bug
-
Resolution: Unresolved
-
Priority:
Major - P3
-
None
-
Affects Version/s: None
-
Component/s: None
-
None
-
Java Drivers
-
None
-
None
-
None
-
None
-
None
-
None
Summary
Since 5.6.0, AsynchronousChannelStream.BasicCompletionHandler.completed (driver-core) wraps the caller's completion handler in a new async callback for every partial read of a message. When the last partial read completes, the completion unwinds the whole chain synchronously on the async-channel-group-N-handler-executor thread.
Over the default TLS transport (TlsChannelStreamFactoryFactory / AsynchronousTlsChannel), TlsChannelImpl.read returns as soon as any decrypted bytes are available, at most one TLS record (16 KB). A large find/getMore reply (up to 16 MB) therefore needs 1000+ partial reads, accumulates 1000+ nesting levels, and all downstream work (BSON decoding, Reactive Streams onNext, BatchCursorFlux.recurseCursor issuing the next getMore) runs under those frames. With the default 1 MB thread stack the result is a StackOverflowError.
Observed in production with mongodb-driver-reactivestreams 5.6.1 and reactor-core 3.8.7 while iterating a cursor (BatchCursorFlux). Internal tracking: CLOUDP-444661.
Regression source
Introduced by commit 3c79d536 "Propagate timeout errors to callback (#1761)" (JAVA-5906), first released in 5.6.0.
5.5.0 passed the original handler straight through, so the stack depth was constant regardless of how many partial reads a message needed:
@Override public void completed(final Integer result, final Void attachment) { AsyncCompletionHandler<ByteBuf> localHandler = getHandlerAndClear(); ByteBuf localByteBuf = byteBufReference.getAndSet(null); if (result == -1) { localByteBuf.release(); localHandler.failed(new MongoSocketReadException("Prematurely reached end of stream", serverAddress)); } else if (!localByteBuf.hasRemaining()) { localByteBuf.flip(); localHandler.completed(localByteBuf); } else { getChannel().read(localByteBuf.asNIO(), operationContext.getTimeoutContext().getReadTimeoutMS(), MILLISECONDS, null, new BasicCompletionHandler(localByteBuf, operationContext, localHandler)); } }
5.6.0+ creates a new AsyncSupplier per partial read and hands the next read c.asHandler() instead of localHandler. Each level's finish(localHandler.asCallback()) is a frame that stays on the stack until the innermost read completes:
@Override public void completed(final Integer result, final Void attachment) { AsyncCompletionHandler<ByteBuf> localHandler = getHandlerAndClear(); beginAsync().<ByteBuf>thenSupply((c) -> { ByteBuf localByteBuf = byteBufReference.getAndSet(null); if (result == -1) { localByteBuf.release(); throw new MongoSocketReadException("Prematurely reached end of stream", serverAddress); } else if (!localByteBuf.hasRemaining()) { localByteBuf.flip(); c.complete(localByteBuf); } else { long readTimeoutMS = operationContext.getTimeoutContext().getReadTimeoutMS(); getChannel().read(localByteBuf.asNIO(), readTimeoutMS, MILLISECONDS, null, new BasicCompletionHandler(localByteBuf, operationContext, c.asHandler())); } }).finish(localHandler.asCallback()); }
The same code is present unchanged in r5.11.1 and on main (c.asHandler() at line 249, finish(localHandler.asCallback()) at line 251). The AsyncTrampoline added by JAVA-6120 covers thenRunDoWhileLoop only and does not touch this read path. NettyStream does not wrap the handler per read and is unaffected.
Stack trace
Frames from a production event (driver 5.6.1, reactor-core 3.8.7), innermost first. The repeating four-frame cycle is one level of the per-partial-read wrapping. The JVM's default -XX:MaxJavaStackTraceDepth=1024 truncates the outer frames, so the trace ends inside the cycle instead of at the thread's entry point.
The overflow reported here is a secondary one: reactor-core 3.8 Exceptions.throwIfFatal logs the primary StackOverflowError at WARN before rethrowing it, and the logging encoder then overflows on the already exhausted stack. The primary overflow happens somewhere in the same driver/reactor chain below.
java.lang.StackOverflowError
at net.logstash.logback.encoder.CompositeJsonEncoder.encode(CompositeJsonEncoder.java:96)
at net.logstash.logback.encoder.CompositeJsonEncoder.encode(CompositeJsonEncoder.java:36)
at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:203)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:257)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:111)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:82)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:431)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:388)
at ch.qos.logback.classic.Logger.warn(Logger.java:702)
at reactor.util.Loggers$Slf4JLogger.warn(Loggers.java:305)
at reactor.core.Exceptions.throwIfFatal(Exceptions.java:512)
at reactor.core.publisher.Operators.onOperatorError(Operators.java:756)
at reactor.core.publisher.Operators.onOperatorError(Operators.java:734)
at reactor.core.publisher.Operators.onOperatorError(Operators.java:716)
at reactor.core.publisher.MonoCreate.subscribe(MonoCreate.java:64)
at reactor.core.publisher.MonoContextWriteRestoringThreadLocals.subscribe(MonoContextWriteRestoringThreadLocals.java:44)
at reactor.core.publisher.Mono.subscribe(Mono.java:4569)
at reactor.core.publisher.Mono.subscribeWith(Mono.java:4634)
at reactor.core.publisher.Mono.subscribe(Mono.java:4535)
at reactor.core.publisher.Mono.subscribe(Mono.java:4471)
at reactor.core.publisher.Mono.subscribe(Mono.java:4443)
at com.mongodb.reactivestreams.client.internal.BatchCursorFlux.recurseCursor(BatchCursorFlux.java:89)
at com.mongodb.reactivestreams.client.internal.BatchCursorFlux.lambda$subscribe$0(BatchCursorFlux.java:59)
at reactor.core.publisher.LambdaMonoSubscriber.onNext(LambdaMonoSubscriber.java:175)
at reactor.core.publisher.MonoContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber.onNext(MonoContextWriteRestoringThreadLocals.java:111)
at reactor.core.publisher.FluxMap$MapSubscriber.onNext(FluxMap.java:122)
at reactor.core.publisher.MonoContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber.onNext(MonoContextWriteRestoringThreadLocals.java:111)
at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:83)
at reactor.core.publisher.FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber.onNext(FluxContextWriteRestoringThreadLocals.java:119)
at reactor.core.publisher.MonoFlatMap$FlatMapMain.secondComplete(MonoFlatMap.java:245)
at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:306)
at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:184)
at reactor.core.publisher.FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber.onNext(FluxContextWriteRestoringThreadLocals.java:119)
at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:177)
at com.mongodb.reactivestreams.client.internal.MongoOperationPublisher.lambda$sinkToCallback$38(MongoOperationPublisher.java:606)
at com.mongodb.reactivestreams.client.internal.OperationExecutorImpl.lambda$execute$1(OperationExecutorImpl.java:99)
at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:47)
at com.mongodb.internal.async.function.AsyncCallbackSupplier.lambda$whenComplete$1(AsyncCallbackSupplier.java:93)
at com.mongodb.internal.async.function.RetryingAsyncCallbackSupplier$RetryingCallback.onResult(RetryingAsyncCallbackSupplier.java:126)
at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:47)
at com.mongodb.internal.async.function.AsyncCallbackSupplier.lambda$whenComplete$1(AsyncCallbackSupplier.java:93)
at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:47)
at com.mongodb.internal.async.function.AsyncCallbackSupplier.lambda$whenComplete$1(AsyncCallbackSupplier.java:93)
at com.mongodb.internal.operation.AsyncOperationHelper.lambda$transformingReadCallback$21(AsyncOperationHelper.java:474)
at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:47)
at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.lambda$executeAsync$0(DefaultServer.java:247)
at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:47)
at com.mongodb.internal.connection.CommandProtocolImpl.lambda$executeAsync$0(CommandProtocolImpl.java:71)
at com.mongodb.internal.connection.UsageTrackingInternalConnection.lambda$sendAndReceiveAsync$1(UsageTrackingInternalConnection.java:139)
at com.mongodb.internal.async.ErrorHandlingResultCallback.onResult(ErrorHandlingResultCallback.java:47)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.SingleResultCallback.complete(SingleResultCallback.java:67)
at com.mongodb.internal.async.AsyncSupplier.lambda$onErrorIf$7(AsyncSupplier.java:173)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.connection.InternalStreamConnection.lambda$sendCommandMessageAsync$9(InternalStreamConnection.java:637)
at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:941)
at com.mongodb.internal.connection.InternalStreamConnection$MessageHeaderCallback$MessageCallback.onResult(InternalStreamConnection.java:904)
at com.mongodb.internal.connection.InternalStreamConnection$2.completed(InternalStreamConnection.java:738)
at com.mongodb.internal.connection.InternalStreamConnection$2.completed(InternalStreamConnection.java:735)
at com.mongodb.connection.AsyncCompletionHandler.lambda$asCallback$0(AsyncCompletionHandler.java:51)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.SingleResultCallback$1.completed(SingleResultCallback.java:49)
at com.mongodb.connection.AsyncCompletionHandler.lambda$asCallback$0(AsyncCompletionHandler.java:51)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.SingleResultCallback$1.completed(SingleResultCallback.java:49)
at com.mongodb.connection.AsyncCompletionHandler.lambda$asCallback$0(AsyncCompletionHandler.java:51)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.AsyncSupplier.lambda$finish$0(AsyncSupplier.java:73)
at com.mongodb.internal.async.SingleResultCallback$1.completed(SingleResultCallback.java:49)
... (the four-frame cycle repeats until the 1024-frame capture limit; the remaining outer frames, back to the thread's entry point, are cut off)
Reproduction
Standalone harness against the published driver jars, no MongoDB server. It drives the real AsynchronousChannelStream with a simulated AsynchronousByteChannel that delivers N bytes per read call and runs each completion in a separate queue iteration (like a real channel group). Temurin 17, -Xss512k. Arguments: total bytes, bytes per read.
| Driver | Total bytes | Bytes per read | Result |
|---|---|---|---|
| 5.6.1 | 1000 | 1 | StackOverflowError |
| 5.6.1 | 1000 | 1000 | completes, max depth 17 |
| 5.6.1 | 100 | 1 | completes, max depth 413 |
| 5.11.1 | 1000 | 1 | StackOverflowError |
| 5.11.1 | 1000 | 1000 | completes, max depth 17 |
The Netty equivalent (feeding NettyStream.handleReadResponse 10,000 one-byte fragments) completes at a constant five-frame depth.
The same effect appears against a real server whenever a reply is large relative to the TLS record size: any cursor batch of a few MB over TLS.
Expected behaviour
Stack depth of the partial-read continuation should be independent of the number of partial reads, as in 5.5.0. Either loop without wrapping the handler per read (keep passing the original handler down while still propagating timeout errors to it), or trampoline the continuation the way JAVA-6120 did for thenRunDoWhileLoop.
Workaround
- Use the Netty transport: MongoClientSettings.builder().transportSettings(TransportSettings.nettyBuilder().build()). NettyStream keeps a single pending reader with the original handler.
- Mitigations only: smaller batchSize on large scans, or a larger -Xss. Both shrink the window without closing it.
Environment
- mongodb-driver-reactivestreams / mongodb-driver-core 5.6.1
- reactor-core 3.8.7
- Amazon Corretto 17.0.20.1, default 1 MB thread stack
- Default TLS transport (TlsChannelStreamFactoryFactory)
- MongoDB Atlas
Related
JAVA-5906/ PR #1761 / commit 3c79d536: introduced the wrapping (5.6.0)JAVA-6120/ PR #1905: AsyncTrampoline for thenRunDoWhileLoop, does not cover this path- JAVA-6071 / PR #1885 (closed unmerged): bulk-write test failure with the same repeating frames while reading a large TLS response
- CLOUDP-444661: internal tracking
- is blocked by
-
-
- In Code Review
-