💿 문제 상황
반차를 내고 선인상가 타건샵을 방문했던 금요일 오후, 슬랙 모니터링 채널에 HTTP 500대 에러 알림이 울렸다.
‘어? /education/gov/applicants? 내 도메인인데…’
황급히 타건을 마무리 짓고 1층 카페로 내려가 노트북을 열었다. 직접적인 에러로그를 확인해보니 아래와 같은 SQL 관련 로그를 볼 수 있었다.
BatchUpdateException: Duplicate entry '8' for key 'PRIMARY'], SQL:
insert into education_course_pre_applicant_history (
id,
REV,
REVTYPE,
...,
...
) values (?, ?, ?, ...)
히스토리(데이터 변경이력 관리) 테이블에 매번 insert가 안되는 거라면 당장 코드를 분석했겠지만, 굉장히 불규칙하게 간헐적으로 에러가 발생하고 있었다.
한동안 패턴을 찾아보려 노력했지만 성과가 없으니 ‘굉장히 사소한 엣지케이스 방어로직을 놓친건가?’, ‘사용자 환경에 따라 에러가 발생할 수 있을까?’ 생각이 들기 시작했고, 결국 ‘패턴이 보이면 그 때 대응하자.’ 라는 안일한 결론을 지었다. ‘기껏해야 1~2건이나 더 발생하겠지…’ 라고 합리화하며 노트북을 덮었다.
늦은 시간 귀가 후 노트북을 열고서야 사태의 심각성을 파악했다.
눈 앞이 아득하고 머리에 열기가 뻗쳤다. ‘왜 넘겨 짚었을까!!’ 머리를 긁으며 잠시 자책을 했다.
그런다고 문제가 해결되지는 않으니…
히스토리 테이블 Duplicate entry * for key... 에러를 집중적으로 조사했다.
💿 해결
의외로 간단하게 원인을 파악할 수 있었다.
히스토리 테이블을 관리하기 위해 JPA envers 프레임워크를 사용하고 있다.
envers 프레임워크는 엔티티의 히스토리 테이블을 만들어 변경 이력을 관리하는데,
기본적으로 엔티티 테이블과 동일한 컬럼들과 REV, REVTYPE 이라는 이름의 추가 컬럼을 갖는다.
여기서 REV 컬럼은 변경 이력의 고유 식별 번호 컬럼이고,
REVTYPE은 변경 동작(0 = 생성, 1 = 수정, 2 = 삭제)을 구분하는 컬럼이다.
가령 위와 같은 “최현팔”, “최현구” 데이터를 생성했다고 치자.
“최현구”의 이름을 “홍길동”으로 변경하면 테이블의 상태가 위와 같을 것이고,
“홍길동”을 제거하면 테이블의 상태가 위와 같게 될 것이다.
엔티티 테이블과 히스토리 테이블을 잘보면
엔티티 테이블에서 PK의 역할을 하는 컬럼은 id, 히스토리 테이블에서 PK 역할을 하는 컬럼은 id, REV 라는 것을 알 수 있다.
즉 히스토리 테이블은 일반적인 엔티티 테이블과 다르게 id와 REV 컬럼을 합쳐서 PK로 가져야한다.
그러나 내가 신중하지 못하게 id 컬럼만 PK로 갖도록 했고,
이로 인해 히스토리 테이블에서는 엔티티의 변화를 감지하고 기록하려 할 때마다
PK가 충돌하여 기록을 하지 못하고 있었던 것이다.
결국 PK 관련 설정을 수정한 DDL을 반영하는 것으로 문제를 해결할 수 있었다.
💿 후기
원인을 빠르게 파악한 덕분에 금새 DDL을 수정하고 배포하여 추가 장애를 막을 수 있었다. 그러나 앞서 합리화하고 넘겨 짚은 시간 때문에 장애가 길어졌다. 패턴이 보이길 기다릴게 아니라 기존 작업 내용을 거슬러 올라가거나, 다른 히스토리 테이블은 어떻게 구성되어있는지만 비교했어도 문제를 더 빠르게 파악할 수 있었다.
더 큰 규모의 장애였다면 어마어마한 불편을 끼쳤을 것이다. 알량한 책임감과 안일한 태도로 개발하면 어떤 일을 겪게 되는지 예고편을 본 것 같다. 이번 일을 통해 개인적인 프로세스를 많이 점검했다.
- 슬랙 모니터링 채널 알림 설정을 다시 한번 체크
- 애플워치에 알림이 계속 울리는게 귀찮더라도 절대 끄지 말자
- 기능배포 직후 일정기간동안 모니터링을 꼭 하자…
- 조기에 발견해서 처리하는 것이 이해도도 높고 가장 좋다…
나는 프로그래밍으로 더 나은 서비스를 제공하라고 돈을 받는 사람이다. 항상 책임감을 갖고 신중을 기하자. 특히나 데이터베이스 관련해서는… 🙏
댓글남기기