Tracing propagation issue in kotlin webflux / mongo in SB 3.2.1 #31893

antechrestos · 2023-12-22T16:11:57Z

Since springboot 3.2 (still present in 3.2.1) there is an issue with kotlin project.

I made a sample project that illustrates very well the issue

branch main is in kotlin
branch java is the same in java

I have a typical RestController that log before calling repository and log after the repository.

Kotlin

Controller

    @PostMapping("/api/v1/users")
    @ResponseStatus(HttpStatus.CREATED)
    suspend fun createUser(@RequestBody user: CreateUserDto) : UserDto {
        logger.debug("Start save of user {}", user)
        return userRepository.create(
            User.newUser(
                firstname = user.firstname,
                name = user.name,
            )
        )
            .let { toWeb(it) }.
            also { logger.debug("Created user {}", it) }
    }

Repository

interface UserRepositoryMongoStore : CoroutineCrudRepository<DBUser, String>

@Repository
class MongoRepository(private val mongoStore: UserRepositoryMongoStore) : UserRepository {


    private val logger = LoggerFactory.getLogger(this.javaClass)

    override suspend fun create(user: User) =
        mongoStore.save(
            DBUser(
                id = user.id,
                firstname = user.firstname,
                name = user.name
            )
        )
            .let { toDomain(it) }
            .also { logger.debug("user created {}", it) }

Logs

2023-12-22T17:02:58.418+01:00 DEBUG 47890 --- [or-http-epoll-2] [5fcf6430ed59604934afc30c7a9a70f5-4e9f67bb9415a589] o.a.s.t.api.web.UserController           : Start save of user CreateUserDto(firstname=Ben, name=Einaudi)
2023-12-22T17:02:58.481+01:00 DEBUG 47890 --- [ntLoopGroup-3-3] [5fcf6430ed59604934afc30c7a9a70f5-4e9f67bb9415a589] o.a.s.t.infrastructure.MongoRepository   : user created User(id=2722442d-8701-40b5-a5e0-cade0e6a4845, firstname=Ben, name=Einaudi)
2023-12-22T17:02:58.483+01:00 DEBUG 47890 --- [ntLoopGroup-3-3] [                                                 ] o.a.s.t.api.web.UserController           : Created user UserDto(id=2722442d-8701-40b5-a5e0-cade0e6a4845, firstname=Ben, name=Einaudi)

Java

Controller

    @PostMapping("/api/v1/users")
    @ResponseStatus(HttpStatus.CREATED)
    public Mono<UserDto> createUser(@RequestBody CreateUserDto user) {
        logger.debug("Start save of user {}", user);
        return userRepository.create(
                        User.newUser(
                                user.firstname(),
                                user.name())
                ).map(this::toWeb)
                .doOnEach(userSignal -> logger.debug("Created {}", userSignal.get()));
    }

Repository

interface UserRepositoryMongoStore extends ReactiveMongoRepository<DBUser, String> {
}

@Repository
class MongoRepository implements UserRepository {

    private static final Logger logger = LoggerFactory.getLogger(MongoRepository.class);
    private final UserRepositoryMongoStore mongoStore;

    MongoRepository(UserRepositoryMongoStore mongoStore) {
        this.mongoStore = mongoStore;
    }


    @Override
    public Mono<User> create(User user) {
        return mongoStore.save(new DBUser(user.id(), user.firstname(), user.name()))
                .map(this::toDomain)
                .doOnEach(userSignal -> logger.debug("Saved {}", userSignal.get()));
    }

Logs

2023-12-22T17:01:28.631+01:00 DEBUG 47059 --- [or-http-epoll-2] [d934e14336e43c1c0a22c8909ae347ef-564b0286668d443e] o.a.s.t.api.web.UserController           : Start save of user CreateUserDto[firstname=Ben, name=Einaudi]
2023-12-22T17:01:28.674+01:00 DEBUG 47059 --- [ntLoopGroup-3-3] [d934e14336e43c1c0a22c8909ae347ef-564b0286668d443e] o.a.s.t.infrastructure.MongoRepository   : Saved User[id=008f2af1-da22-4544-a25e-fc226ee1b53a, firstname=Ben, name=Einaudi]
2023-12-22T17:01:28.675+01:00 DEBUG 47059 --- [ntLoopGroup-3-3] [d934e14336e43c1c0a22c8909ae347ef-564b0286668d443e] o.a.s.t.infrastructure.MongoRepository   : Saved null
2023-12-22T17:01:28.675+01:00 DEBUG 47059 --- [ntLoopGroup-3-3] [d934e14336e43c1c0a22c8909ae347ef-564b0286668d443e] o.a.s.t.api.web.UserController           : Created UserDto[id=008f2af1-da22-4544-a25e-fc226ee1b53a, firstname=Ben, name=Einaudi]
2023-12-22T17:01:28.675+01:00 DEBUG 47059 --- [ntLoopGroup-3-3] [d934e14336e43c1c0a22c8909ae347ef-564b0286668d443e] o.a.s.t.api.web.UserController           : Created null

Somehow the context gets process.

If there is any need of more information, I would be glad to help.

Maybe linked to #31877

The text was updated successfully, but these errors were encountered:

bclozel · 2023-12-22T16:18:20Z

@antechrestos Have you tried with Spring Boot 3.2.1, several issues have been fixed. Also the project is probably private as it's a 404 for me.

antechrestos · 2023-12-22T16:25:29Z

@bclozel it is in spring boot 3.2.1 unfortunately (see my sample project). I updated the description to tell so

sdeleuze · 2024-01-02T18:06:59Z

@antechrestos Can you please make the project public as asked by @bclozel? I can't access it.

antechrestos · 2024-01-02T18:14:56Z

@sdeleuze my bad. I switched it to public.

sdeleuze · 2024-01-02T19:55:31Z

I can now access, thanks.

I see the following error after docker compose up:

tracing-issue-mongo-1                      | /opt/bitnami/scripts/libos.sh: line 346:    48 Illegal instruction     "$@" > /dev/null 2>&1
tracing-issue-mongo-1 exited with code 132

Am I expected to customize something?

antechrestos · 2024-01-02T20:24:33Z

@sdeleuze hmm the infrastructure docker compose is here to provide mongo, otel collector, tempo and grafana.

I have no issue on Ubuntu. What is your os?
Does your os?

antechrestos · 2024-01-02T20:32:07Z

@sdeleuze I guess you have a Mac...
I saw this issue

antechrestos · 2024-01-02T22:47:57Z

@sdeleuze I've pushed one commit on each branch main (for kotlin) and java to switch to official mongo docker image . Tell me whether it is not ok on your side.
Thanks

sdeleuze · 2024-01-03T08:05:00Z

Ok I can now make your sample working thanks. I am wondering if that's not a duplicate of micrometer-metrics/tracing#174. Do you see something indicating that the issue is on Spring Framework side?

antechrestos · 2024-01-03T13:24:00Z

@sdeleuze thaht's an interesting question; I've just pushed a branch where I switch back to springboot 3.1.5 and the example works (see kotlin-sb-3.1.5)

Logs with SB 3.1.5

2024-01-03T14:18:27.015+01:00 DEBUG 12396 --- [or-http-epoll-2] [c0efbbdf416ee6dca9b71e45f71542ad|8da3557af2324cc7] o.a.s.t.api.web.UserController           : Start save of user CreateUserDto(firstname=BeN, name=Einaudi)
2024-01-03T14:18:27.059+01:00 DEBUG 12396 --- [ntLoopGroup-3-3] [c0efbbdf416ee6dca9b71e45f71542ad|8da3557af2324cc7] o.a.s.t.infrastructure.MongoRepository   : user created User(id=c6681a6b-6663-4253-9e2a-0ac72615d846, firstname=BeN, name=Einaudi)
2024-01-03T14:18:27.060+01:00 DEBUG 12396 --- [ntLoopGroup-3-3] [c0efbbdf416ee6dca9b71e45f71542ad|8da3557af2324cc7] o.a.s.t.api.web.UserController           : Created user UserDto(id=c6681a6b-6663-4253-9e2a-0ac72615d846, firstname=BeN, name=Einaudi)

antechrestos · 2024-01-03T13:25:32Z

Should maybe try to run with SB 3.1.5 and forcing micrometer version used by SB3.2.1 🤔 ?

sdeleuze · 2024-01-03T13:52:56Z

Spring Framework 6.1 now has dedicated support for Coroutine context, so Micrometer may have to adapt. I suspect it was half-working with SB 3.1, see micrometer-metrics/tracing#243, looks and micrometer-metrics/tracing#174. We need to move forward on Micrometer side to know what to do here I think.

antechrestos · 2024-01-03T16:23:02Z

It did not work in SB 3.0.0 but started to work after some versions (I don't remember which) and at somepoint I had different behaviour between brave and otel tracing...

From what I see, things are quite moving fast on both SB and micrometer and, as you pointed that Spring Framework has dedicated support for Coroutine context, we should understand what is lacking today as something new without digging too far.

In the current issue, what is funny is the logs

2024-01-03T17:13:04.468+01:00  INFO 7238 --- [or-http-epoll-2] [aad76a17bde097d9f558f856ee1f6965-64b9dff2c1d98386] o.springdoc.api.AbstractOpenApiResource  : Init duration for springdoc-openapi is: 157 ms
2024-01-03T17:13:16.739+01:00 DEBUG 7238 --- [or-http-epoll-2] [22dd6bfd108fcc6012bf3bea187464bf-d99e096a3d4f2322] o.a.s.t.api.web.UserController           : Start save of user CreateUserDto(firstname=BeN, name=Einaudi)
2024-01-03T17:13:16.747+01:00 DEBUG 7238 --- [or-http-epoll-2] [22dd6bfd108fcc6012bf3bea187464bf-d99e096a3d4f2322] o.a.s.t.infrastructure.MongoRepository   : about to create User(id=8ad9d153-9590-4ad1-bbe4-bfb41e1f8327, firstname=BeN, name=Einaudi)
2024-01-03T17:13:16.791+01:00 DEBUG 7238 --- [ntLoopGroup-3-3] [22dd6bfd108fcc6012bf3bea187464bf-d99e096a3d4f2322] o.a.s.t.infrastructure.MongoRepository   : user created User(id=8ad9d153-9590-4ad1-bbe4-bfb41e1f8327, firstname=BeN, name=Einaudi)
2024-01-03T17:13:16.792+01:00 DEBUG 7238 --- [ntLoopGroup-3-3] [                                                 ] o.a.s.t.api.web.UserController           : Created user UserDto(id=8ad9d153-9590-4ad1-bbe4-bfb41e1f8327, firstname=BeN, name=Einaudi)

We see that traceId and span id are still present after returning from CoroutineCrudRepository (the line user created..), yet it is not kept from calling methods even if we are in the same thread (ntLoopGroup-3-3)

In my case I use micrometer-tracing-bridged-otel which provides a class Slf4JEventListener (instanciated by OpenTelemetryAutoConfiguration). Turning its log to trace gives

2024-01-03T17:19:05.537+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.539+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.539+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.539+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@13d5cb8a]
2024-01-03T17:19:05.539+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.539+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@5a7f463c]
2024-01-03T17:19:05.539+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.552+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@5b776ce7]
2024-01-03T17:19:05.552+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.552+01:00 TRACE 7765 --- [         task-1] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.573+01:00 TRACE 7765 --- [         task-1] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@5c569f79]
2024-01-03T17:19:05.573+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.573+01:00 TRACE 7765 --- [         task-1] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.599+01:00 DEBUG 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] o.a.s.t.api.web.UserController           : Start save of user CreateUserDto(firstname=BeN, name=Einaudi)
2024-01-03T17:19:05.606+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.606+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.606+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@5fa54c7]
2024-01-03T17:19:05.606+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.606+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@47d4950d]
2024-01-03T17:19:05.606+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.608+01:00 DEBUG 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] o.a.s.t.infrastructure.MongoRepository   : about to create User(id=7a4e4c54-fd7e-45a8-b2ce-e49db84f974a, firstname=BeN, name=Einaudi)
2024-01-03T17:19:05.623+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.623+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.623+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@14060e1]
2024-01-03T17:19:05.624+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.624+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@5b8c87f6]
2024-01-03T17:19:05.624+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.637+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@199f1c3f]
2024-01-03T17:19:05.638+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.646+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.650+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.650+01:00 DEBUG 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] o.a.s.t.infrastructure.MongoRepository   : user created User(id=7a4e4c54-fd7e-45a8-b2ce-e49db84f974a, firstname=BeN, name=Einaudi)
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@3f346d1b]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@73d4209e]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@5ea8a97b]
2024-01-03T17:19:05.651+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.652+01:00 DEBUG 7765 --- [ntLoopGroup-3-3] [                                                 ] o.a.s.t.api.web.UserController           : Created user UserDto(id=7a4e4c54-fd7e-45a8-b2ce-e49db84f974a, firstname=BeN, name=Einaudi)
2024-01-03T17:19:05.652+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.655+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@2e51c6b3]
2024-01-03T17:19:05.655+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.655+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@ec59e5a]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@33311436]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@10255ae0]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.658+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@13e43df9]
2024-01-03T17:19:05.659+01:00 TRACE 7765 --- [ntLoopGroup-3-3] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.659+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: ScopeAttached{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=<unspecified span name>, kind=SERVER, attributes=null, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=0}] [baggage: {}]}]}]
2024-01-03T17:19:05.660+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope changed event [ScopeAttached{context: [span: null] [baggage: null]}]
2024-01-03T17:19:05.661+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@2f2732e1]
2024-01-03T17:19:05.661+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=http post /api/v1/users, kind=SERVER, attributes=AttributesMap{data={outcome=SUCCESS, status=201, uri=/api/v1/users, http.url=/api/v1/users, method=POST, exception=none}, capacity=128, totalAddedValues=6}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=1704298745660532392}] [baggage: ScopeRestored{context: [span: SdkSpan{traceId=b6ed9d448594b925a864ef0ce0932a77, spanId=12d01b118ea40d90, parentSpanContext=ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}, name=http post /api/v1/users, kind=SERVER, attributes=AttributesMap{data={outcome=SUCCESS, status=201, uri=/api/v1/users, http.url=/api/v1/users, method=POST, exception=none}, capacity=128, totalAddedValues=6}, status=ImmutableStatusData{statusCode=UNSET, description=}, totalRecordedEvents=0, totalRecordedLinks=0, startEpochNanos=1704298745533004373, endEpochNanos=1704298745660532392}] [baggage: {}]}]}]
2024-01-03T17:19:05.662+01:00 TRACE 7765 --- [or-http-epoll-2] [b6ed9d448594b925a864ef0ce0932a77-12d01b118ea40d90] i.m.t.otel.bridge.Slf4JEventListener     : Got scope closed event [io.micrometer.tracing.otel.bridge.EventPublishingContextWrapper$ScopeClosedEvent@5f0f8869]
2024-01-03T17:19:05.662+01:00 TRACE 7765 --- [or-http-epoll-2] [                                                 ] i.m.t.otel.bridge.Slf4JEventListener     : Got scope restored event [ScopeRestored{context: [span: null] [baggage: null]}]

I don't understand everything yet we see some scope closed, the changed one have no tracing info.

sdeleuze · 2024-01-04T07:11:13Z

Thanks for your feedback, everything I see here points toward a lack of proper Coroutines support in Micrometer.

Your comment related to Slf4JEventListener instantiated by OpenTelemetryAutoConfiguration is interesting. Maybe kotlinx-coroutines-slf4j should be involved one way or another for proper Coroutines support. Or maybe KotlinObservationContextElement provided in micrometer-core should be configured, either out-of-the-box or manually thanks to a dedicated Micrometer documentation.

In any case, let's continue the discussion on micrometer-metrics/tracing#174. Happy to fix what need to fixed on Spring side if you find something actionable on our side, but so far, that's not obvious.

antechrestos · 2024-01-24T07:49:23Z

@sdeleuze I still had this issue with SB 3.2.2 . Your comment about MDCComment lead to put an extra CoWebFilter such as

    @Bean
    @ConditionalOnProperty("management.tracing.enabled", havingValue = "true")
    @Order(Ordered.LOWEST_PRECEDENCE - 2)
    fun addMdcContextFilter(observationRegistry: ObservationRegistry): CoWebFilter = object : CoWebFilter() {
        override suspend fun filter(exchange: ServerWebExchange, chain: CoWebFilterChain) {
            withContext(MDCContext()) {
                chain.filter(exchange)
            }
        }
    }

and it solved my problem. I know it is not a proper solution, but it works.

I wonder when I see the code in InvocableHandlerMethod

                        if (isSuspendingFunction) {
				Object coroutineContext = exchange.getAttribute(COROUTINE_CONTEXT_ATTRIBUTE);
				if (coroutineContext == null) {
					return CoroutinesUtils.invokeSuspendingFunction(method, target, args);
				}
				else {
					return CoroutinesUtils.invokeSuspendingFunction((CoroutineContext) coroutineContext, method, target, args);
				}
			}

whether a context should not be put in attribute if it is null... 🤔

thanks anyway

sdeleuze · 2024-02-02T08:53:14Z

@antechrestos Maybe, let's continue the discussion here.

antechrestos changed the title ~~Tracing propagation issue in kotlin webglux / mongo~~ Tracing propagation issue in kotlin webflux / mongo Dec 22, 2023

spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged or decided on label Dec 22, 2023

bclozel added the status: waiting-for-feedback We need additional information before we can continue label Dec 22, 2023

antechrestos changed the title ~~Tracing propagation issue in kotlin webflux / mongo~~ Tracing propagation issue in kotlin webflux / mongo in SB 3.2.1 Dec 22, 2023

spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Dec 22, 2023

bclozel added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Dec 27, 2023

sdeleuze self-assigned this Jan 2, 2024

sdeleuze added the theme: kotlin An issue related to Kotlin support label Jan 2, 2024

spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jan 2, 2024

sdeleuze added status: waiting-for-feedback We need additional information before we can continue and removed status: feedback-provided Feedback has been provided labels Jan 2, 2024

spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Jan 2, 2024

sdeleuze mentioned this issue Jan 3, 2024

Traceid and spanid wrong when using Kotlin Reactor Coroutines micrometer-metrics/tracing#174

Open

sdeleuze mentioned this issue Jan 3, 2024

Improve the documentation and discoverability of CoWebFilter #31877

Closed

sdeleuze closed this as not planned Won't fix, can't repro, duplicate, stale Jan 4, 2024

sdeleuze added for: external-project Needs a fix in external project and removed status: waiting-for-triage An issue we've not yet triaged or decided on status: feedback-provided Feedback has been provided labels Jan 4, 2024

sdeleuze mentioned this issue Feb 2, 2024

@Scheduled task instrumentation does not work for Kotlin suspend functions #32165

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tracing propagation issue in kotlin webflux / mongo in SB 3.2.1 #31893

Tracing propagation issue in kotlin webflux / mongo in SB 3.2.1 #31893

antechrestos commented Dec 22, 2023 •

edited

Loading

bclozel commented Dec 22, 2023

antechrestos commented Dec 22, 2023

sdeleuze commented Jan 2, 2024

antechrestos commented Jan 2, 2024

sdeleuze commented Jan 2, 2024

antechrestos commented Jan 2, 2024

antechrestos commented Jan 2, 2024

antechrestos commented Jan 2, 2024

sdeleuze commented Jan 3, 2024

antechrestos commented Jan 3, 2024

antechrestos commented Jan 3, 2024

sdeleuze commented Jan 3, 2024

antechrestos commented Jan 3, 2024

sdeleuze commented Jan 4, 2024

antechrestos commented Jan 24, 2024 •

edited

Loading

sdeleuze commented Feb 2, 2024

Tracing propagation issue in kotlin webflux / mongo in SB 3.2.1 #31893

Tracing propagation issue in kotlin webflux / mongo in SB 3.2.1 #31893

Comments

antechrestos commented Dec 22, 2023 • edited Loading

Kotlin

Controller

Repository

Logs

Java

Controller

Repository

Logs

bclozel commented Dec 22, 2023

antechrestos commented Dec 22, 2023

sdeleuze commented Jan 2, 2024

antechrestos commented Jan 2, 2024

sdeleuze commented Jan 2, 2024

antechrestos commented Jan 2, 2024

antechrestos commented Jan 2, 2024

antechrestos commented Jan 2, 2024

sdeleuze commented Jan 3, 2024

antechrestos commented Jan 3, 2024

antechrestos commented Jan 3, 2024

sdeleuze commented Jan 3, 2024

antechrestos commented Jan 3, 2024

sdeleuze commented Jan 4, 2024

antechrestos commented Jan 24, 2024 • edited Loading

sdeleuze commented Feb 2, 2024

antechrestos commented Dec 22, 2023 •

edited

Loading

antechrestos commented Jan 24, 2024 •

edited

Loading