okhttp3 IOException: unexpected end of stream on Connection

기존 레거시를 msa 서버 어플리케이션으로 이관 후 중복처리가 발생한 에러에 대해 회고록을 남긴다.

1. 내용 파악

레거시 프로젝트를 이관하면서 에러 케이스에 대비해 다음과 같은 정책을 적용했다.

- 모니터링 기간 동안 모든 request는 기존 레거시 프로젝트가 받는다.

- 레거시 코드 안에서 이관한 API를 retrofit2client로 호출

- 이관 API 에러 응답 시 기존 레거시 코드 실행

 

코드의 느낌은 대략 이렇다.

/* 레거시 프로젝트 컨트롤러 */
...
public Response legacyProcess(Request request) throws CustomException {
    try {
        Response result = getNewApiService().callNewAPI(request).execute;
        if (!result.isSuccessful()) {
            log.error("legacyProcess ERROR " + result.getData());
            throw new CustomException(String.valueOf(error.getData()));
        }
        return result;
    } catch (Exception e) {
        log.error(e.getMessage(), e);
        return oldService.callExistingAPI(request);
    }
}

public NewApiService getNewApiService() {
        Retrofit2Client retrofit2Client = getRetrofit2Client();
        return retrofit2Client.create(NewApiService.class);
}

....
public Response callExistingAPI(Request request) throws CustomException {
    // 기존 로직 그대로
}

...
public interface NewApiService {
    /* 이관된 API 호출 */
    @PUT("이관프로젝트 uri")
    Call<Response> callNewAPI(@Body Request request);
    ...
}

 

상용 배포 후 이관된 프로젝트에서는 성공적으로 request를 받아 처리를 했는데, client단인 레거시 프로젝트 내에서 다음과 같이 IOException이 간헐적으로 발생하고 있었다.

client 단에서는 예외가 발생했기 때문에 기존 레거시 코드를 실행하면서 중복실행이 발생했다.

• 이관된 비즈니스 로직에 오류가 있었다면 들어오는 request 마다 오류가 나야하는데 하루 10개 꼴로 간헐적으로 발생한다.
• IOException이라고 해서 헤더 값이나 Payload에 이상한 구분자가 있는지.. 스트림에 영향을 끼쳤을만한 내용을 확인해봐도 아무 문제가 없음.
• 스테이지에서 디버깅을 해봐도 재현이 되질 않음.

일반 조회성 API라면 두번 이상 실행해도 큰 문제는 없지만, 문제는 이관된 API 중 수정 로직이 있을 경우다.

실제로 로그를 조회해보니 데이터 수정이 일어나는 API에서도 중복실행이 발생하고 있었다.

 

2. 원인

Okhttp3 버그로 보인다.

클라이언트↔ 서버 간 keep-alive timeout 차이로 발생하는 이슈인데 이걸 IOException으로 던지고 있어서 파악하기 어려웠던 것.

- retrofit2로 서버로 request 보내는 클라이언트 duration: 60초
- 서버 nginx 설정 Keep-alive timeout = 20초 

 

오류가 발생하기까지의 순서는 아마 다음과 같을 것이다.

 

에러나는 상황을 재현을 해보려고 timeout 값으로 테스트 중 서버 상태를 netstat으로 확인해보면 FIN_WAIT2 였다.

 

즉, client 입장에서는 더 긴 keep-alive로 ESTABLISHED 상태가 더 오래 지속되기 때문에 server에서는 이미 close() 해버린 connection을 다시 쓰려고 하면서 okhttp3 client단에서 에러가 발생하는 것이다.

 

확인해본 결과는 이렇지만, 그래도 이상한 부분이 있다.
정석적인 TCP 통신에서는 server에서 close하기 전에 FIN, ACK를 보내는 과정이 있어야 되는데 찾아볼 수가 없다.
server가 FIN_WAIT2 상태로 들어갔다면 그걸 client에게 FIN으로 알려주지 않았던걸까?

아니면 알려줬는데도 client에서 무시하는걸까..

여기에 대한 okhttp3 측 대답은 아몰라 처리하기 힘들어 같다...?

 

 

3. 해결

1) RetrofitClient 의 keep-alive timeout을 서버의 타임아웃과 매칭 시켜줬다.

private static final int keepAliveDuration = 60;

2) Connection Failure 발생할 때 다시 tcp connection을 시도하도록 변경했다.

final OkHttpClient.Builder builder = new OkHttpClient.Builder().connectTimeout(connectTimeout, TimeUnit.MILLISECONDS)
        .readTimeout(readTimeout, TimeUnit.MILLISECONDS)
        .writeTimeout(readTimeout, TimeUnit.MILLISECONDS)
        .connectionPool(connectionPool)
        .retryOnConnectionFailure(true);

→ 이후 에러 사라짐

 

결론: Okhttp3(Retrofit) 사용할 때는 keepalive duration값을 요청을 보내는 server의 timeout과 맞추자.

더 생각해볼 것들

1) 나중에 시간나면 서버 상태 다 찍어봐야겠다...
2) retryOnConnectionFailure -> 서버에 부담이 증가 될거 같은데...?

 

4. 참고자료

https://github.com/square/retrofit/issues/1916

Strange behavior: Unexpected end of stream with retrofit 2.1.0 · Issue #1916 · square/retrofit

https://github.com/square/okhttp/issues/2738

OkHttp3 - IOException: unexpected end of stream on okhttp3.Address@9d7c59b5 · Issue #2738 · square/okhttp

https://tech.kakao.com/2016/04/21/closewait-timewait/

CLOSE_WAIT & TIME_WAIT 최종 분석