Missing Logging for Sent Requests During ReadTimeoutException in WebClient

[NavruzshoevDaniel]

Description

When sending requests via WebClient, if the request is successfully sent but a ReadTimeoutException occurs, the event of the request being sent is not logged. Additionally, the logging of the request occurs when the response is returned, rather than at the moment the request is made.

Expected Behavior

The request should be logged at the moment it is sent, regardless of whether a ReadTimeoutException occurs.

Actual Behavior

Currently, if a ReadTimeoutException is thrown, there is no log entry indicating that the request was sent. Logging occurs only when the response is received, which might never happen if a timeout occurs.

Possible Fix

Log the request immediately when the function is called, not after the response is returned.

Steps to Reproduce

1. Send a request via WebClient.
2. Simulate a scenario where the request is sent but the response is delayed or results in a ReadTimeoutException.
3. Check the logs to see that the request was not logged at the time it was sent.
4. Observe that the logging only occurs upon receiving a response (or not at all in the case of a timeout).

Context

This bug affects the ability to track and debug issues related to outgoing requests, particularly when responses are delayed or result in timeouts.

Your Environment

• Version used: org.zalando:logbook-spring-boot-webflux-autoconfigure:2.16.0

Draft decision

Maybe you should add doOnError

package org.zalando.logbook.spring.webflux;

import lombok.RequiredArgsConstructor;
import org.apiguardian.api.API;
import org.springframework.core.io.buffer.DefaultDataBufferFactory;
import org.springframework.http.HttpHeaders;
import org.springframework.web.reactive.function.client.ExchangeFilterFunction;
import org.springframework.web.reactive.function.client.ExchangeFunction;
import org.zalando.logbook.Logbook;
import reactor.core.publisher.Flux;
import reactor.core.publisher.Mono;

import static org.apiguardian.api.API.Status.EXPERIMENTAL;
import static org.springframework.http.HttpHeaders.TRANSFER_ENCODING;
import static org.zalando.fauxpas.FauxPas.*;

@RequiredArgsConstructor
@API(status = EXPERIMENTAL)
@SuppressWarnings({"NullableProblems"})
public class LogbookExchangeFilterFunction implements ExchangeFilterFunction {

    private final Logbook logbook;

    @Override
    public Mono<org.springframework.web.reactive.function.client.ClientResponse> filter(org.springframework.web.reactive.function.client.ClientRequest request, ExchangeFunction next) {
        ClientRequest clientRequest = new ClientRequest(request);
        Logbook.RequestWritingStage requestWritingStage = throwingSupplier(() -> logbook.process(clientRequest)).get();

        return next
                .exchange(org.springframework.web.reactive.function.client.ClientRequest
                        .from(request)
                        .body((outputMessage, context) -> request.body().insert(new BufferingClientHttpRequest(outputMessage, clientRequest), context))
                        .build()
                )
                .doOnError(throwable -> {
                     if (throwable.getCause() instanceof TimeoutException) {
                          requestWritingStage.write();
                      }
              }).flatMap(throwingFunction(response -> {
                    Logbook.ResponseProcessingStage responseProcessingStage = requestWritingStage.write();

                    ClientResponse clientResponse = new ClientResponse(response);
                    Logbook.ResponseWritingStage responseWritingStage = responseProcessingStage.process(clientResponse);

                    return Mono
                            .just(response)
                            .flatMap(it -> {
                                HttpHeaders responseHeaders = response.headers().asHttpHeaders();
                                if (clientResponse.shouldBuffer() && (responseHeaders.getContentLength() > 0 || responseHeaders.containsKey(TRANSFER_ENCODING))) {
                                    return it
                                            .bodyToMono(byte[].class)
                                            .doOnNext(clientResponse::buffer)
                                            .map(b -> response.mutate().body(Flux.just(DefaultDataBufferFactory.sharedInstance.wrap(b))).build());
                                } else {
                                    return Mono.just(it);
                                }
                            })
                            .doOnNext(throwingConsumer(b -> responseWritingStage.write()));
                }));
    }
}

[danilproger]

+1