설정돼 있길래 되는 줄 알았다

백업이 되고 있는 줄 알았다. crontab 에 백업 작업이 등록돼 있었는데 복구가 필요한 상황이 왔을 때 백업 파일이 3개월 전 것이었다.

Open Table of contents

등록만 돼 있었다
실패를 아무도 몰랐다
결과를 확인하게 고쳤다
실패 알림의 한계
검증 — 복구와 다른 예약 작업
정리

등록만 돼 있었다

예약 작업 목록을 봤다.

0 3 * * * /home/deploy/bin/backup.sh

backup.sh 가 등록돼 있다. 그런데 결과 파일이 3개월 전 것에서 멈춰 있었고 로그를 보니 매일 실패하고 있었다.

mysqldump: Got error: 1045: Access denied for user 'backup'@'localhost'

3개월 전에 backup 계정 비밀번호를 바꿨는데 스크립트의 값을 안 바꿨다. 등록돼 있는 것과 성공하는 것은 다르다.

실패를 아무도 몰랐다

스크립트가 실패해도 아무 데도 안 알렸다.

mysqldump -u backup -p"$PASS" shopdb > "$DIR/dump-$(date +%Y%m%d).sql"
gzip "$DIR/dump-$(date +%Y%m%d).sql"

mysqldump 가 실패해도 다음 줄이 돌아서 gzip 이 빈 파일을 압축한다. 결과가 있으니 겉으로는 정상으로 보이고 파일 크기를 안 보면 모른다.

스크립트의 종료 코드는 마지막으로 실행된 명령의 것이다. 중간에서 한 줄이 실패해도 뒤에 성공하는 줄이 있으면 전체가 0으로 끝나고 cron 쪽에서는 성공으로 보인다.

파이프로 이은 자리도 같다. mysqldump 를 gzip 으로 넘기는 형태면 앞이 죽어도 뒤가 정상이라 전체는 0이고 앞쪽 종료 코드는 PIPESTATUS 에 따로 들어 있으니 그것을 봐야 한다.

결과를 확인하게 고쳤다

#!/bin/sh
set -e

DIR=/backup/db
F="$DIR/dump-$(date +%Y%m%d).sql"

mysqldump --defaults-file=/root/.my.cnf shopdb > "$F"

SIZE=$(stat -c%s "$F")
if [ "$SIZE" -lt 1000000 ]; then
  echo "백업 파일이 너무 작습니다: ${SIZE} bytes"
  exit 1
fi

gzip "$F"
echo "백업 완료: ${F}.gz ($(stat -c%s "${F}.gz") bytes)"

set -e 로 중간 실패에서 멈추고 stat 으로 잰 크기가 작으면 실패시킨다.

1000000 은 임의 기준이다. 실제 덤프가 400메가라 훨씬 작으면 뭔가 잘못된 것이다. 명령의 종료 코드만 보면 이런 경우를 못 잡고 결과물을 직접 확인해야 실제로 됐는지가 나온다.

실패 알림의 한계

예약 실행 결과를 메일로 받게 했다.

0 3 * * * /home/deploy/bin/backup.sh || echo "백업 실패 $(date)" | mail -s "[알림] 백업 실패" admin@example.com

mail 은 성공하면 조용하고 실패하면 온다. 이것도 문제가 있었는데 스크립트가 아예 안 돌면 아무것도 안 온다. 예약 자체가 지워졌거나 서버가 죽었으면 조용하다.

알림을 cron 에 맡기지 않은 이유도 있다. cron 은 명령이 뭔가 출력하면 그것을 메일로 보내는데 MAILTO 를 비워 두면 아무 데도 안 가고 안 적어 두면 그 crontab 의 소유자에게 간다. 아무도 안 읽는 로컬 계정으로 가면 안 보낸 것과 같다.

echo "$(date '+%Y-%m-%d %H:%M') OK $(stat -c%s "${F}.gz")" >> /backup/backup.log

성공했을 때도 기록을 남기게 했다. 다른 서버에서 backup.log 의 마지막 줄을 확인해서 어제 날짜가 없으면 알린다.

아무 소식이 없는 것을 정상으로 읽으면 안 된다.

검증 — 복구와 다른 예약 작업

백업이 되는 것을 확인했으니 복구도 확인했다. 시험 서버에 최신 덤프를 넣어 봤다.

$ gunzip -c dump-20160801.sql.gz | mysql -h test-db shopdb_restore
$ mysql -h test-db -e "SELECT COUNT(*) FROM shopdb_restore.product;"
82041

원본과 같은 수가 나왔다. 테이블 수도 봤다.

SELECT COUNT(*) FROM information_schema.TABLES WHERE TABLE_SCHEMA='shopdb_restore';

84개로 원본과 같다. 복구가 되는 것을 확인하기 전에는 백업이 있다고 말할 수 없다.

백업 하나만 이런 상태일 리 없어서 등록된 작업을 전부 뽑았다.

$ crontab -l
$ ls /etc/cron.d/

cron.d 까지 합쳐 열한 개였고 각각 마지막 성공이 언제인지 확인했다.

백업          3개월 전 실패 중  ← 이번 건
로그 정리      정상
통계 집계      2주 전부터 실패   ← 새로 발견
세션 정리      정상
발송 재시도    정상
...

stat_daily 를 채우는 통계 집계도 실패하고 있었고 화면에 옛 숫자가 계속 보이는데 아무도 몰랐다.

예약 작업마다 무엇을 보면 정상인지도 적었다.

백업       /backup/backup.log 마지막 줄이 어제 날짜
로그 정리   /var/log/app 에 7일 넘은 파일이 없음
통계 집계   stat_daily 테이블에 어제 행이 있음
세션 정리   session 테이블 행 수가 1만 미만

주 1회 이 목록을 훑고 몇 분이면 된다.

정리

설정에 등록된 것과 실제로 성공하는 것은 다르다
한 줄이 실패해도 다음 줄이 돌면 정상 종료한다
파이프 앞쪽 종료 코드는 PIPESTATUS 로 따로 본다
결과물의 크기나 개수를 확인하고 이상하면 실패시킨다
cron 메일은 MAILTO 를 비우면 안 가고 안 적으면 소유자에게만 간다
실패 알림만 있으면 아예 안 도는 경우를 못 잡는다
성공 기록도 남기고 그것이 없으면 알린다
아무 소식이 없는 것을 정상으로 읽으면 안 된다
복구를 해 보기 전에는 백업이 있다고 말할 수 없다
하나가 그런 상태면 다른 것도 전부 마지막 성공을 확인한다
작업마다 무엇을 보면 정상인지 적고 주기적으로 훑는다