Java Spring Webflux, logging the time taken for an outbound http call

user_10461625 0
Viewed 2083

Small question regarding how to log the time spent for a http request please.

To avoid confusion, this question is regarding logs (not metrics), this question is about Webflux, this question is about outbound call, I am the client, trying to make a call to a server, and I need to time this operation, but from a log perspective.

Based on this snippet I am using:

 @Override
    public Mono<String> sendOutboundRequest() {
        return webClient.post().retrieve().bodyToMono(String.class);
    }

So far, I tried .log() but this is not writing the time spent directly, this solution needs another layer of parsing of the timestamp from the on subscribe and the on complete of log4j time.

I also tried .metrics(), this gets the time, but this only generates metrics, not a log.

I also tried some method execution surround

 long start = System.nanoTime();
        Mono<String> result = webClientIdms.post().retrieve().bodyToMono(String.class);
        long end = System.nanoTime() - start;
        LOGGER.info("this will not print the actual http request time " + end);
        return result;

but this is not working, since in a reactive stack, this will not time the execution of the request when the reactive pipeline is executed.

May I ask what is the proper way to log the time taken please?

Thank you

spring-webflux java
2 Answers

If you are looking to do this in a reusable way, you can utilise an ExchangeFilterFunction. You can find further examples of an ExchangeFilterFunction on the spring reference docs

Below is an example implementation of an ExchangeFilterFunction that will time each external api call made by a WebClient and log the results. This takes inspiration from MetricsWebClientFilterFunction

@Component
public class MetricsLoggingExchangeFilterFunction implements ExchangeFilterFunction {

    private static final Logger LOGGER = LoggerFactory.getLogger(MetricsLoggingExchangeFilterFunction.class);
    private static final String METRICS_WEBCLIENT_START_TIME = MetricsLoggingExchangeFilterFunction.class.getName() + ".START_TIME";

    @Override
    public Mono<ClientResponse> filter(ClientRequest request, ExchangeFunction next) {
        return next.exchange(request).doOnEach((signal) -> {
            if (!signal.isOnComplete()) {
                Long startTime = signal.getContextView().get(METRICS_WEBCLIENT_START_TIME);
                long duration = System.currentTimeMillis() - startTime;
                LOGGER.info("Downstream called taken {}ms", duration);
            }
        }).contextWrite(ctx -> ctx.put(METRICS_WEBCLIENT_START_TIME, System.currentTimeMillis()));
    }
}

You can then add this to any WebClient instances that you want to log the duration using the provided WebClient.Builder ie.

WebClient.builder().filter(metricsLoggingExchangeFilterFunction).build()
user_30470380

You should make sure to set the start time during the execution phase of the reactive pipeline. You can do that with something like Mono.defer or Mono.fromRunnable

AtomicLong start = new AtomicLong();
Mono.fromRunnable(() -> start.set(System.nanoTime())
    .then(webClient.post()...)
    .doOnNext(it -> LOGGEER.info("time spent {}",System.nanoTime() - start.get());
user_16035110
Related