Missing Trace-ID with ReactiveGridFsTemplate in Spring Boot 3.2.3

[robeatoz]

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:

1. Start MongoDB with Docker using the command: docker run --rm -p "27017:27017" mongo:7.0.6.
2. Launch the application ReactiveGridFsIssueApplication.
3. 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
     

4. 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
     

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 in ReactiveGridFsIssueApplication.
• The functioning endpoint's operations predominantly run on the reactor-http-nio-2 thread, whereas the problematic
  endpoint's operations mainly execute on the nioEventLoopGroup-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!

[mp911de]

I think there's nothing that you can do here but rather this indicates bug in one of the involved components. Paging @rozza for visibility. I might be wrong, but I suspect a missing propagation of CoreSubscriber.currentContext().

[mp911de]

After some debugging it seems that ResizingByteBufferFlux in the driver class GridFSUploadPublisherImpl doesn't propagate the subscriber context from MonoSink.contextView() in Mono.create(sink -> …).

Without context propagation, the trace context is lost.

[robeatoz]

Thank you very much for your investigation! I have created a bug ticket to address this issue here: JAVA-5345

[rozza]

Thanks @mp911de & @robeatoz will investigate in JAVA-5345 👍