운영 서버의 데이터베이스가 사라졌다 – Binary Log 만으로 4시간 만에 복구하기

일 평균 사용자 93명에 달하는 대시허브는 올해 1월 12일 큰 위기를 맞이했다.

홈 서버 위에서 돌던 운영 DB 가 어느 날 갑자기 `Empty set` 이 되었기 때문이다.

백업도 없던 상태에서 초보 개발자가 어떻게 사고를 인지하고 복구하였는지, 그날 밤 있었던 일을 기록하고자 한다.

19시 38분 – 여느 날과 다름없는 평범한 배포였다

`feature/effect` 브랜치를 `main` 에 병합했다. 상점에 신규 아이템들을 띄우는 작은 업데이트였다.

참고로 대시허브는 `GitHub Actions` 를 사용한다. 이미지를 푸시하면 Watchtower 가 30초 간격으로 감지해 컨테이너를 새 이미지로 교체하는 CD 파이프라인이 걸려 있다.

배포 직후 사이드 위젯이 정상으로 뜨는 것을 확인하고, 내 계정에 신규 아이템을 넣고 싶어서 DBeaver 를 열었다. `users.log_count` 라는 개인 재화를 직접 조작해 신규 아이템들을 언제든 살 수 있게 만들 생각이었다.

단순한 `UPDATE` 쿼리 한 줄이 아래 로그를 남겼다.

2026-01-12 19:38:44.531 - Connect with 'localhost' (mysql8-19b91fb8e72-...)
2026-01-12 19:38:47.287 - Connected (..., MySQL Connector/J [mysql-connector-j-8.2.0])
...
2026-01-12 19:40:39.925 - Node 'comments' not found in parent node
  'node://General/datasources/mysql8-.../database/dash_db/table'.
Allowed children: []
2026-01-12 19:40:44.450 - Node 'board_likes' not found in parent node
  'node://General/datasources/mysql8-.../database/dash_db/table'.
Allowed children: []

내용은 간단하다. `Allowed children: [ ]`, 즉 dash_db 안에 테이블이 하나도 없다는 뜻이다.

19시 42분 – 운영 이후 처음으로 불만사항이 접수되었다

문제가 발생한 시각이 하필이면 일과를 마친 뒤 알고리즘 한 문제 풀기 좋은 시간대였다.

나는 곧장 Pi 서버에 SSH 로 붙었다. 먼저 컨테이너 안의 DB 부터 확인했다.

$ docker exec -it dash-mysql mysql -u root -p
mysql> USE dash_db;
mysql> SHOW TABLES;
Empty set (0.00 sec)

테이블이 단 하나도 없다.

19시 45분 – 도커 볼륨은 살아 있을까

현재 어떤 볼륨이 떠 있는지 확인했다.

$ docker volume ls
DRIVER    VOLUME NAME
local     dash_mysql_data

$ docker inspect dash-mysql | grep -A 5 Mounts
        "Mounts": [
            {
                "Type": "volume",
                "Name": "dash_mysql_data",
                "Source": "/var/lib/docker/volumes/dash_mysql_data/_data",
                "Destination": "/var/lib/mysql",

원래 쓰던 그 볼륨, 그 마운트 그대로였다.

이로써 볼륨은 살아 있는데 그 안의 데이터만 사라졌다는 것이 확정되었다.

곧이어 shell 히스토리도 감사했다. 누군가 실수했을 수 있기 때문이다.

$ history | grep -E '(volume|down|rm)'
   29  docker compose down
  117  docker compose down
  124  docker volume ls

그런데 `docker compose down -v` 도, `docker volume rm` 도 없었다. OS 레벨 명령 이력에 destructive 흔적은 없다.

20시 00분 – 가설을 소거하자

무작정 가설을 세우고 검증했다.

가설	검증 명령	결과
Watchtower 가 컨테이너를 교체했다	docker image inspect mysql:8.0 \| grep Created	사고 시점과 무관함
OOM Killer 가 컨테이너를 죽였다	dmesg \| grep -i "kill" · dmesg \| grep -i "Out of memory"	출력 자체가 없음

해당 시기에 컨테이너는 교체되지 않았고, OOM killer 가 컨테이너를 죽인 것도 아니다.

누군가, 혹은 무언가에 의해 DB 안에서 destructive DDL 이 실행되었다는 것이 가장 말이 된다.

20시 25분 – 바이너리 로그로 복구 가능성을 확인했다

MySQL 의 binlog 를 알게 되었고, 그 즉시 확인부터 하였다. 이 옵션이 켜져 있다면, 분명 모든 변경 사항을 추적할 수 있을 것이다.

mysql> SHOW VARIABLES LIKE 'log_bin';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_bin       | ON    |
+---------------+-------+

그 결과는 "ON" 이었다. 로그를 확인했다.

mysql> SHOW BINARY LOGS;
+---------------+-----------+-----------+
| Log_name      | File_size | Encrypted |
+---------------+-----------+-----------+
| binlog.000001 |   2995339 | No        |
| binlog.000002 |       180 | No        |
| binlog.000003 |   3659782 | No        |
| binlog.000004 |   6557378 | No        |
| binlog.000005 |   2207232 | No        |
| binlog.000006 |    515102 | No        |
| binlog.000007 |   2808056 | No        |
| binlog.000008 |   3565082 | No        |
+---------------+-----------+-----------+

바이너리 로그는 1번부터 8번까지 끊김 없이 존재했다. 첫날부터 사고 직전까지의 모든 데이터 변경이 그대로 보존되어 있다는 뜻이다.

20시 40분 – 복구를 위해 실제 내용을 열어 보자

컨테이너 이미지가 경량이라 `mysqlbinlog` 가 없어서 `SHOW BINLOG EVENTS` 출력을 텍스트로 덤프해서 `grep` 했다.

sh-5.1# mysql -u root -p -e "SHOW BINLOG EVENTS IN 'binlog.000008'" > /tmp/log_dump.txt
sh-5.1# grep -i "DROP" /tmp/log_dump.txt

마침내 `DROP` 쿼리를 찾을 수 있었다.

binlog.000008  3216139  Query  1  3217285
  DROP TABLE `dash_db`.`acorn_log`,
             `dash_db`.`algorithm_records`,
             `dash_db`.`battle`,
             `dash_db`.`battle_participant`,
             `dash_db`.`board_likes`,
             `dash_db`.`boards`,
             ... (37개 테이블) ...
             `dash_db`.`flyway_schema_history`,
             ...
             `dash_db`.`users`
  /* generated by server */ /* xid=341878 */

37개의 테이블이 단일 트랜잭션(xid=341878) 에서 한 번에 날아갔다.

복구 후에는 `binlog` 파일을 호스트로 복사해 `mysqlbinlog` 로 풀어 사건 직전 1초의 흐름까지 확인하였다.

# at 3215419
#260112 19:36:32 server id 1 ... Query  thread_id=2396  exec_time=0
SET TIMESTAMP=1768214192/*!*/;
BEGIN
/*!*/;
# at 3215501
#260112 19:36:32 ... Table_map: `dash_db`.`users` mapped to number 205
# at 3215609
#260112 19:36:32 ... Update_rows: table id 205 flags: STMT_END_F
# at 3216029
#260112 19:36:32 ... Xid = 341873
COMMIT/*!*/;

# at 3216139
#260112 19:36:33 server id 1 ... Query  thread_id=2425  exec_time=1  Xid = 341878
SET TIMESTAMP=1768214193/*!*/;
SET @@session.pseudo_thread_id=2425/*!*/;
DROP TABLE `dash_db`.`acorn_log`, ..., `dash_db`.`users` /* generated by server */
/*!*/;

시퀀스를 정리하면 이렇다.

시간	스레드	동작	출처
19:36:32	2396	UPDATE users
19:36:32	2396	COMMIT	xid=341873
▼ 정확히 1초 뒤, 다른 커넥션 확인
19:36:33	2425	DROP TABLE * 37	xid=341878

그런데 무언가 이상하다. `DROP` 을 친 커넥션은 `UPDATE` 와 다른 스레드 아이디다.

1초 차이인 걸 보면 같이 묶여야 할 것 같은데 정보가 다르다. 여기서 한 번 짚고 넘어갈 지점이 있다.

`/* generated by server */` 는 무엇을 의미할까?

짐작가는 내용은 해당 시그니처가 MySQL 이 binlog 에 자동으로 붙이는 표식이란 것이다.

사용자가 직접 SQL 을 친 것이 아니라, 서버가 다른 상위 명령을 기록하기 위해 재작성한 결과로 추정된다.

가령, `DROP DATABASE` 라던가 `DROP SCHEMA` 같은 것 말이다.

같은 파일 안에서 이 시그니처 선례를 확인할 수 있었다.

# at 514625
#260108 20:25:17 server id 1 ... Query  thread_id=2409  exec_time=0
SET TIMESTAMP=1767871517/*!*/;
DROP TABLE `dash_db`.`acorn_log` /* generated by server */
/*!*/;
...
# at 514922
#260108 20:25:52 server id 1 ... Query  thread_id=2409  exec_time=1
SET TIMESTAMP=1767871552/*!*/;
/* ApplicationName=DBeaver 25.3.2 - Main */ DROP SCHEMA `dash_db`
/*!*/;

1월 8일에는 DBeaver 가 `DROP SCHEMA dash_db` 를 실행했고, 그 결과 MySQL 이 동일한 시그니처로 기록한 흔적이 있다.

1월 12일 19시 36분 33초의 `DROP` 쿼리 역시 외부 MySQL 클라이언트가 발행한 destructive DDL 의 서버 재작성 결과일 가능성이 다분하다.

다만 1월 12일의 binlog 에는 1월 8일과 달리 `ApplicationName=` 같은 클라이언트 식별 주석이 남지 않아, 어떤 클라이언트에서 발행됐는지는 `binlog` 만으로 알 수 없다. `binlog` 시그니처가 외부 클라이언트를 시사한다면, "배포된 jar 안의 어떠한 startup hook 이나 마이그레이션이 한 짓은 아닐까" 라는 가능성도 닫게 된다.

그 jar 을 굴리는 CI/CD 파이프라인 자체가 문제일 수는 없을까?

실제로 69번 PR 과 70번 PR 이 짧은 간격으로 Merge 된 직후 발생한 사고였다. 배포 간 Flyway 버전이 꼬여 `clean` 까지 갔을 가능성까지 따져 보자.

`deploy.yml` 을 다시 펼쳐 본다. 이 워크플로우가 하는 일은 정확히 셋이다.

QEMU + Buildx 셋업
GHCR 로그인
`docker build --push` 로 멀티 플랫폼 이미지를 GHCR 에 푸시

SSH 도, Pi 의 MySQL 에 직접 connect 하는 단계도, Flyway clean 같은 마이그레이션 명령도 없다. Runner 와 Pi 사이는 GHCR + Watchtower 의 image pull 한 단계뿐이다.

Pi 위에서 일어나는 일은 결국 'Watchtower 가 새 이미지로 컨테이너를 교체하면, 백엔드 jar 안의 Flyway 가 부팅 시 `migrate()` 호출하는 것' 뿐이다.

Flyway 는 Spring Boot 3.5.8 의 transitive 인 Flyway 10/11 이니 `cleanDisabled` 기본값이 `true` 라서 `flyway.clean()` 자체가 거부된다.

따라서 두 jar 의 마이그레이션이 충돌했더라도 validation 에러로 부팅 실패 정도 선에서 끝났을 것이다.

21시 00분 – 시점 복구 시나리오를 설계하자

트리거는 희미했으나 복구 전략은 명확했다.

binlog.000001 ~ binlog.000008 을 시간순으로 합쳐 SQL 로 변환한다.
변환된 리커버리 SQL 을 빈 DB 에 통째로 주입한다.

가장 먼저 백엔드를 종료했다.

docker stop dash-backend

정확한 원인을 모르는 상태에서 백엔드가 살아 있으면, 복구한 데이터를 또 같은 트리거에 노출시키기 때문이다.

21시 15분 – 바이너리 로그를 추출하자

일단 바이너리 로그들을 호스트로 직접 꺼냈다.

$ docker cp dash-mysql:/var/lib/mysql/ ./all_logs/
Successfully copied 236MB to /home/w-pi/dash/all_logs/

$ ls -lh ./all_logs/ | grep binlog
-rw-r----- 1 w-pi w-pi 2.9M Jan  5 01:55 binlog.000001
-rw-r----- 1 w-pi w-pi  180 Jan  5 02:11 binlog.000002
-rw-r----- 1 w-pi w-pi 3.5M Jan  5 05:12 binlog.000003
-rw-r----- 1 w-pi w-pi 6.3M Jan  5 18:14 binlog.000004
-rw-r----- 1 w-pi w-pi 2.2M Jan  7 04:03 binlog.000005
-rw-r----- 1 w-pi w-pi 504K Jan  8 20:31 binlog.000006
-rw-r----- 1 w-pi w-pi 2.7M Jan 10 18:19 binlog.000007
-rw-r----- 1 w-pi w-pi 3.6M Jan 12 21:12 binlog.000008

이제 리커버리 SQL 을 생성하면 되는데, 그러기 위해서는 `mysqlbinlog` 를 설치해야 한다.

참고로, 라즈베리 파이 5 는 데비안 기반의 64비트 OS 다. 이 환경에서는 순정 `mysql-client` 대신 `default-mysql-client` 패키지를 통해 MariaDB 기반의 클라이언트 툴을 설치할 수 있다.

$ sudo apt install -y default-mysql-client

설치 후 버전을 확인해 보니, 아키텍처에 맞는 MariaDB 버전의 `mysqlbinlog` 가 정상적으로 설치된 것을 볼 수 있었다.

$ mysqlbinlog --version
mysqlbinlog from 11.8.3-MariaDB, client 3.5 for debian-linux-gnu (aarch64)

21시 30분 – 리커버리 SQL 을 생성해 주입하자

8개 파일을 하나로 합쳐 3216139 포지션 직전까지만 잘라냈다.

mysqlbinlog \
  ./all_logs/binlog.000001 \
  ./all_logs/binlog.000002 \
  ./all_logs/binlog.000003 \
  ./all_logs/binlog.000004 \
  ./all_logs/binlog.000005 \
  ./all_logs/binlog.000006 \
  ./all_logs/binlog.000007 \
  ./all_logs/binlog.000008 \
  --stop-position=3216139 \
  > full_recovery.sql

첫 시도에서 세 차례 이슈가 발생했다.

첫째) MariaDB 클라이언트가 만든 출력에 MySQL 이 모르는 변수가 들어 있었다.

ERROR 1193 (HY000) at line 25: Unknown system variable 'check_constraint_checks'

`check_constraint_checks` 는 MariaDB 의 세션 변수다. MySQL 에는 이 이름의 변수가 없기 때문에 해당 줄만 제거하고 재시도하였다.

sed -i '/check_constraint_checks/d' full_recovery.sql

둘째) 이미 존재하는 사용자 계정을 다시 만들려다 실패하였다.

ERROR 1396 (HY000) at line 118190: Operation CREATE USER failed for 'dash_utact'@'%'

무시하고 강행하기 위해 `mysql -f` 로 force 플래그를 붙였다.

셋째) 파이프를 걸자 비밀번호가 전달되지 않았다.

ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: NO)

`cat ... | mysql -p` 로 파이프를 걸면 `mysql` 의 `stdin` 이 이미 SQL 파일로 점유되어 비밀번호 프롬프트를 띄울 자리가 없다. 결국 비밀번호가 한 글자도 전달되지 못한 채로 연결이 시도되고, 그게 위 에러의 `using password: NO` 가 의미하는 바다.

비밀번호를 `stdin` 이 아니라 CLI 인자로 직접 박으면 프롬프트 자체가 발생하지 않을 것이다.

컨테이너 안의 환경변수 `$MYSQL_ROOT_PASSWORD` 를 쉘 안에서 전개해 `-p"패스워드"` 형태로 넣었다.

cat full_recovery.sql | docker exec -i dash-mysql sh -c \
  'mysql -f -u root -p"$MYSQL_ROOT_PASSWORD"'

별다른 출력 없이 명령이 떨어졌다. DBeaver 를 새로고침 해 확인하자 모든 게 복원된 상태였다.

22시 10분 – Flyway 가 직접적인 트리거는 아니지만 고칠 필요는 있다

이참에 Flyway 히스토리의 V1 BASELINE 레코드를 비워, 다음 부팅 시 Flyway 가 직접 정확한 checksum 으로 다시 적게 하였다.

DELETE FROM flyway_schema_history WHERE version = '1';

이외에도 Flyway 설정에 명시적으로 `clean` 잠금을 걸어 두었다.

백엔드를 다시 띄우자 로그에 `Successfully validated 1 migration` 이 떴다. 사이트는 그대로였고 데이터도 그대로였다.

다만 destructive DDL 을 발행한 커넥션의 정체는 그날 끝내 단정하지 못했다.

`binlog` 가 가리킨 마지막 단서는 19시 36분 33초에 `thread_id=2425` 라는 단발성 커넥션이 단 한 줄을 친 후 사라졌다는 사실까지다.

사건 요약

항목	내용
사고 일시	2026-01-12 19:36:33 KST (binlog 에 기록된 DROP 시각) / 19:40:39 KST (DBeaver 에서 인지한 시각)
환경	Raspberry Pi 5 · Docker Compose · MySQL 8.0.44 · Spring Boot 3.5.8 + Flyway · Watchtower 30s polling
결과	인지 후 약 4시간 만에 binlog 기반 PITR 로 데이터 100% 복구

아쉬운 점

지금 다시 생각해 보면, 21시 30분에 발생했던 두 이슈는 애초에 회피 가능한 문제였다.

binlog 를 통째로 replay 하지 않고 `mysqlbinlog --database=dash_db` 로 필요한 이벤트만 뽑아냈다면 SQL 파일에 `CREATE USER` 가 들어가지 않았을 것이다. 그랬다면 force 도, 비밀번호 우회도 필요 없게 된다.

더 큰 아쉬움은 이번에 시스템 로그까지 확인하게 되면서 느꼈다.

4개월 뒤인 오늘, 추적이 막힌 건 결국 사고 추적을 위한 설정을 운영 환경에 켜 두지 않았기 때문이다.

`rsyslog` 가 설치돼 있었다면 `/var/log/auth.log` 에 사고 시점의 SSH 접속 IP 와 사용자가 남았을 것이다.
journald 의 `Storage=persistent` 만 설정해 두었어도 부팅마다 휘발되지 않았을 것이다.
MySQL `general_log` 가 켜져 있었다면 매 쿼리마다 connection 의 host 와 user 가 기록되어 thread 2425 의 정체가 곧장 드러났을 것이다.
bash 의 `HISTTIMEFORMAT` 한 줄만 박아 두었어도 `.bash_history` 에 명령 시각이 함께 찍혔을 것이다.

binlog 가 살아 있어 데이터는 살릴 수 있었다. 하지만 이는 내가 의도한 설계가 아니라 MySQL 8 의 기본값 덕분이었다. 운이 좋아 데이터는 살렸지만, 운이 좋다고 원인까지 살릴 수는 없었다.

이번 인사이트

사용자 데이터가 한 줄이라도 들어 있는 시스템이라면, 누가 언제 어디서 무엇을 했는지 추적할 수 있는 로그가 켜져 있어야 한다. 그것이 이번 사고가 가르쳐 준 다음 운영의 첫 항목이다.

'Project Logs > DashHub' 카테고리의 다른 글

Naive한 MyBatis 구조를 리팩토링하자 (0)	2025.12.02

19시 38분 – 여느 날과 다름없는 평범한 배포였다

19시 42분 – 운영 이후 처음으로 불만사항이 접수되었다

19시 45분 – 도커 볼륨은 살아 있을까

20시 00분 – 가설을 소거하자

20시 25분 – 바이너리 로그로 복구 가능성을 확인했다

20시 40분 – 복구를 위해 실제 내용을 열어 보자

21시 00분 – 시점 복구 시나리오를 설계하자

21시 15분 – 바이너리 로그를 추출하자

21시 30분 – 리커버리 SQL 을 생성해 주입하자

22시 10분 – Flyway 가 직접적인 트리거는 아니지만 고칠 필요는 있다

사건 요약

아쉬운 점

이번 인사이트

'Project Logs > DashHub' 카테고리의 다른 글

티스토리툴바