InnoDB в Zimbra после аварии питания: recovery 1→6 и дамп

Дистрибьютор в Химках, 32 рабочих места, июль 2020 года. В офисном щитке выбило автомат, сервер выключился как есть, а утром база Zimbra отказалась подниматься с assertion failure в логе. Я провёл там день, ночь и раннее утро следующих суток. Разбираю по часам: где я сначала копал не там и в какой момент надо перестать чинить и начать спасать.

Если у вас почтовый сервер стоит физически в офисе, вы этот сценарий уже проходили или пройдёте. Электрики что-то делали в щитке. Или грозой выбило ввод. Или ИБП отработал двенадцать секунд вместо заявленных пятнадцати минут, потому что батареи в нём поменяли последний раз при прошлом директоре.

Сервер выключается мгновенно. Утром его включают, ОС грузится нормально, диски отзываются, всё выглядит живым — кроме почты. Почта не работает вообще, и в консоли что-то про базу данных.

Дальше обычно происходит одно из двух. Либо человек начинает перезапускать службы по кругу в надежде, что на четвёртый раз получится. Либо гуглит слово repair и находит команду, которая в этой ситуации не сделает ровным счётом ничего, но потратит два часа и создаст ощущение, что что-то делается.

Расскажу, как это выглядело у меня, и что помогло на самом деле.

Дистрибьютор бытовой техники, 32 рабочих места, склад и офис в одном здании на въезде в Химки. Сервер — башенный, стоит в кладовой рядом с серверной стойкой связистов, потому что серверной у них нет. Zimbra 8.8.15 Open Source на CentOS 7, штатная MariaDB из комплекта, store 640 гигабайт, база zimbra около одиннадцати гигабайт.

Во вторник в 21:40 в здании выбило вводной автомат. Сервер выключился жёстко. В среду утром его включили, и я приехал к 10:30.

[zimbra@srv ~]$ zmcontrol status
        Host srv.company.local
                ldap                    Running
                logger                  Stopped
                mailbox                 Stopped
                        mysql.server is not running.
                        zmmailboxd is not running.
                mta                     Running
                zmconfigd               Running

Каталог живой, MTA живой и уже копит входящую почту в очереди. Мёртвая только база — и вместе с ней mailboxd, которому без базы делать нечего. Смотрим лог:

[zimbra@srv ~]$ tail -40 /opt/zimbra/log/mysql_error.log
InnoDB: Database page corruption on disk or a failed file read of page [page id: space=0, page number=1847]
InnoDB: You may have to recover from a backup.
InnoDB: Error: trying to access page number 4294967293 in space 0
InnoDB: Assertion failure in file buf0buf.cc line 4593
InnoDB: Failing assertion: ibuf_inside(&mtr)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/

Вот эта строка про доступ к номеру страницы 4294967293 — она и есть диагноз. Это максимальное 32-битное число минус два, то есть движок читает из заголовка мусор вместо адреса и честно пытается по нему пойти. Redo-лог не успел лечь на диск целиком, кэш контроллера отдал не всё, и часть страниц осталась в состоянии «наполовину записана».

Слово corruption в первой строке лога плюс жёсткое выключение сложились у меня в очевидную картину: посыпался массив. Логика простая — если бы пострадала только база, страдала бы одна база, а тут явно физика.

Я потратил на эту версию час двадцать.

• Прогнал smartctl -a по всем четырём дискам. Reallocated_Sector_Ct нули, Pending нули, часы наработки 31 400 с копейками, что для дисков 2016 года нормально.
• Посмотрел состояние массива через утилиту контроллера — RAID10, Optimal, ни одного деградировавшего диска.
• Прошёл dmesg целиком в поисках ошибок ввода-вывода. Пусто.
• На всякий случай сверил контрольную сумму пары крупных файлов из store с тем, что лежало в ночной копии на NAS. Совпало.

Железо было в порядке. И меня это, честно говоря, расстроило: сгоревший диск — понятная беда с понятным лечением. Битые страницы в файле базы — беда неприятная, потому что чинить их нечем.

Полезное из этого часа всё-таки вышло. Я убедился, что писать на диск можно, и что копия на NAS читается. Без этой уверенности дальше двигаться было бы страшно.

Первое, что находит человек в поиске по слову corruption, — это команда починки таблиц. Она есть, она работает, у неё внятный синтаксис. И к нашему случаю она не имеет отношения.

Операция REPAIR TABLE существует для движка MyISAM. У него данные и индекс лежат в отдельных файлах с простой структурой, их можно перебрать и пересобрать. InnoDB устроен иначе: транзакционный движок, табличное пространство, redo-лог, undo-сегменты. Пересобрать это снаружи нельзя, поэтому REPAIR для InnoDB просто не реализован. Вы получите вежливый ответ, что операция для этого движка не поддерживается, и ничего не произойдёт.

А таблицы Zimbra — это InnoDB. Все содержательные: mail_item, mail_item_dumpster, appointment, revision, вся структура mboxgroup-баз.

Единственный работающий путь при порче InnoDB выглядит так, и других вариантов нет:

1. поднять сервер базы в аварийном режиме настолько, насколько он вообще способен подняться;
2. снять дамп — то есть вытащить данные наружу в виде текста;
3. снести повреждённое хранилище и создать чистое;
4. залить дамп обратно.

Ключевая мысль, которую я в тот раз усвоил окончательно: аварийный режим — это не лечение. Это форточка, через которую надо успеть вынести содержимое. Всё, что вы делаете в аварийном режиме, кроме чтения данных, вредит.

Три команды. Первую можно выполнять прямо сейчас на живом сервере — она безопасна и ничего не меняет.

# 1. Полная проверка целостности базы (безопасно, но нагружает диск)
/opt/zimbra/libexec/zmdbintegrityreport -v

# 2. Есть ли в логе базы следы прошлых аварий
grep -iE "corrupt|assertion|crash recovery" /opt/zimbra/log/mysql_error.log | tail -20

# 3. Стоит ли аварийный режим прямо сейчас (его иногда забывают убрать)
grep -n "innodb_force_recovery" /opt/zimbra/conf/my.cnf

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

Аварийный режим InnoDB включается одной строкой в /opt/zimbra/conf/my.cnf, в секции [mysqld]. Значения от 1 до 6, и чем выше, тем больше внутренних проверок движок пропускает, тем выше шанс, что он вообще стартует, — и тем выше риск вытащить данные в несогласованном виде.

# /opt/zimbra/conf/my.cnf
[mysqld]
innodb_force_recovery = 1

Правило простое: начинать с единицы и повышать только тогда, когда предыдущее значение не дало базе подняться. Прыгать сразу на шестёрку нельзя — вы получите данные хуже, чем могли бы.

Мой журнал той среды, по часам:

Разница между тройкой и шестёркой оказалась не косметической. На тройке я вытащил примерно половину содержимого, на шестёрке — всё, что вообще подлежало извлечению. Это совпадает с тем, что описывают в форумных разборах: шестой уровень нередко даёт вдвое больше восстановленных данных, чем третий.

Но здесь важна последовательность, а не сам факт. Если бы я стартовал сразу с шестёрки, я бы не узнал, что тройка тоже поднимает базу, — а на тройке дамп внутренне честнее. В идеале снимают дамп на каждом уровне, который дал старт, и потом берут самый полный. Оборванный дамп с тройки я сохранил просто по привычке — и ночью он меня спас, об этом в следующем разделе.

Команда старта базы отдельно от остальной Zimbra:

# обязательно: mailboxd не должен трогать базу
zmmailboxdctl stop

# поднимаем только сервер БД
mysql.server start
tail -f /opt/zimbra/log/mysql_error.log

# дамп всего и сразу, с прицелом на пересоздание
mysqldump --all-databases --skip-single-transaction --skip-lock-tables \
  --routines --events > /backup/zimbra_all_20200715.sql

ls -lh /backup/zimbra_all_20200715.sql
# -rw-r--r-- 1 zimbra zimbra 9.4G Jul 15 16:53 zimbra_all_20200715.sql

Где я едва не испортил всё

В 14:50, между третьим и четвёртым уровнем, я по привычке набрал zmcontrol start вместо mysql.server start. Поднялось всё: mailboxd, MTA с накопленной очередью, индексатор. И mailboxd немедленно полез писать в базу, которая работает в аварийном режиме, где часть операций записи проходит некорректно.

Я поймал это секунд через сорок по строкам в mailbox.log и остановил. Обошлось. Но если бы я отвлёкся на десять минут, MTA успел бы разложить накопленную за сутки очередь в базу, состояние которой я в этот момент ещё даже не оценил. Отсюда правило, которое я с тех пор не нарушаю: пока идёт спасательная операция, из всей Zimbra живёт только сервер базы. Всё остальное выключено, MTA в том числе.

Дамп на руках, на часах 17:20 среды. Дальше — чистое хранилище.

# копия каталога данных на отдельный раздел, до всего остального
mysql.server stop
cp -a /opt/zimbra/db /mnt/backup/db-20200715

# убираем аварийный режим из конфигурации
sed -i '/innodb_force_recovery/d' /opt/zimbra/conf/my.cnf

# пересоздание базы с нуля
/opt/zimbra/libexec/zmmyinit --sql_root_pw <пароль_из_zmlocalconfig>

# заливка дампа
mysql < /backup/zimbra_all_20200715.sql

Пароль берётся из локальной конфигурации: zmlocalconfig -s mysql_root_password. Записывать его надо до начала работ, а не в процессе, потому что в разгар восстановления искать пароль — отдельное удовольствие.

После заливки я получил сюрприз, к которому был готов только наполовину. Сервер стартовал, но в логе повисли жалобы на отсутствующие системные таблицы: gtid_slave_pos, innodb_index_stats, innodb_table_stats. Дамп их не забрал — они относятся к внутренней кухне движка и в общем экспорте не участвуют.

Лечится это скриптом из комплекта:

find /opt/zimbra/ -name mysql_system_tables.sql
# /opt/zimbra/common/share/mysql_system_tables.sql

mysql.server start
mysql mysql < /opt/zimbra/common/share/mysql_system_tables.sql
mysql.server stop

Та же самая тройка таблиц пропадает после переезда на другую версию MariaDB — это классика при апгрейдах и при переносе на новое железо. Симптом другой, лечение то же самое.

Заливка заняла 1 час 12 минут и закончилась в 18:32. Системные таблицы — ещё десять минут. В 18:45 я запустил контрольный отчёт, уверенный, что через полчаса поеду домой.

Ночь: четыре базы, приехавшие мусором

Отчёт вернулся в 19:20 и был не тот, которого я ждал: четыре таблицы mail_item в mboxgroup-базах 3, 7, 9 и 12 содержали строки с невозможными значениями — отрицательные размеры, даты из 1970 года, ссылки на несуществующие blob-и. Это и есть цена шестого уровня: движок отдал наружу всё, до чего дотянулся, включая то, что на единице отбросил бы как заведомо битое.

Вот здесь и пригодился оборванный дамп с третьего уровня. До конца он не дошёл, но три из четырёх нужных мне баз в этот кусок попали, и там те же таблицы лежали в согласованном виде — просто без последних записей. Четвёртую, mboxgroup 9, пришлось добирать иначе: оставить данные с шестёрки и вычистить руками строки, которые не проходили проверку. Дальше была ровно та работа, ради которой берут почасовую оплату: выдернуть четыре таблицы из обоих дампов, сравнить построчно по идентификаторам, собрать гибрид (согласованная часть с тройки плюс те записи с шестёрки, которые прошли проверку), залить обратно, прогнать отчёт, найти следующую проблему.

# вырезаем из большого дампа секцию одной базы
# (mysqldump --all-databases расставляет метки "-- Current Database:")
sed -n '/^-- Current Database: `zimbra_mboxgroup3`/,/^-- Current Database: `zimbra_mboxgroup4`/p' \
  /backup/zimbra_l3_20200715.sql > /backup/mboxgroup3_l3.sql

# и заливаем её целиком, поверх испорченной
mysql < /backup/mboxgroup3_l3.sql
/opt/zimbra/libexec/zmdbintegrityreport -v

Четыре базы, четыре круга, каждый круг — заливка плюс отчёт на 187 таблицах. Закончил в 05:40 четверга. Если бы я не сохранил дамп с тройки, единственным выходом была бы ночная копия с NAS — и вместе с ней потеря всей среды.

Финальный контроль перед тем, как поднимать почту, в 06:10:

/opt/zimbra/libexec/zmdbintegrityreport -v
# ... 187 tables checked, 0 errors

zmcontrol start
zmcontrol status

Цифры этого случая.

• Почта стояла с 21:40 вторника до 06:30 четверга — 32 часа 50 минут календарных. Из них на рабочее время пришёлся ровно один день: вся среда целиком, десять часов, когда тридцать два человека не могли ни отправить, ни получить. К началу четверга почта уже работала.
• Дамп на шестом уровне: 9,4 ГБ текста, снят за 41 минуту. Заливка обратно — 1 час 12 минут. Плюс оборванный дамп с третьего уровня, 5,8 ГБ, из которого ночью пришлось доставать четыре таблицы.
• Потеряно безвозвратно: 11 писем в трёх ящиках, все получены в промежутке между последней контрольной точкой и моментом выключения. Два из них удалось достать из ящиков отправителей.
• Входящая почта не пропала совсем: отправители держали её в своих очередях и досылали. 340 писем доехали к восьми утра четверга, за полтора часа после подъёма.
• Мои работы — 19 часов подряд, с 10:30 среды до 06:30 четверга, из них десять с лишним ночных. Счёт клиенту 46 000 рублей с ночным коэффициентом.
• Убыток отдела продаж от суток без почты они посчитали сами. Назвали 265 000 рублей — две сорванные отгрузки, где заявку ждали по почте до определённого часа.

Комплект батарей в ИБП, из-за которого всё это произошло, стоил на тот момент 14 000 рублей. Его не купили в марте, потому что «пока держит».

Где самостоятельная попытка обычно ломается

Я расписал последовательность целиком, и она рабочая. Но есть четыре места, где всё идёт под откос, и они видны только когда сам через это прошёл.

Место, где нельзя жадничать. Копию каталога /opt/zimbra/db надо снять до первого запуска в аварийном режиме, а не после. Каждый старт движка что-то дописывает. Я в Химках снял копию сразу и один раз к ней вернулся — когда на четвёртом уровне заподозрил, что делаю хуже.

Место, где кончается диск. Дамп на 9,4 ГБ и копия каталога на 11 ГБ должны куда-то лечь, а раздел под Zimbra обычно и так забит. Если положить дамп на тот же раздел, вы в середине операции упрётесь в нехватку места, и это худший момент из возможных.

Место, где надо остановиться. Есть точка, после которой дальнейшие попытки поднять базу вредят: когда даже на шестом уровне сервер не стартует. Тогда разговор переходит в другую плоскость — восстановление из резервной копии с потерей всего, что накопилось после неё. Это решение принимает владелец бизнеса, а не инженер, и принимать его надо трезво, а не в четыре утра.

Место, где спасает регламент. Проверка целостности базы работает по крону раз в неделю и присылает отчёт. Если она у вас настроена и отчёты кто-то читает — вы узнаете о начавшейся порче за недели до того, как сервер перестанет стартовать. У дистрибьютора в Химках отчёт формировался исправно и уходил на адрес администратора, который уволился в 2018 году.

Если хотите понять, в каком состоянии ваша база прямо сейчас, — пришлите мне вывод /opt/zimbra/libexec/zmdbintegrityreport -v и последние сорок строк mysql_error.log. Отвечу за день: есть ли порча, насколько срочно и во сколько часов обойдётся привести всё в порядок в плановом окне, а не ночью после аварии.

Можно ли сразу поставить innodb_force_recovery = 6 и не тратить время на промежуточные уровни?

Можно, но вы получите худший результат и не узнаете об этом. Каждый следующий уровень отключает очередную внутреннюю проверку согласованности, и данные, снятые на шестёрке, могут содержать записи, которые движок на единице отбросил бы как заведомо битые. Правильная тактика — снимать дамп на каждом уровне, который дал старт, и сравнивать размеры. У меня в Химках тройка дала примерно половину, шестёрка — всё. Но узнал я это, только пройдя лестницу по порядку. Пятнадцать минут на уровень — недорогая плата за понимание, что именно вы вытащили.

Почему нельзя просто восстановиться из ночного бэкапа, зачем эти сложности?

Затем, что бэкап — это точка в прошлом. У дистрибьютора копия снималась в 02:00, авария случилась в 21:40, то есть между ними лежали почти двадцать часов рабочего дня: заказы, согласования, счета. Восстановление из копии стёрло бы всё это гарантированно. Попытка вытащить данные из повреждённой базы стоила девятнадцати часов моей работы и сохранила рабочий день тридцати двух человек. Копия при этом лежала рядом и была моим планом Б — я бы пошёл на неё, если бы шестой уровень не поднял базу. Одно не отменяет другого.

Как понять, что база повреждена, если сервер пока работает нормально?

Отчёт о целостности — это обёртка над стандартной проверкой таблиц, и он находит порчу задолго до того, как она начнёт мешать. Запускайте его вручную командой из статьи, желательно вечером: он читает всю базу и заметно грузит диск. Второй признак — строки со словом corrupt в логе базы, которые появляются и уходят. Третий, косвенный: пользователи жалуются, что письмо не удаляется или папка не переименовывается, а в mailbox.log в этот момент SQL-исключение. Каждая такая жалоба — повод прогнать проверку, а не повод перезапустить службу.

Zimbra сама себя чинит при старте после жёсткого выключения — почему в этот раз не починила?

Штатное восстановление после краха действительно работает и в большинстве случаев справляется: движок доигрывает redo-лог и приводит данные в согласованное состояние. Оно ломается, когда сам redo-лог или страницы данных записаны наполовину — обычно из-за кэша дискового контроллера, который подтвердил запись, но физически её не выполнил. Тогда движок читает мусор вместо адреса страницы и падает на внутренней проверке. Контроллер с кэшем без исправной батарейки — это ровно та ситуация, в которой автоматическое восстановление перестаёт работать.

Сколько времени занимает вся процедура на базе средней конторы?

Для тридцати-сорока ящиков и базы в десять-двенадцать гигабайт — от шести до десяти часов при удачном раскладе. Разбивка примерно такая: час на оценку и копию, полтора-два часа на лестницу уровней, час на дамп, ещё час на пересоздание и заливку, полчаса на системные таблицы и проверку, и час на подъём почты и разбор накопленной очереди. Остальное — ожидание. Основной риск не в сложности команд, а в том, что решение приходится принимать ночью, уставшим, при директоре, который каждые двадцать минут спрашивает, когда будет почта.