[MySQL] The last packet successfully received from the server was 12,345,678 milliseconds ago 에러 대응하기

데이터베이스

[MySQL] The last packet successfully received from the server was 12,345,678 milliseconds ago 에러 대응하기

망나니개발자 2023. 4. 11. 10:00

이번 포스팅은 문제가 발생하였을 때, 어떻게 장애를 인지하고, 원인을 찾고, 조치 및 대응을 하였는지에 대한 흐름을 기록하기 위해 작성하게 되었습니다. 에러 자체는 대응하기 어려웠던 문제는 아니지만, 문제 상황에서 어떻게 대처하는지 궁금하신 분들께 도움이 되었으면 좋겠습니다.

1. The last packet successfully received from the server was 12,345,678 milliseconds ago 에러 대응하기

[ 문제 상황 인지하기 ]

현재 사내에서는 APM 도구인 핀포인트와 로그 수집 도구인 넬로 등을 활용하여 문제 상황을 인지하고 파악하고 있다. 에러 알람이 와서 확인해보니, 다음과 같은 에러가 발생하고 있었다.

org.springframework.dao.RecoverableDataAccessException:
### Error updating database.  Cause: com.mysql.cj.jdbc.exceptions.CommunicationsException: The last packet successfully received from the server was 30,154,160 milliseconds ago. The last packet sent successfully to the server was 12,345,678 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
### The error may involve com.mangkyu.appstore.port.out.SaveAppUsedHistoryPort.save-Inline
### The error occurred while setting parameters
### Cause: com.mysql.cj.jdbc.exceptions.CommunicationsException: The last packet successfully received from the server was 12,345,678 milliseconds ago. The last packet sent successfully to the server was 30,154,160 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
; The last packet successfully received from the server was 12,345,678 milliseconds ago. The last packet sent successfully to the server was 30,154,160 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.; nested exception is com.mysql.cj.jdbc.exceptions.CommunicationsException: The last packet successfully received from the server was 30,154,160 milliseconds ago. The last packet sent successfully to the server was 30,154,160 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
        at org.springframework.jdbc.support.SQLExceptionSubclassTranslator.doTranslate(SQLExceptionSubclassTranslator.java:100)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81)
        ...

문제가 발생하면 다음과 같이 빨간 점들이 쌓이면서 문제가 발생한 지점을 파악할 수 있다. 참고로 아래에서 사용되는 이미지들은 핀포인트 공식 깃허브에서 가져온 이미지이다.

그리고 해당 점들을 드래그하면 각각의 요청 트랜잭션에 대한 스택 트레이스(프로그램이 시작된 시점부터 현재 위치 까지의 메서드 호출 목록) 을 확인해볼 수 있다.

확인해보니 문제가 발생했던 부분은 모든 요청이 끝난 후에 히스토리성 로그를 데이터베이스에 기록하는 부분이였다. 그리고 예외가 발생하긴 하지만, 다행히도 발생하는 예외를 catch하여 먹고 있어서 정상적인 응답(2xx)를 내보내주고 있어서 다행히 외부로의 영향은 없었다. 이후에는 문제가 발생하는 원인을 찾을 차례이다.

만약 여기서 에러가 사용자에게 영향을 끼치고 있었다면, 원인 파악보다도 조치가 먼저 행해졌을 수 있다. 왜냐하면 발생한 에러의 내용("일정 시간이 지나고 패킷이 와서 에러가 발생한다는 부분")만 보아도 재시작 후에는 문제가 없을 것이 명확히 보였기 때문이다.

[ 에러 원인 파악 ]

나 역시도 대세인 ChatGPT를 굉장히 애용하고 있고, 이번에는 GPT에게 에러가 발생한 원인을 물어봤다. GPT에게 물어볼 때는 회사에 관련된 내용이 포함되지 않도록 처리한 후에 물어보도록 하자. 어찌 보면 당연한 부분인데 뉴스에 나올정도로 문제가 많이 생기는 것 같다.

ChatGPT는 친절하게 답변을 해주었다. 내용은 애플리케이션과 MySQL 데이터베이스 사이의 커넥션이 끊어졌고, 그 이유는 MySQL 서버에 설정된 wait_timeout이라는 설정값보다 패킷을 주고 받은 시간이 넘었기 때문이라는 것이다. wait_timeout은 커넥션을 비활성화 할 기간을 결정하는 MySQL 서버의 시스템 변수라고 한다.

그리고 이에 대한 해결책으로 크게 3가지를 제시해주었다. 그러면 현재까지 파악한 내용을 바탕으로 대응해보도록 하자.

커넥션을 사용하기 전에 커넥션이 유효한지 검사한다. 만약 해당 커넥션이 유효하지 않다면 새로운 커넥션을 맺게 된다.
MySQL 서버에 설정된 wait_timeout 값을 증가시킨다.
autoReconnect=true 옵션을 사용한다. 그러면 MySQL Connector/J driver는 커넥션이 끊어진 경우에 자동으로 재연결을 할 것이다.

[ 에러 원인 파악 ]

wait_timeout 설정값 확인하기
autoReconnect=true 옵션 확인하기
Database 로그 확인하기
서버 재시작하기
DataSource 확인하기

1. wait_timeout 설정값 확인하기

가장 먼저 확인할 부분은 wait_timeout을 확인하고, “실제로 요청이 wait_timeout 설정값을 넘어서 주고받은 적이 없었는가?” 이다. 왜냐하면 별도의 설정이 없었다면 wait_timeout은 8시간이고, 문제가 발생했던 시간은 오후 12:48분 쯤으로 이미 오전 중에 요청을 주고 받았을 것이기 때문이다.

SHOW SESSION VARIABLES LIKE "wait_timeout";

확인해보니 해당 값은 기본 설정대로 8시간이였다. 해당 값이 지나치게 짧게 설정되어 있었다면 변경할 필요가 있었겠지만, 이 부분에서 별도의 수정은 필요 없을 거라고 판단하였다.

2. autoReconnect=true 옵션 확인하기

autoReconnect=true 옵션을 주면 커넥션이 끊어진 경우에 자동으로 재연결을 한다. 일단 현재 에러가 발생하는 이유는 연결이 끊어진 커넥션이 존재하기 때문이므로 해당 옵션이 존재하는지 확인하는 것이 중요하다.

jdbc:mysql://localhost:3308/mangkyu?autoReconnect=true&allowMultiQueries=true&validationInterval=60000&useSSL=false&allowPublicKeyRetrieval=true&jdbcCompliantTruncation=false

해당 옵션은 url에 붙여주면 되는데 이미 붙여져 있었고, 그 외에도 관련 설정들 역시 대응되어 있었다.

커넥션 풀에는 있지만 이미 끊어진 커넥션이라서 다시 맺어주는 설정(autoReconnect)
끊어진 커넥션일 경우에 처음에는 에러가 발생하므로 커넥션이 정상 상태인지 확인하는 설정(validationQuery)
넥션 풀 안에 있는 유휴 상태의 커넥션을 대상으로 테스트를 실행하는 설정(testWhileIdle)
특정 시간 간격으로 유효하지 않은 커넥션을 제거하는 설정(timeBetweenEvictionRunsMillis)

참고로 여기에서 주의해야 할 부분은 설정 내용에 따라 데이터 정합성이 깨질 수 있다는 점이다. 예를 들어 autoReconnect 설정만 되어있는 상황에서, 데이터베이스에 INSERT를 3번 한다고 하자. 이때 첫 번째 커넥션으로는 INSERT에 성공했지만, 다른 트랜잭션(커넥션)에서 INSERT 시에 해당 커넥션이 wait_timeout을 초과한 상태일 수 있기 때문이다.

이러한 부분을 해결하고자 validationQuery를 통해 요청 전에 커넥션 상태를 확인할 수 있도록 설정하는데, 그러면 쿼리가 한번 더 실행되는 것이므로 부하가 될 수 있어서 주의가 필요하다.

따라서 현재 상황은 커넥션 풀에 유효하지 않은 커넥션(MySQL 서버와 연결이 끊어진 커넥션)이 존재하게 되었고, 그에 대한 여파로 요청이 계속 실패하고 있음을 짐작할 수 있었다.

3. Database 로그 확인하기

이 부분은 직접 DB 서버로의 접근 권한이 없어서 DBA분께 요청을 드렸다. 하지만 해당 시간에 문제가 발생하는 서버 IP에 대한 로그는 없다고 확인받았다. 그리고 이를 바탕으로 커넥션 풀에서 새로운 커넥션이 계속 만들어지는 것이 아님을 확신할 수 있었다.

4. 서버 재시작하기

히스토리성 데이터이긴 하지만 계속해서 INSERT 쿼리에 실패하고 있고, 에러 로그 알림도 계속해서 오고 있으니 당장 급한 불부터 끄자고 판단하였다. 필요한 설정들이 모두 되어 있음에도 불구하고, 애플리케이션 서버의 커넥션 풀에는 유효하지 않은 커넥션이 남아 있는 상황이다. 따라서 현재로서 할 수 있는 가장 단순하고 확실한 해결책은 애플리케이션을 재시작하여 새로운 커넥션을 커넥션 풀에서 관리하도록 하는 것이다. 그래서 애플리케이션을 재시작하였고, 역시나 에러는 해결되었다.

5. DataSource 확인하기

마지막 남은 부분은 데이터베이스와의 커넥션 객체를 관리하는 DataSource이다. 그래서 현재 사용되는 DataSource를 확인해보니, commons-dbcp-1.4를 사용하고 있었다.

(최근에는 Hikari DataSource가 다른 라이브러리들을 성능상 압도하기 때문에 스프링 부트 역시도 2.0 부터는 이를 기본으로 사용한다. 하지만 문제가 발생했던 서버는 내년에 걸쳐 Fade-out 되는 레거시 서버이며, 기능 추가 없이 유지보수만 되는 상황이라서 DataSource를 변경해주지 않았다. 하지만 계속해서 기능이 추가되는 서버라면 Hikari DataSource를 사용해주는 것이 좋다.)

그래서 해당 버전의 DBCP 버전에서 오류가 있는지 확인을 하던 차에 다음의 포스팅을 발견하게 되었다.

해당 서버는 JDK 1.8을 사용중인데, 그에 맞는 올바른 DBCP 버전을 사용하고 있지 않아서 문제가 발생했을 수 있을 것 같다. 포스팅 내용을 보면 DBCP1.4.1에 메모리 누수 버그도 있었다고 한다. 그래서 DBCP 버전을 올려서 경과를 지켜볼 예정이다.

이번 포스팅은 문제가 발생하였을 때, 어떻게 장애를 인지하고, 원인을 찾고, 조치 및 대응을 하였는지에 대한 흐름을 기록하기 위해 작성하게 되었습니다. 에러 자체는 대응하기 어려웠던 문제는 아니지만, 문제 상황에서 어떻게 대처했는지 어떤 사고 과정을 거쳤는지 궁금하신 분들께 도움이 되었으면 좋겠습니다! 혹시 위 문제와 관련해서 피드백을 주실 부분 등이 있다면 편하게 남겨주세요ㅎㅎ

이 외에도 더 어렵거나 알면 좋을만한 운영 이슈들이 있었는데, 틈틈이 작성해보도록 하겠습니다. 감사합니다:)

저작자표시 비영리 변경금지