[트러블슈팅] RestTemplate 로깅 중 404 응답에 대한 FileNotFoundException 해결

결제 승인 POST 요청 시 RestTemplate 로그에서 발생한 오류

결제 기능을 개발하면서, 결제 승인 요청을 보내는 RestTemplate에 타임아웃을 적용하고, 요청과 응답에 대한 로깅을 추가하고자 했습니다.

 

Baeldung의 "RestTemplage Logging" 과 망나니 개발자님의 로깅 을 참고해서 RestTemplate 에 로그를 추가 했지만 응답을 받을 때, FileNotFoundException 이 발생하며 아래와 같은 스택 트레이스를 확인했습니다.

java.io.FileNotFoundException: https://api.tosspayments.com/v1/payments/confirm
java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1993)
java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1589)
java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getInputStream(HttpsURLConnectionImpl.java:224)
org.springframework.http.client.SimpleClientHttpResponse.getBody(SimpleClientHttpResponse.java:89)
org.springframework.http.client.BufferingClientHttpResponseWrapper.getBody(BufferingClientHttpResponseWrapper.java:66)
airdnb.be.config.RestTemplateConfig$LoggingInterceptor.printResponse(RestTemplateConfig.java:65)
airdnb.be.config.RestTemplateConfig$LoggingInterceptor.intercept(RestTemplateConfig.java:51)

 

스택 트레이스에서 HttpURLConnection.java:1993을 보면, 응답 코드가 404 또는 410일 때 FileNotFoundException이 발생합니다.

if (respCode >= 400) {
    if (respCode == 404 || respCode == 410) {
        throw new FileNotFoundException(url.toString());
    } else {
        throw new java.io.IOException(
        "Server returned HTTP" + " response code: " + respCode + " for URL: " + url.toString());
    }
 }

 

ClientHttpRequestInterceptor와 ResponseErrorHandler의 순서

로깅을 위해 ClientHttpRequestInterceptor를 사용하면, 404와 410 상태 코드를 처리하는 ResponseErrorHandler를 오버라이드해도 문제를 해결할 수 없습니다.

이유는 ClientHttpRequestInterceptor가 먼저 호출된 후, ResponseErrorHandler가 작동하기 때문입니다.

RestTemplate 의 인터셉터와 에러핸들러의 처리 순서

 

따라서, Logging 하기 위해 추가한 Interceptor 에서 발생한 IOException 때문에 ResponseErrorHandler 가 호출 되지 않습니다.

RestTemplate 의 전체 동작 순서도 출처:

출처 : https://terasolunaorg.github.io/guideline/5.1.1.RELEASE/en/ArchitectureInDetail/RestClient.html

해결 방법

이 문제를 해결하려면, 응답 로깅을 위해 getBody()를 호출하기 전에 getStatusCode()를 호출해야 합니다.

즉, ClientHttpResponse 의 getStatusCode()를 먼저 호출한 후 getBody()를 호출합니다.

 

...?

@Slf4j
class LoggingInterceptor implements ClientHttpRequestInterceptor {

    @Override
    public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution) {
        ...
        printResponse(UUID 6자리, ClientHttpResponse);
        ...
    }

    private void printRequest(String sessionNumber, HttpRequest req, byte[] body) {
        ...
    }

    private void printResponse(String sessionNumber, ClientHttpResponse response) throws IOException {
>>>     HttpStatusCode code = response.getStatusCode();
>>>     String body = new BufferedReader(
                new InputStreamReader(response.getBody(), StandardCharsets.UTF_8))
            .lines()
            .collect(Collectors.joining("\n"));

        log.info("[{}] Status:{}, Headers:{}, Body:{}",
                sessionNumber, code, response.getHeaders(), body);
    }
}

 

getStatusCode()와 getBody() 호출 순서의 의미

 

- RestTemplate ResponseErrorHandler cannot handle 404 FileNotFound

- RestTemplate response.getBody throws exception on 4** and 5** errors for put and post request but works fine for get requests

 

* getBody() 는 post, put 요청 시 발생하는 400,500번대 응답에서만 에러를 발생한다고 합니다. 이에 대한 이유 역시 위의 2개의 링크 중 2번째 들어가면 확인이 가능합니다.

 

해당 링크에서는 getStatusCode() 를 호출한 이후에 getBody() 를 호출하면 errorStream 이 null 이 아니라고 얘기합니다.

Why does calling response.getBody() not throw an IOException after you called response.getStatusCode()?
It is because getStatusCode calls getInputStream internally.
Thus, errorStream will be not null when getBody is called.

 

* errorStream 은 getBody() 구현부에 있습니다.

@Override
public InputStream getBody() throws IOException {
    InputStream errorStream = this.connection.getErrorStream();
    this.responseStream = (errorStream != null ? errorStream : this.connection.getInputStream());
    return this.responseStream;
}

 

 

Spring에서는 getStatusCode()가 내부적으로 getInputStream()을 호출하여, 오류가 발생한 경우 errorStream이 설정되도록 설계되어 있습니다.

오류 응답(4xx, 5xx)이 발생하면 HttpURLConnection에서 getInputStream()이 IOException을 발생시키면서 errorStream을 설정합니다.

이로 인해 이후 getBody()를 호출할 때는 errorStream이 null이 아니게 되어, 에러 응답 본문을 읽을 수 있습니다.

그래서, getBody() 를 먼저 호출하면 getInputStream 에서 IOException 인 FileNotFoundException 이 발생하는 것이었습니다.

 

 

---

오류를 해결하는 과정에서 그 이상의 배움을 얻게 됨을 다시 한번 느낍니다.
이상으로 RestTemplate에 로그를 추가하면서 마주했던 오류에 대한 글을 마치겠습니다.