[Error] HikariCP Connection Leak SQL Error: 0, SQLState: null

문제 상황

사용자가 설정한 관심 플랫폼에 따라 메인 페이지에 맞춤 크리에이터를 제공하는 과정에서 발생한 에러
 

관심 플랫폼에 따른 맞춤 크리에이터 제공

 
 
발생한 로그는 다음과 같다.

o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30059ms.

에러 메시지 내용처럼 커넥션 타임 아웃(Time out)으로 인해 발생한 문제임을 알 수 있었다.
이후 발생 가능한 상황을 생각하여 두 가지 예상 원인을 도출했다.

• 특정 API가 커넥션을 물고 있어서 발생한 문제
• 많은 요청 또는 처리 지연 등의 이유로 커넥션이 부족해서 발생한 문제

결론적으로 특정 API가 커넥션을 물고 있어서 발생한 문제였다. 

 

해결 과정

액추에이터나 프로메테우스와 같은 모니터링을 붙이지 않았기 때문에 애플리케이션 레벨에서 커넥션 풀을 확인해야 했다.
따라서 히카리 풀 커넥션 상태(active, idel, waiting)를 로그에 남도록 yaml 파일에 아래의 설정을 추가했다.

logging:
  level:
    com.zaxxer.hikari.HikariConfig: DEBUG
    com.zaxxer.hikari: TRACE

com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)

 
 
그런 다음 아래 포스팅의 도움을 받아 maximum-pool-size를 1개로 설정해 의심되는 API를 하나하나 확인했다.
 
https://techblog.woowahan.com/2664/

HikariCP Dead lock에서 벗어나기 (이론편) | 우아한형제들 기술블로그

 
그 결과, 커넥션 누수로 의심되는 API를 확인할 수 있었다.

 
앞서 이야기한 예상되는 문제 원인을 생각하며 다음의 가정을 바탕으로 테스트하였다.

• 실제 요청을 처리하는데 필요한 커넥션의 수가 2개 이상이고 처리 지연(슬로우 쿼리 등)으로 인해 발생한 문제일 수도 있으므로 커넥션 풀에 보관할 커넥션을 20개(기본값은 10개)로 설정
• 엔드포인트에 여러 번의 요청을 보내어 실제로 커넥션 누수가 발생하는지 확인

 
확인해본 결과 커넥션을 물고 있어서 발생한 문제임을 거의 확신했다.

com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Timeout failure stats (total=20, active=20, idle=0, waiting=10)
o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30059ms.

 
문제 되었던 코드를 보기에 앞서 어떠한 기능이고 정상적일 때의 동작 과정을 짧게 설명해 보자면 다음과 같다.

기능 설명
사용자의 관심 플랫폼과 크리에이터의 대표 플랫폼이 일치하는 크리에이터를 맞춤 크리에이터로 제공
단, 몇 명의 크리에이터 카드를 보여줄지는 커스텀 설정할 수 있다.

정상 동작 과정
1. 사용자의 관심 플랫폼과 일치하는 크리에이터들을 찾는다.
2. 일치한 크리에이터들 중 보여줄 카드의 수만큼 랜덤한 인덱스를 만들어 리스트에 담는다.
3. 리스트에 담긴 크리에이터들을 찾는다.

코드는 다음과 같다.

public List<Creator> findCreatorByInterestPlatform(int size, List<PlatformType> interestPlatforms) {
    // (1)
    List<Long> ids = jpaQueryFactory
            .select(creator.id)
            .from(creator)
            .where(filterByPlatform(interestPlatforms))
            .fetch();

    // (2) 문제 발생
    List<Long> randoms = createRandomBy(ids, size);

    // (3)
    return jpaQueryFactory
            .selectFrom(creator)
            .join(creator.member, member).fetchJoin()
            .where(creator.id.in(randoms))
            .fetch();
}

private BooleanBuilder filterByPlatform(List<PlatformType> platforms) {
    if (Collections.isEmpty(platforms)) return null;

    BooleanBuilder booleanBuilder = new BooleanBuilder();
    for (PlatformType platform : platforms) {
        booleanBuilder.or(creator.platform.platformHeadType.eq(platform));
    }
    return booleanBuilder;
}

private List<Long> createRandomBy(List<Long> ids, int size) {
    Set<Long> randoms = new HashSet<>();

    while (randoms.size() < size) { // 문제 발생. 무한루프
        int random = (int) (Math.random() * ids.size());
        Long e = ids.get(random);

        randoms.add(e);
    }
    return new ArrayList<>(randoms);
}

 
중복되지 않게 맞춤 크리에이터를 보기 위해 Set을 사용하여 데이터를 담고, 설정한 크리에이터의 카드 수만큼 반복하여 실행하였다.

그러나, 정상적인 흐름을 기대했던 것과 달리 조건에 일치하는 크리에이터 수가 설정한 카드의 수보다 적어서 조건식을 만족하지 못해 무한 루프가 돌았다.
그로 인해 커넥션을 반납하지 못해 커넥션 부족이 발생하게 된 것이다.

무한 루프로 인한 문제임을 확인하고, 가져온 데이터가 보여줄 카드의 개수보다 적은 경우 (1)에서 찾은 배열의 요소 개수만큼 반복시키도록 설정하여 해당 문제를 해결하였다.
 
 

결론

실제 사용자를 받아 서비스하지 않은 상황이었고, OSIV(Open Session In View) 설정도 꺼두었기 때문에 커넥션 부족보다는 커넥션 누수에 중점을 두어 문제를 해결해 나갔다.
단순 휴먼 에러로 발생한 문제라 다소 허무함이 느껴졌지만 그럼에도 불구하고, 이를 계기로 경계 조건(Boundary Condition)이 올바른지 검증하고 예외 상황은 없는지 생각할 필요성을 다시금 느꼈다.