How to print complete error message when logging an exception generated by RestTemplate?
Asked Answered
P

2

5

We have a Spring-Boot (2.3.10.RELEASE) based application which calls many REST APIs using RestTemplate.

In case, any REST API returns any 4xx or 5xx HTTP error code along with message body, complete message body is not getting logged.

Here is a minimum reproducible example:

import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
import org.springframework.web.client.HttpClientErrorException;
import org.springframework.web.client.RestTemplate;

@Slf4j
public class RestTemplateTest {

    @Test
    void shouldPrintErrorForRestTemplate() {
        RestTemplate restTemplate = new RestTemplate();
        try {
            restTemplate.getForEntity("http://hellosmilep.free.beeceptor.com/error/notfound", String.class);
        } catch (Exception e) {
            log.error("Error calling REST API", e);
        }
    }
}

Output:

10:28:11.347 [main] ERROR com.smilep.java.webapp.RestTemplateTest - Error calling REST API
org.springframework.web.client.HttpClientErrorException$NotFound: 404 Not Found: [{
  "glossary": {
    "title": "example glossary",
    "GlossDiv": {
      "title": "S",
      "GlossList": {
        "GlossEntry": {
          "ID": "SGML",
          "SortAs": "SGML",
          "Glo... (593 bytes)]
    at org.springframework.web.client.HttpClientErrorException.create(HttpClientErrorException.java:113)
    at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:184)
    at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:125)
    at org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63)
    at org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:780)
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:738)
    at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:672)
    at org.springframework.web.client.RestTemplate.getForEntity(RestTemplate.java:340)
    at com.smilep.java.webapp.RestTemplateTest.shouldPrintErrorForRestTemplate(RestTemplateTest.java:15)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:686)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:149)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:140)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:84)
    at org.junit.jupiter.engine.execution.ExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(ExecutableInvoker.java:115)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.lambda$invoke$0(ExecutableInvoker.java:105)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:104)
    at org.junit.jupiter.engine.execution.ExecutableInvoker.invoke(ExecutableInvoker.java:98)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$6(TestMethodTestDescriptor.java:212)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:208)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:137)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:71)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:135)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
    at java.util.ArrayList.forEach(ArrayList.java:1257)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
    at java.util.ArrayList.forEach(ArrayList.java:1257)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:248)
    at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$5(DefaultLauncher.java:211)
    at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:226)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:199)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:132)
    at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:71)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
    at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:235)
    at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)

You can notice response message is truncated with "Glo... (593 bytes)] in above stack trace. How to log the complete error response body?

I know I can do something like below to print the error response body but it will be too much of boilerplate code to be added in many classes (and also in other applications).

if(e instanceof HttpClientErrorException) {
    log.error("response body : " + ((HttpClientErrorException) e).getResponseBodyAsString());
}
  1. Is there any way by which logging Exception object would log complete error response message body instead of truncating with ... (593 bytes)]?

  2. Is there some default size limit in java after which it truncates any message in error log? If yes, how to change it?

Update :

After jccampanero's answer, I had raised this issue with Spring team to make this logging message size limit configurable. They have removed the limit altogether. This change should be available in some future version of Spring.

Poinciana answered 7/10, 2021 at 5:10 Comment(0)
A
6

By default, RestTemplate uses DefaultErrorHandler for processing errors.

In the implementation of this class, the different handleError methods - see for instance this - rely on the getErrorMessage method:

/**
  * Return error message with details from the response body, possibly truncated:
  * <pre>
  * 404 Not Found: [{'id': 123, 'message': 'my very long... (500 bytes)]
  * </pre>
  */
private String getErrorMessage(
    int rawStatusCode, String statusText, @Nullable byte[] responseBody, @Nullable Charset charset) {


  String preface = rawStatusCode + " " + statusText + ": ";
  if (ObjectUtils.isEmpty(responseBody)) {
    return preface + "[no body]";
  }


  if (charset == null) {
    charset = StandardCharsets.UTF_8;
  }
  int maxChars = 200;


  if (responseBody.length < maxChars * 2) {
    return preface + "[" + new String(responseBody, charset) + "]";
  }


  try {
    Reader reader = new InputStreamReader(new ByteArrayInputStream(responseBody), charset);
    CharBuffer buffer = CharBuffer.allocate(maxChars);
    reader.read(buffer);
    reader.close();
    buffer.flip();
    return preface + "[" + buffer.toString() + "... (" + responseBody.length + " bytes)]";
  }
  catch (IOException ex) {
    // should never happen
    throw new IllegalStateException(ex);
  }
}

As you can see, this is method the one that actually truncates the message.

In order to provide the full message, you can your own provided ResponseErrorHandler implementation.

For instance, reusing the code implement in DefaultErrorHandler:

import java.io.IOException;
import java.nio.charset.Charset;
import java.nio.charset.StandardCharsets;

import org.springframework.http.HttpHeaders;
import org.springframework.http.HttpStatus;
import org.springframework.http.client.ClientHttpResponse;
import org.springframework.lang.Nullable;
import org.springframework.util.ObjectUtils;
import org.springframework.web.client.DefaultResponseErrorHandler;
import org.springframework.web.client.HttpClientErrorException;
import org.springframework.web.client.HttpServerErrorException;
import org.springframework.web.client.UnknownHttpStatusCodeException;

public class CustomRestTemplateResponseErrorHandler extends DefaultResponseErrorHandler {
  
  // This overloaded method version is only available since Spring 5.0
  // For previous versions of the library you can override
  // handleError(ClientHttpResponse response) instead
  @Override
  protected void handleError(ClientHttpResponse response, HttpStatus statusCode) throws IOException {
    String statusText = response.getStatusText();
    HttpHeaders headers = response.getHeaders();
    byte[] body = getResponseBody(response);
    Charset charset = getCharset(response);
    String message = getErrorMessage(statusCode.value(), statusText, body, charset);

    switch (statusCode.series()) {
      case CLIENT_ERROR:
        throw HttpClientErrorException.create(message, statusCode, statusText, headers, body, charset);
      case SERVER_ERROR:
        throw HttpServerErrorException.create(message, statusCode, statusText, headers, body, charset);
      default:
        throw new UnknownHttpStatusCodeException(message, statusCode.value(), statusText, headers, body, charset);
    }
  }

  /**
   * Return error message with details from the response body:
   * <pre>
   * 404 Not Found: [{'id': 123, 'message': 'actual mesage']
   * </pre>
   *
   * In contrast to <code>DefaultResponseErrorHandler</code>, the message will not be truncated.
   */
  private String getErrorMessage(
      int rawStatusCode, String statusText, @Nullable byte[] responseBody, @Nullable Charset charset) {

    String preface = rawStatusCode + " " + statusText + ": ";
    if (ObjectUtils.isEmpty(responseBody)) {
      return preface + "[no body]";
    }

    if (charset == null) {
      charset = StandardCharsets.UTF_8;
    }

    // return the message without truncation
    return preface + "[" + new String(responseBody, charset) + "]";
  }
}

Then, configure RestTemplate to use this custom ResponseErrorHandler:

import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
import org.springframework.web.client.HttpClientErrorException;
import org.springframework.web.client.RestTemplate;

@Slf4j
public class RestTemplateTest {

    @Test
    void shouldPrintErrorForRestTemplate() {
        RestTemplate restTemplate = new RestTemplate();
        ResponseErrorHandler errorHandler = new CustomRestTemplateResponseErrorHandler();
        restTemplate.setErrorHandler(errorHandler);

        try {
            restTemplate.getForEntity("http://hellosmilep.free.beeceptor.com/error/notfound", String.class);
        } catch (Exception e) {
            log.error("Error calling REST API", e);
        }
    }
}

Please, see this related SO question or this article for further examples.

Auburn answered 11/10, 2021 at 14:20 Comment(4)
Thank you for the detailed answer. I have raised this issue to Spring team for the possibility of making maxChars configurable in DefaultResponseErrorHandler.Poinciana
You're welcome @Smile. That's great, well done! I definitely agree with you, I also thought about the possibility of raising a similar issue. I hope you get feedback soon and that the issue will be resolved in a future version of the framework.Auburn
Spring has removed this message size limit. I have added this update to my question. Thank you!Poinciana
It is fantastic @Smile!! I am happy to hear that!!Auburn
F
1

In place of doing an if you can catch an HttpClientErrorException, so with that you can avoid boiler plate

@Test
void shouldPrintErrorForRestTemplate() {
    try {

        RestTemplate restTemplate = new RestTemplate();
        restTemplate.getForEntity("http://hellosmilep.free.beeceptor.com/error/notfound", String.class);

    } catch(HttpClientErrorException e) {
        log.error(e.getResponseBodyAsString(),e);
    }catch (Exception e) {
        log.error("Error calling REST API", e);
    }
}
Frazier answered 7/10, 2021 at 10:54 Comment(1)
Yes, I can do that but I am more inclined to know why the error message is getting truncated, is there some size limit on message for truncation, if yes - how to change this limit.Poinciana

© 2022 - 2024 — McMap. All rights reserved.