Скрипт бэкапа падал молча четыре месяца: cron не умеет жаловаться

MAATRIX

Бэкап-скрипт годами отрабатывал по ночам без единой жалобы: cron запускался, лог был пустой, задача завершалась с кодом 0. А когда однажды понадобилось реально что-то восстановить, выяснилось, что архивы за последние четыре месяца — это несколько десятков байт мусора вместо дампа базы. Ниже — разбор конкретного случая: что видели в логах и мониторинге, какие версии проверили и отбросили, где на самом деле терялась ошибка и что изменили в скрипте и в процессе, чтобы такое не повторилось незаметно.

Как всё вскрылось

Схема бэкапа была рядовая для небольшого проекта на VPS: раз в сутки в 03:00 cron запускал shell-скрипт, который снимал дамп MySQL, паковал его в gzip и заливал через rclone во внешнее хранилище (S3-совместимый бакет на отдельном сервере). Отдельного «взрослого» мониторинга бэкапов не было — только пинг в Healthchecks.io в конце скрипта, который считался достаточным сигналом «всё ок».

Проблему нашли случайно. Разработчик тестировал миграцию на стейджинге, миграция снесла лишнее в тестовой таблице, и вместо того чтобы гонять сид-данные заново, решили быстро поднять вчерашний дамп прода в отдельную схему для сверки. Скачали архив, gunzip отработал без ошибок, но файл распаковался в SQL размером на пару килобайт — вместо привычных сотен мегабайт. Подумали, что это разовый сбой конкретной ночи, скачали архив за позавчера — то же самое. За неделю до этого — то же самое. Отмотали до архивов трёхмесячной давности — везде одна и та же картина: файл лежит, имя правильное, размер — почти ничего.

Дальше стало ясно, что это не разовая накладка, а системная проблема, которая тянется давно, и что «зелёный» пинг в Healthchecks.io всё это время означал только «скрипт доработал до конца», а не «бэкап получился».

Что показывали логи и метрики

Первым делом подняли всё, что могло дать зацепку, и картина была подозрительно чистой:

• journalctl -u cron и /var/log/syslog показывали, что задача из /etc/cron.d/backup-db стартовала каждую ночь строго по расписанию, без пропусков.
• Сам скрипт писал короткий лог в /var/log/backup-db.log, и там не было ни одной строки с ошибкой — только Backup finished, uploading... и Upload complete.
• Код возврата скрипта, который cron логирует через обёртку flock (см. также разбор про cron-задачи, которые не отработали ночью — там похожий по духу, но другой по причине случай тихого сбоя), был 0 каждую ночь без исключений.
• Лог rclone со включённым -v показывал Transferred: 1 / 1, 100%, без единого предупреждения — файл действительно долетал до бакета целиком, просто сам файл был крошечный.
• В самом хранилище через rclone lsl remote:backups/ были видны файлы за каждый день, с правильными именами db-YYYY-MM-DD.sql.gz и корректными датами — то есть по всем формальным признакам ротация и заливка работали штатно.
• Дашборд Healthchecks.io — сплошная зелёная лента, ни одного пропущенного чек-ина за проверяемый период.

То есть все системы, которые в принципе могли бы сигналить, отчитывались «успех», потому что физически ни одна команда в скрипте не завершилась с ненулевым кодом на верхнем уровне. Ошибка происходила внутри, а наружу просачивался только успешный код последней команды в пайпе.

Гипотезы, которые проверили и отбросили

Прежде чем добраться до сути, перебрали четыре версии, каждую из которых логика подсказывала как наиболее вероятную:

Cron вообще не запускал задачу, а старые файлы — это следы ручных прогонов. Отбросили сразу: journalctl показывает точные метки запуска каждую ночь, plus временные метки файлов в бакете сдвинуты ровно на пару минут от времени старта — то есть скрипт реально выполнялся от начала до конца.

Диск на хранилище переполнен, и запись обрезается. Тоже мимо: df -h на сервере с бакетом показывал свободного места с запасом, да и обрезанная запись обычно даёт файл с явно битым gzip-хвостом, который gunzip ругает ошибкой CRC. Здесь же архив был полностью валидным gzip-файлом — просто пустым по содержимому.

Сеть или rclone роняют данные при передаче. Проверили через rclone check remote:backups/ /var/backups/mysql/ --size-only и вручную сверили контрольные суммы локальной временной копии с тем, что лежит в бакете — они совпадали. Это в итоге стало косвенной уликой: раз локальный файл и файл в бакете идентичны и оба крошечные, значит, проблема возникла ещё до заливки, на этапе создания дампа.

Скрипт ротации бэкапов слишком агрессивно чистит старые файлы и подсовывает вместо реального архива что-то не то. Отдельно посмотрели логику ретеншена (find ... -mtime +14 -delete) — она трогала только файлы старше 14 дней и не создавала новых. Файлы за каждый день были свои, с уникальным содержимым (точнее, с уникальным отсутствием содержимого), так что ротация была ни при чём.

После того как все четыре версии отпали, стало ясно: файл создаётся пустым ещё на этапе mysqldump, а не портится и не подменяется позже. Значит, смотреть нужно было в саму команду создания дампа и в то, как скрипт интерпретирует её результат.

Настоящая причина: пайп проглотил код ошибки

Упрощённый фрагмент скрипта выглядел примерно так:

#!/usr/bin/env bash
set -e

DUMP_FILE="/var/backups/mysql/db-$(date +%F).sql.gz"

mysqldump --defaults-extra-file=/etc/backup/mysql-creds.cnf mydb \
  | gzip -c > "$DUMP_FILE"

rclone copy "$DUMP_FILE" remote:backups/
echo "Upload complete"
curl -fsS https://hc-ping.com/xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx

Ключевая деталь — строка с mysqldump | gzip -c > "$DUMP_FILE". В bash код возврата конвейера ($?) по умолчанию — это код возврата *последней* команды в конвейере, а не первой. set -e останавливает скрипт при ошибке, но точно так же смотрит только на итоговый код конвейера. Если mysqldump упадёт с ошибкой доступа, но gzip при этом честно допишет пустой поток и завершится нормально — весь конвейер для bash выглядит успешным, set -e не срабатывает, и скрипт бодро идёт дальше.

А mysqldump действительно начал падать — примерно четыре месяца назад, в ту же неделю, когда в рамках плановой ротации доступов поменяли пароль технической учётки в базе. Пароль обновили в основном конфиге приложения и в панели, но забыли про отдельный файл /etc/backup/mysql-creds.cnf, которым пользовался только ночной бэкап-скрипт — он лежал в стороне от общего конфига именно потому, что «бэкапам свой доступ, поменьше прав». С этого момента каждую ночь mysqldump завершался с ERROR 1045 (28000): Access denied for user 'backup_user'@'localhost', эта строка улетала в stderr, gzip получал на входе пустой stdin и честно упаковывал ноль байт в валидный gzip-контейнер размером около двадцати байт, rclone без вопросов заливал этот валидный, но пустой файл, а финальный curl до Healthchecks.io отправлялся безусловно, в конце скрипта, независимо от того, что происходило внутри.

Отдельно стоит заметить: stderr от mysqldump в этой версии скрипта никуда явно не перенаправлялся и не логировался — он просто улетал в никуда, потому что cron по умолчанию отправляет вывод задачи только если настроена почта (MAILTO), а локальный MTA на сервере не был поднят ещё с момента установки системы. Иначе говоря, ошибка технически печаталась, но её некому было читать.

Как подтвердили эту версию

Гипотезу проверили без риска для прод-данных:

# намеренно неверный пароль в тестовом конфиге
mysqldump --defaults-extra-file=/tmp/bad-creds.cnf mydb | gzip -c > /tmp/test.sql.gz
echo "exit code: $?"
ls -la /tmp/test.sql.gz

Код возврата — 0, файл test.sql.gz — валидный, но около двадцати байт. Это в точности воспроизводило картину из прод-архивов.

Дальше подняли историю изменений вокруг файла mysql-creds.cnf (дата последнего mtime, плюс запись в внутреннем чек-листе ротации доступов) и сопоставили её с датой, когда в бакете размер файлов резко упал с обычных для этой базы сотен мегабайт до системных двадцати байт. Даты совпали день в день. Отдельно прогнали rclone lsl remote:backups/ за весь период и построили из вывода простую таблицу размеров по датам — обрыв виден невооружённым глазом:

Это и стало финальным подтверждением: ошибка началась ровно с момента смены пароля backup-учётки и ни разу не проявилась ни в одном из мест, куда обычно смотрят при проверке «жив ли бэкап» — ни в логе cron, ни в логе rclone, ни в статусе Healthchecks.io.

Что изменили после

Правки внесли на нескольких уровнях сразу, потому что проблема была не в одной строчке, а в самой конструкции проверки «бэкап случился»:

Убрали проглатывание кода ошибки в пайпе.

set -euo pipefail

mysqldump --defaults-extra-file=/etc/backup/mysql-creds.cnf mydb \
  | gzip -c > "$DUMP_FILE"

pipefail заставляет bash брать код возврата конвейера как код возврата первой упавшей команды, а не последней. Теперь при том же сценарии скрипт падает сразу на mysqldump и не доходит до заливки пустого файла.

Добавили явную проверку размера дампа перед заливкой, отдельно от кода возврата — на случай, если что-то отвалится тихо уже после pipefail (например, дамп получится валидным, но подозрительно маленьким из-за частичной блокировки таблиц):

MIN_SIZE=10485760   # 10 МБ как грубый нижний порог для этой базы

actual_size=$(stat -c%s "$DUMP_FILE")
if [ "$actual_size" -lt "$MIN_SIZE" ]; then
  echo "Backup suspiciously small: ${actual_size} bytes" >&2
  exit 1
fi

Порог здесь условный и подбирается под конкретную базу — смысл не в точном числе, а в том, что скрипт вообще перестаёт молча считать любой файл «нормальным бэкапом».

Перенесли пинг в Healthchecks.io в конец, после успешной проверки, а не безусловно. Раньше curl до hc-ping.com стоял последней строкой скрипта и срабатывал независимо от того, что происходило выше. Теперь пинг «всё ок» уходит только после проверки размера и после успешной заливки, а при любой ошибке по пути отправляется /fail-эндпоинт вместо обычного. Подробнее про саму механику dead man's switch и настройку чек-инов из cron — в статье про мониторинг cron-задач через Healthchecks.io.

Добавили регулярный тестовый restore, а не только проверку факта наличия и размера файла. Раз в неделю отдельная задача разворачивает последний архив в scratch-базу на том же сервере и прогоняет пару простых SQL-запросов (SELECT COUNT(*) FROM users, сверка со вчерашним значением). Это ловит не только пустые дампы, но и битые, и логически повреждённые. Общий подход к такой проверке разобран в статье о том, как убедиться, что бэкап реально рабочий.

Завели дашборд с трендом размеров бэкапов, а не только статус «выполнен / не выполнен» — резкий провал размера теперь виден на графике визуально, даже если формальный код возврата почему-то останется нулевым по какой-то ещё не предусмотренной причине. Как построить такой мониторинг бэкапов отдельно от общего мониторинга сервера — в статье про мониторинг бэкапов.

Отдельно завели чек-лист ротации доступов, где смена пароля любой служебной учётки теперь явно включает пункт «проверить все места, где этот пароль используется отдельно от основного конфига» — включая cron-скрипты, systemd-таймеры и любые сторонние интеграции. Именно человеческий разрыв между «поменяли пароль в приложении» и «а скрипт бэкапа использует свой файл с доступом» был первопричиной инцидента — техническая дыра с pipefail лишь позволила ей остаться незамеченной на четыре месяца вместо одной ночи.

Частые вопросы