Spring-cloud-sleuth: Update WebFlux integration to leverage Brave's NettyHttpTracing

[btkelly]

Is your feature request related to a problem? Please describe.
I'm trying to leverage Logbook with Spring's WebFlux and Reactor implementation and Sleuth but the span and trace ids from Sleuth are not available to Logbook at the time it's logging the request. Logbook adds itself as a Netty handler, which I think is a smart way to do this as it's outside of all other processing. The main issue I see is when Logbook logs the incoming request it is way before Sleuth has done anything with span or trace ids and thus it does not include them in its log. The response log does properly include them as it executes after the Sleuth logic.

Describe the solution you'd like
I see that Brave has built it's own Netty handler and I would like Sleuth to leverage this and connect the Netty layer into the Reactor context so it will continue to propagate the ids.

Describe alternatives you've considered
I considered just checking for B3 headers myself in the Netty layer and if missing generating them right then and adding them to the request before it continues. I figured this would work as Sleuth would see this as span and trace ids already existing and use them. I wasn't able to get this working easily and I wasn't even sure if it would work as it might generate a new span id if it thinks it's a request from another service.

[marcingrzejszczak]

Do you have a sample that I could play with to check this instrumentation?

[spring-projects-issues]

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

[btkelly]

@marcingrzejszczak I've created a simple example app here (https://github.com/btkelly/Sleuth-Netty-Example) let me know if you need anything else added to test. Thanks for looking into this!

[marcingrzejszczak]

So @violetagg is working on fixing this in reactor netty.

[violetagg]

@btkelly @marcingrzejszczak Can you take a look at https://github.com/reactor/reactor-netty/pull/1307

[btkelly]

@violetagg It looks good and I was attempting to test it but was having trouble getting the pre release version of Reactor to sync with Gradle using the Spring dependency plugin. Have these changes been released in any of the snapshot repos or do I need to pull them down from source? Any help would be appreciated.

[violetagg]

@btkelly yes use https://repo.spring.io/snapshot/ and for reactor bom use 2020.0.0-SNAPSHOT

[btkelly]

Alright I was able to pull in the changes and test in my sample app and am still seeing the same issue but I might be configuring Netty incorrectly. Included below is how I'm configuring the newly added BraveHttpServerTracing along with the LogbookServerHandler which results in the same behavior of Logbook's logging occuring without Sleuth ids being present in the logs as shown below.

Log Output:
2020-09-30 13:11:05.281 TRACE [SleuthNettyExample,,] 36549 --- [ctor-http-nio-3] org.zalando.logbook.Logbook : Incoming Request: 9e3c787dfc9db85c

Netty Configuration:

    @Bean
    fun braveHttpServerTracing(httpTracing: HttpTracing) = BraveHttpServerTracing
        .create(httpTracing) as BraveHttpServerTracing

    @Bean
    @ConditionalOnClass(NettyServerCustomizer::class)
    fun nettyServerCustomizer(logbook: Logbook, braveHttpServerTracing: BraveHttpServerTracing): NettyServerCustomizer =
        NettyServerCustomizer { httpServer ->
            httpServer.observe(braveHttpServerTracing)
            httpServer.doOnConnection {
                it.addHandlerLast(LogbookServerHandler(logbook))
            }
        }

Also, side thing, I had to manually include reactor-netty-http-brave in my Gradle file as it's not present in the Reactor bom. I wasn't sure if this was supposed to be there yet I just wanted to call it out.

[violetagg]

@btkelly I'm working on some changes in the API. Let me finish that and I'll check the sample app.

[violetagg]

@btkelly Several fixes for the example are needed

I don't now why but I needed to add all Reactor Netty modules

build.gradle

    implementation 'io.projectreactor.netty:reactor-netty-core:1.0.0-SNAPSHOT'
    implementation 'io.projectreactor.netty:reactor-netty-http:1.0.0-SNAPSHOT'
    implementation 'io.projectreactor.netty:reactor-netty-http-brave:1.0.0-SNAPSHOT'

The instrumentation for the client is still a PR so you cannot add this

            val httpClient = HttpClient.create()
                //.observe(braveHttpServerTracing)

The instrumentation on the server for the moment is with childObserve and not observe (this will change as I mentioned in my previous comment that I'm going to change the API - it might result in something like decorateHttpClient and decorateHttpServer)

        NettyServerCustomizer { httpServer ->
            httpServer.childObserve(braveHttpServerTracing)
                      .doOnConnection {
                it.addHandlerLast(LogbookServerHandler(logbook))
            }
        }

How do you request the application?

[btkelly]

Thanks for looking into this @violetagg, good to know about the client as I was seeing some strange behavior there. As for the childObserve I tried it with both it resulted in the same behavior.

When you are asking How do you request the application? do you mean making an http request?

If so, you can run the app by executing ./gradlew clean bootRun from the root directory and using a REST client to make a GET request to http://localhost:8080/local and see what gets printed out in the logs.

[btkelly]

@violetagg You might have also been asking for access to the repo, I added you as a collaborator to the sample app. Feel free to poke around and change whatever as it's just a sample to test this specific issue.

[btkelly]

@violetagg Just checking back in on this. I saw that reactor netty 1.0.0 has been released and was curious if this issue resolution was included in that or not. If so I can run through some tests to verify. Let me know when you get second.

[enrique-ninetynine]

Hello!!

I've tried with io.projectreactor.netty:reactor-netty-http-brave:1.0.3 and Sleuth data is not present when logging with Lombok.

@Configuration
class LogbookNettyConfiguration {

    @Bean
    fun reactorNettyHttpTracing(httpTracing: HttpTracing): ReactorNettyHttpTracing = ReactorNettyHttpTracing.create(httpTracing)

    @Bean
    fun logbookNettyServerCustomizer(logbook: Logbook, tracing: ReactorNettyHttpTracing): NettyServerCustomizer {
        return NettyServerCustomizer { httpServer: HttpServer ->
            tracing.decorateHttpServer(httpServer).doOnConnection { it.addHandlerLast(LogbookServerHandler(logbook)) }
        }
    }
}

I will continue with some testing!

[marcingrzejszczak]

@enrique-ninetynine can you show the logs that are missing this information? Also can you show us how you're the reactor netty part?

[enrique-ninetynine]

I've created a really simple Spring Boot application to reproduce the problem!

package com.example.demo

import brave.http.HttpTracing
import org.slf4j.LoggerFactory
import org.springframework.boot.autoconfigure.SpringBootApplication
import org.springframework.boot.runApplication
import org.springframework.boot.web.embedded.netty.NettyServerCustomizer
import org.springframework.context.annotation.Bean
import org.springframework.context.annotation.Configuration
import org.springframework.web.bind.annotation.GetMapping
import org.springframework.web.bind.annotation.RequestMapping
import org.springframework.web.bind.annotation.RestController
import org.zalando.logbook.Logbook
import org.zalando.logbook.netty.LogbookServerHandler
import reactor.netty.http.brave.ReactorNettyHttpTracing
import reactor.netty.http.server.HttpServer

@SpringBootApplication
class DemoApplication

fun main(args: Array<String>) {
    runApplication<DemoApplication>(*args)
}

@RestController
@RequestMapping("/test")
class TestController {

    private val logger = LoggerFactory.getLogger(javaClass)

    @GetMapping
    fun test(): SomeResponse {
        logger.info("this trace has trace id")
        return SomeResponse()
    }
}

data class SomeResponse(val someValue: String = "VALUE")

@Configuration
class LogbookNettyConfiguration {

    @Bean
    fun reactorNettyHttpTracing(httpTracing: HttpTracing): ReactorNettyHttpTracing =
        ReactorNettyHttpTracing.create(httpTracing)

    @Bean
    fun logbookNettyServerCustomizer(logbook: Logbook, tracing: ReactorNettyHttpTracing): NettyServerCustomizer {
        return NettyServerCustomizer { httpServer: HttpServer ->
            tracing.decorateHttpServer(httpServer).doOnConnection { it.addHandlerLast(LogbookServerHandler(logbook)) }
        }
    }

}

The log is missing the traceId and spanId.

2021-02-05 13:20:35.652  INFO [tracing-demo,b72979e146fa6425,b72979e146fa6425] 14010 --- [ctor-http-nio-2] com.example.demo.TestController          : this trace has trace id
2021-02-05 13:20:35.757 TRACE [tracing-demo,,] 14010 --- [ctor-http-nio-2] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"9445fad082578d5d","protocol":"HTTP/1.1","remote":"/[0:0:0:0:0:0:0:1]:65185","method":"GET","uri":"http://localhost:8080/test","host":"localhost:8080","path":"/test","scheme":"http","port":null,"headers":{"Accept":["*/*"],"Host":["localhost:8080"],"User-Agent":["curl/7.64.1"]}}
2021-02-05 13:20:35.765 TRACE [tracing-demo,,] 14010 --- [ctor-http-nio-2] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"9445fad082578d5d","duration":162,"protocol":"HTTP/1.1","status":200,"headers":{"Content-Length":["21"],"Content-Type":["application/json"]},"body":{"someValue":"VALUE"}}

I am going to create a repository!

EDIT: The repo! https://github.com/enrique-ninetynine/spring-boot-webflux-sleuth-logbook-problem

[enrique-ninetynine]

I have updated reactor-netty-http-brave to 1.0.4 and spring-boot to 2.4.3 with the same results. Maybe it helps.

[mantoshelis]

Seems like the issue still persists in:

• Spring Boot 2.4.4
• Spring Cloud 2020.0.2
• Logbook Spring Boot Webflux autoconfigure 2.6.1

[marcingrzejszczak]

Please create a sample that reproduces the problem. We have successfully with @violetagg managed to solve the issue so we need to see what changed in the meantime

[violetagg]

@mantoshelis The fix in Reactor Netty is still not released https://github.com/reactor/reactor-netty/pull/1555
Please try with 1.0.6-SNAPSHOT (https://repo.spring.io/snapshot)

[mantoshelis]

1.0.6-SNAPSHOT does not provide the expected result also.
I created sample to reproduce the problem: https://github.com/mantoshelis/scs-1690

[marcingrzejszczak]

Please try spring cloud 2020.0.3-SNAPSHOT (notice the 3.0.3 milestone on this issue)

[mantoshelis]

I tried, but it still doesn't work as I expected.
Created branch 2020-0-03-cloud in my sample project.

[violetagg]

@mantoshelis Can you try again Reactor Netty 1.0.6-SNAPSHOT? I added one additional commit.
Also I would like to mention that in the sample you need to add the code below otherwise the HttpClient's Brave support is not enabled:

  @Bean
  ReactorNettyHttpTracing reactorNettyHttpTracing(HttpTracing httpTracing) {
    return ReactorNettyHttpTracing.create(httpTracing);
  }

  @Bean
  WebClient webClient(Logbook logbook, ReactorNettyHttpTracing tracing) {
    return WebClient.builder()
        .clientConnector(
            new ReactorClientHttpConnector(
                tracing.decorateHttpClient(
                        HttpClient.create()
                                .doOnConnected(conn -> conn.addHandlerLast(new LogbookClientHandler(logbook))))))
        .build();
  }

[mantoshelis]

Yes, it works for the Webclient. Thanks.
Unfortunately, span and trace ids are missing for request / responses to service (Netty container). Is there anything we can do?

REQUEST TO SERVER -> 2021-04-07 17:49:37.885 TRACE [,,] 356044 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"827845965856ec2c","protocol":"HTTP/1.1","remote":"/0:0:0:0:0:0:0:1%0:50486","method":"POST","uri":"http://localhost:8080/users","host":"localhost:8080","path":"/users"....
REQUEST USING WEBCLIENT -> 2021-04-07 17:49:38.119 TRACE [,a5344328f486e24a,a5344328f486e24a] 356044 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"92a7bea535b43269",....
RESPONSE USING WEBLICENT -> 2021-04-07 17:49:38.298 TRACE [,a5344328f486e24a,a5344328f486e24a] 356044 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"remote","type":"response","correlation":"92a7bea535b43269","duration":180,....
LOGGING IN SERVER -> 2021-04-07 17:49:38.301  INFO [,a5344328f486e24a,a5344328f486e24a] 356044 --- [or-http-epoll-5] com.scs.issue.Function                   : Creating user whiteelephant903 with request: Function.CreateUserRequest(password=any123)
RESPONSE FROM SERVER -> 2021-04-07 17:49:38.309 TRACE [,,] 356044 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"827845965856ec2c","duration":774,"protocol":"HTTP/1.1","status":204,"headers":{"content-length":["0"]}}

[violetagg]

@mantoshelis and you enabled the tracing on the server? (similar to what I pasted above for the client)

[mantoshelis]

I added the following code to decorate HTTP server. Is that enough?

  @Bean
  NettyServerCustomizer nettyServerCustomizer(ReactorNettyHttpTracing reactorNettyHttpTracing) {
    return reactorNettyHttpTracing::decorateHttpServer;
  }

As a result, inconsistent span and trace ids are added to the request. The response still misses span and trace ids.

REQUEST TO SERVER -> 2021-04-07 18:22:21.684 TRACE [,dcb21254920fb2e3,dcb21254920fb2e3] 377801 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"9c2d88829abbb81f","protocol":"HTTP/1.1","remote":"/0:0:0:0:0:0:0:1%0:51990","method":"POST","uri":"http://localhost:8080/users","host":"localhost:8080","path":"/users","scheme":"http","port":null,"headers":{"Accept":["*/*"],"Accept-Encoding":["gzip, deflate, br"],"Cache-Control":["no-cache"],"Connection":["keep-alive"],"content-length":["28"],"Content-Type":["application/json"],"Host":["localhost:8080"],"Postman-Token":["96a77d5f-c084-4f05-8821-53194b1bb0bc"],"User-Agent":["PostmanRuntime/7.26.10"]},"body":{"password":"any123"}}
REQUEST USING WEBCLIEN -> 2021-04-07 18:22:21.890 TRACE [,5a9cd317672abe37,5a9cd317672abe37] 377801 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"cc960edb23045093","protocol":"HTTP/1.1","remote":"randomuser.me/104.21.9.42:443","method":"GET","uri":"http://randomuser.me/api?results=1","host":"randomuser.me","path":"/api","scheme":"http","port":null,"headers":{"Accept":["application/json"],"host":["randomuser.me"],"user-agent":["ReactorNetty/1.0.6-SNAPSHOT"],"X-B3-ParentSpanId":["5a9cd317672abe37"],"X-B3-Sampled":["0"],"X-B3-SpanId":["f0813d55a1391400"],"X-B3-TraceId":["5a9cd317672abe37"]}}
RESPONSE USING WEBLICENT -> 2021-04-07 18:22:22.074 TRACE [,5a9cd317672abe37,5a9cd317672abe37] 377801 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"remote","type":"response","correlation":"cc960edb23045093","duration":184,"protocol":"HTTP/1.1","status":200,"headers":{"Access-Control-Allow-Origin":["*"],"alt-svc":["h3-27=\":443\"; ma=86400, h3-28=\":443\"; ma=86400, h3-29=\":443\"; ma=86400"],"Cache-Control":["no-cache"],"CF-Cache-Status":["DYNAMIC"],"CF-RAY":["63c4403efa01d443-HAM"],"cf-request-id":["094e867b580000d443b5072000000001"],"Connection":["keep-alive"],"Content-Type":["application/json; charset=utf-8"],"Date":["Wed, 07 Apr 2021 15:22:22 GMT"],"ETag":["W/\"47e-WSCSAAFwxIuG45wjMY8z3hxItp4\""],"Expect-CT":["max-age=604800, report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\""],"NEL":["{\"report_to\":\"cf-nel\",\"max_age\":604800}"],"Report-To":["{\"group\":\"cf-nel\",\"max_age\":604800,\"endpoints\":[{\"url\":\"https:\\/\\/a.nel.cloudflare.com\\/report?s=35TueYtr9yMHDylUwxwXL3Gv%2F988%2B6dl%2BXEYQQzQbdOrhsN9TRHuDqFgcj14NOx6J3tucNePDmQ9ifznZ4d70eiRIgWe19j7lDIXftzZ\"}]}"],"Server":["cloudflare"],"Set-Cookie":["__cfduid=dbc1531e18f1a5a0f25d4576add1076ab1617808941; expires=Fri, 07-May-21 15:22:21 GMT; path=/; domain=.randomuser.me; HttpOnly; SameSite=Lax"],"Transfer-Encoding":["chunked"],"Vary":["Accept-Encoding"],"X-Powered-By":["Express"]},"body":{"results":[{"gender":"female","name":{"title":"Ms","first":"Rose","last":"Patel"},"location":{"street":{"number":6235,"name":"Dufferin St"},"city":"Tecumseh","state":"Prince Edward Island","country":"Canada","postcode":"Y5V 1U5","coordinates":{"latitude":"-64.4085","longitude":"168.2848"},"timezone":{"offset":"-11:00","description":"Midway Island, Samoa"}},"email":"[email protected]","login":{"uuid":"ebf096eb-d337-47ec-837e-fbbe6167ad79","username":"tinywolf756","password":"john1","salt":"ooBE4XWm","md5":"e685eef9f0b1dc1d3aa0146f581e4af7","sha1":"b0bc808ccb00dabd4e9bee131b240b09018df4b4","sha256":"65e794fe1b690eecbee9a9973bf621ddd862020dce2f6d880383f603f2e23b19"},"dob":{"date":"1983-04-30T18:04:16.844Z","age":38},"registered":{"date":"2017-10-17T14:09:41.222Z","age":4},"phone":"044-684-5159","cell":"857-040-2720","id":{"name":"","value":null},"picture":{"large":"https://randomuser.me/api/portraits/women/40.jpg","medium":"https://randomuser.me/api/portraits/med/women/40.jpg","thumbnail":"https://randomuser.me/api/portraits/thumb/women/40.jpg"},"nat":"CA"}],"info":{"seed":"a5e3a55e844b57fb","results":1,"page":1,"version":"1.3"}}}
LOGGING IN SERVER -> 2021-04-07 18:22:22.078  INFO [,5a9cd317672abe37,5a9cd317672abe37] 377801 --- [or-http-epoll-5] com.scs.issue.Function                   : Creating user tinywolf756 with request: Function.CreateUserRequest(password=any123)
RESPONSE FROM SERVER -> 2021-04-07 18:22:22.086 TRACE [,,] 377801 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"9c2d88829abbb81f","duration":713,"protocol":"HTTP/1.1","status":204,"headers":{"content-length":["0"]}}

[violetagg]

@mantoshelis Ok let me check that again in Reactor Netty

[alex183]

@violetagg

Hey guys, sorry for commenting on this already closed issue, but the Netty Server Response trace and span are still not working for me:

Maybe you can help me find if I'm missing something, please?

TESTING LOGGING ->
2021-05-28 09:45:58.651 INFO [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-2] v.m.q.m.book.controllers.BookController : just testing log

NETTY SERVER REQUEST ->
2021-05-28 09:45:58.829 TRACE [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-2] org.zalando.logbook.Logbook : {"origin":"remote","type":"request","correlation":"caef6f10cc6755d9","protocol":"HTTP/1.1","remote":"/[0:0:0:0:0:0:0:1%0]:43008","method":"GET","uri":"http://localhost:8080/api/v1/traceId/test", "host":"localhost","path":"/api/v1/traceId/test","scheme":"http","port":"8080","headers":{"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,/;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["pt-BR,pt;q=0.9,en-US;q=0.8,en;q=0.7"],"Cache-Control":["max-age=0"],"Connection":["keep-alive"],"Cookie":["SESSION=46cac22c-d2c5-4188-b707-ca2b9deba7a8"],"Host":["localhost:8080"],"sec-ch-ua":["\" Not A;Brand\";v=\"99\", \"Chromium\";v=\"90\", \"Google Chrome\";v=\"90\""],"sec-ch-ua-mobile":["?0"],"Sec-Fetch-Dest":["document"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-Site":["none"],"Sec-Fetch-User":["?1"],"Upgrade-Insecure-Requests":["1"],"User-Agent":["Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.93 Safari/537.36"]}}

WEBCLIENT REQUEST ->
2021-05-28 09:45:59.866 TRACE [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-4] org.zalando.logbook.Logbook : {"origin":"local","type":"request","correlation":"e69236c60fd80335","protocol":"HTTP/1.1","remote":"run.mocky.io/46.252.181.103:443","method":"GET","uri":"https://run.mocky.io/v3/d24fe35c-265d-444a-a609-38f7265c390c" ,"host":"run.mocky.io","path":"/v3/d24fe35c-265d-444a-a609-38f7265c390c","scheme":"https","port":"443","headers":{"accept":["/"],"host":["run.mocky.io"],"user-agent":["ReactorNetty/1.0.7"],"X-B3-ParentSpanId":["901fe3e2450c2868"],"X-B3-Sampled":["0"],"X-B3-SpanId":["83de4c085f55926d"],"X-B3-TraceId":["901fe3e2450c2868"]}}

WEBCLIENT RESPONSE ->
2021-05-28 09:46:00.139 TRACE [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-4] org.zalando.logbook.Logbook : {"origin":"remote","type":"response","correlation":"e69236c60fd80335","duration":267,"protocol":"HTTP/1.1","status":200,"headers":{"content-length":["25"],"Content-Type":["application/json; charset=UTF-8"],"Date":["Fri, 28 May 2021 12:45:59 GMT"],"Sozu-Id":["01F6SG52ZCK9TQ8PSRZ0YJZGGQ"]},"body":{"sabor":"queijo"}}

NETTY SERVER RESPONSE - >
2021-05-28 09:46:00.155 TRACE [,,] 142577 --- [or-http-epoll-2] org.zalando.logbook.Logbook : {"origin":"local","type":"response","correlation":"caef6f10cc6755d9","duration":1572,"protocol":"HTTP/1.1","status":200,"headers":{"Content-Length":["18"],"Content-Type":["application/json"],"context-path":["http://localhost:8080/api/v1/traceId/test"],"method":["GET"],"trace-id":["901fe3e2450c2868"]},"body":{"sabor":"queijo"}}

I as i bolded in the Netty Server response, I was able to create a new header using the correct trace-id from the Context, but it's still not showing up in the "TRACE [,,]" section and I don't know why.

  @Autowired
  Tracer tracer;

  @Override
  public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
      exchange.getResponse()
              .getHeaders()
              .addAll(additionalHeaders(exchange));
      return chain.filter(exchange);
  }

  private MultiValueMap<String, String> additionalHeaders(ServerWebExchange exchange) {

      MultiValueMap<String, String> mhm = new LinkedMultiValueMap<String, String>();
      mhm.add("method", exchange.getRequest().getMethodValue());
      mhm.add("context-path", exchange.getRequest().getURI().toString());
      mhm.add("trace-id", tracer.currentSpan().context().traceIdString());

      return mhm;
  }

Configurations:

@Bean
NettyServerCustomizer nettyServerCustomizer(ReactorNettyHttpTracing reactorNettyHttpTracing) {
    return reactorNettyHttpTracing::decorateHttpServer;
}

@Bean
ReactorNettyHttpTracing reactorNettyHttpTracing(HttpTracing httpTracing) {
    return ReactorNettyHttpTracing.create(httpTracing);
}

@Bean
WebClient.Builder webClient(Logbook logbook, ReactorNettyHttpTracing tracing) {
    return WebClient.builder()
            .clientConnector(
                new ReactorClientHttpConnector(
                    tracing.decorateHttpClient(
                        HttpClient.create()
                            .doOnConnected(conn -> conn.addHandlerLast(new LogbookClientHandler(logbook))))));
}

I'm using the following versions:
Spring Boot 2.4.5
Spring Cloud 2020.0.3-SNAPSHOT
Logbook Spring Boot Webflux autoconfigure 2.9.0
Reactor Netty 1.0.7
Reactor Netty Http 1.0.7
Reactor Netty Http Brave 1.0.7

[mantoshelis]

@violetagg

Hey guys, sorry for commenting on this already closed issue, but the Netty Server Response trace and span are still not working for me:

Maybe you can help me find if I'm missing something, please?

TESTING LOGGING ->
2021-05-28 09:45:58.651 INFO [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-2] v.m.q.m.book.controllers.BookController : just testing log

NETTY SERVER REQUEST ->
2021-05-28 09:45:58.829 TRACE [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-2] org.zalando.logbook.Logbook : {"origin":"remote","type":"request","correlation":"caef6f10cc6755d9","protocol":"HTTP/1.1","remote":"/[0:0:0:0:0:0:0:1%0]:43008","method":"GET","uri":"http://localhost:8080/api/v1/traceId/test", "host":"localhost","path":"/api/v1/traceId/test","scheme":"http","port":"8080","headers":{"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,_/_;q=0.8,application/signed-exchange;v=b3;q=0.9"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["pt-BR,pt;q=0.9,en-US;q=0.8,en;q=0.7"],"Cache-Control":["max-age=0"],"Connection":["keep-alive"],"Cookie":["SESSION=46cac22c-d2c5-4188-b707-ca2b9deba7a8"],"Host":["localhost:8080"],"sec-ch-ua":["" Not A;Brand";v="99", "Chromium";v="90", "Google Chrome";v="90""],"sec-ch-ua-mobile":["?0"],"Sec-Fetch-Dest":["document"],"Sec-Fetch-Mode":["navigate"],"Sec-Fetch-Site":["none"],"Sec-Fetch-User":["?1"],"Upgrade-Insecure-Requests":["1"],"User-Agent":["Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.93 Safari/537.36"]}}

WEBCLIENT REQUEST ->
2021-05-28 09:45:59.866 TRACE [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-4] org.zalando.logbook.Logbook : {"origin":"local","type":"request","correlation":"e69236c60fd80335","protocol":"HTTP/1.1","remote":"run.mocky.io/46.252.181.103:443","method":"GET","uri":"https://run.mocky.io/v3/d24fe35c-265d-444a-a609-38f7265c390c" ,"host":"run.mocky.io","path":"/v3/d24fe35c-265d-444a-a609-38f7265c390c","scheme":"https","port":"443","headers":{"accept":["_/_"],"host":["run.mocky.io"],"user-agent":["ReactorNetty/1.0.7"],"X-B3-ParentSpanId":["901fe3e2450c2868"],"X-B3-Sampled":["0"],"X-B3-SpanId":["83de4c085f55926d"],"X-B3-TraceId":["901fe3e2450c2868"]}}

WEBCLIENT RESPONSE ->
2021-05-28 09:46:00.139 TRACE [,901fe3e2450c2868,901fe3e2450c2868] 142577 --- [or-http-epoll-4] org.zalando.logbook.Logbook : {"origin":"remote","type":"response","correlation":"e69236c60fd80335","duration":267,"protocol":"HTTP/1.1","status":200,"headers":{"content-length":["25"],"Content-Type":["application/json; charset=UTF-8"],"Date":["Fri, 28 May 2021 12:45:59 GMT"],"Sozu-Id":["01F6SG52ZCK9TQ8PSRZ0YJZGGQ"]},"body":{"sabor":"queijo"}}

NETTY SERVER RESPONSE - >
2021-05-28 09:46:00.155 TRACE [,,] 142577 --- [or-http-epoll-2] org.zalando.logbook.Logbook : {"origin":"local","type":"response","correlation":"caef6f10cc6755d9","duration":1572,"protocol":"HTTP/1.1","status":200,"headers":{"Content-Length":["18"],"Content-Type":["application/json"],"context-path":["http://localhost:8080/api/v1/traceId/test"],"method":["GET"],"trace-id":["901fe3e2450c2868"]},"body":{"sabor":"queijo"}}

I as i bolded in the Netty Server response, I was able to create a new header using the correct trace-id from the Context, but it's still not showing up in the "TRACE [,,]" section and I don't know why.

  @Autowired
  Tracer tracer;

  @Override
  public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
      exchange.getResponse()
              .getHeaders()
              .addAll(additionalHeaders(exchange));
      return chain.filter(exchange);
  }

  private MultiValueMap<String, String> additionalHeaders(ServerWebExchange exchange) {

      MultiValueMap<String, String> mhm = new LinkedMultiValueMap<String, String>();
      mhm.add("method", exchange.getRequest().getMethodValue());
      mhm.add("context-path", exchange.getRequest().getURI().toString());
      mhm.add("trace-id", tracer.currentSpan().context().traceIdString());

      return mhm;
  }

Configurations:

@Bean
NettyServerCustomizer nettyServerCustomizer(ReactorNettyHttpTracing reactorNettyHttpTracing) {
    return reactorNettyHttpTracing::decorateHttpServer;
}

@Bean
ReactorNettyHttpTracing reactorNettyHttpTracing(HttpTracing httpTracing) {
    return ReactorNettyHttpTracing.create(httpTracing);
}

@Bean
WebClient.Builder webClient(Logbook logbook, ReactorNettyHttpTracing tracing) {
    return WebClient.builder()
            .clientConnector(
                new ReactorClientHttpConnector(
                    tracing.decorateHttpClient(
                        HttpClient.create()
                            .doOnConnected(conn -> conn.addHandlerLast(new LogbookClientHandler(logbook))))));
}

I'm using the following versions:
Spring Boot 2.4.5
Spring Cloud 2020.0.3-SNAPSHOT
Logbook Spring Boot Webflux autoconfigure 2.9.0
Reactor Netty 1.0.7
Reactor Netty Http 1.0.7
Reactor Netty Http Brave 1.0.7

Same for me. I'm waiting for Spring Cloud 2020.3 release. I hope the problem will be fixed there.

[mantoshelis]

I have updated to Spring Cloud 2020.0.3 and Spring Boot 2.5.0 (tried with 2.4.6 also) but it still doesn't work. Any news on this?

Dependencies:
Spring Boot 2.5.0
Spring Cloud 2020.0.3
Logbook Webflux Autoconfigure 2.9.0
Reactor Netty 1.0.7

build.gradle:

plugins {
    id 'org.springframework.boot' version '2.5.0'
    id 'io.spring.dependency-management' version '1.0.11.RELEASE'
    id 'java'
}

group = 'com.scs'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = '11'

repositories {
    mavenCentral()
    maven { url 'https://repo.spring.io/snapshot' }
}

ext {
    set('springCloudVersion', "2020.0.3")
    set('logbookVersion', "2.9.0")
}

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-webflux'
    implementation 'org.springframework.cloud:spring-cloud-starter-sleuth'
    implementation 'io.projectreactor.netty:reactor-netty-http-brave'
    implementation "org.zalando:logbook-spring-boot-webflux-autoconfigure"

    compileOnly "org.projectlombok:lombok"
    annotationProcessor "org.projectlombok:lombok"

    testImplementation 'org.springframework.boot:spring-boot-starter-test'
    testImplementation 'io.projectreactor:reactor-test'
}

dependencyManagement {
    imports {
        mavenBom "org.springframework.cloud:spring-cloud-dependencies:${springCloudVersion}"
        mavenBom "org.zalando:logbook-bom:${logbookVersion}"
    }
}

test {
    useJUnitPlatform()
}

Configuration:

  @Bean
  NettyServerCustomizer nettyServerCustomizer(ReactorNettyHttpTracing reactorNettyHttpTracing) {
    return reactorNettyHttpTracing::decorateHttpServer;
  }

  @Bean
  ReactorNettyHttpTracing reactorNettyHttpTracing(HttpTracing httpTracing) {
    return ReactorNettyHttpTracing.create(httpTracing);
  }

  @Bean
  WebClient webClient(Logbook logbook, ReactorNettyHttpTracing tracing) {
    return WebClient.builder()
        .baseUrl("https://randomuser.me")
        .clientConnector(
            new ReactorClientHttpConnector(
                tracing.decorateHttpClient(
                    HttpClient.create()
                        .doOnConnected(
                            conn -> conn.addHandlerLast(new LogbookClientHandler(logbook))))))
        .build();
  }

Usage:

  private Mono<ServerResponse> createUser(ServerRequest serverRequest) {
    return serverRequest
        .bodyToMono(CreateUserRequest.class)
        .zipWith(getUsername())
        .doOnSuccess(
            tuple -> {
              var request = tuple.getT1();
              var username = tuple.getT2();
              log.info("Creating user {} with request: {}", username, request);
            })
        .then(ServerResponse.noContent().build());
  }

Result on first request (after startup) - missing trace and span ids on the response from the server:

2021-05-31 17:38:15.571 TRACE [,d556099056b1b16e,d556099056b1b16e] 104168 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"8e3c77ac28f6571e","protocol":"HTTP/1.1","remote":"/0:0:0:0:0:0:0:1%0:60730","method":"POST","uri":"http://localhost:8080/users","host":"localhost","path":"/users","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Accept-Encoding":["gzip, deflate, br"],"Cache-Control":["no-cache"],"Connection":["keep-alive"],"content-length":["28"],"Content-Type":["application/json"],"Host":["localhost:8080"],"Postman-Token":["189d0dc1-af6b-4157-a66c-55195f271dfa"],"User-Agent":["PostmanRuntime/7.28.0"]},"body":{"password":"any123"}}
2021-05-31 17:38:15.781 TRACE [,d556099056b1b16e,d556099056b1b16e] 104168 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"d3416c378976b3b0","protocol":"HTTP/1.1","remote":"randomuser.me/172.67.130.203:443","method":"GET","uri":"https://randomuser.me/api?results=1","host":"randomuser.me","path":"/api","scheme":"https","port":"443","headers":{"Accept":["application/json"],"host":["randomuser.me"],"user-agent":["ReactorNetty/1.0.7"],"X-B3-ParentSpanId":["d556099056b1b16e"],"X-B3-Sampled":["0"],"X-B3-SpanId":["ee5dbbe97f155dea"],"X-B3-TraceId":["d556099056b1b16e"]}}
2021-05-31 17:38:16.141 TRACE [,d556099056b1b16e,d556099056b1b16e] 104168 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"remote","type":"response","correlation":"d3416c378976b3b0","duration":360,"protocol":"HTTP/1.1","status":200,"headers":{"Access-Control-Allow-Origin":["*"],"alt-svc":["h3-27=\":443\"; ma=86400, h3-28=\":443\"; ma=86400, h3-29=\":443\"; ma=86400"],"Cache-Control":["no-cache"],"CF-Cache-Status":["DYNAMIC"],"CF-RAY":["6580f1e4c9a315e0-ARN"],"cf-request-id":["0a647582fe000015e07fb6e000000001"],"Connection":["keep-alive"],"Content-Type":["application/json; charset=utf-8"],"Date":["Mon, 31 May 2021 14:38:15 GMT"],"ETag":["W/\"47d-lYrcOL6PJvw/4dJ3Q6xmTwrBjOI\""],"Expect-CT":["max-age=604800, report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\""],"NEL":["{\"report_to\":\"cf-nel\",\"max_age\":604800}"],"Report-To":["{\"endpoints\":[{\"url\":\"https:\\/\\/a.nel.cloudflare.com\\/report\\/v2?s=RLzzp%2FD5h%2B8NLr9pXuLF3V14y0lXdTV92k0O6osa2TXvsfagreiW9Z0SjoWgUcDE9T6xIJd8QFoS4H5SKduJ7xR8oMAHx5CQOUjSNYIp211a%2FGboeGEwXU%2BeqA%3D%3D\"}],\"group\":\"cf-nel\",\"max_age\":604800}"],"Server":["cloudflare"],"Transfer-Encoding":["chunked"],"Vary":["Accept-Encoding"],"X-Powered-By":["Express"]},"body":{"results":[{"gender":"female","name":{"title":"Ms","first":"Tessel","last":"Doeleman"},"location":{"street":{"number":7553,"name":"Hintham"},"city":"Rottum Fr","state":"Drenthe","country":"Netherlands","postcode":91747,"coordinates":{"latitude":"42.4965","longitude":"148.2569"},"timezone":{"offset":"+5:45","description":"Kathmandu"}},"email":"[email protected]","login":{"uuid":"e2fccbb0-e5a5-406b-978f-9f638ddec51d","username":"whitemeercat974","password":"life","salt":"tPvdzSJB","md5":"43af2e462fd74c09159ab6124a1976aa","sha1":"9032bc3fe6bb6ba9edb7f480ca294ae23e1f84a9","sha256":"cb9d557ebda20ae8c52a804a8f994e06a16cb33dd19a881128617e8fb2558d0f"},"dob":{"date":"1967-02-08T21:53:59.286Z","age":54},"registered":{"date":"2006-05-24T19:45:01.211Z","age":15},"phone":"(888)-730-8626","cell":"(834)-459-4418","id":{"name":"BSN","value":"97073068"},"picture":{"large":"https://randomuser.me/api/portraits/women/52.jpg","medium":"https://randomuser.me/api/portraits/med/women/52.jpg","thumbnail":"https://randomuser.me/api/portraits/thumb/women/52.jpg"},"nat":"NL"}],"info":{"seed":"7318c967e718a78b","results":1,"page":1,"version":"1.3"}}}
2021-05-31 17:38:16.144  INFO [,d556099056b1b16e,d556099056b1b16e] 104168 --- [or-http-epoll-5] com.scs.issue.Function                   : Creating user whitemeercat974 with request: Function.CreateUserRequest(password=any123)
2021-05-31 17:38:16.151 TRACE [,,] 104168 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"8e3c77ac28f6571e","duration":1124,"protocol":"HTTP/1.1","status":204,"headers":{"content-length":["0"]}}

Result after further requests - missing trace and span ids on the request and response using WebClient and on the response from the server:

2021-05-31 17:38:42.472 TRACE [,b87c69b844209ab7,b87c69b844209ab7] 104168 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"97192565e8b23685","protocol":"HTTP/1.1","remote":"/0:0:0:0:0:0:0:1%0:60730","method":"POST","uri":"http://localhost:8080/users","host":"localhost","path":"/users","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Accept-Encoding":["gzip, deflate, br"],"Cache-Control":["no-cache"],"Connection":["keep-alive"],"content-length":["28"],"Content-Type":["application/json"],"Host":["localhost:8080"],"Postman-Token":["94511d54-3ccd-429b-b1f7-fb947228f5a7"],"User-Agent":["PostmanRuntime/7.28.0"]},"body":{"password":"any123"}}
2021-05-31 17:38:42.475 TRACE [,,] 104168 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"ed2186c8c627ef7b","protocol":"HTTP/1.1","remote":"randomuser.me/172.67.130.203:443","method":"GET","uri":"https://randomuser.me/api?results=1","host":"randomuser.me","path":"/api","scheme":"https","port":"443","headers":{"Accept":["application/json"],"host":["randomuser.me"],"user-agent":["ReactorNetty/1.0.7"],"X-B3-ParentSpanId":["b87c69b844209ab7"],"X-B3-Sampled":["0"],"X-B3-SpanId":["fbd839e6bc72f0c6"],"X-B3-TraceId":["b87c69b844209ab7"]}}
2021-05-31 17:38:42.692 TRACE [,,] 104168 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"remote","type":"response","correlation":"ed2186c8c627ef7b","duration":217,"protocol":"HTTP/1.1","status":200,"headers":{"Access-Control-Allow-Origin":["*"],"alt-svc":["h3-27=\":443\"; ma=86400, h3-28=\":443\"; ma=86400, h3-29=\":443\"; ma=86400"],"Cache-Control":["no-cache"],"CF-Cache-Status":["DYNAMIC"],"CF-RAY":["6580f28be84315e0-ARN"],"cf-request-id":["0a6475eb6e000015e08cb8d000000001"],"Connection":["keep-alive"],"Content-Type":["application/json; charset=utf-8"],"Date":["Mon, 31 May 2021 14:38:42 GMT"],"ETag":["W/\"48d-NheyTBJo4DVMZWNKnkXJgMrdny8\""],"Expect-CT":["max-age=604800, report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\""],"NEL":["{\"report_to\":\"cf-nel\",\"max_age\":604800}"],"Report-To":["{\"endpoints\":[{\"url\":\"https:\\/\\/a.nel.cloudflare.com\\/report\\/v2?s=bCrYyEgpxApNaKp1Nwa4VBmcZVu9JaJJUHKvAovP01HceJWR3hMxQyw97iqMkI7F%2FbBmE9GTce4iWXOkfAaK2AeabH%2FHFdoSN0sZ0FhXR1KVwk0ECAAv6lA5%2FA%3D%3D\"}],\"group\":\"cf-nel\",\"max_age\":604800}"],"Server":["cloudflare"],"Transfer-Encoding":["chunked"],"Vary":["Accept-Encoding"],"X-Powered-By":["Express"]},"body":{"results":[{"gender":"male","name":{"title":"Mr","first":"Mattia","last":"Naarden"},"location":{"street":{"number":2454,"name":"Iegepoeledijk"},"city":"Ingelum","state":"Limburg","country":"Netherlands","postcode":32332,"coordinates":{"latitude":"40.3320","longitude":"-39.5073"},"timezone":{"offset":"-7:00","description":"Mountain Time (US & Canada)"}},"email":"[email protected]","login":{"uuid":"9723c673-ebed-4ae4-a000-10c62b83e39f","username":"beautifulbear159","password":"18436572","salt":"6S4ZN5pP","md5":"66813116670b77421dd0fc362a33ca94","sha1":"08a0de90070d530ce8cc372eaa522477335d1f79","sha256":"788018b47ca76bdb8f620aaff02f31af9c3df40fe8503f04d885b03d139d0f0e"},"dob":{"date":"1945-07-23T21:47:47.687Z","age":76},"registered":{"date":"2015-07-24T18:42:00.952Z","age":6},"phone":"(165)-282-5923","cell":"(556)-520-4553","id":{"name":"BSN","value":"23154705"},"picture":{"large":"https://randomuser.me/api/portraits/men/43.jpg","medium":"https://randomuser.me/api/portraits/med/men/43.jpg","thumbnail":"https://randomuser.me/api/portraits/thumb/men/43.jpg"},"nat":"NL"}],"info":{"seed":"7ec16e47a96bd729","results":1,"page":1,"version":"1.3"}}}
2021-05-31 17:38:42.694  INFO [,b87c69b844209ab7,b87c69b844209ab7] 104168 --- [or-http-epoll-5] com.scs.issue.Function                   : Creating user beautifulbear159 with request: Function.CreateUserRequest(password=any123)
2021-05-31 17:38:42.695 TRACE [,,] 104168 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"97192565e8b23685","duration":229,"protocol":"HTTP/1.1","status":204,"headers":{"content-length":["0"]}}

[violetagg]

@mantoshelis

If you add LogbookServerHandler do you see the trace ids?

    @Bean
    NettyServerCustomizer nettyServerCustomizer(Logbook logbook, ReactorNettyHttpTracing reactorNettyHttpTracing) {
        return server -> reactorNettyHttpTracing.decorateHttpServer(
                server.doOnConnection(conn -> conn.addHandlerFirst(new LogbookServerHandler(logbook))));
    }

[mantoshelis]

@mantoshelis

If you add LogbookServerHandler do you see the trace ids?

    @Bean
    NettyServerCustomizer nettyServerCustomizer(Logbook logbook, ReactorNettyHttpTracing reactorNettyHttpTracing) {
        return server -> reactorNettyHttpTracing.decorateHttpServer(
                server.doOnConnection(conn -> conn.addHandlerFirst(new LogbookServerHandler(logbook))));
    }

With this kind of configuration its only works on the first request (after startup):

2021-06-04 10:00:43.987 TRACE [,b3ab223b72ad3db2,b3ab223b72ad3db2] 7146 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"d643fe28629d2a35","protocol":"HTTP/1.1","remote":"/0:0:0:0:0:0:0:1%0:52386","method":"POST","uri":"http://localhost:8080/users","host":"localhost","path":"/users","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Accept-Encoding":["gzip, deflate, br"],"Cache-Control":["no-cache"],"Connection":["keep-alive"],"content-length":["28"],"Content-Type":["application/json"],"Host":["localhost:8080"],"Postman-Token":["2334cf3d-060e-4995-8798-bbcce35c3e3c"],"User-Agent":["PostmanRuntime/7.28.0"]},"body":{"password":"any123"}}
2021-06-04 10:00:44.335 TRACE [,b3ab223b72ad3db2,b3ab223b72ad3db2] 7146 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"bebbbdfde584682f","protocol":"HTTP/1.1","remote":"randomuser.me/104.21.9.42:443","method":"GET","uri":"https://randomuser.me/api?results=1","host":"randomuser.me","path":"/api","scheme":"https","port":"443","headers":{"Accept":["application/json"],"host":["randomuser.me"],"user-agent":["ReactorNetty/1.0.7"],"X-B3-ParentSpanId":["b3ab223b72ad3db2"],"X-B3-Sampled":["0"],"X-B3-SpanId":["d7f95d3ff35e57e2"],"X-B3-TraceId":["b3ab223b72ad3db2"]}}
2021-06-04 10:00:44.621 TRACE [,b3ab223b72ad3db2,b3ab223b72ad3db2] 7146 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"remote","type":"response","correlation":"bebbbdfde584682f","duration":290,"protocol":"HTTP/1.1","status":200,"headers":{"Access-Control-Allow-Origin":["*"],"alt-svc":["h3-27=\":443\"; ma=86400, h3-28=\":443\"; ma=86400, h3-29=\":443\"; ma=86400, h3=\":443\"; ma=86400"],"Cache-Control":["no-cache"],"CF-Cache-Status":["DYNAMIC"],"CF-RAY":["659f49311bcb4180-HAM"],"cf-request-id":["0a776c12b400004180e90b8000000001"],"Connection":["keep-alive"],"Content-Type":["application/json; charset=utf-8"],"Date":["Fri, 04 Jun 2021 07:00:44 GMT"],"ETag":["W/\"473-Sw4VeEmnADQH00fiA6gxGcqnO7o\""],"Expect-CT":["max-age=604800, report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\""],"NEL":["{\"report_to\":\"cf-nel\",\"max_age\":604800}"],"Report-To":["{\"endpoints\":[{\"url\":\"https:\\/\\/a.nel.cloudflare.com\\/report\\/v2?s=pHqfAT5qGuC%2BkX7r3xbsbc0qYRV1lmUIszsizXGXDYYU50Kfg0pDKQEE5NLSNefp%2F5sWU99NK72PLtFA0IEVcsIL3OaNkiEaEFROe4q%2FCUfJ76URj1PGJGI3ig%3D%3D\"}],\"group\":\"cf-nel\",\"max_age\":604800}"],"Server":["cloudflare"],"Transfer-Encoding":["chunked"],"Vary":["Accept-Encoding"],"X-Powered-By":["Express"]},"body":{"results":[{"gender":"male","name":{"title":"Mr","first":"Niklas","last":"Jutila"},"location":{"street":{"number":5760,"name":"Esplanadi"},"city":"Lavia","state":"Ostrobothnia","country":"Finland","postcode":19900,"coordinates":{"latitude":"-10.7868","longitude":"-66.1616"},"timezone":{"offset":"-9:00","description":"Alaska"}},"email":"[email protected]","login":{"uuid":"a3291681-aceb-4d82-902a-5a360c2a6870","username":"blackostrich436","password":"1981","salt":"NW3Q2Hkg","md5":"7cec81c02dbde3c300dc2f171cc48fe7","sha1":"4e3fad2b5590357cc39b5d8b3bc9995df616bf61","sha256":"cf3edc1889511e17555bfc478aa6f48682b575f74d2520807cb7fc1b2c062394"},"dob":{"date":"1979-07-01T15:49:46.241Z","age":42},"registered":{"date":"2006-02-25T01:59:43.823Z","age":15},"phone":"02-716-454","cell":"040-089-45-43","id":{"name":"HETU","value":"NaNNA203undefined"},"picture":{"large":"https://randomuser.me/api/portraits/men/41.jpg","medium":"https://randomuser.me/api/portraits/med/men/41.jpg","thumbnail":"https://randomuser.me/api/portraits/thumb/men/41.jpg"},"nat":"FI"}],"info":{"seed":"66b0e637edd60ba8","results":1,"page":1,"version":"1.3"}}}
2021-06-04 10:00:44.629  INFO [,b3ab223b72ad3db2,b3ab223b72ad3db2] 7146 --- [or-http-epoll-5] com.scs.issue.Function                   : Creating user blackostrich436 with request: Function.CreateUserRequest(password=any123)
2021-06-04 10:00:44.649 TRACE [,b3ab223b72ad3db2,b3ab223b72ad3db2] 7146 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"d643fe28629d2a35","duration":1404,"protocol":"HTTP/1.1","status":204,"headers":{"content-length":["0"]}}

Further requests are missing WebClient trace and span ids:

2021-06-04 10:01:25.045 TRACE [,02b73147bbd2b499,02b73147bbd2b499] 7146 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"remote","type":"request","correlation":"9691d7fa83140c01","protocol":"HTTP/1.1","remote":"/0:0:0:0:0:0:0:1%0:52386","method":"POST","uri":"http://localhost:8080/users","host":"localhost","path":"/users","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Accept-Encoding":["gzip, deflate, br"],"Cache-Control":["no-cache"],"Connection":["keep-alive"],"content-length":["28"],"Content-Type":["application/json"],"Host":["localhost:8080"],"Postman-Token":["f29694a1-c467-4b8d-b209-6e01a5b5921e"],"User-Agent":["PostmanRuntime/7.28.0"]},"body":{"password":"any123"}}
2021-06-04 10:01:25.047 TRACE [,,] 7146 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"local","type":"request","correlation":"c91e79c4aa42a2df","protocol":"HTTP/1.1","remote":"randomuser.me/104.21.9.42:443","method":"GET","uri":"https://randomuser.me/api?results=1","host":"randomuser.me","path":"/api","scheme":"https","port":"443","headers":{"Accept":["application/json"],"host":["randomuser.me"],"user-agent":["ReactorNetty/1.0.7"],"X-B3-ParentSpanId":["02b73147bbd2b499"],"X-B3-Sampled":["0"],"X-B3-SpanId":["1abd0192bbed81c7"],"X-B3-TraceId":["02b73147bbd2b499"]}}
2021-06-04 10:01:25.198 TRACE [,,] 7146 --- [or-http-epoll-5] org.zalando.logbook.Logbook              : {"origin":"remote","type":"response","correlation":"c91e79c4aa42a2df","duration":149,"protocol":"HTTP/1.1","status":200,"headers":{"Access-Control-Allow-Origin":["*"],"alt-svc":["h3-27=\":443\"; ma=86400, h3-28=\":443\"; ma=86400, h3-29=\":443\"; ma=86400, h3=\":443\"; ma=86400"],"Cache-Control":["no-cache"],"CF-Cache-Status":["DYNAMIC"],"CF-RAY":["659f4a2f98f84180-HAM"],"cf-request-id":["0a776cb1c300004180d39cd000000001"],"Connection":["keep-alive"],"Content-Type":["application/json; charset=utf-8"],"Date":["Fri, 04 Jun 2021 07:01:25 GMT"],"ETag":["W/\"489-AwLLxpS0zUAjQKoL2NAq+3DYhh8\""],"Expect-CT":["max-age=604800, report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\""],"NEL":["{\"report_to\":\"cf-nel\",\"max_age\":604800}"],"Report-To":["{\"endpoints\":[{\"url\":\"https:\\/\\/a.nel.cloudflare.com\\/report\\/v2?s=jeBxzqotiqS1z0rYR7jTbGRYUSakK40JONeg%2FAJt%2BF8VO3ceu5yZMRBCgBvWDPpiJpMraa8jrJinTFvjIuWHx0cM%2BfvZ8rQKEP1HupZpSMLVT7cFxMcRi1L%2FQw%3D%3D\"}],\"group\":\"cf-nel\",\"max_age\":604800}"],"Server":["cloudflare"],"Transfer-Encoding":["chunked"],"Vary":["Accept-Encoding"],"X-Powered-By":["Express"]},"body":{"results":[{"gender":"male","name":{"title":"Mr","first":"Abdulrahman","last":"Hauge"},"location":{"street":{"number":2481,"name":"Øivinds vei"},"city":"Movatn","state":"Sør-Trøndelag","country":"Norway","postcode":"6829","coordinates":{"latitude":"51.8526","longitude":"-159.4957"},"timezone":{"offset":"-3:00","description":"Brazil, Buenos Aires, Georgetown"}},"email":"[email protected]","login":{"uuid":"0453f8b0-d778-4460-bb22-385b8b32d007","username":"blackdog275","password":"popo","salt":"ZEBIrya8","md5":"1e2bef7d01b19ff9e269bc065a6b2ed3","sha1":"da976a325561a2f57d28da3506f0fcc03b472d1e","sha256":"934b2fdb295c74b4d08ee7fadf3e98e68ce5d37423831f80bd68591c56b672ca"},"dob":{"date":"1974-12-25T01:34:26.160Z","age":47},"registered":{"date":"2008-01-03T13:55:31.168Z","age":13},"phone":"67218004","cell":"48108438","id":{"name":"FN","value":"25127402119"},"picture":{"large":"https://randomuser.me/api/portraits/men/73.jpg","medium":"https://randomuser.me/api/portraits/med/men/73.jpg","thumbnail":"https://randomuser.me/api/portraits/thumb/men/73.jpg"},"nat":"NO"}],"info":{"seed":"359d06d949f4a72a","results":1,"page":1,"version":"1.3"}}}
2021-06-04 10:01:25.199  INFO [,02b73147bbd2b499,02b73147bbd2b499] 7146 --- [or-http-epoll-5] com.scs.issue.Function                   : Creating user blackdog275 with request: Function.CreateUserRequest(password=any123)
2021-06-04 10:01:25.201 TRACE [,02b73147bbd2b499,02b73147bbd2b499] 7146 --- [or-http-epoll-3] org.zalando.logbook.Logbook              : {"origin":"local","type":"response","correlation":"9691d7fa83140c01","duration":161,"protocol":"HTTP/1.1","status":204,"headers":{"content-length":["0"]}}

[sergey-volkov-lm]

Could it be logbook issue? 🤔

[violetagg]

@mantoshelis @sergey-volkov-lm The issue is in Reactor Netty and should be fixed with this PR https://github.com/reactor/reactor-netty/pull/1656. It is related only to HttpClient when a connection pool is in use.

[violetagg]

You should be able to try Reactor Netty 1.0.8-SNAPSHOT