zmcontrol status висит и врёт: PID-файлы, таймаут 60 секунд

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

Самая дорогая авария — та, которую сделали своими руками, поверив показаниям. Датчик показал ноль, человек начал спасать, и через два часа спасать действительно есть что.

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

Если вы хоть раз видели картину «в панели служб нет, а почта при этом ходит» — вы уже сталкивались с этим и, скорее всего, списали на глюк. Это не глюк. Это три разных механизма, и ни один из них не означает, что сервер сломан.

Разберу все три на конкретном сервере, включая то место, где я сам всё усугубил.

Декабрь 2021, Подольск: сутки простоя на ровном месте

Проектное бюро, 17 рабочих мест, офис на первом этаже жилого дома в Подольске. Своего администратора нет, есть приходящий.

Началось с отключения электричества на сорок минут. Сервер стоял без источника бесперебойного питания и погас жёстко.

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

• дважды перезапускал Zimbra целиком;
• перезагрузил сервер трижды;
• завершил процессы через kill -9, потому что «висли»;
• по совету из форума удалил какие-то файлы в каталоге логов — какие именно, не запомнил;
• сутки говорил директору, что «сервер умер, надо новый».

Меня позвали на вторые сутки. Первое, что я сделал, — не полез в панель, а проверил, работает ли почта. Она работала. Я отправил письмо с телефона на ящик директора, оно пришло за девять секунд. IMAP отвечал, веб-клиент открывался. Всё, кроме показаний приборов, было в порядке.

Конфигурация: Zimbra 8.8.15 Open Source Edition на CentOS 7, физический сервер, 16 ГБ памяти, 17 ящиков, store 84 ГБ. Скучно и типично.

Я начал с того, что показалось очевидным. Команда проверки состояния у Zimbra ходит в каталог LDAP, а обращение к LDAP идёт по TLS. Истёкший или битый сертификат ломает именно это и даёт очень характерную ошибку:

ERROR: Unable to start TLS: SSL connect attempt failed
error:14090086:SSL routines:ssl3_get_server_certificate:certificate verify failed
when connecting to ldap master.

Версия была разумная: питание пропало, служба сертификатов могла не подняться, а сертификаты Let's Encrypt имеют обыкновение протухать именно тогда, когда никто не смотрит. Проверил:

$ su - zimbra
$ zmcertmgr viewdeployedcrt ldap | head -20
# системный openssl на CentOS 7 — это 1.0.2, он не знает -starttls ldap,
# поэтому TLS к каталогу проверяю тем путём, которым ходит сама Zimbra:
$ ldapsearch -ZZ -x -H ldap://localhost:389 -b "" -s base 2>&1 | tail -2

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

Заодно отбросил вторую очевидную мысль — что не поднялся сам LDAP. Он поднялся, отвечал, данные отдавал:

$ ldapsearch -x -H ldap://localhost:389 -D uid=zimbra,cn=admins,cn=zimbra \
    -w $(zmlocalconfig -s zimbra_ldap_password | awk '{print $3}') \
    -b '' -s base '(objectclass=*)' | head -5

Каталог был на месте. То есть службы работали, а рапортовали о себе неправильно. Значит, ломался не сервер, а сам механизм отчёта.

Я сделал то, что почему-то делают редко, — засёк время выполнения проверки состояния:

$ su - zimbra
$ time zmcontrol status
Host mail.bureau.local
        antispam                Running
        antivirus               Running
        ldap                    Running
        logger                  Stopped
        mailbox                 Stopped
        mta                     Running
        ...
real    1m34.212s
user    0m6.088s
sys     0m2.774s

Девяносто четыре секунды. И вот здесь всё сходится. Внутри механизма сбора статуса зашит таймаут в 60 секунд. Если реальный сбор занимает дольше — а у нас он занимал полтора раза дольше, — код не успевает корректно разобрать вывод. Службы, отчёт по которым не приехал вовремя, отображаются остановленными. Не потому что они остановлены. Потому что о них не успели рассказать.

Обратите внимание, какие именно службы попали в «Stopped»: logger и mailbox — самые тяжёлые на опрос. Быстрые отвечают вовремя и показываются честно. Это, кстати, хороший диагностический признак: если у вас «остановлены» именно тяжёлые компоненты, а почта при этом ходит, — почти наверняка вы смотрите на таймаут, а не на аварию.

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

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

$ ps -u zimbra -o comm= | sort -u
$ ss -tlnp | grep -E ':(25|143|993|7071|389|8080|8443)\b'

Если процессы на месте, а порты слушаются — служба работает, что бы ни говорил статус.

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

Can't kill a non-numeric process ID at /opt/zimbra/bin/zmstatctl line 204.

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

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

Смотрим, что там на самом деле:

$ ls -l /opt/zimbra/log/*.pid
-rw-r--r-- 1 zimbra zimbra  6 дек 14 09:12 /opt/zimbra/log/logswatch.pid
-rw-r--r-- 1 zimbra zimbra  0 дек 14 09:12 /opt/zimbra/log/zmmailboxd.pid
-rw-r--r-- 1 zimbra zimbra  5 дек 14 09:12 /opt/zimbra/log/zmmailboxd_java.pid

# каждый файл — против живого процесса
$ for f in /opt/zimbra/log/*.pid; do
    p=$(cat "$f" 2>/dev/null)
    printf '%-45s [%s] ' "$f" "$p"
    ps -p "$p" -o comm= 2>/dev/null || echo 'НЕТ ПРОЦЕССА'
  done

Файл нулевого размера — вот он, виновник сообщения про нечисловой идентификатор.

Лечение выглядит просто, и в этой простоте кроется ловушка, в которую я и попал.

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

$ su - zimbra
$ rm -f /opt/zimbra/log/*.pid
$ zmcontrol start

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

$ ps -u zimbra -o pid,etime,comm | grep java
 2841  1-04:14:07 java
31556       00:52 java

Разница по времени работы — двадцать восемь часов против пятидесяти двух секунд. Красноречиво.

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

Правильный порядок, к которому я после этого пришёл и от которого не отступаю:

1. Сначала ps -u zimbra — узнать, что живо на самом деле.
2. Сопоставить каждый PID-файл с живым процессом циклом из предыдущего раздела.
3. Удалять только те файлы, за которыми процесса нет.
4. Если живые процессы есть, а стартовать надо с нуля — сначала штатно остановить их, дождаться пустого ps, и только потом чистить.

И отдельно: управлять Zimbra нужно из-под пользователя zimbra, а не от root. Запуск от root оставляет файлы с неверным владельцем, и следующий штатный старт спотыкается уже об это. Половина случаев «после чистки стало хуже» растёт именно отсюда.

Есть ещё один сценарий, который выглядит как «сервер завис», а на деле означает «подождите». Штатная остановка доходит до зимлетов и застревает:

$ zmcontrol shutdown
Host mail.bureau.local
        Stopping zmconfigd...Done.
        Stopping zimlet webapp...

И дальше ничего. Десять минут, пятнадцать. Человек за консолью решает, что процесс умер, и жмёт прерывание — а потом ещё и убивает процессы вручную. Так и рождаются битые PID-файлы из предыдущего раздела: круг замыкается.

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

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

Что проверять в этом случае:

$ systemctl status crond --no-pager | head -5
$ systemctl status rsyslog --no-pager | head -5
# если конфигурация syslog для Zimbra разъехалась, её пересобирает
# /opt/zimbra/libexec/zmsyslogsetup (запускать от root)
$ df -h /opt/zimbra /var/log
$ ls -l --time-style=+%H:%M /opt/zimbra/log/zmstat/ | tail -3

Правило простое: командной строке верить больше, чем панели, а системным утилитам — больше, чем командной строке Zimbra.

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

# 1. Что реально живо
ps -u zimbra -o pid,etime,comm --sort=etime | head -20

# 2. Слушаются ли порты
ss -tlnp | grep -E ':(25|143|993|7071|8443)\b'

# 3. Сколько на самом деле собирается статус
su - zimbra -c 'time zmcontrol status'

# 4. Есть ли осиротевшие PID-файлы
for f in /opt/zimbra/log/*.pid; do p=$(cat "$f" 2>/dev/null); \
  ps -p "$p" >/dev/null 2>&1 || echo "СИРОТА: $f = [$p]"; done

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

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

Дальше сделали три вещи, чтобы это не повторилось:

• купили источник бесперебойного питания с корректным завершением работы по сигналу — 24 тысячи рублей, аппарат до сих пор жив;
• завели мониторинг не по статусу Zimbra, а по портам и по факту доставки контрольного письма — проверка отвечает за 2 секунды и не умеет врать так, как умеет статус;
• написали администратору памятку на одну страницу: перед любым перезапуском сначала ps и ss.

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

Считали так: 17 человек × 8 часов ≈ 136 человеко-часов простоя при 600 рублях за час — около 81 тысячи рублей. Плюс уже почти подписанный счёт на новый сервер на 190 тысяч, который отменили в тот же вечер. Разбор стоил заказчику меньше десяти тысяч.

Меня в этой истории смущает не администратор. Он действовал ровно так, как подсказывал прибор. Смущает то, что прибор при этом штатный, поведение известное, а в панели администратора об этом ни слова.

• «Stopped» в статусе — не факт, а мнение. Факты дают ps и ss.
• Меряйте время сбора статуса. Больше минуты — показаниям верить нельзя, и это не поломка.
• Битые PID-файлы переживают перезагрузку. Отсюда ощущение «ребут не помогает»: он и не может помочь.
• Не удаляйте PID-файлы вслепую. Я это сделал и получил два mailboxd и десять минут реального простоя на сервере, который до меня работал.
• Мониторить надо результат, а не статус. Доставленное контрольное письмо доказывает работу почты; строка в панели не доказывает ничего.

И контр-совет к популярному «если что-то не так — перезагрузите сервер». Для почтового сервера это плохая первая мера. Перезагрузка не чинит осиротевшие файлы, не ускоряет сбор статуса и не обновляет кэш панели — зато гарантированно роняет то, что работало. В Подольске три перезагрузки не исправили ничего и добавили работы.

Если у вас прямо сейчас показывает, что служб нет, — не перезапускайте. Выполните четыре команды из проверки выше и пришлите мне вывод: список процессов, слушающие порты, время выполнения zmcontrol status и строки про сирот. За день отвечу, работает ваш сервер или действительно лежит, и что делать дальше. В половине случаев ответ будет «не трогайте, оно работает» — и это тоже ответ.

Панель показывает, что служб нет, а почта ходит. Кому верить?

Верьте почте и системным утилитам. Панель администратора не опрашивает службы в момент, когда вы на неё смотрите, — она показывает записанное ранее состояние. Если запись перестала обновляться (встал планировщик, забился раздел с логами, сломался системный лог), панель будет уверенно показывать вчерашнюю картину неограниченно долго. Проверяется за две секунды: ps -u zimbra покажет живые процессы, ss -tlnp — слушаются ли порты 25, 143, 993 и 8443. Если процессы есть и порты открыты, сервер работает, и трогать его не нужно.

Что означает «Can't kill a non-numeric process ID at /opt/zimbra/bin/zmstatctl line 204»?

Скрипт управления прочитал файл с идентификатором процесса в каталоге /opt/zimbra/log и не нашёл там числа: файл пустой или в нём обрывок записи. Так бывает после жёсткого выключения питания — процесс исчезает мгновенно и убрать за собой не успевает. Перезагрузка это не лечит, файлы никуда не деваются. Порядок такой: посмотреть ps -u zimbra, сверить каждый PID-файл с живым процессом, удалить только осиротевшие и стартовать из-под пользователя zimbra. Удалять всё подряд нельзя — можно получить второй экземпляр уже работающей службы.

Остановка зависла на «Stopping zimlet webapp...». Ждать или прерывать?

Подождите пять–семь минут. Этот шаг известен тем, что подвисает на десять–пятнадцать минут, и чаще всего он всё-таки завершается сам. Если не сдвинулось — прерывайте, но дальше не убивайте процессы наугад. Сначала посмотрите, что осталось живо, штатно завершите оставшееся, дождитесь пустого вывода ps -u zimbra, уберите осиротевшие PID-файлы и только потом стартуйте. Обратный порядок — прерывание, kill -9, немедленный старт — как раз и создаёт ту кашу, с которой потом приходят к подрядчику.

Почему сбор статуса вообще может занимать полторы минуты?

Потому что это не одно обращение, а последовательный опрос всех компонентов, и каждый отвечает со своей скоростью. Если сервер чем-то занят — идёт проверка целостности базы, переиндексация, диск загружен под сотню, — опрос растягивается. У клиента в Подольске после жёсткого выключения работала проверка базы, и сбор занимал 94 секунды; через сутки, когда она закончилась, время упало до 21 секунды и статус стал показывать правду сам. Честно скажу: я не уверен, что нашёл там единственную причину. Но связь с загрузкой диска видел уже на трёх серверах.

Как мониторить Zimbra, чтобы не получать ложные тревоги?

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