«Possibly corrupt index»: переиндексация, которая зацикливалась

Юридическая фирма в Мытищах, 29 рабочих мест, октябрь 2022 года. Партнёр искал в почте переписку по договору и не находил письма, которое сам же мне показал в папке. Началось всё с одной строчки в логе, а закончилось тем, что я запустил переиндексацию всего домена на ночь и получил утром лежащий сервер.

Это жалоба, которую почти всегда сначала не воспринимают всерьёз. Человек говорит, что поиск не находит письмо. Ему отвечают: посмотрите внимательнее, проверьте папку, может, вы искали не то слово. Он проверяет. Письмо на месте, лежит во «Входящих», открывается, читается.

А поиск его не отдаёт. Ни по теме, ни по отправителю, ни по слову из текста. Ноль результатов.

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

Причина у этого одна и она чинится. Но чинится не тем способом, который первым приходит в голову — я на этом попался и положил клиенту сервер на утро. Рассказываю по порядку.

Юридическая фирма, 29 рабочих мест, офис на Олимпийском проспекте. Специализация — арбитраж и корпоративные споры, то есть переписка у них не просто архив, а рабочий материал, который иногда доходит до суда.

Zimbra 8.8.15 Open Source, CentOS 7, store 310 гигабайт, индекс 26 гигабайт на отдельном разделе. Ящик управляющего партнёра — 41 гигабайт, около 96 тысяч писем, копившихся с 2014 года.

Позвонил сам партнёр, в пятницу вечером, довольно резко. Он готовил позицию по спору и искал письмо от контрагента, где тот в 2021 году соглашался на перенос сроков. Письмо он помнил, нашёл его глазами в папке за март 2021 года, открыл, прочитал. А поиск по фамилии отправителя это письмо не показывал. Как и ещё десяток соседних.

Первое, что я сделал, — попросил его повторить поиск при мне и посмотрел лог в ту же секунду:

[zimbra@mail ~]$ grep -i "corrupt index" /opt/zimbra/log/mailbox.log | tail -5
WARN [qtp1863702030-1642] [name=partner@lawfirm.ru;] mailbox - Possibly corrupt index:
 14 indexing operations failed in mailbox transaction
WARN [qtp1863702030-1642] [name=partner@lawfirm.ru;] index - Caught exception while
 indexing message id [178432] - indexing blocked. Possibly corrupt index?

Вот и диагноз, причём в первую же минуту. Индекс ящика повреждён, и письма, которые в него не попали, для поиска не существуют. Физически они целы, лежат в хранилище, открываются. Просто в указателе их нет.

Обратите внимание на номер в квадратных скобках. Он мне очень пригодится дальше, но в тот вечер я его пролистал.

Честно скажу: минут двадцать я потратил на версию, что дело в пользователе. Причины были — я до этого дважды выезжал на «поиск сломан», и оба раза он был не сломан.

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

Поэтому в Мытищах я начал с того же: попросил поискать по-разному. По адресу отправителя. По слову из темы. С областью поиска на весь ящик.

Ничего.

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

Мне это стоило двадцати минут и лёгкого раздражения партнёра, который к моменту проверки уже дважды повторил, что письмо он видит своими глазами.

Письмо в Zimbra хранится в трёх местах одновременно, и это важно понимать, чтобы дальше не было сюрпризов.

• Само тело письма со всеми вложениями — файлом в хранилище, в /opt/zimbra/store.
• Метаданные: кому, от кого, когда, в какой папке, прочитано или нет — строкой в базе данных.
• Полнотекстовый указатель для поиска — в отдельном каталоге, в /opt/zimbra/index.

Поиск работает только по третьему. Не по файлам в /opt/zimbra/store и не по таблице mail_item в базе — по указателю в /opt/zimbra/index/0/. Поэтому письмо может быть в полном порядке и при этом быть невидимым для поиска.

Ломается указатель по нескольким причинам, и все они бытовые: сервер выключился в момент записи в /opt/zimbra/index; кончилось место на индексном разделе; mailboxd упал по OutOfMemoryError в середине транзакции; попалось письмо, которое разборщик не смог обработать — обычно с экзотическим или битым вложением на 20–40 МБ.

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

Ещё одна деталь, про которую забывают. Индексный том отдельный от хранилища писем, и место под него считается отдельно. Обычная пропорция — от 8 до 12 процентов объёма почты. В Мытищах: 310 гигабайт писем и 26 гигабайт индекса, то есть чуть больше восьми процентов. Держите это соотношение в голове, оно нам понадобится, когда я дойду до своей ошибки.

Три команды под пользователем zimbra. Ничего не меняют.

# 1. Есть ли жалобы на индекс за последнее время
grep -icE "corrupt index|indexing blocked" /opt/zimbra/log/mailbox.log
grep -oP 'name=\S+?;' /opt/zimbra/log/mailbox.log | sort | uniq -c | sort -rn | head

# 2. Сколько места на индексном томе
df -h /opt/zimbra/index
du -sh /opt/zimbra/index /opt/zimbra/store

# 3. Внутренний номер ящика конкретного пользователя
zmprov gmi partner@lawfirm.ru

Последняя строка — та самая, из-за которой я в Мытищах получил лежащий сервер. Дальше расскажу как.

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

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

Написал цикл, запустил, проверил, что процессы пошли, и уехал домой в 21:30.

# то, чего делать было нельзя
for acct in $(zmprov -l gaa lawfirm.ru); do
    zmprov rim $acct start
done

В субботу в 9:15 позвонил дежурный юрист: почта не открывается вообще. Формально она лежала с часу ночи — просто в субботу до девяти утра туда никто не заглядывал.

[zimbra@mail ~]$ df -h /opt/zimbra/index
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/cl-index   40G   40G     0 100% /opt/zimbra/index

[zimbra@mail ~]$ tail -3 /opt/zimbra/log/mailbox.log
ERROR [ReIndex] [] index - Error deleting index before re-indexing
java.io.IOException: No space left on device

Что произошло. Я запускал эту пачку с мыслью «новый указатель соберётся рядом, старый уйдёт после» — и ошибался ровно наоборот. Zimbra сначала сносит существующий индекс ящика и только потом собирает его заново. Это буквально написано в строке, которую я получил: Error deleting index before re-indexing — упало на шаге удаления, потому что даже удаление требует записи (движок открывает индекс на пересоздание и должен положить новый служебный файл).

Место съел не «двойной объём», а пик сборки. Указатель строится сегментами, и время от времени сегменты сливаются в один; в момент слияния на диске одновременно лежат и исходные сегменты, и результат, так что временный расход кратно больше, чем весит готовый индекс. Двадцать девять таких сборок одновременно — двадцать девять независимых пиков на разделе, где свободного было 14 гигабайт из 40. К часу ночи место кончилось, дальше процессы падали один за другим, а mailboxd захлебнулся, потому что писать ему стало некуда.

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

Разгребал я это до 14:30 субботы: чистил незавершённые каталоги в /opt/zimbra/index/0/, поднимал mailboxd, запускал ящики по одному. Клиенту не выставил ничего. Это была моя ошибка, и платить за неё должен был я.

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

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

Вот здесь и пригодился номер из квадратных скобок, который я пролистал в пятницу.

# смотрим лог живьём во время переиндексации
tail -f /opt/zimbra/log/mailbox.log | grep -iE "indexing|reindex"

WARN [ReIndex] [name=partner@lawfirm.ru;] index - Caught exception while indexing
 message id [178432] - indexing blocked. Possibly corrupt index?
WARN [ReIndex] [name=partner@lawfirm.ru;] index - Caught exception while indexing
 message id [178432] - indexing blocked. Possibly corrupt index?

Один и тот же номер, раз за разом. Это внутренний идентификатор элемента почты, и по нему письмо можно вытащить и посмотреть:

[zimbra@mail ~]$ zmmailbox -z -m partner@lawfirm.ru getMessage 178432 | head -30

Письмо оказалось из мая 2021 года, от контрагента, с вложением на 34 МБ — архивом, внутри которого лежал повреждённый файл на 11 МБ. Открывалось оно нормально, читалось, вложение даже скачивалось. Разборщик текста вложений падал на нём стабильно, все 100% попыток.

Дальше — самая тонкая часть, и делать её надо руками пользователя, а не своими:

1. Партнёр сам открыл это письмо и сохранил его на диск отдельным файлом. Оно у него в деле, оно нужно.
2. Затем удалил его из ящика окончательно, минуя корзину.
3. Я перезапустил переиндексацию только этого ящика.

zmprov rim partner@lawfirm.ru start
# ждём
zmprov rim partner@lawfirm.ru status
# status: running
# numSucceeded: 68420
# numFailed: 0
# numRemaining: 27980
# ...
# status: idle

Полная переиндексация ящика на 41 гигабайт и 96 тысяч писем заняла 2 часа 40 минут. После неё поиск нашёл всё, включая то самое мартовское письмо про перенос сроков, из-за которого всё началось: оно лежало в слепой зоне вокруг другого проблемного вложения — виновников в этом ящике набралось одиннадцать, и майское было лишь первым, на котором процесс зацикливался.

Отдельно замечу: переиндексировать можно не только ящик целиком, но и конкретные элементы по их номерам. Это спасает, когда речь про два-три письма и не хочется гонять весь ящик несколько часов:

zmprov rim partner@lawfirm.ru start ids 178430,178431,178433

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

В этом случае каталог указателя чистят вручную. Найти его можно по внутреннему номеру ящика:

# узнаём номер ящика
[zimbra@mail ~]$ zmprov gmi partner@lawfirm.ru
mailboxId: 47
quotaUsed: 44023414784

# каталог указателя именно этого ящика
ls -la /opt/zimbra/index/0/47/index/0

# останавливаем mailboxd, иначе файлы заняты
zmmailboxdctl stop
rm -rf /opt/zimbra/index/0/47/index/0/*
zmmailboxdctl start

# и только теперь пересборка
zmprov rim partner@lawfirm.ru start

Три вещи, которые здесь легко испортить.

Номер ящика. Каталоги называются числами, и промахнуться на единицу очень легко. Снесёте указатель не того ящика — беды не будет, но человек на несколько часов останется без поиска, и объяснять это придётся вам.

Владелец каталога. Если чистили от root и каталог пересоздался с неправильным владельцем, пересборка упадёт с той же самой ошибкой, и вы будете ходить по кругу, думая, что дело в месте.

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

Цифры по Мытищам.

• Диагноз поставлен за 1 минуту по строке в логе. Ещё 20 минут я потратил на версию про пользователя.
• Ящиков с повреждённым указателем: 6 из 29.
• Писем, невидимых для поиска, в ящике партнёра: 1 187 из 96 400. Чуть больше процента, и все — вокруг одиннадцати проблемных вложений.
• Моя ошибка стоила клиенту 5 часов 15 минут нерабочей почты в субботу, а мне — субботы и неполученных 22 000 рублей.
• Переиндексация ящика на 41 ГБ: 2 часа 40 минут. Остальные пять ящиков — от 20 минут до полутора часов, по одному, в течение недели по ночам.
• Индексный раздел расширили с 40 до 80 ГБ, чтобы запас был не 14, а 54 гигабайта.
• Итоговый счёт: 28 000 рублей за неделю ночных работ.

Теперь про цену бездействия, и здесь она считается не в часах простоя. Слепые зоны в поиске у этой фирмы существовали больше года — самые старые записи в логе я нашёл за август 2021 года. Всё это время юристы искали в архиве и иногда не находили. Что именно они не нашли за год и во что это обошлось в спорах, где переписка была доказательством, никто уже не восстановит. Партнёр оценил один эпизод: в 2022 году они не смогли предъявить согласование по электронной почте и признали пункт, который стоил доверителю около 400 тысяч рублей. Утверждать, что виноват был индекс, я не берусь. Но искали они тогда именно то письмо и именно в том ящике.

Где эта работа перестаёт быть простой

Процедуру я описал целиком, и на одном ящике она делается за вечер. Осложняется в четырёх местах.

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

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

Место, где придётся говорить с пользователем. Проблемное письмо удаляет владелец ящика, а не инженер. Это письмо часто оказывается важным — у нас оно было приложением к спору. Разговор про «мне нужно, чтобы вы удалили вот это письмо» требует объяснений, и его лучше вести заранее, а не в час ночи.

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

Хотите понять, есть ли у вас слепые зоны в поиске прямо сейчас, — пришлите мне вывод двух команд: подсчёт совпадений по corrupt index в mailbox.log и df -h /opt/zimbra/index. За день отвечу, сколько ящиков затронуто, сколько часов займёт восстановление и в каком порядке это делать, чтобы не положить сервер, как это однажды сделал я.

Письма пропали или просто не ищутся?

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

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

Работать можно, почта принимается и отправляется как обычно. Что реально страдает — поиск в том ящике, который сейчас пересобирается: он будет отдавать неполные результаты, пока процесс не закончится. Время зависит от объёма: у меня в Мытищах ящик на 41 гигабайт и 96 тысяч писем пересобирался 2 часа 40 минут, ящики по 3-5 гигабайт — от двадцати минут до часа. Планируйте по грубой прикидке час на 15 гигабайт и делайте это ночью, потому что дисковую подсистему процесс нагружает всерьёз.

Почему нельзя переиндексировать все ящики разом, если всё равно ночь?

По двум причинам, и обе я проверил на себе. Первая: место. Старый указатель Zimbra сносит перед сборкой, но сама сборка идёт пиками — сегменты периодически сливаются, и в момент слияния на диске лежат и исходники, и результат. Двадцать девять параллельных сборок дают двадцать девять таких пиков сразу. У меня на разделе было 14 свободных гигабайт из 40, и место кончилось к часу ночи. Вторая: параллельное перечитывание всего хранилища кладёт дисковую подсистему на сто процентов, и к утру сервер непригоден для работы, даже если места хватило. Правильно — по одному ящику, с проверкой свободного места перед каждым запуском.

Как понять, что переиндексация зациклилась, а не просто идёт долго?

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

Можно ли обойтись без удаления проблемного письма?

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