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

[aldex32]

I am seeing the same problem when a read timeout occurs, the request is not logged. I am using SpringRest client.

[kasmarian]

I've merged a PR (#2000) that should address this. It'll be part of the next version.

[aldex32]

Hi @kasmarian, this fix seems only for WebClient. What about spring RestClient?

[kasmarian]

RestClient may use different http clients that use different Logbook request/response interceptor implementations. Most of them would log the request immediately and not wait for the response. Which one do you use?

[aldex32]

The underlying http client that I am using is the jdk HttpClient (JdkClientHttpRequestFactory)

[kasmarian]

Help me reproduce it.
I just tested RestClient with LogbookClientHttpRequestInterceptor and JdkClientHttpRequestFactory and the outgoing request is logged during timeouts.

I'm getting 3 logs: 1) remote request, 2) local request, 3) local response

19:28:05.206 [XNIO-1 task-2] DEBUG org.zalando.logbook.Logbook - {"origin":"remote","type":"request","correlation":"8d55748a4732ff88","protocol":"HTTP/1.1","remote":"0:0:0:0:0:0:0:1","method":"GET","uri":"http://localhost:8080/google","host":"localhost","path":"/google","scheme":"http","port":"8080","headers":{"Accept":["*/*"],"Host":["localhost:8080"],"User-Agent":["curl/8.5.0"]}}
19:28:05.207 [XNIO-1 task-2] DEBUG org.zalando.logbook.Logbook - {"origin":"local","type":"request","correlation":"e2585bdb0385b763","protocol":"HTTP/1.1","remote":"localhost","method":"GET","uri":"https://www.google.com/","host":"www.google.com","path":"/","scheme":"https","port":null,"headers":{"Content-Length":["0"]}}
19:28:05.236 [XNIO-1 task-2] DEBUG org.zalando.logbook.Logbook - {"origin":"local","type":"response","correlation":"8d55748a4732ff88","duration":30,"protocol":"HTTP/1.1","status":500,"headers":{"Connection":["keep-alive"],"Content-Length":["73"],"Content-Type":["text/plain;charset=UTF-8"],"Date":["Tue, 14 Jan 2025 18:28:05 GMT"]},"body":"I/O error on GET request for \"https://www.google.com/\": Request timed out"}

[aldex32]

Yes I am using LogbookClientHttpRequestInterceptor. I think I found the issue why it is not logging the request when a read timeout occurs. It is because I have logbook set up with status-at-least strategy:

logbook.strategy=status-at-least
logbook.minimum-status=400

So if I remove these properties, the request that times out is being logged.

Do you know whether I can still use this strategy but at the same time to log also timeout requests?

[kasmarian]

StatusAtLeastStrategy is pretty simple. You can implement your custom strategy to e.g. always log requests.
But keep in mind that postponing the decision to log the request as it's done in this strategy comes with the cost, that Logbook's response interceptor will not be called on timeouts or other issues.