Spring WebFlux: How to Log Responses With WebClient

You can use a Spring WebFlux WebClient builder to log responses as well as requests. And it ain't too tricky, either.

In this guide, I'll show you how to do it.

Or you can go straight to the source code.

Now with that brief intro out of the way, let's get busy.

The Business Requirements

Your boss Smithers walks into your office. He's mad again.

"More logging!" he shouts.

"You logged the request but you didn't log the response! How can we get all the info we need if you don't log the response?!?"

You're not sure how to reply.

"Log the response for all service-to-service requests!" he yells once more as he storms out of your office.

Building on What You've Got

As Smithers mentioned, you've already created a solution that logs outgoing requests. Now you need to log the response.

It's going to be just as easy.

All you're going to do is create another static method in the WebClientFilter class that handles logging responses.

Then, you'll add that filter in the WebClient builder.

So start by adding these methods in WebClientFilter.

	public static ExchangeFilterFunction logResponse() {
		return ExchangeFilterFunction.ofResponseProcessor(response -> {
			logStatus(response);
			logHeaders(response);
			
			return logBody(response);
		});
	}
	

	private static void logStatus(ClientResponse response) {
		HttpStatus status = response.statusCode();
		LOG.debug("Returned staus code {} ({})", status.value(), status.getReasonPhrase());
	}
	
	
	private static Mono<ClientResponse> logBody(ClientResponse response) {
		if (response.statusCode() != null && (response.statusCode().is4xxClientError() || response.statusCode().is5xxServerError())) {
			return response.bodyToMono(String.class)
					.flatMap(body -> {
						LOG.debug("Body is {}", body);						
						return Mono.just(response);
					});
		} else {
			return Mono.just(response);
		}
	}
	
	
	private static void logHeaders(ClientResponse response) {
		response.headers().asHttpHeaders().forEach((name, values) -> {
			values.forEach(value -> {
				logNameAndValuePair(name, value);
			});
		});
	}

You can leave everything else alone.

Take a look at that first method up there. Note that it's using the ofResponseProcessor() static method on ExchangeFilterFunction instead of ofRequestProcessor() like you did in the last guide.

That makes sense because the code here is handling responses here instead of requests. That also means that it will bounce around a ClientResponse object instead of a ClientRequest object.

And, once again, it's using a lambda expression to make the good stuff happen.

Take a look at the first two lines within that lambda block. They log the status and the headers, respectively. The code that deals with those two tasks is pretty straightforward.

But pay attention to that third line. It's returning logBody(). 

That seems odd because the other two methods return void. So why is logBody() returning anything at all?

Reacting to the Reactive

TL;DR: You need to log the response within a method that returns a publisher. 

Why? Because you don't want to consume the response body just so you can log it.

If you consume the body for logging purposes, then it's gone and won't be available so that your business logic can do something useful with it.

Back up a moment: remember that when you use Spring WebFlux, you're operating within a reactive environment. And when you're dealing with reactive frameworks, you're working within a publisher/subscriber model.

If you subscribe to the publisher just so you can log the response, then the body is consumed by the logger instead of by the business logic. 

And it's gone forever. Vanished. Poof. Done.

You don't want that. Instead, you want to log the body when the authorized subscriber retrieves it. Not before.

And Another Thing...

That brings me to the next point: you don't want to log a successful response with a filter. Nope.

Why? Because you can just as easily log the successful response once you've got the data back. Just transform the object into JSON or XML and spit it out in your log.

So what you'll do here is log error messages returned when you get a 4xx or 5xx status code.

That's useful because those kinds of status codes are often accompanied by a body that reads something like: "Oops! You really messed up with this request!"

Now you can put that body in the log for further diagnosis.

So with all that in mind, take a look at the logBody() method that does all the heavy lifting here:

	private static Mono<ClientResponse> logBody(ClientResponse response) {
		if (response.statusCode() != null && (response.statusCode().is4xxClientError() || response.statusCode().is5xxServerError())) {
			return response.bodyToMono(String.class)
					.flatMap(body -> {
						LOG.debug("Body is {}", body);						
						return Mono.just(response);
					});
		} else {
			return Mono.just(response);
		}
	}

First of all, note that if the response status code doesn't show a 4xx or 5xx error, then it just returns the publisher back to the original method.

If you're asking yourself "Where is a publisher anywhere in that code?" Just keep in mind that not all class names are perfectly intuitive.

Remember: Mono represents a publisher of 0 or 1 data sequences. Here, it publishes a ClientResponse.object.

If the response comes back as an error, though, then the code above gets busy with logging.

First, it takes the response and uses it to grab a publisher that returns a String result. That's the response.bodyToMono() bit you see above.

That String object is the response body as text.

But the code needs to write that text to the log. For that it uses flatMap().

Why? Because it doesn't need to do any synchronous transformations here. Otherwise, it would use map().

Instead, this block just logs the body and sends back the original response as a publisher.

Getting Classy With the Client

You still aren't done. You need to tell the WebClient builder to log the response.

Do that in your service class:

    public UserService(@Value("${ecosystem.properties.file.location}") String ecosystemFile) {
        PropertiesUtil propertiesUtil = new PropertiesUtil(ecosystemFile);
        String endpoint = propertiesUtil.getProperty("ecosystem-user-service.endpoint");
        
        userClient = WebClient
	        		.builder()
	        		.baseUrl(endpoint)
	        		.filter(WebClientFilter.logRequest())
	        		.filter(WebClientFilter.logResponse())
	        		.build();
    }

Note the addition of an extra filter(). That's the one that logs the response.

And by the way: the code above uses two filters. But you can add as many filters as you like.

Testing Season

As is usually the case, I prefer to test this kind of code with an initializer. Here's what that looks like:

@Component
public class ApplicationListenerInitialize implements ApplicationListener<ApplicationReadyEvent>  {
	
	@Autowired
	private UserService userService;
	
    public void onApplicationEvent(ApplicationReadyEvent event) {        	
    	SalesOwner owner = userService.fetchUser("Bearer eyJhbGciOiJI...");
    	
    	try {
	    	ObjectMapper objectMapper = new ObjectMapper();
	    	objectMapper.setSerializationInclusion(JsonInclude.Include.NON_NULL);
	    	objectMapper.setSerializationInclusion(JsonInclude.Include.NON_EMPTY);
	    	System.err.println(objectMapper.writerWithDefaultPrettyPrinter().writeValueAsString(owner));
    	} catch (Exception e) {
    		e.printStackTrace();
    	}
    }
}

You'll need a valid bearer token if you're going to try what you see above. I've abbreviated the token in the code.

To get the bearer token, just use Postman to authenticate against the user service. Then paste in the bearer token in the code.

Also: I intentionally modified the downstream service so it returns a 400 (Bad Request) status code with message: "You did something wrong." You can do that as well with code that looks like this:

    @GetMapping("/me")
    public ResponseEntity<?> me() {
        return ResponseEntity.badRequest().body("You did something wrong.");
    }

Just put that in the controller.

Now with all that in mind, restart your Spring Boot application and wait for it to finish loading. Then, check the log and you should see something like this:

[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Returned status code 400 (Bad Request)
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Vary=Origin
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Vary=Access-Control-Request-Method
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Vary=Access-Control-Request-Headers
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Vary=Origin
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Vary=Access-Control-Request-Method
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Vary=Access-Control-Request-Headers
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - X-Content-Type-Options=nosniff
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - X-XSS-Protection=1; mode=block
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Cache-Control=no-cache, no-store, max-age=0, must-revalidate
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Pragma=no-cache
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Expires=0
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - X-Frame-Options=DENY
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Content-Type=text/plain;charset=UTF-8
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Content-Length=24
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Date=Fri, 22 Jan 2021 23:57:00 GMT
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Connection=close
[reactor-http-nio-1] DEBUG c.c.contact.service.WebClientFilter - Body is You did something wrong.

The first line shows you the status code with the message.

The next several lines show you the headers sent back with the response.

The last line shows you the body of the response. As you can see, it matches exactly what you put in the code above.

By the way, your Spring Boot application probably crashed. That's because WebClient threw an exception. I'll cover how to deal with that in a future guide.

But now let's make sure it works the way it's supposed to when there aren't any errors.

On the user service side, update that controller method so it does what it's supposed to do:

    @GetMapping("/me")
    public ResponseEntity<?> me() {
        User user = securityUtil.getCurrentUser();
        return ResponseEntity.ok(user);
    }

Now restart your Spring Boot application again. This time, you should see something like this in a nice shade of red:

{
  "id" : "5f78d8fbc1d3246ab4303f2b",
  "firstName" : "Darth",
  "lastName" : "Vader",
  "email" : "darth@xmail.com",
  "username" : "darth",
  "phoneNumber" : "474-555-1212"
}

And if you look above, you should also see that the headers and status code got logged.

Wrapping It Up

Awesome. Now you're logging requests and responses with WebClient. 

It's up to you to take it to the next level. Think about how you might like to log specific types of error responses differently. Or maybe you'd like to log only certain types of headers.

As always, feel free to just grab the code on GitHub.

Have fun!

Photo by João Vítor Heinrichs from Pexels