간헐적으로 쓰레드가 Block 되는 이슈를 쫓아서 … [Apache HttpClient 사용 이슈]

Denia·2024년 9월 2일

HTTPClient Spring

TroubleShooting

목록 보기

25/25

제가 입사하고 나서 맡게된 프로젝트가 하나 있는데, 해당 프로젝트에서 간헐적으로 반년 넘게 속을 썩이던 이슈가 하나 있었고 최근에 그 이슈를 해결했습니다.

해결한 내용에 관해서 간략하게나마 정리를 해보겠습니다.

증상

간헐적으로 쓰레드가 Block이 됨

이슈 트래킹

이슈를 설명드리기 전에 Akka에 대해서 조금은 설명을 드리고 넘어가는게 좋을 것 같습니다.

해당 프로젝트에서는 Akka라는 프레임워크를 사용하고 있습니다.
Akka는 Actor라는 객체를 여러개 만들고, 이렇게 만들어진 Actor끼리 서로 메세지를 주고 받게 (Actor는 특정 메세지를 받으면 특정 로직을 수행) 하면서 동시성과 비동기를 모두 챙긴 프레임워크라고 이해하시면 될 것 같습니다.

그리고 Actor의 로직을 처리하던 쓰레드가 Block이 되어버리면 해당 Actor의 남아있는 나머지 메세지들도 모두 처리가 되지 않습니다.

처음에는 로그를 확인하여, 문제의 범위를 좁히고 코드 디버깅을 통해 문제를 해결하려고 했었습니다.
하지만 관련 로그가 드문드문 남겨져 있었어서 문제를 찾기가 쉽지 않았습니다.
결국 처음부터 끝까지 코드를 모두 훑어보면서 문제를 찾으려고 했지만, 특별하게 문제가 될만한 부분을 발견하지 못했고 문제의 실마리도 보이지 않았습니다.
그러다보니 Actor 쓰레드가 간헐적으로 멈추는 것은 순전히 Akka 프레임워크의 버그라고 생각을 했었습니다.

그래서 재현을 해보고자 Local에서 Akka 프레임워크를 이용해 메세지를 수십만개를 처리하도록 해봤지만 문제는 여전히 발생하지 않았습니다.
(유명한 프레임워크에 이러한 크리티컬 이슈라니, 저의 아주 멍청한 생각이었습니다 😅)
이슈가 발생하면 어플리케이션 재시작을 통해 문제를 해결한지도 어느새 2달이 넘어가자 해당 이슈도 어떠한 경향성을 보인다는 것을 알 수 가 있었습니다.
- 이슈가 자주 발생하는 특정 시간대가 존재 (주말보다는 평일, 오전 9시 ~ 10시 사이에 주로 발생)
- 해당 Block 이슈가 발생하기 전에 Http 통신 관련 Log가 여러번 찍힘
저는 여기서 Http 통신 관련 Log가 여러번 찍히는 것에 주목을 했습니다.
- 그래서 Http 통신을 하는 부분의 코드를 집중적으로 확인했습니다.
  
  해당 프로젝트에서는 Apache의 HttpClient 라이브러리를 사용하고 있었는데, Http 통신을 하고 나서 Connection에 대한 close 처리가 제대로 되어있지 않다는 것을 확인할 수 있었습니다.

Local Test

이슈 트래킹의 마지막에서 HttpClient의 close 관련 문제가 있음을 확인했기 때문에 이를 확인해보고자 close 처리를 하지 않고 HttpClient를 사용하면 어떤 문제가 발생하는지 Local에서 테스트를 해봤습니다.

Http 요청을 할 때마다 새로 HttpClient를 만들어서 사용 → 큰 문제 없음

	private HttpResponse executeHttp(HttpGet httpGet) throws IOException {
		HttpClient httpClient = HttpClients.createDefault();
		
	  HttpResponse response = httpClient.execute(httpGet);
	  
	  log.info("response: " + response);		
		
		return response;
	}

Http 요청을 할 때 이전에 만들어둔 HttpClient를 그대로 사용 → 문제가 발생

	private HttpResponse executeHttp(HttpGet httpGet) throws IOException {
		HttpClient httpClient = HttpClients.createDefault();
		HttpResponse response = null;
		
		int count = 0;
		while (count++ < 5) {
			response = httpClient.execute(httpGet);
			
			try {
					Thread.sleep(1000); // 1초 대기
			} catch (InterruptedException e) {
					e.printStackTrace();
			}
		}
		
	  log.info("response: " + response);		
		
		return response;
	}

문제가 발생하는 원인 분석

결론부터 짧게 말씀드리면 HttpClient의 기본 설정은 다음과 같고, HttpClient 사용 후 Response에 대해서 close()를 해주지 않으면 커넥션풀이 고갈나서 커넥션 풀의 최대 커넥션 수를 넘어서는 요청은 무한정 Block 에 빠질 수 있습니다.

HttpClient 기본 설정

Default 커넥션 풀 사이즈: 2개

Default 커넥션 요청 타임아웃: 없음 (무제한으로 대기)

저희 프로젝트에서 Http 통신을 할 때, 서버로부터 429 (Too Many Request)을 받으면 다시 요청을 하는 로직이 있는데 이 부분에서 close 없이 다시 요청을 했고, 그 때문에 커넥션 풀이 고갈되어 해당 쓰레드가 Block이 되는 이슈가 발생했습니다.

이 부분을 매 요청마다 response에 대해서 close 하도록 개선하여 문제를 해결했습니다.

	private String executeHttp(HttpGet httpGet) throws IOException {
		int count = 0;
 		while (count++ < 5) {
 			try (CloseableHttpClient httpClient = HttpClients.createDefault()) {
 				CloseableHttpResponse response = httpClient.execute(httpGet);
 				final HttpEntity entity = response.getEntity();
 				final String body = EntityUtils.toString(entity);
 				EntityUtils.consume(entity);
  				
 				log.info("body: " + body);
  				
 				return body;
 			} catch (IOException e) {
 				log.error("Exception Occurred!!!", e);
 				break;
 			}
  			
 			try {
 					Thread.sleep(1000); // 1초 대기
 			} catch (InterruptedException e) {
 					e.printStackTrace();
 			}
 		}
 		
 		return "Error Occurred!!!";
 	}

HttpClient 코드 디버깅

Default 커넥션 풀 사이즈 설정은 다음 부분에서 확인이 가능합니다.

// PoolingHttpClientConnectionManager.java

// 커넥션 풀을 생성할 때, 기본 값을 쓰게 되면 다음과 같습니다.)
// new CPool(new InternalConnectionFactory(this.configData, connFactory), 2, 20, timeToLive, timeUnit)에서
// defaultMaxPerRoute: 2, maxTotal: 20

public PoolingHttpClientConnectionManager(HttpClientConnectionOperator httpClientConnectionOperator, HttpConnectionFactory<HttpRoute, ManagedHttpClientConnection> connFactory, long timeToLive, TimeUnit timeUnit) {
    this.log = LogFactory.getLog(this.getClass());
    this.configData = new ConfigData();
    this.pool = new CPool(new InternalConnectionFactory(this.configData, connFactory), 2, 20, timeToLive, timeUnit);
    this.pool.setValidateAfterInactivity(2000);
    this.connectionOperator = (HttpClientConnectionOperator)Args.notNull(httpClientConnectionOperator, "HttpClientConnectionOperator");
    this.isShutDown = new AtomicBoolean(false);
}

Default 커넥션 요청 타임아웃 설정은 다음 부분에서 확인이 가능합니다.

HttpClient httpClient를 생성할 때 HttpClients.createDefault()로 생성 하게 되면
InternalHttpClient객체를 만듭니다.
해당 객체를 만들때 connectionRequestTimeout (커넥션을 얻을때까지 기다리는 시간) 의 값을 -1 (기본값) 으로 만듭니다. (-1이 들어가면 결국 무제한으로 기다립니다.)

MainClientExec.java에서 managedConn = connRequest.get(timeout > 0 ? (*long*)timeout : 0L, TimeUnit.MILLISECONDS); 하는 부분이 있는데

이 부분을 타고 타고 가보면 결국 PoolingHttpClientConnectionManager의
leaseConnection메서드를 호출하게 되고 여기서 더 타고 타고 가보면 AbstractConnPool에서 getPoolEntryBlocking을 호출합니다.

마지막으로 getPoolEntryBlocking에서 *this*.condition.await();를 호출하게 되는데 해당 메서드를 호출하면 해당 쓰레드는 커넥션이 생길때까지 무한정 Block이 됩니다.

//MainClientExec.java 의 execute() 메서드
public CloseableHttpResponse execute(
	HttpRoute route,
	HttpRequestWrapper request,
	HttpClientContext context,
	HttpExecutionAware execAware
) throws IOException, HttpException {

	// ... 중략
	
	ConnectionRequest connRequest = this.connManager.requestConnection(route, userToken);

	RequestConfig config = context.getRequestConfig();

	HttpClientConnection managedConn;
	try {
		int timeout = config.getConnectionRequestTimeout();
		managedConn = connRequest.get( //중요한 부분
			timeout > 0 ? (long)timeout : 0L, TimeUnit.MILLISECONDS
			);
	} 
	
	// ... 중략
}
	
//AbstractConnPool.java 의 getPoolEntryBlocking() 메서드
private E getPoolEntryBlocking(
	T route,
	Object state,
	long timeout,
	TimeUnit timeUnit,
	Future<E> future
) throws IOException, InterruptedException, ExecutionException, TimeoutException {
	// ... 중략

	try {
		// ... 중략
		
		if (deadline != null) {
			success = this.condition.awaitUntil(deadline);
		} else {
			this.condition.await(); //중요한 부분
			success = true;
		}
		
		// ... 중략
	}
	
	// ... 중략
}

참고 자료

Denia

HW -> FW -> Web

이전 포스트