Tracing is not working as expected in server side

[ilterpehlivan]

Hi,

I have a simple Rsocket client/server application and I am trying to pass traceId in between those services. I use spring-cloud-sleuth to generate the traceId and pass it to the next service.
When I debug, client side is passing the traceId to the service properly however in the server the traceId is not visible until "doSubscribe" event.
Here is the logs shows that until "doOnSubscribe" the traceId is not printed in the logs!

. ____ _ __ _ _
/\ / ' __ _ () __ __ _ \ \ \
( ( )__ | '_ | '| | ' / ` | \ \ \
\/ )| |)| | | | | || (| | ) ) ) )
' || .__|| ||| |_, | / / / /
=========||==============|/=////
:: Spring Boot :: (v2.2.4.RELEASE)

2020-03-17 14:08:49.138 INFO [,,,] 46809 --- [ main] o.ilt.example.rpc.server.SpringBootApp : No active profile set, falling back to default profiles: default
14:08:49.138 [main] INFO o.i.example.rpc.server.SpringBootApp - No active profile set, falling back to default profiles: default
2020-03-17 14:08:49.790 INFO [,,,] 46809 --- [ main] o.s.cloud.context.scope.GenericScope : BeanFactory id=03685ab6-08d3-3b2b-8db2-3a1215573bc2
14:08:49.790 [main] INFO o.s.cloud.context.scope.GenericScope - BeanFactory id=03685ab6-08d3-3b2b-8db2-3a1215573bc2
2020-03-17 14:08:50.071 INFO [,,,] 46809 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cloud.sleuth.instrument.web.client.TraceWebClientAutoConfiguration$NettyConfiguration' of type [org.springframework.cloud.sleuth.instrument.web.client.TraceWebClientAutoConfiguration$NettyConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
14:08:50.071 [main] INFO o.s.c.s.PostProcessorRegistrationDelegate$BeanPostProcessorChecker - Bean 'org.springframework.cloud.sleuth.instrument.web.client.TraceWebClientAutoConfiguration$NettyConfiguration' of type [org.springframework.cloud.sleuth.instrument.web.client.TraceWebClientAutoConfiguration$NettyConfiguration] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2020-03-17 14:08:50.512 INFO [,,,] 46809 --- [ main] o.ilt.example.rpc.server.SpringBootApp : Started SpringBootApp in 2.255 seconds (JVM running for 2.902)
14:08:50.512 [main] INFO o.i.example.rpc.server.SpringBootApp - Started SpringBootApp in 2.255 seconds (JVM running for 2.902)
2020-03-17 14:08:50.513 INFO [,,,] 46809 --- [ main] o.ilt.example.rpc.server.SpringBootApp : Starting the Test Service...
14:08:50.513 [main] INFO o.i.example.rpc.server.SpringBootApp - Starting the Test Service...
2020-03-17 14:09:20.379 INFO [,,,] 46809 --- [actor-tcp-nio-2] o.i.e.rpc.server.DefaultSimpleService : requestReply:span null,
14:09:20.379 [reactor-tcp-nio-2] INFO o.i.e.r.server.DefaultSimpleService - requestReply:span null,
2020-03-17 14:09:20.380 INFO [,,,] 46809 --- [actor-tcp-nio-2] o.i.e.rpc.server.DefaultSimpleService : requestReply:got message -> hello welcome example
14:09:20.380 [reactor-tcp-nio-2] INFO o.i.e.r.server.DefaultSimpleService - requestReply:got message -> hello welcome example
14:09:20.385 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - Created span [brave.opentracing.BraveSpan@4e40be5f], with name [RequestReply], child of [brave.opentracing.BraveSpanContext$Complete@6558b030]
2020-03-17 14:09:20.390 INFO [,cbd9a15dfc54197a,cbd9a15dfc54197a,false] 46809 --- [actor-tcp-nio-2] o.i.e.rpc.server.DefaultSimpleService : doOnsubscribe:org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber@4127652
14:09:20.390 [reactor-tcp-nio-2] INFO o.i.e.r.server.DefaultSimpleService - doOnsubscribe:org.springframework.cloud.sleuth.instrument.reactor.ScopePassingSpanSubscriber@4127652
14:09:20.391 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - On subscribe
14:09:20.391 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - On subscribe - span continued
14:09:20.391 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - Request
14:09:20.391 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - Request - continued
14:09:20.392 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - Request after cleaning. Current span [brave.opentracing.BraveSpan@4e40be5f]
14:09:20.406 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - Cleaning up
14:09:20.406 [reactor-tcp-nio-2] TRACE i.rsocket.rpc.tracing.SpanSubscriber - Span closed

When I look at the generated code, it looks like applying the Tracing span after executing the "requestreply" function:

return service.requestReply(io.netifi.rsocket.example.SimpleRequest.parseFrom(is), metadata).map(serializer).transform(requestReply).transform(*requestReplyTrace.apply(spanContext)
*);

and when I do the some change in the code as below, then trace works fine!

 return Mono.just(payload)
                .transform(requestReplyTrace.apply(spanContext))
                .flatMap(
                    p -> {
                      com.google.protobuf.CodedInputStream is =
                          com.google.protobuf.CodedInputStream.newInstance(payload.getData());
                      try {
                        return service.requestReply(SimpleRequest.parseFrom(is), metadata);
                      } catch (IOException e) {
                        return Mono.error(e);
                      }
                    })
                .map(serializer)
                .transform(requestReply);

Can you please help this one?

Thanks