JDBC setReadOnly 호출 이슈 해결기
안녕하세요. 인프랩 백엔드 개발자 인트, 제이입니다.
인프랩의 백엔드 서버는 대부분 Node.JS로 구성되어 있지만 일부 JVM 서버도 함께 운영됩니다.
JVM 서버의 경우 모니터링으로 핀포인트를 활용하고 있습니다.
최근에 핀포인트를 통해 간헐적으로 원인을 파악하기 어려운 에러 알림이 발생했었는데, 이에 대한 해결 경험을 공유하고자 합니다.
문제가 발생한 환경
- Spring Boot 3.2.5
- Spring JDBC 6.1.6
- PostgreSQL Driver 42.6.2
- AWS Advanced JDBC Wrapper 2.2.3
- AWS Aurora PostgreSQL 14.9.6
문제 상황
핀포인트에서는 다음과 같은 에러 메시지를 확인할 수 있었습니다.
이번에 경험한 에러는 특정 API에서만 발생하는 게 아닌 불특정 조회 API에서 간헐적으로 발생했습니다.
핀포인트 로그
에러 메시지는 다음과 같습니다.
Cannot change transaction read-only property in the middle of a transaction핀포인트 로그를 보면 에러는 트랜잭션의 마지막에 commit과 close를 하는 과정에서 발생했습니다.
여기서 특이한 점을 발견할 수 있었습니다.
- 커넥션을 반납하는 과정에서 의문의 쿼리 요청이 발생
- 에러가 발생했지만 이후 정상적으로 다른 트랜잭션이 처리됨 (API는 정상적으로 응답)
에러 발생 위치
먼저 에러 메시지를 통해 어떠한 코드에서 에러가 발생했는지 파악하고자 했습니다.
에러 메시지를 해석하면 트랜잭션 내에서 읽기 전용 속성을 변경할 수 없다는 의미라는 것을 확인할 수 있습니다.
핀포인트에서 에러 발생지점 근처에 사용한 클래스는 PgConnection, ProxyConnection, PgStatement 라는걸 확인할 수 있습니다.
이를 통해 PostgreSQL JDBC 드라이버 내부에서 발생했다는 것을 의심할 수 있었습니다.
실제로 드라이버의 PgConnection 클래스
내부 setReadOnly 메서드
에 동일한 에러 메시지를 출력하는 코드를 찾을 수 있었습니다.
메서드의 첫 번째 분기에 해당하면 에러가 발생하며 queryExecutor의 트랜잭션 상태가 IDLE이 아닌 경우입니다.
queryExecutor.getTransactionState()는 TransactionState 열거형을 반환하며, 다음 세 가지 상태를 가집니다.
public enum TransactionState {
IDLE,
OPEN,
FAILED
}이름을 통해 예상할 수 있듯이 트랜잭션 시작 전에는 IDLE, 트랜잭션이 시작되면 OPEN이 됩니다.
PgConnection은 JDBC의 Connection 인터페이스를 구현하고 있으며, 해당 인터페이스 setReadOnly 메서드의 설명을 보면 다음과 같습니다.
setReadonly는 드라이버에게 데이터베이스 최적화를 위한 힌트를 제공하는 메서드로, 트랜잭션 중에는 호출할 수 없다고 명시되어 있습니다.
의문의 쿼리
이후 트랜잭션 종료 시점에 호출된 의문의 쿼리를 살펴보았습니다.
핀포인트에서 확인한 실행한 쿼리는 다음과 같습니다.
SELECT SERVER_ID,
CASE WHEN SESSION_ID = 'MASTER_SESSION_ID' THEN TRUE ELSE FALSE END,
CPU,
COALESCE(REPLICA_LAG_IN_MSEC, 0),
LAST_UPDATE_TIMESTAMP
FROM aurora_replica_status()
WHERE EXTRACT(EPOCH FROM (NOW() - LAST_UPDATE_TIMESTAMP)) <= 300
OR SESSION_ID = 'MASTER_SESSION_ID'이 쿼리는 백엔드 서버 코드상에는 존재하지 않았습니다.
하지만 FROM절에 aurora_replica_status()라는 함수를 호출하는 것으로 보아,
저희가 사용하는 Aurora PostgreSQL과 관련된 코드에서 발생한 것으로 추정할 수 있었습니다.
AWS JDBC 래퍼 드라이버
AWS Aurora에는 쓰기 인스턴스가 다운되었을 때 읽기 인스턴스 중 하나가 쓰기 인스턴스로 승격되는 failover 기능이 있는데요.
AWS에서는 failover로 발생하는 다운타임을 최소화하기 위해, 기존 JDBC 드라이버를 감싼 래퍼 드라이버를
제공하고 있습니다.
인프랩은 메인 데이터베이스로 AWS Aurora PostgreSQL 클러스터를 사용하며, 한 대의 쓰기 인스턴스와 여러 읽기 인스턴스로 구성되어 있습니다.
JVM 백엔드 서버는 강의 도메인을 담당하며 결제, 정산 등 서비스의 중요 도메인을 다룹니다.
이에 따라 높은 가용성이 필요했고 쓰기 인스턴스가 교체되는 상황에서 빠른 failover(fast failover)를 이루고자 래퍼 드라이버를 사용하고 있습니다.
Failover Plugin
AWS 래퍼 드라이버는 fast failover 뿐만 아니라 다른 여러 가지 기능을 제공합니다.
드라이버는 이를 플러그인 형태로 제공하며 드라이버 설정을 통해 원하는 플러그인을 활성화할 수 있습니다.
GitHub에 존재하는 공식 문서를 살펴보면 failover가 어떠한 방식으로 이루어지는지 볼 수 있습니다.
애플리케이션에서 JDBC 메서드를 실행하면 원본 Connection(PgConnection) 대신 드라이버가 감싼 커넥션의 메서드가 먼저 호출됩니다.
만약 쓰기 인스턴스가 실패한 경우 드라이버는 내부 topology 캐시를 통해 새로운 쓰기 인스턴스를 찾습니다. 이후 물리적 커넥션을 교체해 새롭게 승격된 인스턴스를 더 빠르게 사용할 수 있게 합니다.
저희는 이 래퍼 드라이버가 의문의 쿼리를 실행했다는 것을 의심했고, 드라이버 코드 저장소를
살펴보니 의문의 쿼리와 동일한 코드
를 찾을 수 있었습니다.
쿼리를 만드는 메서드 이름은 getTopologyQuery며 클러스터의 상태를 확인해 쓰기 인스턴스의 교체 여부를 파악합니다.
앞으로 이 쿼리를 topology 쿼리라고 부르겠습니다.
원인 추론
지금까지의 분석을 바탕으로 정리하면 다음과 같습니다.
- 트랜잭션 종료 시 간헐적으로 topology 쿼리가 실행됨
- 해당 쿼리는 AWS에서 제공하는 JDBC 래퍼 드라이버 내부에서 실행됨
- JDBC의
setReadOnly메서드는 트랜잭션 중에 호출할 수 없음
이에 따라 다음과 같은 시나리오로 에러가 발생했을 것으로 추론됩니다.
- (1) 트랜잭션 종료
- (2)
TransactionState가IDLE로 변경됨 - (3) 특정 조건에서 topology 쿼리가 실행됨
- (4)
TransactionState가 다시OPEN으로 변경됨 - (5)
setReadOnly메서드 호출 - (6) 에러 발생
간단한 해결 방안
지금까지의 분석을 통해 이 에러를 해결하는 가장 간단한 방법은 AWS 래퍼 드라이버를 사용하지 않는 것입니다.
왜냐하면 래퍼 드라이버가 트랜잭션 종료 시점에 topology 쿼리를 실행하기 때문에 발생한 문제이기 때문입니다.
저희가 이 드라이버를 사용한 이유는 앞서 언급한 대로 쓰기 인스턴스 장애의 다운타임을 최소화하기 위함이었는데요.
하지만 이러한 장애는 발생 빈도가 낮고 현재 대부분의 백엔드 서버 스택인 Node.JS에는 래퍼 드라이버가 없기에, 일부 JVM 서버만 적용해서 얻는 이점이 크지는 않다고 생각합니다.
그래도 다음과 같은 이유로 인해 이 방법을 적용하지 않았습니다.
- 앞서 언급한 높은 가용성을 포기하는 선택지는 최대한 배제
- 문제의 근본적인 원인을 파악하지 않고 단순히 해당 원인을 제거하는 게 적절한가에 대한 의문
- 드라이버 설정을 제대로 하지 않아 발생한 문제일 수 있기에, 이를 파악하는 게 더 중요하다고 판단
- 간헐적으로 발생하는 에러는 원인을 찾기 어렵지만, 해결하는 과정에서 많은 것을 배울 수 있다고 생각
에러 재현
디버깅 환경: IntelliJ IDEA 2024.2.3
근본적인 원인을 파악하려면 지금까지의 분석이 맞는지 검증이 필요합니다.
또한 다음과 같은 의문을 해결해야 합니다.
- topology 쿼리가 트랜잭션 종료 과정에서 실행되는 이유는 무엇인가?
- AWS 드라이버는 어떤 상황에서 topology 쿼리를 실행하는가?
- 트랜잭션 종료 과정에서
setReadOnly메서드가 호출되는 이유는 무엇인가?
이를 위해 로컬에서 디버깅을 통해 에러를 재현해 보기로 했습니다.
에러는 불특정 조회 API에서 간헐적으로 발생했기 때문에 다음과 같은 방법을 사용했습니다.
- 임의의 조회 API를 선택
- 에러 발생 위치에 중단점을 설정하고 디버그 모드로 서버 실행
- 부하 테스트 스크립트를 사용해 선택한 조회 API를 반복 호출
스크립트를 실행한 후 일정 시간이 지나 중단점이 트리거 되었습니다.
위 화면에서 파악할 수 있는 정보는 다음과 같습니다.
- (A)
CourseApiRepository의findBySlug메서드 실행 시 에러 발생 - (B)
readOnly상태를true로 바꾸려고 시도 - (C)
TransactionStatus의 상태는OPEN - (D) 현재 커넥션의
readOnly값은true
추측한 대로 TransactionStatus 의 상태가 OPEN인 상황에서 setReadOnly 메서드가 호출되었습니다.
findBySlug 메서드는 @Transactional(readOnly = true) 어노테이션이 적용된 (클래스에 어노테이션 적용) getCourseWithVoucher 메서드에서 실행되었으며 이 메서드의 가장 첫
번째 쿼리 호출입니다.
여기서 몇 가지 의문점이 더 발생합니다.
- 핀포인트에는 트랜잭션을 commit 하는 과정에서 에러가 발생했다고 나오지만, 로컬에서는 트랜잭션의 첫 번째 쿼리에서 발생
PgConnection의 readOnly 상태는 이미true
내부 라이브러리 코드 파악
핀포인트에서 확인한 흐름은 아니지만 동일한 에러가 발생하도록 재현한 상황에서 더 자세한 정보가 필요했습니다.
IntelliJ IDEA는 기본적으로 내부 라이브러리 호출 스택을 하나로 묶어 디버깅 화면에서 표시해 주는데요.
우리는 내부 드라이버의 동작을 확인해야 하는 상황이므로, 스택 화면을 우클릭 후 Hide Frames from Libraries 옵션을 해제합니다.
스택 내부를 살펴보면 다음과 같습니다.
여기서 눈여겨 볼 점은
- (A), (B), (C)
setReadOnly메서드는 다양한Connection구현체에서 사용 HikariProxyConnection→ProxyConnection→ConnectionWrapper→PgConnection순으로 호출- (D) 가장 바깥쪽에 존재하는
setReadOnly를 호출하는 클래스는LazyConnectionDataSourceProxy의getTargetConnection
앞서 언급한 래퍼 드라이버 설명과 동일하게 실제 커넥션보다 래퍼의 커넥션이 먼저 사용되는 걸 확인할 수 있습니다. (B)
이제 getTargetConnection를 선택해 (D) setReadOnly 메서드의 첫 호출부를 확인합니다.
해당 메서드는 이름처럼(getTargetConnection) 커넥션 풀에서부터 트랜젝션에 사용하기 위한 커넥션을 가져옵니다.
기존의 실행 중인 트랜젝션이 없다면 this.target 이 null이고, 이때 DataSource 에서 커넥션을 가져와 할당합니다.
이후 다시 이 메서드가 호출되면 처음 호출될 때와는 다르게 기존에 할당된 this.target을 반환합니다.
이 메서드는 아래의 두 조건을 모두 만족할 때 target의 setReadOnly를 호출합니다.
this.readOnly가 truereadOnlyDataSource가 null
디버깅 메뉴의 표현식을 보면 (하단 박스) this.readOnly는 true 이며 readOnlyDataSource 값 또한 null이기 때문에 setReadOnly 가 불리는 조건을 모두 만족해 함수를 호출하게 됩니다.
this.readOnly는 기본값이 false이며,@Transactional(readOnly = true)어노테이션을 사용하면 true로 변경됩니다.
Topology 캐시
아직 남은 의문점 중 하나인 AWS 래퍼 드라이버는 어떠한 상황에서 topology 쿼리를 수행하는 지 살펴보려고 합니다.
앞서 보여드린 커넥션 간의 스택 트레이스에는 topology 쿼리 호출부를 찾을 수 없었는데요.
이는 이미 topology 쿼리를 실행 한 이후의 스택을 보여주기 때문입니다.
이를 해결하기 위해 topology 쿼리를 만드는 getTopologyQuery 메서드를 호출하는 곳에 중단점은 건 후 부하 테스트를 진행하였습니다.
getTopologyQuery메서드를 호출하는 곳은 래퍼 드라이버의 AuroraHostListProvider 클래스의 queryForTopology 메서드입니다.
queryForTopology 메서드는 getTopology 메서드가 호출하는데 이곳에서 중단점이 트리거 된 상황에서의 스택을 살펴보면 다음과 같습니다.
여기서 많은 정보를 파악할 수 있습니다.
- (A) AWS 래퍼 드라이버의
setReadOnly메서드를 호출 - (B)
FailOverConnectionPlugin의updateTopology메서드가 호출 - (C)
AuroraHostListProvider의getTopology메서드를 호출 - (D)
getTopology메서드는topologyCache에서 호스트 정보를 조회 - (E) 호스트 정보가 존재하지 않으면 topology 쿼리를 수행
- (F) 조회한 쿼리 결과를 캐시에 저장
- (G) 캐시의 만료시간은 30000000000 nanosecond이며 30초를 의미
래퍼 드라이버는 jdbc의 특정 메서드가 실행되면 topology 쿼리를 수행할지 여부를 확인합니다.
만약 topology 쿼리를 수행했다면 결과를 캐시에 저장하고, 캐시가 만료되면 다시 topology 쿼리를 수행합니다.
이제 다음 시나리오가 발생했을 때 에러가 발생한다는 것을 파악할 수 있습니다.
LazyConnectionDataSourceProxy의getTargetConnection메서드가 호출됨this.target의setReadOnly메서드가 호출됨- AWS 래퍼 드라이버의
setReadOnly메서드가 호출됨 - 마침 topology 캐시가 만료되어
topology쿼리가 수행됨 PgConnection의TransactionStatus의 상태가OPEN으로 변경됨PgConnection의setReadOnly메서드가 호출됨- 에러 발생
일반적으로 LazyConnectionDataSourceProxy의 getTargetConnection 메서드가 호출되고, 가져온 커넥션의 setReadOnly 메서드를 호출하는 시점에는
아직 아무런 쿼리를 실행하지 않는 상황이기에 TransactionStatus 의 상태가 IDLE이며 따라서 setReadOnly 메서드가 호출되어도 에러가 발생하지 않습니다.
하지만 AWS 래퍼 드라이버를 사용하게되면 PgConnection의 setReadOnly 호출하기 전에 topology 캐시의 만료 여부를 확인합니다.
만약 캐시가 만료되었다면 새로운 topology 쿼리를 수행하게 되고, setReadonly 호출보다 먼저 TransactionStatus의 상태가 OPEN으로 변경됩니다.
이로인해 결국 에러가 발생하게 됩니다.
즉 이러한 조건이 모두 맞아야만 에러가 발생하기에 불특정 조회 API에서 간헐적으로 발생했던 것입니다.
마지막 의문점 해결
아직 해결하지 못한 의문점이 하나 있습니다.
바로 핀포인트에서 확인한 에러 발생 시점과 로컬에서 발생한 시점이 다르다는 것이었습니다.
핀포인트는 commit 메서드, 즉 트랜잭션이 마무리되는 시점에서 에러가 발생했고 로컬에서는 트랜잭션의 시작 (첫 쿼리를 수행하는 부분) 에서 발생했습니다.
로컬에서도 commit 시점에 이슈가 재현되도록 하기 위해 IntelliJ IDEA의 조건부 중단점 기능을 활용하였습니다.
이 기능을 활용하면 중단점을 설정할 때 특정 중단점을 먼저 트리거 된 이후 해당 중단점이 트리거 되도록 할 수 있습니다.
즉 중단점 간의 선후관계를 설정할 수 있습니다.
저희는 PgConnection의 commit 이후에 setReadOnly 에러가 발생하는 걸 감지해야 하므로 각 메서드에 중단점을 설정하고,
setReadOnly 메서드에는 조건부 중단점을 설정해 commit 이후에만 중단되도록 설정했습니다.
이제 부하 테스트를 수행했고 원하는 상황을 재현할 수 있었습니다.
다음은 중단점이 트리거 된 상황에서의 스택입니다.
이곳에서도 다음과 같은 정보를 파악할 수 있습니다.
- (A)
commit이 수행됨- 스택 트레이스에는 안보이지만
PgConnection의commit메서드가 호출됨 - 따라서
TransactionStatus의 상태가OPEN에서IDLE로 변경됨
- 스택 트레이스에는 안보이지만
- (B)
DataSourceUtils의resetConnectionAfterTransaction이 수행됨 - (C) 이 메서드는
resetReadOnly값이true인 경우setReadOnly를 호출하고 인자를false로 변경resetReadOnly의 값은@Transactional어노테이션의 readOnly 옵션과 동일
- (D) 래퍼 드라이버의
setReadOnly메서드가 호출됨
이를 통해 트랜잭션 종료 시점에서도 setReadOnly 메서드가 호출되는 것을 확인할 수 있었습니다.
setReadOnly를 수행하는 메서드명은 resetConnectionAfterTransaction이며 이름처럼 트랜잭션 종료 시점에 커넥션을 리셋하는 메서드입니다.
이 메서드는 조회용으로 사용된 커넥션이었는지 확인하고 쓰기용으로도 사용될 수 있도록 setReadOnly를 호출해 false로 변경합니다.
이는 자연스러운 동작이지만 래퍼 드라이버를 사용하는 환경에서는 첫 쿼리시점과 동일한 이유로 에러가 발생할 수 있습니다.
때마침 topology 캐시가 만료되어 쿼리를 수행하게 되면 TransactionStatus의 상태가 다시 OPEN으로 변경되고 setReadOnly 메서드가 호출되기 때문입니다.
해결 방법
지금까지 트랜잭션의 시작과 종료 시점에 setReadOnly 메서드가 호출되는 상황과 이로 인한 에러의 원인을 파악했습니다.
이제 이를 해결하기 위한 방법을 공유하겠습니다.
setReadOnlyDataSource
래퍼 드라이버는 JDBC의 메서드를 수행하기 전에 topology 캐시를 확인하고 만료되었을 때 새로운 쿼리를 수행합니다.
하지만 TransactionStatus의 상태가 IDLE인 상황에서 호출해야 하는 setReadOnly 메서드를 호출할 때 topology 쿼리를 먼저 수행하게 되면 에러가 발생합니다.
따라서 래퍼 드라이버의 코드를 수정하는 방안이 있지만, 저희는 앞서 살펴본 LazyConnectionDataSourceProxy의 코드를 통해 다른 방안을 찾을 수 있었습니다.
바로 getTargetConnection 메서드에서 setReadOnly 메서드를 호출하지 않도록 노란색 분기를 false로 만드는 것입니다.
this.readOnly는 @Transactional의 readOnly 옵션을 통해 결정되는 값이라서 이 값을 false로 변경할 수는 없습니다.
하지만 readOnlyDataSource의 값은 setReadOnlyDataSource 메서드를 통해 설정할 수 있습니다.
위 메서드는 Spring 6.1.2 버전부터 추가된 메서드로 읽기전용 DataSource를 설정하는 메서드입니다.
JavaDoc 내용 중에, 읽기전용 DataSource는 사전에 readOnly의 기본값을 true로 설정한 것을 기대하기에
매번 트랜잭션의 시작과 끝에서 readOnly값을 스위치하지 않도록 한다는 문구가 눈에 띄었습니다.
그전에 읽기전용 DataSource readOnly 기본값을 true로 설정하는 걸 기대한다는 의미를 살펴보겠습니다.
저희는 하나의 쓰기 인스턴스와 여러 읽기 인스턴스를 사용하고 있기에, DataSource도 쓰기용과 읽기용으로 나누어 사용하고 있습니다.
그리고 읽기전용 DataSource는 readOnly 기본값을 true로 설정하고 있었습니다.
spring:
datasource:
writer:
driverClassName: 'software.amazon.jdbc.Driver'
jdbcUrl: '쓰기 인스턴스 URL'
reader:
driverClassName: 'software.amazon.jdbc.Driver'
jdbcUrl: '읽기 인스턴스 URL'
read-only: true이 옵션을 통해 커넥션 풀에서 커넥션을 생성할 때 readOnly 값을 true로 설정합니다.
이전 에러 재현 장에서 PgConnection의 setReadOnly 메서드가 호출되는 시점에서 readOnly 값이 이미 true로 설정된 이유였습니다.
LazyConnectionDataSourceProxy 추가기능
setReadOnlyDataSource 메서드를 통해 새로 얻게 된 기능이 있습니다.
바로 @Transactional의 readOnly 옵션에 따라 DataSource를 분기할 수 있다는 것입니다.
LazyConnectionDataSourceProxy는 쿼리를 실제로 호출이 필요한 시점까지 JDBC 커넥션 생성을 지연시킵니다.
해당 클래스의 getTargetConnection 메서드가 호출되는 시점이 바로 커넥션이 생성되는 시점입니다.
해당 메서드를 보면 getDataSourceToUse 메서드를 호출하는데, 이 메서드는 readOnly 옵션에 따라 적절한 DataSource를 반환합니다.
this.readOnly 값이 true이면서 readOnlyDataSource가 설정되어 있으면 readOnlyDataSource를 반환하고, 그렇지 않으면 targetDataSource를 반환합니다.
이를 통해 targetDataSource에는 쓰기용 DataSource를, readOnlyDataSource에는 읽기전용 DataSource를 설정하면 트랜잭션 readOnly 옵션에 따라 DataSource를 분기할 수 있습니다.
최종 설정
저희는 기존에 DataSource 분기를 위해 RoutingDataSource를 사용하고 있었습니다.
현재는 다음과 같이 수정해서 사용하고 있습니다.
요약
- AWS 래퍼 드라이버를 사용하는 환경에서 트랜잭션 종료 시점에
setReadOnly호출 시 간헐적으로 에러발생 PgConnection의setReadOnly메서드는 트랜잭션 중에 호출할 수 없음- 래퍼 드라이버의 Failover 플러그인은 클러스터 상태를 확인하기 위해 topology 쿼리를 수행
- IDE 디버깅 기능을 활용해 원인 재현 및 분석 수행
- 트랜잭션 시작과 끝에서
setReadOnly호출 시 topology 쿼리를 수행하면 에러 발생하는걸 확인 LazyConnectionDataSourceProxy의setReadOnlyDataSource메서드로 읽기전용 DataSource를 설정해 해결
마무리
지금까지 JDBC setReadOnly 관련 이슈의 원인에 대한 설명과 해결 과정을 공유하였습니다.
쉽게 해결하는 방법이 있던 이슈였지만 지속적인 디버깅을 통해 스프링이 트랜잭션을 어떻게 관리하는지 파악할 수 있었습니다.
또한 저희가 단순히 가져다 써왔던 드라이버에 대한 내부 동작을 이해할 수 있었습니다.
다음에 더 유익한 글로 찾아뵙겠습니다.
긴 글 읽어주셔서 감사합니다.
