Егор Карпович
Коллеги, приветствую.
На прошлой неделе у нас произошел факап, который пытаемся разобрать до сих пор. В определенный момент стали недоступными VM, около половины osd вылетели в down, рандомно на разных нодах (всего нод 9шт, используем proxmox 6.2-10 и ceph 14.2.10). Ниже информация, которую удалось собрать по логам. Очень хочется разобраться в реальных причинах аварии, чтобы не повторялась впредь, помогите плз, знающие люди.
1. Утром (точного времени нет, высчитано по значению секунд в варнинге)
1 slow ops, oldest one blocked for число sec, mon.srv1 has slow ops (SLOW_OPS)
Узнать причину можно было только с помощью systemctl status ceph-mon@srv1
Но этот момент мы прошляпили.
2. 15:54 - на srv2 также возникает проблема 1 slow ops.
Сразу после этого количество слоу-опс растёт (1 - 4 - 10 - 20).
Далее интересный вывод, что srv3 запущен как стендбай менеджер, после чего уменьшается слоу-опс вновь до одного на srv1:
2020-11-10 15:55:01.753645 mon.srv1 (mon.0) 651093 : cluster [WRN] Health check update: 20 slow ops, oldest one blocked for 53 sec, mon.srv2 has slow ops (SLOW_OPS)
2020-11-10 15:55:01.924411 mon.srv1 (mon.0) 651095 : cluster [DBG] Standby manager daemon srv3 started
2020-11-10 15:55:02.928696 mon.srv1 (mon.0) 651096 : cluster [DBG] mgrmap e1021756: srv1(active, since 7d), standbys: srv3
2020-11-10 15:55:06.754888 mon.srv1 (mon.0) 651100 : cluster [WRN] Health check update: 10 slow ops, oldest one blocked for 633089 sec, daemons [mon.srv1,mon.srv2] have slow ops. (SLOW_OPS)
...
2020-11-10 15:55:11.755773 mon.srv1 (mon.0) 651108 : cluster [WRN] Health check update: 1 slow ops, oldest one blocked for 633094 sec, mon.srv1 has slow ops (SLOW_OPS)
но после этого:
2020-11-10 15:55:36.759233 mon.srv1 (mon.0) 651133 : cluster [WRN] Health check update: 7 slow ops, oldest one blocked for 633119 sec, daemons [mon.srv1,mon.srv2] have slow ops. (SLOW_OPS)
2020-11-10 15:55:36.783024 mon.srv1 (mon.0) 651134 : cluster [DBG] mgrmap e1021757: srv1(active, since 7d)
Дальше слоу-опс начинают расти как снежный ком.
3. 16:05 - osd 55 отправляется в down менеджером (srv1) в связи с тем, что не отвечает продолжительное время (901.836896 секунд), т.е. что то случилось с осд.55 примерно в 15:50. Согласно логам никаких операций на осд.55 не запускалось после 10 утра
4. 16:05 - ещё 6 осд отправляются в down менеджером (srv1). Дальше идет ком отвалов и растущих слоу-опс. Единственная интересная запись в окрестностях 15:50:
2020-11-10 15:49:20.316003 mon.srv1 (mon.0) 650741 : cluster [WRN] 1 clock skew 4.99269s > max 1s (монитор на srv1 сообщает о проблеме с часами на srv2).
Но! Такая запись возникала все сутки, да и все предыдущие. Повторяется и до этого, и после каждые 5 минут, а каждый час с сообщением "clock skew detected on mon.srv2".
5. 17:26 - сделали перезагрузку srv2, которая так же привела к тому, что в 17:26 mon.srv1 был объявлен новым лидером в кворуме. Это приводит к началу процесса уменьшения слоу-опс с 15000 в 17:25 до 197 в 17:29. Но эффект не долгий, постепенно слоу-опс поднимаются до отметки в 4-5 тысяч, происходит резкое уменьшение слоу-опс в промежутке 19:26-19:28 до 400.
6. Кластеру становится хорошо когда:
2020-11-10 19:28:30.139613 mon.srv1 (mon.0) 668399 : cluster [DBG] osd.55 failure report canceled by osd.40
Далее идут аналогичные сообщения, что осд srv2 отменяют свои репорты на другие осд. Слоу-опсы продолжают уменьшаться до 21шт..
7. 19:29 около 19:36 точно заработали VM (т.е. цеф прочихался). Учитывая проблемы выше с часами на srv2 и тем, что репорты об отказах других осд шли от осд srv2, хочется назвать srv2 виновником. НО!!!!!! Часы пришли в норму почти 2 часами ранее, а начало отмены репортов примерно совпадает с ребутом srv3
2020-11-10 19:28:42.401430 mon.srv1 (mon.0) 668433 : cluster [WRN] Health check update: 1 host (6 osds) down (OSD_HOST_DOWN)
Стоит отметить, что отдельных логов по осд, мон и мгр не ведется - только общий лог, видимо это неправильно, но что имеем, то имеем.
Штатный экстрасенс в отпуске, сорри :)