Skip to content

Missing Trace-ID with ReactiveGridFsTemplate in Spring Boot 3.2.3 #4650

Closed as not planned
@robeatoz

Description

@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!

Metadata

Metadata

Assignees

Labels

for: external-projectFor an external project and not something we can fix

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions