빌링 시스템 장애, 이러지 말란 Maria~ - 우아한형제들 기술 블로그

우아한 6시

안녕하세요! 우아한형제들에서 빌링/정산 시스템 개발을 맡고 있는 이주현이라고 합니다.
저는 지난 7월 입사한 이래로 배민에서 진행하는 다양한 이벤트에 대응하며 짧지만 강한 경험들을 하고 있습니다. 그중 얼마 전 있었던 빌링 시스템 장애와 관련된 이야기를 해보려 합니다.

질문: “선임님, 우리 회사는 왜 퇴근 시간이 6시 30분인가요?”

대답: “응 그건 바로 6시 이벤트에 대응하기 위해 서지..”

(사실은 점심 시간이 11:30 ~ 13:00라 그렇습니다. ^.^)

빌링 시스템

빌링시스템은 사용자의 결제 요청을 PG사에 전달하고 응답을 잘 정리하여 주문 시스템에 넘겨주는 역할을 하고 있습니다.
총 7대의 Spring boot application 서버와 Mariadb로 구성되어 있으며 mariadb-connector-j와 JDBC Connection Pool을 이용합니다. 할인 이벤트는 대부분 오후 6시에 진행되기 때문에 퇴근 전까지 긴장을 늦추지 않고 NewRelic, Pinpoint를 통해 모니터링하며 여러가지 상황에 대비합니다.

장애 발생

지난 달 오후 6시. 선착순 1000명에게 3,000원을 할인해주는 카드사 이벤트가 시작되었습니다. 그런데 무난하게 초록색을 그리며 올라가던 Pinpoint 그래프에 얼마 지나지 않아 빨간 불이 들어오기 시작했고 약 1분간 14000개의 요청중 140개의 에러가 발생했습니다. 결제를 시도하려는 단계에서 에러가 발생했을 수도 있지만 결제 인증을 완료하고 승인하는 과정에서 문제가 생겼을 수도 있습니다. 특히 후자의 경우 결제 수단에 대한 모든 정보를 입력한 사용자 입장에서 정말 화가 날 수 있습니다.

이벤트 포스터

에러 내용은 대부분 빌링 시스템에서 보낸 요청을 네트워크 문제로 PG사에서 받지 못해 발생한것으로 보였습니다. 그런데 빌링 시스템 문제로 추정되는 다른 에러도 발견되었습니다.

어디한번 확인해봅시다.

Application에서 발생한 Exception

DataAccessResourceFailureException: Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

Caused by: java.sql.SQLNonTransientConnectionException: Could not connect to xxx.xxx.xxx.xxx unexpected end of stream, read 0 bytes from 4

DB Error 로그

2016-12-08 18:00:55 xxxx [Warning] Aborted connection 37170 to db: ‘unconnected’ user: ‘unauthenticated’ host: ‘xxx.xxx.xxx.xxx’ (Unknown error)

처음 보는 에러입니다. ㅠㅠ ~~몰라 뭐야 그거 무서워~~

Connection Pool 설정을 의심하고 확인해봤지만 특별한 문제점을 찾지 못했습니다.
시간이 지남에 따라 에러는 더 이상 발생하지 않고 소멸되었지만 언제 또다시 이런 일이 발생할지 모릅니다. ‘별거 아니겠지’는 큰 재앙을 불러올 수 있습니다.
우선 위의 메세지를 토대로 DB 커넥션을 추가적으로 연결하려고 했지만, 인증단계에서 실패한 것으로 추정했고 ‘mysql unauthenticated user’를 중심으로 구글링 하기 시작했습니다.

의심1. 데이터베이스 서버

검색 결과는 대부분 --skip-name-resolve 옵션에 대하여 언급했습니다. MySQL(Mariadb)은 새로운 커넥션 요청이 있을 때 인증을 위해 클라이언트의 IP 주소를 통하여 hostname이 host_cache 테이블에 있는지 확인합니다. 만약 없거나 인증 flag가 false라면 IP 주소로 hostname을 알아내는 과정을 거치게 됩니다. 이때 오류가 발생하거나 시간이 오래 소요되어 너무 많은 클라이언트가 연결에 성공하지 못하면 해당 호스트의 추가 연결을 차단하게 됩니다.

MySQL 공식 문서에 따르면 DNS가 느리거나 많은 호스트들을 가지고 있다면 --skip-name-resolve 옵션을 my.cnf 파일에 추가하여 위와 같은 과정을 무시(disable DNS lookup) 할 수 있다고 합니다. (인증 관련 문제가 생길 수 있기 때문에 사전에 확인하시기 바랍니다.)

하지만 저희는 이미 사용 중인 옵션이었습니다.

> show global variables like 'skip_name_resolve';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| skip_name_resolve | ON    |
+-------------------+-------+
1 row in set (0.00 sec)

이럴 때면 머리가 복잡해집니다.
그런데 말입니다.. 의외로 쉬운 부분을 놓치고 있었습니다.

의심2. 웹 애플리케이션 서버

저희 팀은 io.spring.dependency-management 0.5.6 버젼을 사용중입니다. 이 버젼은 자동으로 mariadb-java-client 1.4.6 버젼을 지정해주는데요 같은 팀의 선임님께서 mariadb-connector-j 최신 버젼 1.5.5를 사용하도록 gradle 설정을 변경하고 난 뒤에 문제가 재현되지 않았습니다.

결국 driver 문제로 생각되고.. 문제는 해결된 것 같지만.. 도대체 왜! 그런지 알 수 없는 상태가 되었습니다.

이벤트포스터

우선 mariadb-connector-j의 changelog를 하나씩 찾아본 결과 의심되는 패치 내역을 확인했고 해당 jira issue를 찾아 어떤 내용이 등록 되었는지 살펴보았습니다.

새로운 커넥션을 생성하는데 DriverManager.getConnection()에서 SQLNonTransientConnectionException이 발생한다.
mysql connector를 사용하면 문제가 사라진다.
PID를 가져오는 ManagementFactory.getRuntimeMXBean().getName() 부분에서 문제가 발생하는것 같다.

증상이 일치하네요! commit 내역을 살펴봅시다.

이렇게 바뀌었습니다.

https://github.com/MariaDB/mariadb-connector-j/commit/77834ccc7dad77f3c7dbc0c26637e12b7a3d5644

변경 전 코드를 보시면 SendHandshakeResponsePacket.java에서 인증 정보를 송신하기 위해 현재 pid@hostname을 받아오는 부분이 있습니다. 이때 hotname을 가져오기 위해 InetAddress.getLocalHost().getHostName()을 호출하는데 문제는 getLocalHost()에서 발생합니다. 해당 기능은 자바에서 제공되는 클래스로 hostname을 기반으로 IP 주소를 찾아 반환하는 기능을 담당하는데요 아래는 그 소스를 간략화한 것입니다.

public static InetAddress getLocalHost() throws UnknownHostException {
    if (local.equals("localhost")) {
        return impl.loopbackAddress();
    }

    // -> cache 확인 (마지막 요청 시간이 5초 이내면 cache값 반환)

    localAddrs = InetAddress.getAddressesFromNameService(local, null);

    // -> localAddrs[0] -> cache 처리
}

현재 hostname이 ‘localhost’라면 loopback 주소를 바로 반환하겠지만 만약 아니라면..? getAddressesFromNameService()메서드에서 DNSNameService Class의 lookupAllHostAddr()라는 보기만 해도 무섭고 복잡한 메서드를 호출합니다. 해당 메서드는 호스트네임을 가지고 IP 주소를 조회하는 역할을 하는데 만약 DNS 상태가 좋지 않아 시간이 지연된다면 데이터베이스에서는 connect_timeout 설정값에 따라 더 이상 기다려줄 수 없는 상황이 오게 됩니다. 저희 웹 애플리케이션 서버에서 테스트 결과 lookupAllHostAddr() 메서드에서 약 6초 정도가 소요되는 것으로 확인되었습니다. 빌링 데이터베이스의 connect_timeout 설정값이 5초였기 때문에 당연히 에러가 발생하겠지요.

이러한 문제를 JNA를통하여 현재 pid만 반환하도록 하는 내용이 commit되었으며 2016년 10월에 1.5.4버젼으로 릴리즈 되었습니다.

속이 시원합니다.

빌링 웹 애플리케이션 서버에서 새로운 DB 커넥션을 생성할 때 dnslookup이 6초 이상 걸리는 바람에 DB 서버의 connect_timeout(=5초)이 발생한 문제라는 것을 알 수 있게 되었습니다.

문제를 해결하기 위한 또 다른 방법!

hostname을 localhost로 사용합니다.
/etc/hosts에 IP주소와 hostname을 등록하여 최우선적으로 IP 주소를 반환하도록 합니다.

무엇보다 라이브러리는 최신 버젼을 지향하는 게 정신 건강에 이롭습니다 ^.^