PgBouncer 뒤에서 @Transactional 쓰기만 죽었다 — log4jdbc가 부른 트랜잭션 장애 트러블슈팅

읽기는 멀쩡한데 쓰기만 전부 500으로 죽었다. 그것도 어제까지 잘 돌던 서비스가. 범인은 의외로 "SQL 로그 좀 예쁘게 보려고" 끼워 넣은 드라이버였다. PgBouncer 뒤에서 @Transactional 쓰기 요청만 골라 죽이던 이 장애를 어떻게 잡았는지 정리한다.

핵심 요약

• 증상: 조회(SELECT)는 정상, @Transactional 쓰기 요청만 전부 500 (CannotCreateTransactionException). 헬스체크도 DOWN.
• 환경: 앱이 PostgreSQL에 직접 붙지 않고 PgBouncer(커넥션 풀러)를 경유. pool_mode = transaction.
• 방아쇠: 누군가 JDBC 드라이버를 org.postgresql.Driver → log4jdbc(DriverSpy, SQL 로깅 프록시)로 바꿈.
• 근본 원인: PgBouncer 트랜잭션 풀링 + server-side prepared statement 충돌. 드라이버를 바꾸며 prepareThreshold=0 옵션이 빠짐.
• 해결: 드라이버 원복 + prepareThreshold=0 (또는 해당 DB만 pool_mode=session).

1. 배경 — 우리 DB 앞엔 PgBouncer가 있다

먼저 구조부터. 보통 스프링 앱은 이렇게 PostgreSQL에 바로 붙는다고 생각한다.

App (Spring/JPA)  ──►  PostgreSQL

그런데 우리 환경은 중간에 한 단이 더 있다. 커넥션 수가 폭증해 DB 커넥션 슬롯이 고갈되는 걸 막으려고, 서버 담당이 PgBouncer라는 커넥션 풀러를 앞단에 둔 것이다.

App (Spring/JPA)  ──►  PgBouncer  ──►  PostgreSQL
                       (pool_mode=transaction)

PgBouncer는 "수십 개의 앱 커넥션을 소수의 실제 DB 커넥션으로 다중화"해주는 중간 관리자다. 문제는 이 다중화 방식(pool_mode)이 몇 가지가 있다는 점이다.

pool_mode	서버 커넥션을 언제까지 빌려주나	특징
session	클라이언트가 연결을 끊을 때까지	세션 기능 안전, 커넥션 절약 효과 적음
transaction	트랜잭션 하나 끝날 때까지만	커넥션 절약 큼, 세션 상태 안 살아남음
statement	쿼리 한 문장 단위	가장 공격적, 제약 많음

우리는 커넥션 절약이 절실해서 transaction 모드였다. 이 한 줄이 이번 장애의 절반을 차지한다. "트랜잭션이 끝나면 서버 커넥션을 회수해서 다른 클라이언트에게 넘긴다"는 동작을 꼭 기억하자.

2. 문제 발생 — 읽기는 되는데 쓰기만 죽는다

어느 날 아침, 백엔드가 이상하게 굴기 시작했다.

• 화면 조회(단순 SELECT) → 정상
• 등록/수정처럼 @Transactional이 걸린 쓰기 API → 전부 500
• 스프링 액추에이터 /health → DOWN

로그를 까보니 쓰기 요청마다 이 예외가 찍혔다.

org.springframework.transaction.CannotCreateTransactionException:
    Could not open JDBC Connection for transaction;
    nested exception is org.postgresql.util.PSQLException: ...
  at o.s.jdbc.datasource.DataSourceTransactionManager.doBegin(...)
  at o.s.jdbc.datasource.DataSourceTransactionManager.doBegin(...)
  ...

CannotCreateTransactionException. 스프링이 "트랜잭션을 시작조차 못 하겠다"고 손을 든 것이다. 읽기는 되는데 트랜잭션 쓰기만 깨진다니, 직관적으로 잘 안 와닿는 비대칭이었다.

3. 진단 과정 — 범위를 좁혀나가다

3-1. DB가 죽었나? → 아니다

가장 먼저 의심한 건 DB 자체였다. 그래서 앱을 거치지 않고, 파이썬 psycopg2로 DB에 직접 INSERT를 날려봤다.

import psycopg2
conn = psycopg2.connect(host="db-host", port=5432, dbname="appdb",
                        user="app", password="****")
cur = conn.cursor()
cur.execute("INSERT INTO t_test(name) VALUES ('hello')")
conn.commit()   # ← 정상 커밋됨!
print("write ok")

정상적으로 들어갔다. DB도, 스키마도, 권한도 멀쩡하다. 즉 문제는 PostgreSQL이 아니라 앱 ↔ DB 사이 어딘가에 있다. 이 한 번의 실험으로 용의선상에서 "DB 서버"를 지웠다. 트러블슈팅에서 제일 중요한 건 이렇게 범위를 반씩 잘라내는 것이다.

3-2. 최근 바뀐 게 뭐지? → 드라이버 교체

"어제까지 됐는데 오늘 안 된다"면 그 사이 변경점을 의심해야 한다. 커밋 로그를 뒤져보니, 전날 누군가 SQL 로그를 보기 좋게 찍으려고 JDBC 드라이버를 바꿔놨다.

# before (정상)
spring.datasource.driver-class-name=org.postgresql.Driver
spring.datasource.url=jdbc:postgresql://pgbouncer-host:6432/appdb?prepareThreshold=0

# after (장애)
spring.datasource.driver-class-name=net.sf.log4jdbc.sql.jdbcapi.DriverSpy
spring.datasource.url=jdbc:log4jdbc:postgresql://pgbouncer-host:6432/appdb

두 가지가 동시에 바뀌었다. ① 드라이버가 org.postgresql.Driver → log4jdbc DriverSpy(실제 드라이버 앞에 끼는 로깅 프록시). ② 그러면서 URL의 prepareThreshold=0 옵션이 슬그머니 사라졌다.

3-3. 교차검증 — 세 모델에게 같은 질문을 던졌다

원인이 PgBouncer인지 드라이버인지 확신이 안 서서, 같은 증상·환경을 정리해 Claude·GPT·Gemini 세 모델에 똑같이 물어봤다. 셋 다 입을 모아 "PgBouncer 트랜잭션 모드 × server-side prepared statement 충돌"을 지목했다. 특히 GPT가 메커니즘을 가장 정확히 짚어줬다. 한 모델만 봤으면 놓쳤을 디테일을 교차검증이 잡아줬다.

4. 근본 원인 — prepared statement는 "그 커넥션의 사물함"이다

핵심 메커니즘은 이렇다. PostgreSQL JDBC 드라이버(pgJDBC)는 같은 쿼리가 반복되면, 매번 파싱하지 않으려고 일정 횟수(prepareThreshold, 기본 5) 이후 server-side prepared statement로 승격시킨다. 서버에 S_1 같은 이름표를 붙여 미리 준비해두고, 다음부턴 그 이름표만 호출하는 방식이다.

비유: prepared statement는 헬스장 사물함에 미리 넣어둔 운동화다. "3번 사물함에 내 신발 있어요"라고 외치면 직원이 꺼내준다. 그런데 PgBouncer transaction 모드는, 운동 한 세트(=트랜잭션)가 끝날 때마다 사물함을 회수해 다른 회원에게 배정한다. 다음에 갔더니 나한테는 5번 사물함이 배정됐는데, 거기엔 내 신발이 없다. "3번에 있다며요?" → 직원: "그런 신발 없는데요(prepared statement does not exist)."

즉 트랜잭션이 끝나면 PgBouncer가 서버 커넥션(backend)을 회수하므로, 다음 트랜잭션은 다른 backend에 붙을 수 있다. 그런데 드라이버는 "아까 만든 S_1 그대로 쓰면 되지" 하고 호출한다. 새 backend엔 S_1이 없다. 그래서 이런 류의 에러가 터진다.

ERROR: prepared statement "S_1" does not exist        (SQLSTATE 26000)
-- 또는
ERROR: prepared statement "S_3" already exists         (SQLSTATE 42P05)

그럼 왜 읽기는 되고 쓰기만 죽었나?

• 읽기: 단발성 autocommit SELECT는 트랜잭션에 길게 묶이지 않고, prepared statement 승격 임계치에도 잘 안 닿는다. 그래서 표면적으로 멀쩡해 보인다.
• 쓰기: @Transactional은 BEGIN으로 트랜잭션을 명시적으로 열고, Hibernate가 INSERT/UPDATE/시퀀스 조회 등 여러 PreparedStatement를 반복 사용한다. prepared statement mismatch가 정통으로 터지는 구간이다.

여기에 log4jdbc 프록시가 기름을 부었다. 정상이던 prepareThreshold=0(=server-side prepared statement 끄기) 옵션이 드라이버를 바꾸며 빠지자, pgJDBC 기본값(5)으로 돌아가 prepared statement가 다시 켜졌고, PgBouncer 트랜잭션 모드와 정면충돌했다. 결국 스프링 입장에선 트랜잭션을 정상적으로 시작·유지할 수 없으니 CannotCreateTransactionException으로 감싸 던진 것이다.

5. 해결 — 두 단계로

5-1. 즉시 복구: 드라이버 원복

운영 장애 상황이라 먼저 출혈을 막아야 했다. 로깅 프록시 드라이버를 걷어내고 표준 드라이버로 되돌렸다.

spring.datasource.driver-class-name=org.postgresql.Driver
spring.datasource.url=jdbc:postgresql://pgbouncer-host:6432/appdb?prepareThreshold=0

되돌리자마자 쓰기 트랜잭션이 즉시 복구됐고, 헬스체크도 UP으로 돌아왔다.

5-2. 영구 대응: 옵션을 명시적으로 박는다

핵심은 PgBouncer 트랜잭션 모드 뒤에서는 server-side prepared statement를 끄는 것이다. JDBC URL에 다음을 명시한다.

jdbc:postgresql://pgbouncer-host:6432/appdb?prepareThreshold=0&preparedStatementCacheQueries=0

• prepareThreshold=0 : server-side prepared statement로 승격하지 않음 (핵심).
• preparedStatementCacheQueries=0 : 클라이언트 측 statement 캐시까지 줄이는 보조 옵션.

선택지를 표로 정리하면 이렇다.

대응	방법	트레이드오프
prepareThreshold=0	앱 JDBC URL에 옵션 추가 (권장)	가장 흔한 해결책. 앱만 고치면 됨
pool_mode=session	해당 DB/유저만 세션 풀링	호환성 최고, 커넥션 절약 효과 감소
max_prepared_statements	PgBouncer 1.21+에서 0이 아닌 값	버전·메모리 고려 필요
로깅 프록시 제거	운영에선 log4jdbc 상시 사용 지양	SQL 로깅은 관측 도구/슬로우쿼리로 대체

진단에 쓴 명령

PgBouncer 풀 상태는 관리 콘솔에서 바로 확인할 수 있다. 풀이 소진된 건지, 설정(mode) 문제인지 가르는 데 유용하다.

$ psql -p 6432 -U pgbouncer_admin -d pgbouncer -c "SHOW POOLS"
# database | pool_mode | cl_active | cl_waiting | maxwait | ...
#  appdb   | transaction |    3     |     0      |   0     | ...

cl_waiting·maxwait가 쌓이면 풀 소진, 그게 아니라면 pool_mode와 클라이언트 JDBC 설정을 의심하면 된다.

보너스 ① — log4jdbc(DriverSpy)는 대체 뭘 하길래

log4jdbc는 그 자체로 DB에 붙는 드라이버가 아니다. 실제 드라이버 앞에 끼어드는 프록시(wrapper)다. 구조를 그림으로 보면 이렇다.

// 표준 경로
App  ──►  org.postgresql.Driver  ──►  DB

// log4jdbc를 끼우면
App  ──►  DriverSpy (프록시)  ──►  org.postgresql.Driver  ──►  DB
              │
              └─► 오가는 JDBC 호출(SQL/파라미터/타이밍)을 가로채 SLF4J로 로깅

그래서 쓰려면 두 가지를 바꿔야 한다. ① 드라이버 클래스를 net.sf.log4jdbc.sql.jdbcapi.DriverSpy로 ② JDBC URL 앞에 jdbc:log4jdbc: 접두사를 붙이기. 문제는 이 과정에서 기존 URL에 붙어 있던 쿼리 파라미터(?prepareThreshold=0 등)를 그대로 옮겨 적어야 한다는 점이다. 우리는 바로 이걸 놓쳤다. 프록시가 모든 JDBC 호출을 한 번 더 감싸 들여다보는 구조라, 미묘한 드라이버 동작 차이나 옵션 누락이 그대로 사고로 이어진다. "로깅하려고 끼운 게 동작까지 바꾼다"는 게 프록시 드라이버의 양날의 검이다.

보너스 ② — 비슷한 증상이면 이 순서로 점검

혹시 지금 "조회는 되는데 쓰기만 깨지는" 상황이라면, 아래 순서로 좁혀가면 빠르다.

1. DB 직접 쓰기로 DB 결백부터 확인 (psycopg2 / psql). 되면 DB는 용의선상에서 제외.
2. 예외의 nested cause를 끝까지 까본다. prepared statement "..." does not exist / already exists, SQLSTATE 26000 / 42P05가 보이면 거의 확정.
3. 앞단에 PgBouncer/풀러가 있는지, 있다면 SHOW POOLS로 pool_mode를 확인. transaction이면 의심 강화.
4. JDBC URL에 prepareThreshold=0이 있는지 확인. 없으면 추가하고 재기동해 바로 살아나는지 본다.
5. 최근 드라이버/데이터소스 설정 변경 이력을 확인. 로깅 프록시 드라이버가 끼었는지 본다.

이 다섯 줄이면 대부분 30분 안에 원인이 잡힌다.

6. 교훈

• "로그 좀 예쁘게"가 운영을 멈출 수 있다. log4jdbc 같은 프록시 드라이버는 실제 드라이버 앞에 끼어들어 동작을 바꾼다. 특히 PgBouncer 트랜잭션 모드처럼 까다로운 환경에선 상시 사용을 피하자. SQL 로깅은 p6spy 상시 투입보다 관측 도구·슬로우쿼리 로그로 빼는 게 안전하다.
• 설정을 바꿀 땐 "옵션이 따라왔는지"까지 본다. 이번 장애의 진짜 트리거는 드라이버 자체가 아니라, 교체 과정에서 조용히 빠진 prepareThreshold=0 한 줄이었다.
• PgBouncer transaction 모드 = 세션 상태가 안 살아남는다. prepared statement, SET, 임시 테이블, advisory lock, LISTEN/NOTIFY 같은 세션 기반 기능은 이 모드와 상극이다. 풀러 뒤에 있다는 걸 항상 의식해야 한다.
• "읽기는 되는데 쓰기만 죽는다"는 강력한 단서다. DB가 통째로 죽은 게 아니라, 트랜잭션·세션 상태가 얽힌 경로만 깨진다는 뜻. 증상의 비대칭을 그냥 넘기지 말자.
• 범위를 반씩 잘라라. psycopg2 직접 쓰기 한 번으로 "DB는 결백"을 증명하고 나니, 남은 건 앱↔풀러↔드라이버 구간뿐이었다. 의심 범위를 빠르게 좁히는 게 곧 해결 속도다.

같은 구조(앱 → PgBouncer → PostgreSQL)를 쓰는 분이라면, pool_mode가 transaction인지 먼저 확인하고 JDBC URL에 prepareThreshold=0이 박혀 있는지 점검해보길. 어느 날 갑자기 쓰기만 죽는 그 황당한 장애를, 한 줄로 예방할 수 있다.