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
mainis in kotlin - branch
javais 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
Comment From: bclozel
@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.
Comment From: antechrestos
@bclozel it is in spring boot 3.2.1 unfortunately (see my sample project). I updated the description to tell so
Comment From: sdeleuze
@antechrestos Can you please make the project public as asked by @bclozel? I can't access it.
Comment From: antechrestos
@sdeleuze my bad. I switched it to public.
Comment From: sdeleuze
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?
Comment From: antechrestos
@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?
Comment From: antechrestos
@sdeleuze I guess you have a Mac... I saw this issue
Comment From: antechrestos
@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
Comment From: sdeleuze
Ok I can now make your sample working thanks. I am wondering if that's not a duplicate of https://github.com/micrometer-metrics/tracing/issues/174. Do you see something indicating that the issue is on Spring Framework side?
Comment From: antechrestos
@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)
Comment From: antechrestos
Should maybe try to run with SB 3.1.5 and forcing micrometer version used by SB3.2.1 :thinking: ?
Comment From: sdeleuze
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 https://github.com/micrometer-metrics/tracing/issues/243, looks and https://github.com/micrometer-metrics/tracing/issues/174. We need to move forward on Micrometer side to know what to do here I think.
Comment From: antechrestos
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.
Comment From: sdeleuze
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 https://github.com/micrometer-metrics/tracing/issues/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.
Comment From: antechrestos
@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... :thinking:
thanks anyway
Comment From: sdeleuze
@antechrestos Maybe, let's continue the discussion here.