Description
Hello,
I've encountered an issue with ReactiveGridFsTemplate
in Spring Boot version 3.2.3, where the trace-ID is not being
logged as expected under certain conditions. To illustrate the problem, I've prepared a minimal example that
demonstrates the unexpected behavior: https://github.com/robeatoz/reactive-gridfs-missing-trace-id-issue
Environment:
- Java 17
- Spring Boot Version: 3.2.3
- MongoDB Version: 7.0.6 (Docker)
Issue Summary:
There are two REST endpoints in my example:
/workingTraceIdButAllElementsInMemory
logs trace-IDs as expected but requires all elements to be loaded into memory,
which is impractical for my use case due to memory limitations.
/notWorkingTraceIdButOnlyFewElementsInMemory
does not log trace-IDs but suits my memory usage requirements by only
keeping currently processing elements in memory.
Steps to Reproduce:
- Start MongoDB with Docker using the command:
docker run --rm -p "27017:27017" mongo:7.0.6
. - Launch the application
ReactiveGridFsIssueApplication
. - Access the endpoint
/workingTraceIdButAllElementsInMemory
at http://localhost:8080/workingTraceIdButAllElementsInMemory.- Observe that trace-IDs are logged for all operations, including those within the inner Flux.
2024-03-01T10:51:07.515+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] c.e.r.controller.EntityController : Starting workingTraceIdButAllElementsInMemory 2024-03-01T10:51:07.521+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | onSubscribe([Synchronous Fuseable] FluxIterable.IterableSubscription) 2024-03-01T10:51:07.521+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | request(unbounded) 2024-03-01T10:51:07.521+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | onNext(Entity(id=1)) 2024-03-01T10:51:07.522+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | onNext(Entity(id=2)) 2024-03-01T10:51:07.523+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | onNext(Entity(id=3)) 2024-03-01T10:51:07.523+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | onNext(Entity(id=4)) 2024-03-01T10:51:07.523+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | onNext(Entity(id=5)) 2024-03-01T10:51:07.523+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [reactor-http-nio-2] reactor.Flux.Stream.1 : | onComplete() 2024-03-01T10:51:07.553+01:00 INFO --- [65e1a50bc69f2d227207d92ca22aea51:7207d92ca22aea51] [nioEventLoopGroup-3-3] c.e.r.controller.EntityController : GridFS File stored: 65e1a50bb330555a2fabde12
- Observe that trace-IDs are logged for all operations, including those within the inner Flux.
- Access the endpoint
/notWorkingTraceIdButOnlyFewElementsInMemory
at http://localhost:8080/notWorkingTraceIdButOnlyFewElementsInMemory.- Note that trace-IDs are not logged for operations within the inner Flux.
2024-03-01T10:52:58.085+01:00 INFO --- [65e1a57a306b1bd4b9ff5433b7cf93fa:b9ff5433b7cf93fa] [reactor-http-nio-2] c.e.r.controller.EntityController : Starting notWorkingTraceIdButOnlyFewElementsInMemory 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | onSubscribe([Synchronous Fuseable] FluxIterable.IterableSubscription) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | request(1) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | onNext(Entity(id=1)) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | request(1) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | onNext(Entity(id=2)) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | request(1) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | onNext(Entity(id=3)) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | request(1) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | onNext(Entity(id=4)) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | request(1) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | onNext(Entity(id=5)) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | request(1) 2024-03-01T10:52:58.089+01:00 INFO --- [:] [nioEventLoopGroup-3-3] reactor.Flux.Stream.2 : | onComplete() 2024-03-01T10:52:58.092+01:00 INFO --- [65e1a57a306b1bd4b9ff5433b7cf93fa:b9ff5433b7cf93fa] [nioEventLoopGroup-3-3] c.e.r.controller.EntityController : GridFS File stored: 65e1a57ab330555a2fabde14
- Note that trace-IDs are not logged for operations within the inner Flux.
Expected Behavior:
Trace-IDs should be consistently logged across all operations, including those within inner Fluxes, to ensure effective
debugging and monitoring.
Actual Behavior:
Trace-IDs are missing from logs when using the /notWorkingTraceIdButOnlyFewElementsInMemory
endpoint, which does not
load all elements into memory.
Code Snippets:
Endpoint /workingTraceIdButAllElementsInMemory
:
@GetMapping(path = "/workingTraceIdButAllElementsInMemory")
private Mono<String> workingTraceIdButAllElementsInMemory() {
log.info("Starting workingTraceIdButAllElementsInMemory");
Mono<ObjectId> objectIdMono =
fetchLotOfEntities()
.log()
.map(this::mapToDataBuffer)
.reduce(
(dataBuffer1, dataBuffer2) -> dataBufferFactory.join(List.of(dataBuffer1, dataBuffer2))
)
.flatMap(dataBuffer -> reactiveGridFsTemplate.store(Mono.just(dataBuffer), FILE_NAME));
return objectIdMono
.doOnNext(objectId -> log.info("GridFS File stored: {}", objectId))
.flatMap(this::fetchContentOfFile);
}
Endpoint /notWorkingTraceIdButOnlyFewElementsInMemory
:
@GetMapping(path = "/notWorkingTraceIdButOnlyFewElementsInMemory")
private Mono<String> notWorkingTraceIdButOnlyFewElementsInMemory() {
log.info("Starting notWorkingTraceIdButOnlyFewElementsInMemory");
Flux<DataBuffer> dataBufferFlux =
fetchLotOfEntities()
.log()
.map(this::mapToDataBuffer);
Mono<ObjectId> objectIdMono = reactiveGridFsTemplate.store(dataBufferFlux, FILE_NAME);
return objectIdMono
.doOnNext(objectId -> log.info("GridFS File stored: {}", objectId))
.flatMap(this::fetchContentOfFile);
}
Observations:
- The
Hooks.enableAutomaticContextPropagation();
method is already invoked inReactiveGridFsIssueApplication
. - The functioning endpoint's operations predominantly run on the
reactor-http-nio-2
thread, whereas the problematic
endpoint's operations mainly execute on thenioEventLoopGroup-3-3
thread.
I am unsure whether this behavior indicates a bug or a misuse of Flux on my part. Any insights or suggestions would be
greatly appreciated.
Thank you for your assistance!